Page MenuHomePhabricator
Create Task
Maniphest T184103

ircecho doesn't reconnect on failure
Closed, ResolvedPublic
Actions

Description

In the last 3 days, icinga-wm was not in the operation channel (and all the others in which it's usually connected to), hence all the IRC notification failed to be delivered.

The error on the host's log are just showing:

Jan  1 23:15:16 einsteinium ircecho[11960]: Error writing: Not connected.Dropping this message: "PROBLEM - Host logstash1008 is DOWN: PING CRITICAL - Pac
ket loss = 100%"
Jan  1 23:15:16 einsteinium ircecho[11960]: Error writing: Not connected.Dropping this message: "PROBLEM - Host chlorine is DOWN: PING CRITICAL - Packet loss = 100%"
Jan  1 23:15:16 einsteinium ircecho[11960]: Error writing: Not connected.Dropping this message: "PROBLEM - Host bohrium is DOWN: PING CRITICAL - Packet loss = 100%"
Jan  1 23:15:16 einsteinium ircecho[11960]: Error writing: Not connected.Dropping this message: "PROBLEM - Host planet1001 is DOWN: PING CRITICAL - Packet loss = 100%"
....

Given the kind of messages, my first guess is that the host had a brief connection issue and ircecho failed to reconnect after it. Also our puppettization was not able to detect this and restart ircecho in the next run.

Details

SubjectRepoBranchLines +/-
ircecho: set EchoNotifier threads as daemonoperations/puppetproduction+1 -0
ircecho: Normalize print statementsoperations/puppetproduction+2 -2
ircecho: Force unbuffered stdin/stdout/stderroperations/puppetproduction+1 -1
ircecho: Remove redundant threadoperations/puppetproduction+23 -22
Customize query in gerrit

Event Timeline

Volans created this task.Jan 3 2018, 7:06 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 3 2018, 7:06 PM
Volans triaged this task as High priority.Jan 3 2018, 7:06 PM
Volans added a subscriber: • cwdent.

Thanks to @cwdent for notifying us.

Peachey88 added a project: IRCecho.Jan 3 2018, 8:31 PM
akosiaris added a comment.Jan 5 2018, 11:49 AM

After some minor changes here and there I did a gdb on the thing and after forcefully closing the TCP connectio to the IRC server we get

(gdb) bt
#0  0x00007fd89967b010 in sem_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x000000000057ba10 in PyThread_acquire_lock (waitflag=1, lock=0x16862b0) at ../Python/thread_pthread.h:324
#2  lock_PyThread_acquire_lock.lto_priv.2568 () at ../Modules/threadmodule.c:52
...

Looks like the main thread, that is the one that runs the IRC bot itself, is stuck waiting a semaphore from some other thread.

A cursory look on the code does seem to have mutexes [1] in order to make the code thread safe

https://github.com/jaraco/irc/blob/60f747a578157b03c952c050c765e2924d4fdc00/irc/client.py#L193

and it is used in various parts of the code so the possibility some deadlock is triggered does exist.

gerritbot subscribed.Jan 5 2018, 12:40 PM

Change 402081 had a related patch set uploaded (by Alexandros Kosiaris; owner: Alexandros Kosiaris):
[operations/puppet@production] ircecho: Remove redundant thread

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

gerritbot added a project: Patch-For-Review.Jan 5 2018, 12:40 PM

Change 402101 had a related patch set uploaded (by Alexandros Kosiaris; owner: Alexandros Kosiaris):
[operations/puppet@production] ircecho: Force unbuffered stdin/stdout/stderr

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

gerritbot added a comment.Jan 5 2018, 12:40 PM

Change 402343 had a related patch set uploaded (by Alexandros Kosiaris; owner: Alexandros Kosiaris):
[operations/puppet@production] ircecho: Normalize print statements

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

gerritbot added a comment.Jan 5 2018, 12:40 PM

Change 402344 had a related patch set uploaded (by Alexandros Kosiaris; owner: Alexandros Kosiaris):
[operations/puppet@production] ircecho: set EchoNotifier threads as daemon

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

akosiaris added a comment.Jan 5 2018, 12:43 PM

After some experimentation it looks like the main thread is just waiting for the other threads to terminate. This can never happen in normal conditions as they are effectively forever loops. Setting them as daemon threads [1] allows the mainthread to terminate successfully and the entire python application to terminate as well. Then systemd will takeover and restart it

[1] https://docs.python.org/2/library/threading.html#threading.Thread.daemon

akosiaris moved this task from Inbox to In progress on the observability board.Jan 8 2018, 4:03 PM
gerritbot added a comment.Jan 9 2018, 11:01 AM

Change 402081 merged by Alexandros Kosiaris:
[operations/puppet@production] ircecho: Remove redundant thread

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

gerritbot added a comment.Jan 9 2018, 11:01 AM

Change 402101 merged by Alexandros Kosiaris:
[operations/puppet@production] ircecho: Force unbuffered stdin/stdout/stderr

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

gerritbot added a comment.Jan 9 2018, 11:01 AM

Change 402343 merged by Alexandros Kosiaris:
[operations/puppet@production] ircecho: Normalize print statements

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

gerritbot added a comment.Jan 9 2018, 11:01 AM

Change 402344 merged by Alexandros Kosiaris:
[operations/puppet@production] ircecho: set EchoNotifier threads as daemon

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

akosiaris closed this task as Resolved.Jan 9 2018, 1:05 PM
akosiaris claimed this task.

This should finally be resolved with the above changes

Volans reopened this task as Open.Jan 11 2018, 11:04 PM
This comment was removed by Volans.
Volans closed this task as Resolved.Jan 11 2018, 11:08 PM
Volans added a subscriber: Dzahn.

This was a misunderstanding on my side, @Dzahn actually stopped it manually.

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