How to troubleshoot the setup tool?

Jerome.Jargot's picture
Jerome.Jargot
Tuesday, April 9, 2019 - 10:00
Blog Categories: 
Troubleshooting

Component: PostGreSQL | Version: 9.3
Component: Bonita | Version: 7.8.3

Downloading the configuration from Bonita engine database into the local disk using setup.sh pull is super slow: arround 60 seconds.

Answer

Usually, this action is taking less than 2 seconds.

Change configuration to make the tool general all traces

The setup tool is using logback mechanism.
Replace the content of the BonitaSubscription-7.8.3-Tomcat-8.5.34/setup/logback.xml file with:

<configuration debug="false" scan="false">
    <statusListener class="ch.qos.logback.core.status.NopStatusListener" />
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d %logger [%level] %msg%n</pattern>
        </encoder>
    </appender>
    <timestamp key="bySecond" datePattern="yyyyMMddHHmmss"/>
    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
            <file>setup_${bySecond}.log</file>
            <encoder>
                <pattern>%d %logger [%level] %msg%n</pattern>
            </encoder>
        </appender>
    <root level="TRACE">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
    </root>
</configuration>

Make the PostGreSQL server trace each and every connection attempt

Edit the postgresql.conf file
Enable log_connection

log_connections = on

Add timestamp if not already present in the messages, add %m

log_line_prefix = '%m'

Instruct PostGreSQL to reload the configuration

pg_ctl reload

Validate that the configuration had been reloaded

grep reload pg_log/postgresql-2019-03-25_091512.log

Output

2019-03-25 16:01:18.295 UTCLOG:  received SIGHUP, reloading configuration files

Run again setup.sh pull

cd  BonitaSubscription-7.8.3-Tomcat-8.5.34/setup
./setup.sh pull

ls setup_*log

Output

setup_20190325104053.log

Analyze the messages both sides

setup_20190325104053.log file

It can be seen that each connection needs 6 seconds to be established:

2019-03-25 11:00:53,902 org.apache.tomcat.jdbc.pool.PooledConnection [DEBUG] Instantiating driver using class: org.postgresql.Driver [url=jdbc:postgresql://SRV-BONITA01:5432/bonita]
2019-03-25 11:00:53,902 org.apache.tomcat.jdbc.pool.ClassLoaderUtil [DEBUG] Attempting to load class[org.postgresql.Driver] from sun.misc.Launcher$AppClassLoader@2503dbd3
2019-03-25 11:00:59,871 org.apache.tomcat.jdbc.pool.PooledConnection [DEBUG] Instantiating driver using class: org.postgresql.Driver [url=jdbc:postgresql://SRV-BONITA01:5432/bonita]
2019-03-25 11:00:59,871 org.apache.tomcat.jdbc.pool.ClassLoaderUtil [DEBUG] Attempting to load class[org.postgresql.Driver] from sun.misc.Launcher$AppClassLoader@2503dbd3

postgresql-2019-03-25_091512.log file

It can be seen that PostGreSQL server needs 6 seconds to authorize each new connection

2019-03-25 11:00:53.909 UTCLOG: connection received: host=172.17.0.2 port=42216
2019-03-25 11:00:59.865 UTCLOG: connection authorized: user=bonita database=bonita

Resolution

In your situation, this line was found into the pg_hba.conf file:

hostnossl all all mylaptop.my-net.fr    trust

After having removed the line; the connection duration to postgresql server came back to normal.
It seems that PostGreSQL server is issuing a gethostbyname for each connection attempt: 6 seconds was needed because a DNS request was sent.

Notifications