Page MenuHomePhabricator
Create Task
Maniphest T199406

rsyslog's in:imtcp thread stuck on recvfrom loop from down/rebooted hosts
Open, HighPublic
Actions

Description

It happened on lithium a couple of times, and this morning on wezen. In icinga it is usually listed with the rsyslog service in UNKNOWN status with description Service timeout. The pattern is the following:

top -h shows:

 PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
6925 root      20   0  706056  70056   4892 R 99.9  0.4   2441:03 in:imtcp

strace -p 6925 shows:

recvfrom(706, 0x7fc477691650, 31, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(706, 0x7fc477691650, 31, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(706, 0x7fc477691650, 31, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(706, 0x7fc477691650, 31, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(706, 0x7fc477691650, 31, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
recvfrom(706, 0x7fc477691650, 31, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
[...]

Then from /proc/:

elukey@wezen:~$ sudo file /proc/6925/fd/706
/proc/6925/fd/706: broken symbolic link to socket:[118444005]

And finally:

elukey@wezen:~$ sudo lsof | grep 118444005
rsyslogd   6920                   root  706u     IPv4          118444005         0t0        TCP in:imuxso  6920  6923             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imklog  6920  6924             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imtcp   6920  6925             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imudp   6920  6926             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
rs:main    6920  6927             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imtcp   6920  6928             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imtcp   6920  6929             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imtcp   6920  6930             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)
in:imtcp   6920  6931             root  706u     IPv4          118444005         0t0        TCP wezen.codfw.wmnet:syslog-tls->tegmen.wikimedia.org:44892 (ESTABLISHED)

gdb shows (didn't find debug symbols to install):

(gdb) thread apply all bt

Thread 1 (Thread 0x7fc483fff700 (LWP 6925)):
#0  0x00007fc48dd3cb17 in ?? () from /usr/lib/x86_64-linux-gnu/rsyslog/lmnetstrms.so
#1  0x00007fc48db36ff3 in ?? () from /usr/lib/x86_64-linux-gnu/rsyslog/lmtcpsrv.so
#2  0x00007fc48db372c7 in ?? () from /usr/lib/x86_64-linux-gnu/rsyslog/lmtcpsrv.so
#3  0x00005608e3302970 in ?? ()
#4  0x00007fc48ff67064 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5  0x00007fc48f07862d in clone () from /lib/x86_64-linux-gnu/libc.so.6

Usually a restart fixes the problem. Seems very similar to https://github.com/rsyslog/rsyslog/issues/318.

elukey@wezen:~$ dpkg -l | grep rsyslog
ii  rsyslog                         8.23.0-2~bpo8+1                  amd64        reliable system and kernel logging daemon
ii  rsyslog-gnutls                  8.23.0-2~bpo8+1                  amd64        TLS protocol support for rsyslog

Details

SubjectRepoBranchLines +/-
Revert "toil: remove rsyslog_tls_remedy"operations/puppetproduction+24 -0
toil: remove rsyslog_tls_remedyoperations/puppetproduction+0 -24
role: remove rsyslog TLS remedyoperations/puppetproduction+1 -1
toil: rsyslog_tls_remedy log to journaldoperations/puppetproduction+7 -5
toil: add rsyslog TLS remedyoperations/puppetproduction+22 -0
Customize query in gerrit

Related Objects

Event Timeline

elukey triaged this task as High priority.Jul 12 2018, 6:25 AM
elukey created this task.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 12 2018, 6:25 AM
elukey updated the task description. (Show Details)Jul 12 2018, 6:25 AM
Stashbot subscribed.Jul 12 2018, 6:26 AM

Mentioned in SAL (#wikimedia-operations) [2018-07-12T06:26:08Z] <elukey> restart rsyslog on wezen - T199406

elukey updated the task description. (Show Details)Jul 12 2018, 6:28 AM
elukey updated the task description. (Show Details)
elukey added subscribers: MoritzMuehlenhoff, Volans.Jul 12 2018, 8:04 AM
fgiunchedi added a comment.Jul 12 2018, 10:12 AM

Interesting! I thought it was something similar to we've experienced this problem before in T136312: Encrypt syslog traffic and https://github.com/rsyslog/rsyslog/issues/1728. Supposedly the latest rsyslog version fixes it but this seems a different issue altogether?

Stashbot added a comment.Oct 5 2018, 9:37 AM

Mentioned in SAL (#wikimedia-operations) [2018-10-05T09:37:48Z] <elukey> restart rsyslog on lithium - broken connection to tegmen - T199406

Stashbot added a comment.Dec 20 2018, 7:10 AM

Mentioned in SAL (#wikimedia-operations) [2018-12-20T07:10:16Z] <elukey> restart rsyslog on lithium - in:imtcp stuck in recvfrom ms-be2047.codfw.wmnet - T199406

• Phabricator_maintenance moved this task from Backlog to Acknowledged on the SRE board.Jan 26 2019, 10:10 PM
Stashbot added a comment.May 6 2019, 2:57 PM

Mentioned in SAL (#wikimedia-operations) [2019-05-06T14:57:25Z] <godog> capture strace / core for rsyslog on wezen / lithium and restart - T199406

fgiunchedi added a comment.May 6 2019, 3:37 PM

Same issue today, rsyslog was stuck on lithium and wezen, strace shows a whole lot of this:

37672 recvfrom(837, 0x7f092c765c30, 55, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
37672 recvfrom(837, 0x7f092c765c30, 55, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
37672 recvfrom(837, 0x7f092c765c30, 55, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
37672 recvfrom(837, 0x7f092c765c30, 55, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)

And sure enough, fd 837 is the connection to cp1083 which died around the same time rsyslog got stuck:

rsyslogd 37653 root  837u  IPv4           64101317        0t0        TCP lithium.eqiad.wmnet:syslog-tls->cp1083.eqiad.wmnet:23981 (ESTABLISHED)

While annoying, I think before digging further we should focus on upgrading to stretch central syslog servers instead.

MoritzMuehlenhoff added a comment.May 7 2019, 8:14 AM
In T199406#5160429, @fgiunchedi wrote:

While annoying, I think before digging further we should focus on upgrading to stretch central syslog servers instead.

+1

Stashbot added a comment.May 23 2019, 9:22 AM

Mentioned in SAL (#wikimedia-operations) [2019-05-23T09:22:30Z] <godog> bounce rsyslog on lithium - listener stuck /T199406

fgiunchedi added a project: User-fgiunchedi.May 23 2019, 9:25 AM
fgiunchedi moved this task from Backlog to Up next on the User-fgiunchedi board.May 29 2019, 7:48 AM
Stashbot added a comment.Jun 7 2019, 3:34 PM

Mentioned in SAL (#wikimedia-operations) [2019-06-07T15:34:15Z] <godog> bounce rsyslog on wezen - T199406

Stashbot added a comment.Jun 26 2019, 7:50 AM

Mentioned in SAL (#wikimedia-operations) [2019-06-26T07:50:53Z] <godog> bounce rsyslog on lithium - T199406

fgiunchedi mentioned this in T226703: rsyslog output modules (fwd, kafka) failures should not affect each other.Jun 27 2019, 11:37 AM
herron subscribed.Jun 27 2019, 2:19 PM
Stashbot added a comment.Jul 2 2019, 9:58 AM

Mentioned in SAL (#wikimedia-operations) [2019-07-02T09:58:40Z] <godog> restart rsyslog on wezen - T199406

gerritbot added a comment.Jul 2 2019, 10:22 AM

Change 520207 had a related patch set uploaded (by Filippo Giunchedi; owner: Filippo Giunchedi):
[operations/puppet@production] (WIP) toil: add rsyslog TLS remedy

https://gerrit.wikimedia.org/r/520207

gerritbot added a project: Patch-For-Review.Jul 2 2019, 10:22 AM
fgiunchedi mentioned this in T220500: logstash1012 lock up caused central logging stuck.Jul 22 2019, 2:19 PM
fgiunchedi added a comment.Jul 29 2019, 10:19 AM

This failure happened on Sun as well, with wezen and centrallog1001 "stuck" on recvfrom from cloudvirt1015, e.g. on centrallog1001

21108 recvfrom(1465, 0x7f5e053eee63, 278, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
21108 recvfrom(1465, 0x7f5e053eee63, 278, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
21108 recvfrom(1465, 0x7f5e053eee63, 278, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
21108 recvfrom(1465, 0x7f5e053eee63, 278, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
21108 recvfrom(1465, 0x7f5e053eee63, 278, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
21108 recvfrom(1465, 0x7f5e053eee63, 278, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
rsyslogd 21094 root 1465u     IPv4           28025343        0t0        TCP centrallog1001.eqiad.wmnet:syslog-tls->cloudvirt1015.eqiad.wmnet:34854 (ESTABLISHED)
fgiunchedi added a comment.Jul 29 2019, 11:04 AM

Opened a new upstream issue: https://github.com/rsyslog/rsyslog/issues/3770 referencing https://github.com/rsyslog/rsyslog/issues/318 too

fgiunchedi renamed this task from rsyslog's in:imtcp thread stuck on old sockets to rsyslog's in:imtcp thread stuck on recvfrom loop from down/rebooted hosts.Jul 29 2019, 11:08 AM
Stashbot added a comment.Jul 30 2019, 4:22 PM

Mentioned in SAL (#wikimedia-operations) [2019-07-30T16:22:45Z] <godog> bounce rsyslog on centrallog1001 - T199406

gerritbot added a comment.Aug 6 2019, 8:18 AM

Change 520207 merged by Filippo Giunchedi:
[operations/puppet@production] toil: add rsyslog TLS remedy

https://gerrit.wikimedia.org/r/520207

gerritbot added a comment.Aug 6 2019, 8:27 AM

Change 528395 had a related patch set uploaded (by Filippo Giunchedi; owner: Filippo Giunchedi):
[operations/puppet@production] toil: rsyslog_tls_remedy log to journald

https://gerrit.wikimedia.org/r/528395

gerritbot added a comment.Aug 6 2019, 8:29 AM

Change 528395 merged by Filippo Giunchedi:
[operations/puppet@production] toil: rsyslog_tls_remedy log to journald

https://gerrit.wikimedia.org/r/528395

fgiunchedi changed the task status from Open to Stalled.Oct 2 2019, 5:09 PM

Setting as stalled for now, the immediate issue has been bandaided

fgiunchedi moved this task from Up next to Backlog on the User-fgiunchedi board.Oct 2 2019, 5:10 PM
fgiunchedi moved this task from Backlog to Doing on the User-fgiunchedi board.Oct 8 2020, 10:34 AM
Maintenance_bot removed a project: Patch-For-Review.Oct 8 2020, 11:11 AM
fgiunchedi added a comment.Oct 16 2020, 10:00 AM

Note that with the latest rsyslog version (cfr T259780: rsyslog occasional segfault on centrallog hosts) this bug might be fixed too, and thus we can remove the bandaid

fgiunchedi moved this task from Doing to Up next on the User-fgiunchedi board.Oct 20 2020, 10:26 AM
gerritbot added a comment.Jan 19 2021, 9:24 AM

Change 657052 had a related patch set uploaded (by Filippo Giunchedi; owner: Filippo Giunchedi):
[operations/puppet@production] role: remove rsyslog TLS remedy

https://gerrit.wikimedia.org/r/657052

gerritbot added a project: Patch-For-Review.Jan 19 2021, 9:24 AM
gerritbot added a comment.Jan 19 2021, 4:42 PM

Change 657052 merged by Filippo Giunchedi:
[operations/puppet@production] role: remove rsyslog TLS remedy

https://gerrit.wikimedia.org/r/657052

Maintenance_bot removed a project: Patch-For-Review.Jan 19 2021, 5:11 PM
gerritbot added a comment.Jan 20 2021, 9:32 AM

Change 657293 had a related patch set uploaded (by Filippo Giunchedi; owner: Filippo Giunchedi):
[operations/puppet@production] toil: remove rsyslog_tls_remedy

https://gerrit.wikimedia.org/r/657293

gerritbot added a project: Patch-For-Review.Jan 20 2021, 9:32 AM
gerritbot added a comment.Jan 20 2021, 9:40 AM

Change 657293 merged by Filippo Giunchedi:
[operations/puppet@production] toil: remove rsyslog_tls_remedy

https://gerrit.wikimedia.org/r/657293

fgiunchedi closed this task as Resolved.Jan 20 2021, 9:43 AM
fgiunchedi claimed this task.

Resolving, with recent rsyslog on centrallog hosts we haven't experienced this bug

Maintenance_bot removed a project: Patch-For-Review.Jan 20 2021, 10:11 AM
fgiunchedi reopened this task as Open.Feb 4 2021, 1:22 PM

Unfortunately I spoke too fast, the bug is still there, e.g.

4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
25511 <... poll resumed> )              = 0 (Timeout)
25511 poll([{fd=98, events=POLLIN}, {fd=86, events=POLLIN}], 2, 999 <unfinished ...>
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
4370  recvfrom(50, 0x7f062021acc3, 53, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

So the remedy is going back in :(

gerritbot added a comment.Feb 4 2021, 1:25 PM

Change 661720 had a related patch set uploaded (by Filippo Giunchedi; owner: Filippo Giunchedi):
[operations/puppet@production] Revert "toil: remove rsyslog_tls_remedy"

https://gerrit.wikimedia.org/r/661720

gerritbot added a project: Patch-For-Review.Feb 4 2021, 1:25 PM
gerritbot added a comment.Feb 4 2021, 3:44 PM

Change 661720 merged by Filippo Giunchedi:
[operations/puppet@production] Revert "toil: remove rsyslog_tls_remedy"

https://gerrit.wikimedia.org/r/661720

Maintenance_bot removed a project: Patch-For-Review.Feb 4 2021, 4:10 PM
fgiunchedi mentioned this in T277739: rsyslog-kubernetes missing in buster-wikimedia.Mar 18 2021, 2:10 PM
fgiunchedi moved this task from Up next to Backlog on the User-fgiunchedi board.Oct 4 2021, 1:32 PM
fgiunchedi removed fgiunchedi as the assignee of this task.Feb 22 2023, 1:16 PM
JMeybohm edited projects, added SRE Observability; removed SRE.Feb 27 2023, 1:31 PM
lmata edited projects, added Observability-Logging; removed SRE Observability.Jul 18 2023, 9:54 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits