Fatal lock manager error: invalid lock id

[hvlad]

User reported about Firebird crash with message in firebird.log: "Fatal lock manager error: invalid lock id".
The crash dump was provided and stack trace allows to find the reason of the issue.

One thread commit some DDL command that ALTERs some relation.
It acquires relation's "rescan" lock in EX mode to notify other attachments about changes (frame 18).
Lock manager releases existing lock request (SR) and waits while new lock request (EX) will be granted (frames 14 and up):

Thread stack

Thread 6 (Thread 0x7f1cf5502700 (LWP 6859)):
#0  0x00007f2a1980e54d in __lll_lock_wait () from /lib64/libpthread.so.0
#1  0x00007f2a19809eb6 in _L_lock_941 () from /lib64/libpthread.so.0
#2  0x00007f2a19809daf in pthread_mutex_lock () from /lib64/libpthread.so.0
#3  0x00007f2a117f362d in enter (aReason=<optimized out>, this=<optimized out>) at /usr/home/firebird/v4.0-release/src/include/../common/classes/locks.h:209
#4  LockTableGuard (owner=-1, f=<optimized out>, lm=0x7f2a1ac70440, this=0x7f1cf54fd650) at /usr/home/firebird/v4.0-release/src/lock/../lock/lock_proto.h:305
#5  Jrd::LockManager::downgrade (this=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1cf54fd8f0, statusVector=statusVector@entry=0x7f1cf54fd770, request_offset=request_offset@entry=30191936)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:654
#6  0x00007f2a11559dac in DOWNGRADE (lock=0x7f1e67499a20, tdbb=0x7f1cf54fd8f0) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:180
#7  LCK_downgrade (tdbb=tdbb@entry=0x7f1cf54fd8f0, lock=0x7f1e67499a20) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:454
#8  0x00007f2a11384321 in Jrd::Attachment::blockingAstMonitor (ast_object=0x7f1f2c057b40) at /usr/home/firebird/v4.0-release/src/jrd/Attachment.cpp:979
#9  0x00007f2a117f139f in Jrd::LockManager::blocking_action (this=this@entry=0x7f2a1ac70440, tdbb=0x7f1cf55000a0, blocking_owner_offset=blocking_owner_offset@entry=29897528)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:1408
#10 0x00007f2a117f1a45 in Jrd::LockManager::signal_owner (this=this@entry=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1cf55000a0, blocking_owner=blocking_owner@entry=0x7f2a06af6338)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:3244
#11 0x00007f2a117f1cf8 in Jrd::LockManager::post_blockage (this=this@entry=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1cf55000a0, request=request@entry=0x7f2a0632f7d8, 
    lock=lock@entry=0x7f2a04f71230) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:2715
#12 0x00007f2a117f1fc9 in Jrd::LockManager::wait_for_request (this=this@entry=0x7f2a1ac70440, tdbb=0x7f1cf55000a0, request=request@entry=0x7f2a0632f7d8, lck_wait=lck_wait@entry=1)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:3807
#13 0x00007f2a117f28a1 in Jrd::LockManager::grant_or_que (this=this@entry=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1cf55000a0, request=request@entry=0x7f2a0632f7d8, 
    lock=lock@entry=0x7f2a04f71230, lck_wait=lck_wait@entry=1) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:2239
#14 0x00007f2a117f2bcf in Jrd::LockManager::enqueue (this=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1cf55000a0, statusVector=statusVector@entry=0x7f1cf54fdf40, 
    prior_request=prior_request@entry=12934312, series=series@entry=27, value=value@entry=0x7f1e495cca78 "\371\001", length=4, type=6 '\006', ast_routine=
    0x7f2a11566c40 <rescan_ast_relation(void*)>, ast_argument=0x7f1e37a8b400, data=0, lck_wait=1, owner_offset=30475128) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:535
#15 0x00007f2a1155b886 in enqueue (wait=1, level=6, lock=0x7f1e495cca00, statusVector=0x7f1cf54fdf40, tdbb=0x7f1cf55000a0) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:947
#16 ENQUEUE (wait=1, level=6, lock=0x7f1e495cca00, statusVector=0x7f1cf54fdf40, tdbb=0x7f1cf55000a0) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:149
#17 LCK_lock (tdbb=tdbb@entry=0x7f1cf55000a0, lock=0x7f1e495cca00, level=level@entry=6, wait=wait@entry=1) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:673
#18 0x00007f2a114d3ccc in make_version (tdbb=0x7f1cf55000a0, phase=<optimized out>, work=<optimized out>, transaction=<optimized out>)
    at /usr/home/firebird/v4.0-release/temp/Release/jrd/dfw.cpp:11089
#19 0x00007f2a114ca176 in DFW_perform_work (tdbb=tdbb@entry=0x7f1cf55000a0, transaction=transaction@entry=0x7f1e3d653ec0) at /usr/home/firebird/v4.0-release/temp/Release/jrd/dfw.cpp:4977
#20 0x00007f2a115d1b42 in TRA_commit (tdbb=tdbb@entry=0x7f1cf55000a0, transaction=transaction@entry=0x7f1e3d653ec0, retaining_flag=retaining_flag@entry=true)
    at /usr/home/firebird/v4.0-release/src/jrd/tra.cpp:488
#21 0x00007f2a1152a5af in commit (retaining_flag=true, transaction=0x7f1e3d653ec0, tdbb=0x7f1cf55000a0) at /usr/home/firebird/v4.0-release/src/jrd/jrd.cpp:6766

Another thread prepare SELECT statements that refers the same relation.
It need to scan relation metadata and acquires "rescan" lock in SR mode (frames 18, 17).
This lock request is not compatible with EX request of first thread, thus AST is send to the attachment of first thread.
AST handler attempts to release "rescan" lock (frame 8).
But Lock object of 1st attachment still contains (already released) lock_id and lock manager reported fatal error (frame 3).

Thread stack

#0  0x00007f2a19468387 in raise () from /lib64/libc.so.6
#1  0x00007f2a19469a78 in abort () from /lib64/libc.so.6
#2  0x00007f2a118d6fc5 in fb_utils::logAndDie (text=0x7f1d0f94c100 "Fatal lock manager error: invalid lock id (12934312), errno: 22\n--Invalid argument")
    at /usr/home/firebird/v4.0-release/src/common/utils.cpp:1716
#3  0x00007f2a117ebd38 in Jrd::LockManager::bug (this=this@entry=0x7f2a1ac70440, statusVector=statusVector@entry=0x0, string=string@entry=0x7f1d0f94e140 "invalid lock id (12934312)")
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:1643
#4  0x00007f2a117ec08b in Jrd::LockManager::get_request (this=this@entry=0x7f2a1ac70440, offset=offset@entry=12934312) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:2146
#5  0x00007f2a117efb61 in Jrd::LockManager::dequeue (this=0x7f2a1ac70440, request_offset=request_offset@entry=12934312) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:719
#6  0x00007f2a1155c12b in DEQUEUE (lock=0x7f1e495cca00, tdbb=0x7f1d0f94e470) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:169
#7  LCK_release (tdbb=tdbb@entry=0x7f1d0f94e470, lock=0x7f1e495cca00) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:805
#8  0x00007f2a11566c88 in rescan_ast_relation (ast_object=0x7f1e37a8b400) at /usr/home/firebird/v4.0-release/temp/Release/jrd/met.cpp:9989
#9  0x00007f2a117f139f in Jrd::LockManager::blocking_action (this=this@entry=0x7f2a1ac70440, tdbb=0x7f1d0f950520, blocking_owner_offset=blocking_owner_offset@entry=30475128)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:1408
#10 0x00007f2a117f1a45 in Jrd::LockManager::signal_owner (this=this@entry=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1d0f950520, blocking_owner=blocking_owner@entry=0x7f2a06b83378)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:3244
#11 0x00007f2a117f1cf8 in Jrd::LockManager::post_blockage (this=this@entry=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1d0f950520, request=request@entry=0x7f2a052ec4c0, 
    lock=lock@entry=0x7f2a04f71230) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:2715
#12 0x00007f2a117f2186 in Jrd::LockManager::wait_for_request (this=this@entry=0x7f2a1ac70440, tdbb=0x7f1d0f950520, request=request@entry=0x7f2a052ec4c0, lck_wait=lck_wait@entry=1)
    at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:4010
#13 0x00007f2a117f28a1 in Jrd::LockManager::grant_or_que (this=this@entry=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1d0f950520, request=request@entry=0x7f2a052ec4c0, 
    lock=lock@entry=0x7f2a04f71230, lck_wait=lck_wait@entry=1) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:2239
#14 0x00007f2a117f2bcf in Jrd::LockManager::enqueue (this=0x7f2a1ac70440, tdbb=tdbb@entry=0x7f1d0f950520, statusVector=statusVector@entry=0x7f1d0f94eac0, prior_request=prior_request@entry=0, 
    series=series@entry=27, value=value@entry=0x7f2075f8fc58 "\371\001", length=4, type=2 '\002', ast_routine=0x7f2a11566c40 <rescan_ast_relation(void*)>, ast_argument=0x7f2075f73b80, 
    data=0, lck_wait=1, owner_offset=11456648) at /usr/home/firebird/v4.0-release/src/lock/lock.cpp:535
#15 0x00007f2a1155b886 in enqueue (wait=1, level=2, lock=0x7f2075f8fbe0, statusVector=0x7f1d0f94eac0, tdbb=0x7f1d0f950520) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:947
#16 ENQUEUE (wait=1, level=2, lock=0x7f2075f8fbe0, statusVector=0x7f1d0f94eac0, tdbb=0x7f1d0f950520) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:149
#17 LCK_lock (tdbb=tdbb@entry=0x7f1d0f950520, lock=0x7f2075f8fbe0, level=level@entry=2, wait=wait@entry=1) at /usr/home/firebird/v4.0-release/src/jrd/lck.cpp:673
#18 0x00007f2a1156befb in MET_scan_relation (tdbb=tdbb@entry=0x7f1d0f950520, relation=0x7f2075f73b80) at /usr/home/firebird/v4.0-release/temp/Release/jrd/met.cpp:9591
#19 0x00007f2a1142e328 in Jrd::RelationSourceNode::parse (tdbb=0x7f1d0f950520, csb=0x7f1fb5689940, blrOp=<optimized out>, parseContext=<optimized out>)
    at /usr/home/firebird/v4.0-release/src/jrd/RecordSourceNodes.cpp:523
#20 0x00007f2a11590f12 in PAR_rse (tdbb=0x7f1d0f950520, csb=csb@entry=0x7f1fb5689940, rse_op=67) at /usr/home/firebird/v4.0-release/src/jrd/par.cpp:1330

[hvlad]

The bug was reported against HQbird LI-V4.0.6.3222 but the corresponding code is old enough and present in all supported versions of Firebird.