Uploaded image for project: 'RHEL'
  1. RHEL
  2. RHEL-67639

rsyslog "omfwd/tls" hangs forever during the TLS handshake

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Undefined Undefined
    • rhel-9.7
    • rhel-9.5
    • rsyslog
    • None
    • rhel-sst-security-special-projects
    • ssg_security
    • None
    • False
    • Hide

      None

      Show
      None
    • None
    • Red Hat Enterprise Linux
    • None
    • None
    • None
    • None

      What were you trying to do that didn't work?

      When forwarding logs to a TLS server, it appears that the rsyslog client will wait forever on TLS handshake function if the TLS server doesn't send any "greeting".
      A customer hit this issue when connecting to the TLS server behind a F5 Big-IP load balancer: for some reason the F5 isn't forwarding the connection, which causes no handshake to occur.

      In order to avoid this, we need to implement a timeout in the TLS handshake.

      What is the impact of this issue to you?

      Forwarding of logs doesn't happen

      Please provide the package NVR for which the bug is seen:

      All rsyslog releases

      How reproducible is this bug?:

      Always

      Steps to reproduce

      1. Configure a client to forward logs to a dummy (fake) TLS server 
        *.* action(type="omfwd" protocol="tcp" target="127.0.0.1" port="6514"
       StreamDriver="gtls" StreamDriverMode="1" StreamDriverAuthMode="anon")
      2. Start a dummy (fake) TLS server not doing any TLS handshake 
        # ncat -4 -lkv 6514
      3. Start rsyslog

      Expected results

      Every couple of seconds/minutes, rsyslog breaks the connection to 127.0.0.1:6514 and tries to reconnect.

      Actual results

      Thread 3 waits forever reading on the socket, waiting for the handshake to be performed (Frame 11):

      (gdb) t 3
[Switching to thread 3 (Thread 0x7effd1cb8640 (LWP 4811))]
#0  __libc_recv (flags=<optimized out>, len=5, buf=0x7effc403cf0b, fd=9) at ../sysdeps/unix/sysv/linux/recv.c:28
28	  return SYSCALL_CANCEL (recvfrom, fd, buf, len, flags, NULL, NULL);
(gdb) bt
#0  __libc_recv (flags=<optimized out>, len=5, buf=0x7effc403cf0b, fd=9) at ../sysdeps/unix/sysv/linux/recv.c:28
#1  __libc_recv (fd=9, buf=0x7effc403cf0b, len=5, flags=0) at ../sysdeps/unix/sysv/linux/recv.c:23
#2  0x00007effd27877cf in _gnutls_stream_read (ms=0x7effd1cb734c, pull_func=0x7effd26708f0 <system_read>, size=5, bufel=<synthetic pointer>, session=0x7effc4038180) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/buffers.c:332
#3  _gnutls_read (ms=0x7effd1cb734c, pull_func=0x7effd26708f0 <system_read>, size=5, bufel=<synthetic pointer>, session=0x7effc4038180) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/buffers.c:408
#4  _gnutls_io_read_buffered.constprop.0 (session=session@entry=0x7effc4038180, total=5, ms=0x7effd1cb734c, recv_type=<optimized out>) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/buffers.c:561
#5  0x00007effd2647240 in recv_headers (ms=<optimized out>, record=0x7effd1cb7370, htype=GNUTLS_HANDSHAKE_HELLO_RETRY_REQUEST, type=GNUTLS_HANDSHAKE, record_params=0x7effc4033270, session=0x7effc4038180)
    at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/record.c:1159
#6  _gnutls_recv_in_buffers (session=0x7effc4038180, type=GNUTLS_HANDSHAKE, htype=GNUTLS_HANDSHAKE_HELLO_RETRY_REQUEST, ms=<optimized out>) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/record.c:1288
#7  0x00007effd264cb55 in _gnutls_handshake_io_recv_int (session=session@entry=0x7effc4038180, htype=GNUTLS_HANDSHAKE_HELLO_RETRY_REQUEST, hsk=hsk@entry=0x7effd1cb75a0, optional=optional@entry=1)
    at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/buffers.c:1409
#8  0x00007effd264e84f in _gnutls_recv_handshake (session=0x7effc4038180, type=<optimized out>, optional=1, buf=0x0) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/handshake.c:1585
#9  0x00007effd2658d36 in handshake_client (session=0x7effc4038180) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/handshake.c:3076
#10 gnutls_handshake (session=0x7effc4038180) at /usr/src/debug/gnutls-3.8.3-4.el9_4.x86_64/lib/handshake.c:2876
#11 0x00007effd2e437c0 in Connect (pNsd=0x7effc402d2f0, family=0, port=<optimized out>, host=0x562acbba6e40 "127.0.0.1", device=<optimized out>) at /usr/src/debug/rsyslog-8.2310.0-4.el9.x86_64/runtime/nsd_gtls.c:2306
#12 0x0000562aca7b087a in TCPSendInit (pvData=0x7effc4000d20) at /usr/src/debug/rsyslog-8.2310.0-4.el9.x86_64/tools/omfwd.c:843
#13 0x0000562aca7b1237 in doTryResume (pWrkrData=0x7effc4000d20) at /usr/src/debug/rsyslog-8.2310.0-4.el9.x86_64/tools/omfwd.c:1009
#14 0x0000562aca80866b in actionDoRetry (pThis=pThis@entry=0x562acbba8200, pWti=pWti@entry=0x562acbbacc80) at ../runtime/../action.c:868
#15 0x0000562aca808b11 in actionTryResume (pWti=0x562acbbacc80, pThis=0x562acbba8200) at ../runtime/../action.c:1046
#16 actionPrepare (pThis=pThis@entry=0x562acbba8200, pWti=pWti@entry=0x562acbbacc80) at ../runtime/../action.c:1074
#17 0x0000562aca80db9b in actionPrepare (pWti=<optimized out>, pThis=<optimized out>) at ../runtime/../action.c:1696
#18 processMsgMain (pAction=pAction@entry=0x562acbba8200, pWti=pWti@entry=0x562acbbacc80, pMsg=pMsg@entry=0x7effcc0175d0, ttNow=ttNow@entry=0x7effd1cb79e0) at ../runtime/../action.c:1683
#19 0x0000562aca80df52 in doSubmitToActionQ (pAction=0x562acbba8200, pWti=0x562acbbacc80, pMsg=0x7effcc0175d0) at ../runtime/../action.c:1855
#20 0x0000562aca803c08 in execAct (pWti=0x562acbbacc80, pMsg=0x7effcc0175d0, stmt=0x562acbba54f0) at ../runtime/ruleset.c:209
#21 scriptExec (root=<optimized out>, pMsg=pMsg@entry=0x7effcc0175d0, pWti=pWti@entry=0x562acbbacc80) at ../runtime/ruleset.c:599
#22 0x0000562aca804d77 in processBatch (pBatch=0x562acbbaccb0, pWti=0x562acbbacc80) at ../runtime/ruleset.c:660
#23 0x0000562aca7b2ecc in msgConsumer (notNeeded=<optimized out>, pBatch=0x562acbbaccb0, pWti=0x562acbbacc80) at /usr/src/debug/rsyslog-8.2310.0-4.el9.x86_64/tools/rsyslogd.c:779
#24 0x0000562aca7fe186 in ConsumerReg (pThis=0x562acbba0530, pWti=0x562acbbacc80) at ../runtime/queue.c:2158
#25 0x0000562aca7fb6ec in wtiWorker (pThis=0x562acbbacc80) at ../runtime/wti.c:430
#26 0x0000562aca7fbc51 in wtpWorker (arg=0x562acbbacc80) at ../runtime/wtp.c:435
#27 0x00007effd2c89c02 in start_thread (arg=<optimized out>) at pthread_create.c:443
#28 0x00007effd2d0ded4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100

            [RHEL-67639] rsyslog "omfwd/tls" hangs forever during the TLS handshake

            RHEL Jira bot added a comment -

            Issues in the RHEL project can only have one value in the FixVersion/s field, the latest version has been set.

            RHEL Jira bot added a comment - Issues in the RHEL project can only have one value in the FixVersion/s field, the latest version has been set.

            Attila Lakatos added a comment -

            I created an upstream PR, https://github.com/rsyslog/rsyslog/pull/5494 , which sets the connection to be non-blocking before doing the actual handshake.

            Attila Lakatos added a comment - I created an upstream PR, https://github.com/rsyslog/rsyslog/pull/5494 , which sets the connection to be non-blocking before doing the actual handshake.

            Attila Lakatos added a comment -

            The bug is indeed reproducible if the fake server is created before rsyslog starts running. The GnuTLS handshake will not return in any means because the connection was not set to be non-blocking. Even though rsyslog continues to collect other logs (from other souces) during this process, it is not able to output them. Eventually the internal buffer (main queue) will be full and messages can get lost.

            Thanks Renaud for the very precise description and investigation, much appreciated.

            Attila Lakatos added a comment - The bug is indeed reproducible if the fake server is created before rsyslog starts running. The GnuTLS handshake will not return in any means because the connection was not set to be non-blocking. Even though rsyslog continues to collect other logs (from other souces) during this process, it is not able to output them. Eventually the internal buffer (main queue) will be full and messages can get lost. Thanks Renaud for the very precise description and investigation, much appreciated.

              rh-ee-alakatos Attila Lakatos
              rhn-support-rmetrich Renaud Métrich
              Attila Lakatos Attila Lakatos
              SSG Security QE SSG Security QE
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

                Created:
                Updated: