[Ev3nt]

Fix server hang on request over an already-broken external connection

Problem

Consider two hosts. Host 1 executes an external request to host 2, and while that request is in progress the connection to host 2 (from host 1) is terminated, e.g. via DELETE FROM MON$ATTACHMENTS. If host 1 then tries to send any further packet to host 2 (for example, on COMMIT or ROLLBACK), the DBMS hangs.

Cause

By the time the packet is sent, the connection to host 2 has already been broken. The server still sends the request to the socket and then waits indefinitely for a response.

Reproduction

Run the following on host 1 (and, while it is running, delete the corresponding attachment via MON$ATTACHMENTS):

set term ^;
EXECUTE BLOCK
AS
  DECLARE i INTEGER = 1;
  DECLARE v_name VARCHAR(200);
  DECLARE v_sql VARCHAR(500);
BEGIN
  WHILE (i <= 1000000) DO
  BEGIN
    v_name = 'Doc_' || i;
    v_sql = 'INSERT INTO document (id, name) VALUES (' || i || ', ''' || v_name || ''');';
   EXECUTE STATEMENT (v_sql)
      ON EXTERNAL 'host2:' || rdb$get_context('SYSTEM', 'DB_NAME') AS USER 'SYSDBA' PASSWORD 'masterkey';
    i = i + 1;
  END
END^
commit^
set term ;^

[hvlad]

I want to be sure that issue reason is identified correctly, thus questions:

Host 1 executes an external request to host 2, and while that request is in progress the connection to host 1 is terminated
...
By the time the packet is sent, the connection to host 2 has already been broken

What connection is broken - "user -> host1" or "host1 -> host2" ?

waits indefinitely for a response

Where indefinite waits happens ? Call stack, please

[Ev3nt]

What connection is broken - "user -> host1" or "host1 -> host2" ?

Host1 -> host2.

Where indefinite waits happens ? Call stack, please

In the poll().

Call stack

Thread 11 (Thread 0x7f3b17054700 (LWP 1217497) "firebird"):
#0  0x00007f3d5f3c6051 in poll () from /lib64/libc.so.6
#1  0x00007f3d5f770792 in Select::select (timeout=<optimized out>, this=<optimized out>) at src/remote/inet.cpp:462
#2  packet_receive (port=0x7f39e3731bc0, buffer=0x7f38ef222040 "b\300h\aA\344E\030\230$ 43h\347+\003", buffer_length=8192, length=0x7f3b170525ce) at src/remote/inet.cpp:3061
#3  0x00007f3d5f7717af in packet_receive2 (port=0x7f39e3731bc0, p=0x7f38ef222040 "b\300h\aA\344E\030\230$ 43h\347+\003", bufSize=8192, length=0x7f3b17052650) at src/remote/inet.cpp:2840
#4  0x00007f3d5f780e6f in REMOTE_inflate (port=0x7f39e3731bc0, packet_receive=packet_receive@entry=0x7f3d5f771740 <packet_receive2(rem_port*, UCHAR*, SSHORT, SSHORT*)>, buffer=buffer@entry=0x7f3bcd57e340 "", buffer_length=<optimized out>, length=length@entry=0x7f3b170526be) at src/remote/remote.cpp:1673
#5  0x00007f3d5f76c296 in inet_read (xdrs=0x7f3cf1172fb0) at src/remote/inet.cpp:2823
#6  InetXdr::x_getbytes (bytecount=<optimized out>, buff=0x7f3b1705271c "=\177", this=<optimized out>) at src/remote/inet.cpp:2656
#7  InetXdr::x_getbytes (this=0x7f3cf1172fb0, buff=<optimized out>, bytecount=<optimized out>) at src/remote/inet.cpp:2599
#8  0x00007f3d5f84465f in GETLONG (lp=<synthetic pointer>, xdrs=0x7f3cf1172fb0) at src/common/xdr.cpp:80
#9  xdr_enum (xdrs=0x7f3cf1172fb0, ip=0x7f3a56e480c0) at src/common/xdr.cpp:473
#10 0x00007f3d5f778aef in xdr_protocol (xdrs=0x7f3cf1172fb0, p=p@entry=0x7f3a56e480c0) at src/remote/protocol.cpp:295
#11 0x00007f3d5f76bf95 in receive (main_port=0x7f39e3731bc0, packet=0x7f3a56e480c0) at src/include/../common/classes/auto.h:154
#12 0x00007f3d5f797ab3 in Remote::receive_packet_with_callback (port=0x7f39e3731bc0, packet=0x7f3a56e480c0) at src/remote/client/interface.cpp:9295
#13 0x00007f3d5f79d8d3 in Remote::receive_packet_noqueue (port=0x7f39e3731bc0, packet=0x7f397b609080) at src/remote/client/interface.cpp:9413
#14 0x00007f3d5f7a14e6 in Remote::receive_packet (packet=0x7f397b609080, port=0x7f39e3731bc0) at src/remote/client/interface.cpp:9273
#15 Remote::receive_response (status=0x7f3b17052df8, rdb=0x7f397b609040, packet=0x7f397b609080) at src/remote/client/interface.cpp:9561
#16 0x00007f3d5f7b031d in Remote::release_object (id=<optimized out>, op=op_rollback, rdb=0x7f397b609040, status=0x7f3b17052df8) at src/remote/client/interface.cpp:9653
#17 Remote::Transaction::freeClientData (this=0x7f39807e6aa0, status=0x7f3b17052df0, force=<optimized out>) at src/remote/client/interface.cpp:6826
#18 0x00007f3d5f7b0693 in Remote::Transaction::rollback (this=0x7f39807e6aa0, status=0x7f3b17052df0) at src/remote/client/interface.cpp:6864
#19 0x00007f3d5f7bd62e in Firebird::ITransactionBaseImpl<Remote::Transaction, Firebird::CheckStatusWrapper, Firebird::IReferenceCountedImpl<Remote::Transaction, Firebird::CheckStatusWrapper, Firebird::Inherit<Firebird::IVersionedImpl<Remote::Transaction, Firebird::CheckStatusWrapper, Firebird::Inherit<Firebird::ITransaction> > > > >::clooprollbackDispatcher (self=<optimized out>, status=0x7f3b17052ff8) at src/include/firebird/IdlFbInterfaces.h:11380
#20 0x00007f3d5f72e5f7 in Firebird::ITransaction::rollback<Firebird::CheckStatusWrapper> (status=0x7f3b17052ff0, this=0x7f39807e6aa8) at src/include/firebird/IdlFbInterfaces.h:1421
#21 Firebird::ITransaction::rollback<Firebird::CheckStatusWrapper> (status=0x7f3b17052ff0, this=0x7f39807e6aa8) at src/include/firebird/IdlFbInterfaces.h:1407
#22 operator() (__closure=0x7f3b17052f20) at src/yvalve/why.cpp:5430
#23 std::__invoke_impl<void, Why::YTransaction::rollback(Firebird::CheckStatusWrapper*)::<lambda()>&> (__f=...) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/invoke.h:60
#24 std::__invoke_r<void, Why::YTransaction::rollback(Firebird::CheckStatusWrapper*)::<lambda()>&> (__fn=...) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/invoke.h:110
#25 std::_Function_handler<void(), Why::YTransaction::rollback(Firebird::CheckStatusWrapper*)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/std_function.h:291
#26 0x00007f3d5f75ead5 in std::function<void ()>::operator()() const (this=<optimized out>) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/std_function.h:622
#27 Why::done<Why::YTransaction>(Firebird::CheckStatusWrapper*, Why::YEntry<Why::YTransaction>&, Why::YTransaction*, std::function<void ()>, std::function<void ()>) (status=0x7f3b17052ff0, entry=..., y=0x7f3c79b42630, newClose=..., oldClose=...) at src/yvalve/why.cpp:1362
#28 0x00007f3d5f7418f3 in Why::YTransaction::rollback (this=0x7f3c79b42630, status=<optimized out>) at src/yvalve/why.cpp:5429
#29 0x00007f3d5f741be1 in isc_rollback_transaction (userStatus=<optimized out>, traHandle=0x7f3966530c38) at src/include/../common/classes/RefCounted.h:189
#30 0x00007f3d50b48baf in EDS::IscProvider::isc_rollback_transaction (this=<optimized out>, user_status=<optimized out>, tra_handle=<optimized out>) at src/jrd/extds/IscDS.cpp:875
#31 0x00007f3d50b4a26e in EDS::IscTransaction::doRollback (this=0x7f3966530bf0, status=0x7f3b170534d0, tdbb=<optimized out>, retain=<optimized out>) at src/jrd/extds/IscDS.cpp:410
#32 0x00007f3d50b3f56f in EDS::Transaction::rollback (this=0x7f3966530bf0, tdbb=0x7f3b17053c98, retain=<optimized out>) at src/jrd/extds/ExtDS.cpp:1659
#33 0x00007f3d50b34d55 in EDS::Connection::clearTransactions (this=0x7f39a58cbfb0, tdbb=0x7f3b17053c98) at src/jrd/extds/ExtDS.cpp:763
#34 0x00007f3d50b373f3 in EDS::Connection::detach (tdbb=0x7f3b17053c98, this=0x7f39a58cbfb0) at src/jrd/extds/ExtDS.cpp:804
#35 EDS::Connection::deleteConnection (tdbb=0x7f3b17053c98, conn=0x7f39a58cbfb0) at src/jrd/extds/ExtDS.cpp:632
#36 0x00007f3d50b3d993 in EDS::Provider::releaseConnection (this=0x7f3d505a4590, tdbb=0x7f3b17053c98, conn=..., inPool=<optimized out>) at src/jrd/extds/ExtDS.cpp:558
#37 0x00007f3d50b389b5 in EDS::Provider::jrdAttachmentEnd (this=0x7f3d505a4590, tdbb=0x7f3b17053c98, att=0x7f3cb6dc20c0, forced=false) at src/jrd/extds/ExtDS.cpp:480
#38 0x00007f3d50b340da in EDS::Manager::jrdAttachmentEnd (tdbb=tdbb@entry=0x7f3b17053c98, att=att@entry=0x7f3cb6dc20c0, forced=forced@entry=false) at src/jrd/extds/ExtDS.cpp:277
#39 0x00007f3d508c77ee in purge_attachment (tdbb=<optimized out>, sAtt=0x7f3ba4919ff0, flags=<optimized out>) at src/jrd/jrd.cpp:8836
#40 0x00007f3d508cd1d6 in (anonymous namespace)::shutdownAttachments (arg=0x7f3a8e944d40, signal=<optimized out>) at src/jrd/../jrd/jrd.h:817
#41 0x00007f3d508ce3dd in (anonymous namespace)::attachmentShutdownThread (arg=arg@entry=0x7f3b4a12d0a0) at src/jrd/jrd.cpp:9364
#42 0x00007f3d50d38f59 in (anonymous namespace)::ThreadArgs::run (this=<synthetic pointer>) at src/common/ThreadStart.cpp:78
#43 (anonymous namespace)::threadStart (arg=0x7f3a2a8f0070) at src/common/ThreadStart.cpp:94
#44 0x00007f3d5f4a258e in start_thread () from /lib64/libpthread.so.0

[hvlad]

What connection is broken - "user -> host1" or "host1 -> host2" ?

Host1 -> host2.

So, what connection was terminated ? You wrote:

connection to host 1 is terminated

but this is definitely not "host1 -> host2"

Where indefinite waits happens ? Call stack, please

In the poll().
Call stack

The line numbers in inet.cpp have nothing common with master branch.
If connection on the host2 was terminated, there are two cases
a) TCP socket was not closed yet - isc_shutdown should be returned
b) TCP socket was closed - OS should return error, isn't is ?
Even is there is no error from OS, but host1 is hung in poll() already - how your path could avoid it ?

If connection on the host1 is terminating, there is no reason for it to not get answer from connection to the host2.

All of this is very confusing...

[dyemanov]

Connection user->host1 is killed, as a result signalShutdown() calls force_close() for connection host1->host2. Surprisingly, subsequent attempts to send op_rollback / op_disconnect (during attachment cleanup) hang (maybe temporarily, waiting for TCP timeout?) instead of returning an error. This is how it looks like.

[aafemt]

Surprisingly, subsequent attempts to send op_rollback / op_disconnect (during attachment cleanup) hang (maybe temporarily, waiting for TCP timeout?) instead of returning an error.

Perhaps this is because SEL_CHECK_MASK doesn't include POLLERR/POLLHUP/POLLNVAL so returned error is not handled at all and the loop is endless.

[hvlad]

This confirms that the patch is not enough to fix the actual reason of the issue.

[dyemanov]

If the hang comes from poll(), this means that (somehow) op_rollback / op_disconnect were already sent over a forcibly closed socket and we're waiting for the reply. The patch does solve it by preventing sending the cleanup packets (the flag check inside send* calls). But it does not solve the issue with poll() in general.