Firebird's internal timer incorrectly resets existing timer entries [CORE6182] #6427

firebird-automations · 2019-11-03T14:46:16Z

According to %FB4_HOME%\doc\sql.extensions\README.external_connections_pool, parameter ExtConnPoolLifeTime is "idle connection lifetime, seconds".
It seems that if 'main' database performs PSQL which uses EDS to several (>=2) different databases then value of ExtConnPoolLifeTime is applied to the LAST moment when activity was, regardless to some concrete database.
Connection(s) to some DB that was handled before any others will exist until *all* activity will gone, rather than to *this* ("earliest") DB.

Steps to reproduce:
1) prepare firebird.conf:

Servermode = Super #⁠ or SuperClassic
ExtConnPoolSize = 10
ExtConnPoolLifeTime = 10

2) restart FB if it is running as service;

3) run following script (change path and names of temp databases if needed):

set bail on;

shell del c:\\temp\\tmp4eds\_01\.fdb 2\>nul;
shell del c:\\temp\\tmp4eds\_02\.fdb 2\>nul;
shell del c:\\temp\\tmp4eds\_03\.fdb 2\>nul;
shell del c:\\temp\\tmp4eds\_04\.fdb 2\>nul;
shell del c:\\temp\\tmpmain\.fdb 2\>nul;

create database 'localhost:c:\\temp\\tmp4eds\_01\.fdb' user SYSDBA password 'masterkey';
commit;
create database 'localhost:c:\\temp\\tmp4eds\_02\.fdb' user SYSDBA password 'masterkey';
commit;
create database 'localhost:c:\\temp\\tmp4eds\_03\.fdb' user SYSDBA password 'masterkey';
commit;
create database 'localhost:c:\\temp\\tmp4eds\_04\.fdb' user SYSDBA password 'masterkey';
commit;

create database 'localhost:c:\\temp\\tmpmain\.fdb' user SYSDBA password 'masterkey';
commit;

create table tdelay\(id int primary key\);
commit;
create sequence g;
commit;

set term ^;
create procedure sp\_delay returns\( dts1 timestamp, dts2 timestamp, elap\_ms int \) as
    declare v\_id int;
begin
    v\_id = gen\_id\(g,1\);
    dts1 = cast\('now' as timestamp\);
    insert into tdelay\(id\) values\( :v\_id \);
    in autonomous transaction do
    begin
        insert into tdelay\(id\) values\( :v\_id \);
        when any do
        begin
        end
    end
    delete from tdelay where id = :v\_id;
    dts2 = cast\('now' as timestamp\);
    elap\_ms = datediff\( millisecond from dts1 to dts2\);
    suspend;
end
^

create procedure sp\_do\_eds \( a\_target\_db varchar\(128\) \) returns\( source\_dts timestamp, source\_db varchar\(128\), target\_db varchar\(128\), target\_dts timestamp \) as
begin
    source\_dts = cast\('now' as timestamp\);
    for 
        execute statement 
            \('select cast\(? as varchar\(128\)\) as connect\_from\_db, mon$database\_name as connect\_to\_db, cast\(''now'' as timestamp\) from mon$database'\)
            \( rdb$get\_context\('SYSTEM', 'DB\_NAME'\)  \)
            on external
                'localhost:' \|\| a\_target\_db
            as
                user 'sysdba'
                password' masterkey'
        into source\_db, target\_db,  target\_dts
   do
       suspend;
end
^

set term ;^
commit;
\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

set list on;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_01\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_02\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_03\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set transaction lock timeout 8;
select \* from sp\_do\_eds\( 'c:\\temp\\tmp4eds\_04\.fdb' \);
select p\.\* from sp\_delay p;
commit;

set heading off;

set bail off;

drop database; \-\-\-\-\-\-\-\-\-\- tmpmain

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_01\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_02\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_03\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-\-

rollback;
connect 'localhost:c:\\temp\\tmp4eds\_04\.fdb';
select 'Point before DROP ' \|\| rdb$get\_context\('SYSTEM', 'DB\_NAME'\) \|\| ': ' \|\| cast\('now' as timestamp\) from rdb$database;

set echo on;
drop database;
set echo off;

=======

Console will be filled with messages

SOURCE_DTS 2019-11-03 14:28:41.4960
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_01.FDB
TARGET_DTS 2019-11-03 14:28:41.9100 -------------------------------------------------------- [ 1 ]
. . .
SOURCE_DTS 2019-11-03 14:29:06.5020
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_04.FDB
TARGET_DTS 2019-11-03 14:29:06.7940

-- and after this:

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_01.FDB: 2019-11-03 14:29:14.8240 --------------------- [ 2 ]

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_01.FDB is in use

So, we can see here that:
1) last ctivity in TMP4EDS_01.FDB was at "2019-11-03 14:28:41.9100" (see line marked as "[ 1 ]" )
2) attempt to drop this DB was at 2019-11-03 14:29:14.8240 ( line "[ 2 ]" )

datediff() between these values is ~33 seconds. This is much more than 10 seconds which was assigned to ExtConnPoolLifeTime.

Commits: 1c13dbb 0d33f4e

====== Test Details ======

Currently test is only for FB 4.0. One need to found other test case for FB 3.x because ExpPool feature not accessible there.

The text was updated successfully, but these errors were encountered:

firebird-automations · 2019-11-03T15:25:44Z

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

firebird-automations · 2019-11-05T21:48:15Z

Commented by: @hvlad

I can't reproduce the issue.

This is what i see

====================================================================

SOURCE_DTS 2019-11-05 20:40:21.9130
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_01.FDB
TARGET_DTS 2019-11-05 20:40:22.0720

DTS1 2019-11-05 20:40:22.0740
DTS2 2019-11-05 20:40:30.0770
ELAP_MS 8003

SOURCE_DTS 2019-11-05 20:40:30.0790
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_02.FDB
TARGET_DTS 2019-11-05 20:40:30.2140

DTS1 2019-11-05 20:40:30.2150
DTS2 2019-11-05 20:40:38.2160
ELAP_MS 8001

SOURCE_DTS 2019-11-05 20:40:38.2190
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_03.FDB
TARGET_DTS 2019-11-05 20:40:38.3590

DTS1 2019-11-05 20:40:38.3600
DTS2 2019-11-05 20:40:46.3610
ELAP_MS 8001

SOURCE_DTS 2019-11-05 20:40:46.3640
SOURCE_DB C:\TEMP\TMPMAIN.FDB
TARGET_DB C:\TEMP\TMP4EDS_04.FDB
TARGET_DTS 2019-11-05 20:40:46.5040

DTS1 2019-11-05 20:40:46.5130
DTS2 2019-11-05 20:40:54.5130
ELAP_MS 8000

Use CONNECT or CREATE DATABASE to specify a database

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_01.FDB: 2019-11-05 20:40:54.6610

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_02.FDB: 2019-11-05 20:40:54.7970

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_03.FDB: 2019-11-05 20:40:54.8930

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_03.FDB is in use
After line 123 in file C:\Temp\core-6182.sql
set echo off;

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_04.FDB: 2019-11-05 20:40:55.0910

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_04.FDB is in use
After line 133 in file C:\Temp\core-6182.sql
set echo off;

====================================================================

i.e. databases 01 and 02 was dropped succesfully and 03 and 04 failed to drop due to presence of (idle) external connections to it.

Note, external connection become idle not when its statement is executed but when local transaction is finished.
Thus, when script start to drop databases, there are two idle external connections in pool : db03 (2 seconds to expire) and db04 (10 seconds to expire).

All works as expected.

firebird-automations · 2019-11-06T01:02:24Z

Commented by: @pavel-zotov

In your result I see that there was no error when script did this:

CONCATENATION Point before DROP C:\TEMP\TMP4EDS_01.FDB: 2019-11-05 20:40:54.6610

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database

It's strange! Please look in the sreen that i've created just now for actual FB 4.x.

PS. Used config:

BugCheckAbort = 1
RemoteServicePort = 3400
FileSystemCacheThreshold = 65536K
IpcName = fb40_SS
ServerMode = Super
DefaultDbCachePages = 20000
TempBlockSize = 2M
TempCacheLimit = 2147483647
LockHashSlots = 22111
LockMemSize = 5M
ExtConnPoolSize = 10
ExtConnPoolLifeTime = 10
ReadConsistency = 0
TempDirectories=C:\TEMP\firebird
MaxUnflushedWrites = -1
MaxUnflushedWriteTime = -1
AuthServer = Legacy_Auth, Srp, Win_Sspi
UserManager = Legacy_UserManager, Srp
AuthClient = Legacy_Auth, Srp, Srp256, Win_Sspi
ExternalFileAccess = Full
WireCrypt = Enabled
KeyHolderPlugin = KeyHolder

firebird-automations · 2019-11-06T01:02:36Z

Modified by: @pavel-zotov

Attachment: c6182-check.png [ 13398 ]

firebird-automations · 2019-11-06T01:09:12Z

Commented by: @pavel-zotov

PS. WI-T4.0.0.1639 Firebird 4.0 Beta 1

firebird-automations · 2019-11-06T16:36:05Z

Commented by: @hvlad

The issue is reproducidble with Legacy_Auth plugin.

The real problem is inside TimerControl implementation in Firebird.
It incorrectly resets existing timer entries and because of this some events could happen much later then it should be.

Legacy_Auth plugin creates own timer to release cached connection to the security database.
Due to test case nature this timer resets every 8 seconds (when external connection is authenticated) and prevents firing of EDS connection pool timer.

Looks like the same issue was described at CORE6082

firebird-automations · 2019-11-06T17:22:11Z

Commented by: @hvlad

The issue with timers should be present in v3 also.
Of course it should be reproduced in some other way.

firebird-automations · 2019-11-06T17:22:11Z

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

Fix Version: 3.0.5 [ 10885 ]

Fix Version: 4.0 Beta 2 [ 10888 ]

firebird-automations · 2019-11-09T13:29:21Z

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

QA Status: No test => Done successfully

firebird-automations · 2019-11-09T13:29:28Z

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Closed [ 6 ]

firebird-automations · 2019-11-09T13:31:07Z

Modified by: @pavel-zotov

status: Closed [ 6 ] => Closed [ 6 ]

QA Status: Done successfully => Done with caveats

Test Details: Currently test is only for FB 4.0. One need to found other test case for FB 3.x because ExpPool feature not accessible there.

firebird-automations · 2019-12-13T11:55:51Z

Modified by: @dyemanov

summary: ExtConnPoolLifeTime acts as countdown for activity in MOST RECENT database (of several) rather then separate for each of used databases => Firebird's internal timer incorrectly resets existing timer entries

firebird-automations closed this as completed Nov 9, 2019

firebird-automations added affect-version: 4.0 Beta 1 fix-version: 3.0.5 fix-version: 4.0 Beta 2 resolution: fixed priority: major component: engine type: bug qa: done with caveats labels Apr 25, 2021

firebird-automations assigned hvlad Apr 25, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Firebird's internal timer incorrectly resets existing timer entries [CORE6182] #6427

Firebird's internal timer incorrectly resets existing timer entries [CORE6182] #6427

firebird-automations commented Nov 3, 2019

firebird-automations commented Nov 3, 2019

firebird-automations commented Nov 5, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 9, 2019

firebird-automations commented Nov 9, 2019

firebird-automations commented Nov 9, 2019

firebird-automations commented Dec 13, 2019

Firebird's internal timer incorrectly resets existing timer entries [CORE6182] #6427

Firebird's internal timer incorrectly resets existing timer entries [CORE6182] #6427

Comments

firebird-automations commented Nov 3, 2019

Steps to reproduce: 1) prepare firebird.conf:

Servermode = Super #⁠ or SuperClassic ExtConnPoolSize = 10 ExtConnPoolLifeTime = 10

3) run following script (change path and names of temp databases if needed):

Console will be filled with messages

-- and after this:

drop database; Statement failed, SQLSTATE = 40001 lock time-out on wait transaction -object C:\TEMP\TMP4EDS_01.FDB is in use

firebird-automations commented Nov 3, 2019

firebird-automations commented Nov 5, 2019

firebird-automations commented Nov 6, 2019

In your result I see that there was no error when script did this:

drop database; set echo off; Use CONNECT or CREATE DATABASE to specify a database

PS. Used config:

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 6, 2019

firebird-automations commented Nov 9, 2019

firebird-automations commented Nov 9, 2019

firebird-automations commented Nov 9, 2019

firebird-automations commented Dec 13, 2019

Steps to reproduce:
1) prepare firebird.conf:

Servermode = Super #⁠ or SuperClassic
ExtConnPoolSize = 10
ExtConnPoolLifeTime = 10

drop database;
Statement failed, SQLSTATE = 40001
lock time-out on wait transaction
-object C:\TEMP\TMP4EDS_01.FDB is in use

drop database;
set echo off;
Use CONNECT or CREATE DATABASE to specify a database