jahschwa / sibyl

a python chatbot with a focus on XBMC
GNU General Public License v3.0
7 stars 6 forks source link

matrix: it's possible to end up with 2 listener threads #58

Open jahschwa opened 5 years ago

jahschwa commented 5 years ago

Encountered a situation where Sibyl was double-bridging messages in the Matrix --> XMPP direction. Some investigation revealed double log entries from the SDK, notable the transaction_id and event_id are the same in both:

2018-11-29 11:03:06 | matrix   | DEB | {u'origin_server_ts': 1543507371033, u'sender': u'@sibyl:domain.com <http://domain.com/>', u'event_id': u'$15435073711085QQVxI:domain.com <http://domain.com/>', u'unsigned': {u'age': 366, u'transaction_id': u'1341543507385642'}, u'content': {u'body': u'[ schwa ] O.o', u'msgtype': u'm.text'}, 'room_id': u'!foobar:domain.com <http://domain.com/>', u'type': u'm.room.message'}
2018-11-29 11:03:06 | matrix   | DEB | {u'origin_server_ts': 1543507371033, u'sender': u'@sibyl:domain.com <http://domain.com/>', u'event_id': u'$15435073711085QQVxI:domain.com <http://domain.com/>', u'unsigned': {u'age': 367, u'transaction_id': u'1341543507385642'}, u'content': {u'body': u'[ schwa ] O.o', u'msgtype': u'm.text'}, 'room_id': u'!foobar:domain.com <http://domain.com/>', u'type': u'm.room.message'}

Confirmed there were 3 threads for sibyl running on the box (which at the time we guessed were the main thread plus 2 matrix threads):

bob@server:~$ ps -T -p 9155
  PID  SPID TTY          TIME CMD
 9155  9155 ?        01:12:46 python2
 9155  9160 ?        00:57:49 python2
 9155 27038 ?        00:03:22 python2

Threading reports 3 threads:

#exec import threading; bot.reply(threading.enumerate(), mess)

[<_MainThread(MainThread, started 140450851469056)>, <Thread(Thread-1, started daemon 140450548987648)>, <Thread(Thread-14587, started daemon 140450540594944)>]

And yep, the last 2 are Matrix threads:

#exec import threading; bot.reply(   threading.enumerate()[1]._Thread__target   , mess)

<bound method MatrixClient.listen_forever of <matrix_client.client.MatrixClient object at 0x7fbd3fbaa690>>
#exec import threading; bot.reply(   threading.enumerate()[2]._Thread__target   , mess)

<bound method MatrixClient.listen_forever of <matrix_client.client.MatrixClient object at 0x7fbd300eec90>>

Notably they belong to different MatrixClient objects. So it seems like what happened was:

  1. sibyl_matrix caught an exception and passed an equivalent on to sibyl
  2. As part of that it does call stop_listener_thread() on this line which is here in the SDK
  3. That apparently did not stop the original thread
  4. Sibyl waits 30 secs then reconnects, calling connect() from sibyl_matrix (which instantiates a new MatrixClient object)
  5. We now have 2 threads, both of which dispatch Message object to the bot