[Bug 1888926] Re: tls.tlscfgcmd not recognized; rebuild rsyslog against librelp 1.5.0

Tue Aug 4 02:20:26 UTC 2020

Hello,

I checked the backtrace of a crashed dhcpd running on 4.4.1-2.1ubuntu5.

(gdb)  info threads
  Id   Target Id                        Frame 
* 1    Thread 0x7fb4ddecb700 (LWP 3170) __GI_raise (sig=sig at entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
  2    Thread 0x7fb4dd6ca700 (LWP 3171) __lll_lock_wait (futex=futex at entry=0x7fb4de6d2028, private=0) at lowlevellock.c:52
  3    Thread 0x7fb4de6cc700 (LWP 3169) futex_wake (private=<optimized out>, processes_to_wake=1, futex_word=<optimized out>) at ../sysdeps/nptl/futex-internal.h:364
  4    Thread 0x7fb4de74f740 (LWP 3148) futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fb4de6cd0d0) at ../sysdeps/nptl/futex-internal.h:183

(gdb) frame 2
#2  0x00007fb4dec85985 in isc_assertion_failed (file=file at entry=0x7fb4decd8878 "../../../../lib/isc/unix/socket.c", line=line at entry=3361, type=type at entry=isc_assertiontype_insist, 
    cond=cond at entry=0x7fb4decda033 "!sock->pending_send") at ../../../lib/isc/assertions.c:52
(gdb) bt
#1  0x00007fb4deaa7859 in __GI_abort () at abort.c:79
#2  0x00007fb4dec85985 in isc_assertion_failed (file=file at entry=0x7fb4decd8878 "../../../../lib/isc/unix/socket.c", line=line at entry=3361, type=type at entry=isc_assertiontype_insist, 
    cond=cond at entry=0x7fb4decda033 "!sock->pending_send") at ../../../lib/isc/assertions.c:52
#3  0x00007fb4decc17e1 in dispatch_send (sock=0x7fb4de6d4990) at ../../../../lib/isc/unix/socket.c:4041
#4  process_fd (writeable=<optimized out>, readable=<optimized out>, fd=11, manager=0x7fb4de6d0010) at ../../../../lib/isc/unix/socket.c:4054
#5  process_fds (writefds=<optimized out>, readfds=0x7fb4de6d1090, maxfd=13, manager=0x7fb4de6d0010) at ../../../../lib/isc/unix/socket.c:4211
#6  watcher (uap=0x7fb4de6d0010) at ../../../../lib/isc/unix/socket.c:4397
#7  0x00007fb4dea68609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#8  0x00007fb4deba4103 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(gdb) frame 3
#3  0x00007fb4decc17e1 in dispatch_send (sock=0x7fb4de6d4990) at ../../../../lib/isc/unix/socket.c:4041
4041	in ../../../../lib/isc/unix/socket.c
(gdb) p sock->pending_send
$2 = 1

The code is crashing on this assertion: https://gitlab.isc.org/isc-projects/bind9/-/blob/v9_11_3/lib/isc/unix/socket.c#L3364
This was already reported and marked as fixed in debian (?) via [0]

""Now if a wakeup event occurres the socket would be dispatched for
processing regardless which kind of event (timer?) triggered the wakeup.
At least I did not find any sanity checks in process_fds() except
SOCK_DEAD(sock).

This leads to the following situation: The sock is not dead yet but it
is still pending when it is dispatched again.

I would now check sock->pending_send before calling dispatch_send().This
 would at least prevent the assertion failure - well knowing that the
situation described above ( not dead but still pending and alerting ) is
not a very pleasant one - until someone comes up with a better solution.
"""

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=430065#20

** Follow up questions:

0) The reproducer doesn't seems consistent and seems to be related to a race 
condition associated with a internal timer/futex. 
1) Can anyone confirm that a pristine upstream 4.4.1 doesn't reproduces the issue?

** Bug watch added: Debian Bug tracker #430065
   https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=430065

-- 
You received this bug notification because you are a member of Ubuntu
Sponsors Team, which is subscribed to the bug report.
https://bugs.launchpad.net/bugs/1888926

Title:
  tls.tlscfgcmd not recognized; rebuild rsyslog against librelp 1.5.0

Status in rsyslog package in Ubuntu:
  Fix Released
Status in rsyslog source package in Focal:
  In Progress
Status in rsyslog source package in Groovy:
  Fix Released

Bug description:
  [Description]

  Problem is according to https://launchpad.net/ubuntu/+source/librelp/+publishinghistory,
  librelp-dev 1.5.0 was published into focal at 2020-04-21, but reverse dependencies
  (such as rsyslog) weren't rebuilt after this new version was published

  # dpkg -l | grep librelp
  ii librelp-dev:amd64 1.5.0-1ubuntu2 amd64 Reliable Event Logging Protocol (RELP) library - development files
  ii librelp0:amd64 1.5.0-1ubuntu2 amd64 Reliable Event Logging Protocol (RELP) library

  rsyslogd: error during parsing file /etc/rsyslog.d/FILENAME.conf, on
  or before line 22: imrelp: librelp does not support input parameter
  'tls.tlscfgcmd'; it probably is too old (1.5.0 or higher should be
  fine); ignoring setting now. [v8.2001.0 try
  https://www.rsyslog.com/e/2207 ]

  [Reproducer]

  Setup a focal machine with rsyslog, using the following configuration:

  ----
  module(load="imrelp" tls.tlslib="openssl")

  input(
      type="imrelp" port="2515"
      tls="on"
      # This should work in rsyslog 8.2006.0:
      #tls.mycert="/etc/rsyslog.tls/fullchain.pem"
      # for now we use the work-around discussed in:
      # https://github.com/rsyslog/rsyslog/issues/4360
      tls.cacert="/etc/rsyslog.tls/chain.pem"
      tls.mycert="/etc/rsyslog.tls/cert.pem"
      tls.myprivkey="/etc/rsyslog.tls/privkey.pem"
      tls.tlscfgcmd="ServerPreference CipherString=ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384 Ciphersuites=TLS_AES_128_GCM_SHA256:TLS_CHACHA20_POLY1305_SHA256:TLS_AES_256_GCM_SHA384 MinProtocol=TLSv1.2"
  )
  ----

  This error comes from this code in plugins/imrelp/imrelp.c:

  ----
  #if defined(HAVE_RELPENGINESETTLSCFGCMD)
                          inst->tlscfgcmd = (uchar*)es_str2cstr(pvals[i].val.d.estr, NULL);
  #else
                          parser_errmsg("imrelp: librelp does not support input parameter 'tls.tlscfgcmd'; "
                                  "it probably is too old (1.5.0 or higher should be fine); ignoring setting now.");
  #endif
  ----

  The build log for focal:
  https://launchpadlibrarian.net/464665610/buildlog_ubuntu-focal-arm64.rsyslog_8.2001.0-1ubuntu1_BUILDING.txt.gz
  says:
  checking for relpSrvSetTlsConfigCmd... no
  checking for relpSrvSetTlsConfigCmd... (cached) no

  The build log for groovy:
  https://launchpadlibrarian.net/486409321/buildlog_ubuntu-groovy-arm64.rsyslog_8.2006.0-2ubuntu1_BUILDING.txt.gz
  says:
  checking for relpSrvSetTlsConfigCmd... yes
  checking for relpSrvSetTlsConfigCmd... (cached) yes

  If I rebuild the rsyslog package, I get:
  checking for relpSrvSetTlsConfigCmd... yes
  checking for relpSrvSetTlsConfigCmd... (cached) yes

  I suspect that the rsyslog package was built against and older librelp
  version. A simple rebuild of rsyslog should fix this, though a more
  complete fix would be to raise the Build-Depends from librelp-dev (>=
  1.4.0) to librelp-dev (>= 1.5.0).

  [Risk potential]

  * No identified as this is a rebuild that should have been done on all 
  reverse dependencies of librelp-dev when upgraded from 1.4.0 to 1.5.0

  [Fix]

  Provide a rebuild SRU for focal.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/rsyslog/+bug/1888926/+subscriptions