TSqlDatabasePool timer event

[eerimez]

I have a concern that the TSqlDatabasePool is not working.It seems that the timerEvent method should be called every ten seconds. But, from what I can observe, it appears to only be called once.

I have added some debugging to some of the class methods to trace calls.

init:

void TSqlDatabasePool::init()
{
    tSystemDebug("TSqlDatabasePool::init");

...

    if (aval) {
        // Starts the timer to close extra-connection
        tSystemDebug("TSqlDatabasePool::init - timer.start");
        timer.start(10000, this);
    }
}

database:

QSqlDatabase TSqlDatabasePool::database(int databaseId)
{
    tSystemDebug("TSqlDatabasePool::database");

timerEvent:

void TSqlDatabasePool::timerEvent(QTimerEvent *event)
{
    tSystemDebug("TSqlDatabasePool::timerEvent");

Running TreeFrog using the blog tutorial example,

2019-11-28 22:15:05 DEBUG [390] Max number of app servers: 1
2019-11-28 22:15:05 INFO  [390] TreeFrog Framework version 1.27.0
2019-11-28 22:15:05 INFO  [390] Execution environment: Qt 5.13.2 / Manjaro Linux
2019-11-28 22:15:05 DEBUG [390] system bus open : /tmp/treefrog_systembus_390
2019-11-28 22:15:05 DEBUG [390] TreeFrog application servers starting up.  port:8800
2019-11-28 22:15:05 DEBUG [390] serverCount: 0
2019-11-28 22:15:05 DEBUG [390] export LD_LIBRARY_PATH=.
2019-11-28 22:15:05 DEBUG [390] tfserver started
2019-11-28 22:15:05 DEBUG [390] serverCount: 1
2019-11-28 22:15:05 INFO  [390] TreeFrog application servers started up.
2019-11-28 22:15:05 DEBUG [400] Logger added: FileLogger
2019-11-28 22:15:05 DEBUG [400] Web Root: /home/user/CLionProjects/tf2blog/
2019-11-28 22:15:05 DEBUG [400] MaxThreads: 5
2019-11-28 22:15:05 DEBUG [400] Library loaded: /home/user/CLionProjects/tf2blog/lib/libcontroller.so
2019-11-28 22:15:05 DEBUG [400] Library loaded: /home/user/CLionProjects/tf2blog/lib/libview.so
2019-11-28 22:15:05 DEBUG [400] Available controllers: 
2019-11-28 22:15:05 DEBUG [418] Found method: staticInitialize()
2019-11-28 22:15:05 DEBUG [418] Invoke method: applicationcontroller.staticInitialize
2019-11-28 22:18:25 DEBUG [420] incomingConnection  sd:12  thread count:0  max:5
2019-11-28 22:18:25 DEBUG [420] thread ptr: 94271728060544
2019-11-28 22:18:25 DEBUG [1216] THttpSocket  sid:0
2019-11-28 22:18:25 DEBUG [1216] content-length: 0
2019-11-28 22:18:25 DEBUG [1216] HTTP request count: 1
2019-11-28 22:18:25 DEBUG [1216] method : GET
2019-11-28 22:18:25 DEBUG [1216] path : /Blog/index
2019-11-28 22:18:25 DEBUG [1216] Routing: controller:  action:
2019-11-28 22:18:25 DEBUG [1216] Active Controller : blogcontroller
2019-11-28 22:18:25 DEBUG [1216] Found method: index()
2019-11-28 22:18:25 DEBUG [1216] Invoke method: blogcontroller.index

Pool is initialized:

2019-11-28 22:18:25 DEBUG [1216] TSqlDatabasePool::init
2019-11-28 22:18:25 DEBUG [1216] SQL database available
2019-11-28 22:18:25 DEBUG [1216] SQL driver name:QPSQL  dbname:blogx
2019-11-28 22:18:25 DEBUG [1216] Database HostName: 192.168.0.28
2019-11-28 22:18:25 DEBUG [1216] Database Port: 0
2019-11-28 22:18:25 DEBUG [1216] Database UserName: blogx
2019-11-28 22:18:25 DEBUG [1216] Database Password: blogx
2019-11-28 22:18:25 DEBUG [1216] Database ConnectOptions: 
2019-11-28 22:18:25 DEBUG [1216] Database postOpenStatements: 
2019-11-28 22:18:25 DEBUG [1216] Database enableUpsert: 0
2019-11-28 22:18:25 DEBUG [1216] Add Database successfully. name:rdb00_0
...
2019-11-28 22:18:25 DEBUG [1216] Add Database successfully. name:rdb00_4
2019-11-28 22:18:25 DEBUG [1216] SQL driver name:QPSQL  dbname:blog
2019-11-28 22:18:25 DEBUG [1216] Database HostName: 192.168.0.28
2019-11-28 22:18:25 DEBUG [1216] Database Port: 0
2019-11-28 22:18:25 DEBUG [1216] Database UserName: blog
2019-11-28 22:18:25 DEBUG [1216] Database Password: blog
2019-11-28 22:18:25 DEBUG [1216] Database ConnectOptions: 
2019-11-28 22:18:25 DEBUG [1216] Database postOpenStatements: 
2019-11-28 22:18:25 DEBUG [1216] Database enableUpsert: 0
2019-11-28 22:18:25 DEBUG [1216] Add Database successfully. name:rdb01_0
...
2019-11-28 22:18:25 DEBUG [1216] Add Database successfully. name:rdb01_4

Event timer is started:

2019-11-28 22:18:25 DEBUG [1216] TSqlDatabasePool::init - timer.start
2019-11-28 22:18:25 DEBUG [1216] TSqlDatabasePool::database
2019-11-28 22:18:25 DEBUG [1216] SQL database opened successfully (env:dev)
2019-11-28 22:18:25 DEBUG [1216] Gets database: rdb01_4
2019-11-28 22:18:25 DEBUG [1216] No such object class : layouts_blogView
2019-11-28 22:18:25 DEBUG [1216] No such object class : layouts_applicationView
2019-11-28 22:18:25 DEBUG [1216] Not found default layout. Renders without layout.
2019-11-28 22:18:25 DEBUG [1216] Pooled database: rdb01_4
2019-11-28 22:18:25 DEBUG [1216] Session garbage collector : rand = 8

Timer event is called once and not again:

2019-11-28 22:18:34 DEBUG [1216] TSqlDatabasePool::timerEvent
2019-11-28 22:18:35 DEBUG [1216] KeepAlive timeout : socket:0
2019-11-28 22:18:35 DEBUG [1216] THttpSocket deleted  sid:0
2019-11-28 22:22:23 DEBUG [420] incomingConnection  sd:12  thread count:0  max:5
2019-11-28 22:22:23 DEBUG [420] thread ptr: 94271728060544
2019-11-28 22:22:23 DEBUG [2484] THttpSocket  sid:1
2019-11-28 22:22:23 DEBUG [2484] content-length: 0
2019-11-28 22:22:23 DEBUG [2484] HTTP request count: 1
2019-11-28 22:22:23 DEBUG [2484] method : GET
2019-11-28 22:22:23 DEBUG [2484] path : /Blog/index
2019-11-28 22:22:23 DEBUG [2484] Routing: controller:  action:
2019-11-28 22:22:23 DEBUG [2484] Active Controller : blogcontroller
2019-11-28 22:22:23 DEBUG [2484] Found method: index()
2019-11-28 22:22:23 DEBUG [2484] Invoke method: blogcontroller.index
2019-11-28 22:22:23 DEBUG [2484] TSqlDatabasePool::database
2019-11-28 22:22:23 DEBUG [2484] Gets cached database: rdb01_4
2019-11-28 22:22:23 DEBUG [2484] No such object class : layouts_blogView
2019-11-28 22:22:23 DEBUG [2484] No such object class : layouts_applicationView
2019-11-28 22:22:23 DEBUG [2484] Not found default layout. Renders without layout.
2019-11-28 22:22:23 DEBUG [2484] Pooled database: rdb01_4
2019-11-28 22:22:23 DEBUG [2484] Session garbage collector : rand = 27
2019-11-28 22:22:33 DEBUG [2484] KeepAlive timeout : socket:1
2019-11-28 22:22:33 DEBUG [2484] THttpSocket deleted  sid:1
2019-11-28 22:58:41 DEBUG [420] incomingConnection  sd:12  thread count:0  max:5
2019-11-28 22:58:41 DEBUG [420] thread ptr: 94271728060544
2019-11-28 22:58:41 DEBUG [11048] THttpSocket  sid:2
2019-11-28 22:58:41 DEBUG [11048] content-length: 0
2019-11-28 22:58:41 DEBUG [11048] HTTP request count: 1
2019-11-28 22:58:41 DEBUG [11048] method : GET
2019-11-28 22:58:41 DEBUG [11048] path : /Blog/index
2019-11-28 22:58:41 DEBUG [11048] Routing: controller:  action:
2019-11-28 22:58:41 DEBUG [11048] Active Controller : blogcontroller
2019-11-28 22:58:41 DEBUG [11048] Found method: index()
2019-11-28 22:58:41 DEBUG [11048] Invoke method: blogcontroller.index
2019-11-28 22:58:41 DEBUG [11048] TSqlDatabasePool::database
2019-11-28 22:58:41 DEBUG [11048] Gets cached database: rdb01_4
2019-11-28 22:58:41 DEBUG [11048] No such object class : layouts_blogView
2019-11-28 22:58:41 DEBUG [11048] No such object class : layouts_applicationView
2019-11-28 22:58:41 DEBUG [11048] Not found default layout. Renders without layout.
2019-11-28 22:58:41 DEBUG [11048] Pooled database: rdb01_4
2019-11-28 22:58:41 DEBUG [11048] Session garbage collector : rand = 81
2019-11-28 22:58:51 DEBUG [11048] KeepAlive timeout : socket:2
2019-11-28 22:58:51 DEBUG [11048] THttpSocket deleted  sid:2

Should the eventTimer method be called every 10 seconds? If so, did I discover a problem? Or, is my methodology flawed?

[treefrogframework]

Thank you so much! You are correct.
Fixed the bug in 3272384.
So, the database connection is closed if it is not used for approximately 30 seconds.

[eerimez]

Thank you.