Issues with syslog-ng-3.22.1 - many restarts

Message

hanj · Post by **hanj** » Sat Aug 17, 2019 5:40 am

I recently upgraded to 3.22.1 and noticed some weird behaviour in the logs...

Aug 16 23:25:36 comp.net stunnel: LOG5[16]: Service [syslog-ng] accepted connection from 127.0.0.1:34141
Aug 16 23:25:36 comp.net stunnel: LOG5[16]: s_connect: connected 10.0.0.32:20514
Aug 16 23:25:36 comp.net stunnel: LOG5[16]: Service [syslog-ng] connected remote server from 172.16.0.2:41188
Aug 16 23:25:37 comp.net syslog-ng[4206]: syslog-ng starting up; version='3.22.1'
Aug 16 23:25:37 comp.net syslog-ng[4206]: Syslog connection established; fd='14', server='AF_INET(127.0.0.1:514)', local='AF_INET(0.0.0.0:0)'
Aug 16 23:25:37 comp.net stunnel: LOG5[17]: Service [syslog-ng] accepted connection from 127.0.0.1:45869
Aug 16 23:25:37 comp.net stunnel: LOG5[17]: s_connect: connected 10.0.0.32:20514
Aug 16 23:25:37 comp.net stunnel: LOG5[17]: Service [syslog-ng] connected remote server from 172.16.0.2:41190
Aug 16 23:27:16 comp.net syslog-ng[4234]: syslog-ng starting up; version='3.22.1'
Aug 16 23:27:16 comp.net syslog-ng[4234]: Syslog connection established; fd='14', server='AF_INET(127.0.0.1:514)', local='AF_INET(0.0.0.0:0)'
Aug 16 23:27:16 comp.net stunnel: LOG5[18]: Service [syslog-ng] accepted connection from 127.0.0.1:38213
Aug 16 23:27:16 comp.net stunnel: LOG5[18]: s_connect: connected 10.0.0.32:20514
Aug 16 23:27:16 comp.net stunnel: LOG5[18]: Service [syslog-ng] connected remote server from 172.16.0.2:41192
Aug 16 23:30:02 comp.net syslog-ng[4298]: syslog-ng starting up; version='3.22.1'
Aug 16 23:30:02 comp.net syslog-ng[4298]: Syslog connection established; fd='14', server='AF_INET(127.0.0.1:514)', local='AF_INET(0.0.0.0:0)'
Aug 16 23:30:02 comp.net stunnel: LOG5[19]: Service [syslog-ng] accepted connection from 127.0.0.1:37777
Aug 16 23:30:02 comp.net stunnel: LOG5[19]: s_connect: connected 10.0.0.32:20514
Aug 16 23:30:02 comp.net stunnel: LOG5[19]: Service [syslog-ng] connected remote server from 172.16.0.2:41196
Aug 16 23:32:56 comp.net syslog-ng[4298]: syslog-ng shutting down; version='3.22.1'
Aug 16 23:33:21 comp.net syslog-ng[4441]: syslog-ng starting up; version='3.22.1'
Aug 16 23:33:21 comp.net syslog-ng[4441]: Syslog connection established; fd='14', server='AF_INET(127.0.0.1:514)', local='AF_INET(0.0.0.0:0)'
Aug 16 23:33:21 comp.net stunnel: LOG5[20]: Service [syslog-ng] accepted connection from 127.0.0.1:35619
Aug 16 23:33:21 comp.net stunnel: LOG5[20]: s_connect: connected 10.0.0.32:20514
Aug 16 23:33:21 comp.net stunnel: LOG5[20]: Service [syslog-ng] connected remote server from 172.16.0.2:41312

The service and stunnel are constantly restarting. This is using a remote syslog server to centrally store logs, and I'm getting these logs there as well. If I issues a `logger yo` I see 'yo' on my central logging server, but I do not see it in the local /var/log/message. It appears that any time a log is written, syslog sends the log, and restarts the service. I didn't have a problem until this recent update.

Code: Select all

[ebuild   R    ] app-admin/syslog-ng-3.22.1::gentoo  USE="-amqp -caps -dbi -geoip -geoip2 -http -ipv6 -json -kafka -libressl -mongodb -pacct -python -redis -smtp -snmp -spoof-source -systemd -tcpd" PYTHON_SINGLE_TARGET="python3_6 -python2_7 -python3_5 (-python3_7)" PYTHON_TARGETS="python2_7 python3_5 python3_6 (-python3_7)" 4865 KiB
[ebuild   R    ] net-misc/stunnel-5.50-r1::gentoo  USE="ssl -ipv6 -libressl (-selinux) -stunnel3 -tcpd" 951 KiB

Code: Select all

@version: 3.22
#
# Syslog-ng default configuration file for Gentoo Linux

# https://bugs.gentoo.org/426814
@include "scl.conf"

options {
        stats_freq(43200);
        use_fqdn(yes);
        keep_hostname(yes);
        use_dns(yes);
        log_fifo_size(10000);
};

source src {
    unix-stream("/dev/log");
    internal();
        file("/proc/kmsg");
};


destination messages { file("/var/log/messages" owner(root) group(adm) perm(0640)); };
destination lpr { file("/var/log/lpr.log"); };
destination mail { file("/var/log/mail.log" owner(root) group(adm) perm(0640)); };
destination authlog { file("/var/log/auth.log" owner(root) group(adm) perm(0640)); };
destination d_sec {
        program("/usr/bin/sec -input=\"-\" -conf=/etc/sec/sec.conf -log=/var/log/sec.log -pid=/var/run/sec.pid");
};

destination console { usertty("root"); };
destination console_all { file("/dev/tty12"); };

filter f_lpr { facility(lpr); };
filter f_mail { facility(mail); };
filter f_dhcp { facility(local7); };
filter f_messages { level(info..emerg) and not facility(mail,lpr); };
filter f_emergency { level(emerg); };
filter f_auth { facility(auth); };
filter f_authpriv { facility(auth, authpriv); };

log { source(src); filter(f_lpr); destination(lpr); };
log { source(src); filter(f_mail); destination(mail); };
log { source(src); filter(f_messages); destination(messages); };
log { source(src); filter(f_emergency); destination(console); };
log { source(src); filter(f_authpriv); destination(authlog); };

destination loghost {tcp("127.0.0.1" port(514));};
log { source(src); filter(f_messages); destination(loghost); };
log { source(src); destination(d_sec); };

Any ideas?

Thanks!
hanji

freke · Post by **freke** » Sat Aug 17, 2019 2:25 pm

Not using stunnel myself and haven't had any issues after updating to syslog-ng 3.22.1

Code: Select all

tor ~ # cat /etc/syslog-ng/syslog-ng.conf
@version: 3.22
#
# Syslog-ng default configuration file for Gentoo Linux

# https://bugs.gentoo.org/426814
@include "scl.conf"

options {
        threaded(yes);
        keep_hostname(yes);
        stats_freq(43200);
        mark_freq(3600);
};

template t_papertrail {
  template("<$PRI>$DATE tor.vlh.dk $PROGRAM: $MSG\n");
};

source s_local {
        system();
        internal();
        };

destination d_logs {
        file("/var/log/messages" owner("root") group("root") perm(0666));
        };

destination d_papertrail {
        tcp("xxxx.papertrailapp.com" port(xxxxx) template(t_papertrail) tls(ca_dir("/etc/ssl/papertrail")) );
        };

log {
        source(s_local);
        destination(d_logs);
        destination(d_papertrail);
        };

hanj · Post by **hanj** » Sun Aug 18, 2019 2:27 am

Okay.. looks like it might be stunnel. I set stunnel debug to 7 and writing to a file.

Code: Select all

2019.08.17 20:23:05 LOG6[1]: Read socket closed (readsocket)
2019.08.17 20:23:05 LOG7[1]: Sending close_notify alert
2019.08.17 20:23:05 LOG7[1]: TLS alert (write): warning: close notify
2019.08.17 20:23:05 LOG6[1]: SSL_shutdown successfully sent close_notify alert
2019.08.17 20:23:05 LOG7[1]: TLS alert (read): warning: close notify
2019.08.17 20:23:05 LOG6[1]: TLS closed (SSL_read)
2019.08.17 20:23:05 LOG7[1]: Sent socket write shutdown
2019.08.17 20:23:05 LOG5[1]: Connection closed: 1259 byte(s) sent to TLS, 0 byte(s) sent to socket
2019.08.17 20:23:05 LOG7[1]: Remote descriptor (FD=9) closed
2019.08.17 20:23:05 LOG7[1]: Local descriptor (FD=8) closed
2019.08.17 20:23:05 LOG7[1]: Service [syslog-ng] finished (0 left)
2019.08.17 20:23:06 LOG7[main]: Found 1 ready file descriptor(s)
2019.08.17 20:23:06 LOG7[main]: FD=4 events=0x2001 revents=0x0
2019.08.17 20:23:06 LOG7[main]: FD=6 events=0x2001 revents=0x1
2019.08.17 20:23:06 LOG7[main]: Service [syslog-ng] accepted (FD=8) from 127.0.0.1:43923
2019.08.17 20:23:06 LOG7[2]: Service [syslog-ng] started
2019.08.17 20:23:06 LOG7[2]: Setting local socket options (FD=8)
2019.08.17 20:23:06 LOG7[2]: Option TCP_NODELAY set on local socket
2019.08.17 20:23:06 LOG5[2]: Service [syslog-ng] accepted connection from 127.0.0.1:43923
2019.08.17 20:23:06 LOG6[2]: s_connect: connecting 10.0.0.32:20514
2019.08.17 20:23:06 LOG7[2]: s_connect: s_poll_wait 10.0.0.32:20514: waiting 10 seconds
2019.08.17 20:23:06 LOG5[2]: s_connect: connected 10.0.0.32:20514
2019.08.17 20:23:06 LOG5[2]: Service [syslog-ng] connected remote server from 172.16.0.2:51764
2019.08.17 20:23:06 LOG7[2]: Setting remote socket options (FD=9)
2019.08.17 20:23:06 LOG7[2]: Option TCP_NODELAY set on remote socket
2019.08.17 20:23:06 LOG7[2]: Remote descriptor (FD=9) initialized
2019.08.17 20:23:06 LOG6[2]: SNI: sending servername: 10.0.0.32
2019.08.17 20:23:06 LOG6[2]: Peer certificate not required
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): before/connect initialization
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): SSLv3 write client hello A
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): SSLv3 read server hello A
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): SSLv3 read finished A
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): SSLv3 write change cipher spec A
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): SSLv3 write finished A
2019.08.17 20:23:06 LOG7[2]: TLS state (connect): SSLv3 flush data
2019.08.17 20:23:06 LOG7[2]:      3 client connect(s) requested
2019.08.17 20:23:06 LOG7[2]:      3 client connect(s) succeeded
2019.08.17 20:23:06 LOG7[2]:      0 client renegotiation(s) requested
2019.08.17 20:23:06 LOG7[2]:      2 session reuse(s)
2019.08.17 20:23:06 LOG6[2]: TLS connected: previous session reused
2019.08.17 20:23:06 LOG6[2]: TLSv1 ciphersuite: ECDHE-RSA-AES256-SHA (256-bit encryption)
2019.08.17 20:23:06 LOG7[2]: Compression: null, expansion: null
2019.08.17 20:23:06 LOG6[2]: Session id: 621AF09CBBC1B17E8104C46DF0A676C4B3FD31B6C6CA70A6404C6BDC35EF8687
2019.08.17 20:23:42 LOG7[main]: Found 1 ready file descriptor(s)
2019.08.17 20:23:42 LOG7[main]: FD=4 events=0x2001 revents=0x0
2019.08.17 20:23:42 LOG7[main]: FD=6 events=0x2001 revents=0x1
2019.08.17 20:23:42 LOG7[main]: Service [syslog-ng] accepted (FD=10) from 127.0.0.1:46259
2019.08.17 20:23:42 LOG7[3]: Service [syslog-ng] started
2019.08.17 20:23:42 LOG7[3]: Setting local socket options (FD=10)
2019.08.17 20:23:42 LOG7[3]: Option TCP_NODELAY set on local socket
2019.08.17 20:23:42 LOG5[3]: Service [syslog-ng] accepted connection from 127.0.0.1:46259
2019.08.17 20:23:42 LOG6[3]: s_connect: connecting 10.0.0.32:20514
2019.08.17 20:23:42 LOG7[3]: s_connect: s_poll_wait 10.0.0.32:20514: waiting 10 seconds
2019.08.17 20:23:42 LOG5[3]: s_connect: connected 10.0.0.32:20514
2019.08.17 20:23:42 LOG5[3]: Service [syslog-ng] connected remote server from 172.16.0.2:51766
2019.08.17 20:23:42 LOG7[3]: Setting remote socket options (FD=11)
2019.08.17 20:23:42 LOG7[3]: Option TCP_NODELAY set on remote socket
2019.08.17 20:23:42 LOG7[3]: Remote descriptor (FD=11) initialized
2019.08.17 20:23:42 LOG6[3]: SNI: sending servername: 10.0.0.32
2019.08.17 20:23:42 LOG6[3]: Peer certificate not required
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): before/connect initialization
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): SSLv3 write client hello A
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): SSLv3 read server hello A
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): SSLv3 read finished A
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): SSLv3 write change cipher spec A
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): SSLv3 write finished A
2019.08.17 20:23:42 LOG7[3]: TLS state (connect): SSLv3 flush data
2019.08.17 20:23:42 LOG7[3]:      4 client connect(s) requested
2019.08.17 20:23:42 LOG7[3]:      4 client connect(s) succeeded
2019.08.17 20:23:42 LOG7[3]:      0 client renegotiation(s) requested
2019.08.17 20:23:42 LOG7[3]:      3 session reuse(s)
2019.08.17 20:23:42 LOG6[3]: TLS connected: previous session reused
2019.08.17 20:23:42 LOG6[3]: TLSv1 ciphersuite: ECDHE-RSA-AES256-SHA (256-bit encryption)
2019.08.17 20:23:42 LOG7[3]: Compression: null, expansion: null
2019.08.17 20:23:42 LOG6[3]: Session id: 621AF09CBBC1B17E8104C46DF0A676C4B3FD31B6C6CA70A6404C6BDC35EF8687
2019.08.17 20:23:42 LOG6[cron]: Executing cron jobs
2019.08.17 20:23:42 LOG6[cron]: Cron jobs completed in 0 seconds
2019.08.17 20:23:42 LOG7[cron]: Waiting 86400 seconds

If I write to /var/log/messages, stunnel restarts..specifically this:

Code: Select all

2019.08.17 20:23:05 LOG6[1]: Read socket closed (readsocket)
2019.08.17 20:23:05 LOG7[1]: Sending close_notify alert
2019.08.17 20:23:05 LOG7[1]: TLS alert (write): warning: close notify
2019.08.17 20:23:05 LOG6[1]: SSL_shutdown successfully sent close_notify alert
2019.08.17 20:23:05 LOG7[1]: TLS alert (read): warning: close notify
2019.08.17 20:23:05 LOG6[1]: TLS closed (SSL_read)
2019.08.17 20:23:05 LOG7[1]: Sent socket write shutdown

Still digging...

hanji

alix · Post by **alix** » Sun Aug 18, 2019 6:35 am

hanj wrote:The service and stunnel are constantly restarting.

Do you run a 32 bit system by chance? I have a weird case of a 64 bit kernel and 32 bit userland, and 3.22.1 stops with assertion failure shortly after start:

Code: Select all

ERROR:lib/window-size-counter.c:76:window_size_counter_sub: assertion failed: (old_value >= value)

The problem isn't reported on syslog-ng github issues yet.

You can check what's happening in your case by starting syslog-ng in foreground (--foreground)

hanj · Post by **hanj** » Sun Aug 18, 2019 9:35 pm

Okay.. I'm not sure what's up, but the solution was to remove unix-stream("/dev/log"; and add system(); to the source

Old..

Code: Select all

source src {
    unix-stream("/dev/log");
    internal();
        file("/proc/kmsg");
};

Current

Code: Select all

source src {
    system();
    internal();
        file("/proc/kmsg");
};

No stunnel/syslog-ng is not restarting. Not sure what's up with that. Any ideas on explanation? This was working perfectly fine before.

Thanks!
hanji

alix · Post by **alix** » Mon Aug 19, 2019 2:36 pm

Good catch! Restarts due to assert failures stopped and 3.22.1 seems to be running fine now.

hanj · Post by **hanj** » Mon Aug 19, 2019 2:47 pm

alix wrote:Good catch! Restarts due to assert failures stopped and 3.22.1 seems to be running fine now.

Assert failures?

alix · Post by **alix** » Mon Aug 19, 2019 2:56 pm

Yeah, syslog-ng fails some internal assertion and quits; after that it is being restarted by its supervisor and the cycle repeats forever.

I think I was clear enough in my previous post...

hanj · Post by **hanj** » Mon Aug 19, 2019 3:22 pm

alix wrote:Yeah, syslog-ng fails some internal assertion and quits; after that it is being restarted by its supervisor and the cycle repeats forever.

I think I was clear enough in my previous post...

Sorry.. I didn't understand. That clears it up.

Thanks
hanji

Sargastic · Post by **Sargastic** » Wed Sep 18, 2019 12:41 pm

Hi,

We had exactly this problem, on one machine (despite that it is « the same » as 10 others, the problem did show on only one computer). Any type of logging would trigger a syslog-ng restart after logging (so no loss of messages).

hanj wrote:Okay.. I'm not sure what's up, but the solution was to remove unix-stream("/dev/log"; and add system(); to the source

This seems to have done the trick. Thanks for the tip.

Issues with syslog-ng-3.22.1 - many restarts

Issues with syslog-ng-3.22.1 - many restarts

Re: Issues with syslog-ng-3.22.1 - many restarts