Page MenuHomePhabricator

Bridgebot freaks out and sends double messages from IRC to Telegram
Open, Stalled, MediumPublicBUG REPORT

Description

Quick fix:

$ ssh login.tools.wmflabs.org
$ become bridgebot
$ bb.sh restart 'Double IRC messages to other bridges'

This has been seen several times now: 2022-03-22, 2022-04-04, 2022-04-05. Things are going along fine and then something happens which makes the bot start outputting double messages from IRC source channels to Telegram sink channels.

Related upstream issue: Duplicate messages when bridging IRC/ZNC to Telegram after some days #1564

Logs grabbed during the 2022-04-05 occurrence hint that the bot got disconnected from it's ZNC bouncer and when it reconnected it is receiving 2 copies of each message:

time="2022-04-05T12:14:45Z" level=debug msg="<= Sending message from * on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc

time="2022-04-05T12:14:47Z" level=error msg="Connection is not alive: &model.App Error{Id:"api.context.session_expired.app_error", Message:"Invalid or expired session, please login again.", DetailedError:"", RequestId:"37xqyp9hd3nozmtzepmy3c7gmh", StatusCode:401, Where:"", IsOAuth:false, params:map[string]interface {}(nil)}" prefix=matterclient

time="2022-04-05T12:14:52Z" level=error msg="error:read tcp 192.168.222.129:35490->172.16.5.238:443: use of closed network connection" prefix=matterclient

time="2022-04-05T12:14:52Z" level=info msg="Found version 5.27.0.5.27.0.db2087c7e98dbb848bfc441d46ca3a0d.false" prefix=matterclient

time="2022-04-05T12:14:52Z" level=debug msg="Registering callbacks" func=handleNewConnection file="bridge/irc/handlers.go:121" prefix=irc
time="2022-04-05T12:14:53Z" level=info msg="found 640 users in team wikimedia" prefix=matterclient

time="2022-04-05T12:14:57Z" level=error msg="error:websocket: close 1006 (abnormal closure): unexpected EOF" prefix=matterclient

time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc001332f30), Tags:girc.Tags{"time":"2022-04-05T12:14:58.906Z"}, Timestamp
:time.Date(2022, time.April, 5, 12, 14, 58, 906000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-es-wikiproyectos", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc

...snip...

time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by hare [sid388306@user/hare] [2021-06-16 01:01:08 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc

time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by hare [sid388306@user/hare] [2021-06-16 01:01:08 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc

Details

TitleReferenceAuthorSource BranchDest Branch
[hack] Patch irc handler to offset BNC event replytoolforge-repos/bridgebot-matterbridge!1bd808work/bd808/T305487main
Customize query in GitLab

Event Timeline

bd808 triaged this task as High priority.Apr 5 2022, 4:06 PM
bd808 updated the task description. (Show Details)

I have double checked that the settings from Every time I connect to my BNC, I see the channel buffers from the last time I connected! in the upstream ZNC FAQ are enabled. The behavior itself really also rules out buffered playback as the core problem here as the duplication has been shown to be an ongoing condition once it has started.

The log data pretty clearly shows the bot thinking that it is getting two copies of each IRC message. This likely rules out issues in the Telegram client code as the source of duplication.

My own IRC client's view around the time of the 2022-04-05 incident (timestamps in UTC):

#wikimedia-cloud
[11:58]  <   arturo> some network operations happening right now
[12:04]  <    jelto> fyi: some horizon/VPS projects are affected. At least in "devtools" project and some bots disconneted also ^
[12:12]  <   arturo> bots should be back online soon
[12:15]  <   isaacj> ^^ this would explain PAWS being inaccessible too? (i assume it's run via VPS)

The bot's view of IRC activity in the same time window (timestamps in UTC):

irc.log
time="2022-04-05T11:58:23Z" level=debug msg="== Receiving PRIVMSG: arturo some network operations happening right now girc.Event{Source:(*girc.Source)(0xc00101a6c0), Tags:girc.Tags{"time":"2022-04-05T11:58:23.454Z"}, Timestamp:time.Date(2022, time.April, 5, 11, 58, 23, 454000000, time.Local), Command:"PRIVMSG", Params:[]string{"#wikimedia-cloud", "some network operations happening right now"}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T11:58:23Z" level=debug msg="detected ISO-8859-1 confidence 40" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T11:58:23Z" level=debug msg="<= Sending message from #wikimedia-cloud on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="== Receiving PRIVMSG: calcium.libera.chat *** Looking up your hostname... girc.Event{Source:(*girc.Source)(0xc000d7a300), Tags:girc.Tags{"time":"2022-04-05T12:14:42.259Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 42, 259000000, time.Local), Command:"NOTICE", Params:[]string{"*", "*** Looking up your hostname..."}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="== Receiving PRIVMSG: calcium.libera.chat *** Checking Ident girc.Event{Source:(*girc.Source)(0xc0006e9b00), Tags:girc.Tags{"time":"2022-04-05T12:14:42.259Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 42, 259000000, time.Local), Command:"NOTICE", Params:[]string{"*", "*** Checking Ident"}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="detected ISO-8859-1 confidence 23" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="<= Sending message from * on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="detected ISO-8859-1 confidence 75" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="<= Sending message from * on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="== Receiving PRIVMSG: calcium.libera.chat *** Found your hostname: nat.cloudgw.eqiad1.wikimediacloud.org girc.Event{Source:(*girc.Source)(0xc0006e9fb0), Tags:girc.Tags{"time":"2022-04-05T12:14:42.464Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 42, 464000000, time.Local), Command:"NOTICE", Params:[]string{"*", "*** Found your hostname: nat.cloudgw.eqiad1.wikimediacloud.org"}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="detected ISO-8859-1 confidence 15" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T12:14:42Z" level=debug msg="<= Sending message from * on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc
time="2022-04-05T12:14:45Z" level=debug msg="== Receiving PRIVMSG: calcium.libera.chat *** No Ident response girc.Event{Source:(*girc.Source)(0xc000e9e690), Tags:girc.Tags{"time":"2022-04-05T12:14:45.050Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 45, 50000000, time.Local), Command:"NOTICE", Params:[]string{"*", "*** No Ident response"}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T12:14:45Z" level=debug msg="detected ISO-8859-1 confidence 63" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T12:14:45Z" level=debug msg="<= Sending message from * on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc
time="2022-04-05T12:14:52Z" level=debug msg="Registering callbacks" func=handleNewConnection file="bridge/irc/handlers.go:121" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc001332f30), Tags:girc.Tags{"time":"2022-04-05T12:14:58.906Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 906000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-es-wikiproyectos", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc001332f30), Tags:girc.Tags{"time":"2022-04-05T12:14:58.906Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 906000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-es-wikiproyectos", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000c64b40), Tags:girc.Tags{"time":"2022-04-05T12:14:58.908Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 908000000, time.Local), Command:"JOIN", Params:[]string{"#IABot", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by hare [sid388306@user/hare] [2021-06-16 01:01:08 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by hare [sid388306@user/hare] [2021-06-16 01:01:08 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Joan [2021-10-23 20:43:24 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000d7a2d0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.909Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 909000000, time.Local), Command:"JOIN", Params:[]string{"#Wikimedia-co", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Joan [2021-10-23 20:43:24 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000d7b980), Tags:girc.Tags{"time":"2022-04-05T12:14:58.909Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 909000000, time.Local), Command:"JOIN", Params:[]string{"#wikinews-it", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000d7b980), Tags:girc.Tags{"time":"2022-04-05T12:14:58.909Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 909000000, time.Local), Command:"JOIN", Params:[]string{"#wikinews-it", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000d7a2d0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.909Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 909000000, time.Local), Command:"JOIN", Params:[]string{"#Wikimedia-co", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000c64b40), Tags:girc.Tags{"time":"2022-04-05T12:14:58.908Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 908000000, time.Local), Command:"JOIN", Params:[]string{"#IABot", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Nemo_bis [federico@kapsi.fi] [2021-05-26 19:04:35 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Nemo_bis [federico@kapsi.fi] [2021-05-26 19:04:35 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc00059b380), Tags:girc.Tags{"time":"2022-04-05T12:14:58.910Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 910000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-sp", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc00059b380), Tags:girc.Tags{"time":"2022-04-05T12:14:58.910Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 910000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-sp", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Daki [~galahad@wikimedia/Galahad] [2022-01-17 03:36:39 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Daki [~galahad@wikimedia/Galahad] [2022-01-17 03:36:39 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc00108afc0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.910Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 910000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-no", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Jhs [~Jhs---@user/jhs] [2021-05-21 08:02:41 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc00108afc0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.910Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 910000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-no", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Jhs [~Jhs---@user/jhs] [2021-05-21 08:02:41 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000aa07e0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.911Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 911000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-wikicon-na", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000aa07e0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.911Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 911000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-wikicon-na", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc0004c23f0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.911Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 911000000, time.Local), Command:"JOIN", Params:[]string{"#translatewiki", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Nikerabbit [2021-10-30 13:15:36 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc0004c23f0), Tags:girc.Tags{"time":"2022-04-05T12:14:58.911Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 911000000, time.Local), Command:"JOIN", Params:[]string{"#translatewiki", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Nikerabbit [2021-10-30 13:15:36 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000539260), Tags:girc.Tags{"time":"2022-04-05T12:14:58.912Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 912000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-cloud", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000539260), Tags:girc.Tags{"time":"2022-04-05T12:14:58.912Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 912000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-cloud", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by mdipietro [sid510527@wikimedia/MDipietro-WMF] [2021-11-15 14:10:01 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by mdipietro [sid510527@wikimedia/MDipietro-WMF] [2021-11-15 14:10:01 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc00082e780), Tags:girc.Tags{"time":"2022-04-05T12:14:58.919Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 919000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-abstract", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc00082e780), Tags:girc.Tags{"time":"2022-04-05T12:14:58.919Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 919000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-abstract", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by quiddity [~quiddity@user/quiddity] [2021-06-21 19:04:46 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by quiddity [~quiddity@user/quiddity] [2021-06-21 19:04:46 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000fca120), Tags:girc.Tags{"time":"2022-04-05T12:14:58.919Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 919000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-it-sysop", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000fca120), Tags:girc.Tags{"time":"2022-04-05T12:14:58.919Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 919000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-it-sysop", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Daimona [2021-05-23 10:38:10 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by Daimona [2021-05-23 10:38:10 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000c27980), Tags:girc.Tags{"time":"2022-04-05T12:14:58.920Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 920000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-hackathon", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000c27980), Tags:girc.Tags{"time":"2022-04-05T12:14:58.920Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 58, 920000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-hackathon", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by legoktm [~quassel@wikipedia/Legoktm] [2022-03-22 00:16:26 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:58Z" level=debug msg="333: Topic set by legoktm [~quassel@wikipedia/Legoktm] [2022-03-22 00:16:26 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000aa0d20), Tags:girc.Tags{"time":"2022-04-05T12:14:59.006Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 59, 6000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-it", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000aa0d20), Tags:girc.Tags{"time":"2022-04-05T12:14:59.006Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 59, 6000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-it", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="333: Topic set by Nemo_bis [federico@wikimedia/Nemo-bis] [2021-10-30 09:39:45 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="333: Topic set by Nemo_bis [federico@wikimedia/Nemo-bis] [2021-10-30 09:39:45 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000d15680), Tags:girc.Tags{"time":"2022-04-05T12:14:59.007Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 59, 7000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-language", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="333: Topic set by Nikerabbit [2021-11-17 09:33:26 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="333: Topic set by Nikerabbit [2021-11-17 09:33:26 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000f00c30), Tags:girc.Tags{"time":"2022-04-05T12:14:59.007Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 59, 7000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-abstract-alerts", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="333: Topic set by quiddity [~quiddity@wikimedia/quiddity] [2022-03-10 21:02:52 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000f00c30), Tags:girc.Tags{"time":"2022-04-05T12:14:59.007Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 59, 7000000, time.Local), Command:"JOIN", Params:[]string{"#wikipedia-abstract-alerts", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="333: Topic set by quiddity [~quiddity@wikimedia/quiddity] [2022-03-10 21:02:52 +0000 UTC]" func=handleTopicWhoTime file="bridge/irc/handlers.go:263" prefix=irc
time="2022-04-05T12:14:59Z" level=debug msg="handle girc.Event{Source:(*girc.Source)(0xc000d15680), Tags:girc.Tags{"time":"2022-04-05T12:14:59.007Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 14, 59, 7000000, time.Local), Command:"JOIN", Params:[]string{"#wikimedia-language", "wm-bridgebot", "https://wikitech.wikimedia.org/wiki/Tool:Bridgebot"}, Sensitive:false, Echo:false}" func=handleJoinPart file="bridge/irc/handlers.go:117" prefix=irc
time="2022-04-05T12:15:09Z" level=debug msg="== Receiving PRIVMSG: isaacj ^^ this would explain PAWS being inaccessible too? (i assume it's run via VPS) girc.Event{Source:(*girc.Source)(0xc0005f4960), Tags:girc.Tags{"time":"2022-04-05T12:15:09.942Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 15, 9, 942000000, time.Local), Command:"PRIVMSG", Params:[]string{"#wikimedia-cloud", "^^ this would explain PAWS being inaccessible too? (i assume it's run via VPS)"}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T12:15:09Z" level=debug msg="== Receiving PRIVMSG: isaacj ^^ this would explain PAWS being inaccessible too? (i assume it's run via VPS) girc.Event{Source:(*girc.Source)(0xc0005f4960), Tags:girc.Tags{"time":"2022-04-05T12:15:09.942Z"}, Timestamp:time.Date(2022, time.April, 5, 12, 15, 9, 942000000, time.Local), Command:"PRIVMSG", Params:[]string{"#wikimedia-cloud", "^^ this would explain PAWS being inaccessible too? (i assume it's run via VPS)"}, Sensitive:false, Echo:false}" func=handlePrivMsg file="bridge/irc/handlers.go:195" prefix=irc
time="2022-04-05T12:15:09Z" level=debug msg="detected ISO-8859-1 confidence 41" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T12:15:09Z" level=debug msg="<= Sending message from #wikimedia-cloud on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc
time="2022-04-05T12:15:09Z" level=debug msg="detected ISO-8859-1 confidence 41" func=handlePrivMsg file="bridge/irc/handlers.go:220" prefix=irc
time="2022-04-05T12:15:09Z" level=debug msg="<= Sending message from #wikimedia-cloud on irc.libera-bridgebot to gateway" func=handlePrivMsg file="bridge/irc/handlers.go:240" prefix=irc

I am pretty sure I see what is happening here now...

  • Between 2022-04-05T11:58:23Z and 2022-04-05T12:14:42Z the ZNC instance loses network connectivity to libera.chat due to network changes being made by arturo. The bot itself is still connected to the ZNC instance at this time.
  • At 2022-04-05T12:14:42Z the ZNC instance has reconnected to libera.chat and the first message from the server's initialization is seen by the bot.
  • At 2022-04-05T12:14:52Z the bot recieves a NewConnection event triggered by the ZNC playback of connecting to the libra.chat server. The bot runs the handleNewConnection function in bridge/irc/handlers.go to process the event.
  • handleNewConnection connects a second set of IRC message handlers which then leads to duplicate messages being seen going forward by due to the duplicate message handler registrations.

Findings from T305487#7833726 reported upstream along with an idea of how this might be fixed by clearing any IRC event handlers before registering new ones.

Mentioned in SAL (#wikimedia-cloud) [2022-04-05T22:55:06Z] <wm-bot> <bd808> Restarting with custom matterbridge build to test fix for IRC message duplication (T305487)

bd808 changed the task status from Open to In Progress.Apr 5 2022, 10:55 PM
bd808 claimed this task.

Mentioned in SAL (#wikimedia-cloud) [2022-04-05T22:58:46Z] <wm-bot> <bd808> Restarting to swtich back to official matterbridge-1.25.0-linux-64bit build (T305487)

Mentioned in SAL (#wikimedia-cloud) [2022-04-05T22:55:06Z] <wm-bot> <bd808> Restarting with custom matterbridge build to test fix for IRC message duplication (T305487)

Tailing the logs with this build running, it looked like the IRC client was working as expected. Unexpectedly however the Telegram client did not seem to work. No IRC messages were relayed to Telegram and no Telegram messages were relayed to IRC.

Mentioned in SAL (#wikimedia-cloud) [2022-04-05T22:58:46Z] <wm-bot> <bd808> Restarting to swtich back to official matterbridge-1.25.0-linux-64bit build (T305487)

After switching back, one of two test messages sent from IRC while the custom client was running was relayed to Telegram. The only test message sent from Telegram was relayed to IRC. I feel it is more likely that my golang binary build was not quite right somehow than the trivial one line patch causing this unexpected behavior.

diff --git a/bridge/irc/handlers.go b/bridge/irc/handlers.go
index 987df2c5..7a7b4b42 100644
--- a/bridge/irc/handlers.go
+++ b/bridge/irc/handlers.go
@@ -122,6 +122,7 @@ func (b *Birc) handleNewConnection(client *girc.Client, event girc.Event) {
     i := b.i
     b.Nick = event.Params[0]

+    i.Handlers.ClearAll()
     i.Handlers.AddBg("PRIVMSG", b.handlePrivMsg)
     i.Handlers.AddBg("CTCP_ACTION", b.handlePrivMsg)
     i.Handlers.Add(girc.RPL_TOPICWHOTIME, b.handleTopicWhoTime)
bd808 changed the task status from In Progress to Stalled.Apr 5 2022, 11:26 PM

Marking as stalled for now. Let's see what upstream has to say.

Mentioned in SAL (#wikimedia-cloud) [2022-04-06T14:02:26Z] <wm-bot> <bd808> Restarting for duplicate IRC messages. (T305487)

Mentioned in SAL (#wikimedia-cloud) [2022-05-09T23:08:08Z] <wm-bot> <bd808> Update to matterbridge v1.25.1; release contains upstream attempt at fixing T305487

Mentioned in SAL (#wikimedia-cloud) [2022-05-09T23:18:21Z] <bd808> Forced ZNC reconnect to test matterbridge behavior when ZNC reconnects while bot is active (T305487)

Mentioned in SAL (#wikimedia-cloud) [2022-05-09T23:21:16Z] <wm-bot> <bd808> Reset after failed test of fix for T305487

bd808 changed the task status from Stalled to Open.May 9 2022, 11:58 PM

My attempt at patching this upstream was not successful. I am still confident that the analysis in T305487#7833726 of what causes the duplicate messages is correct. Unfortunately my attempt to fix this is not correct. It will take more staring at the golang code to see if I (or anyone else!) can figure out how to stop the second event handler registration from happening.

Instead of clearing the handlers, why not avoid registering the handlers again?

Something like

static registered = false;
if (registered)
    return;
registered = true;
i.Handlers.AddBg("PRIVMSG", b.handlePrivMsg)
i.Handlers.AddBg("CTCP_ACTION", b.handlePrivMsg)
...

I really need to work on this again. The bot breaks a lot and @LucasWerkmeister is amazing for noticing and restarting it. This really just needs me to take a little time to understand the golang build chain used in the upstream project so I can easily iterate on a fix like the one @Platonides proposed years ago in T305487#7915998.

This work could also be a good reason to figure out how to update things so that the tool runs using newer Toolforge features like build service and job service. I would hope that work would make the tool a bit easier for someone else to take over in the future if needed.

Mentioned in SAL (#wikimedia-cloud) [2024-04-24T16:38:44Z] <bd808> Added jhsoby as a co-maintainer. He kindly volunteered to help with restarts when the bot is double posting to Telegram (T305487)

[02:04]  wm-bb (~wm-bridge@wikimedia/bot/wm-bridgebot) left IRC (Quit: Bouncer quit)
[02:04]  wm-bb (~wm-bridge@wikimedia/bot/wm-bridgebot) joined the channel
[02:04] ChanServ sets mode +v wm-bb
[02:05]  <    bd808> I just cycled wm-bb connection. Double messages to telegram now or ?
[02:06]  <    wm-bb> <bd808> omg! single message

Mentioned in SAL (#wikimedia-cloud) [2024-04-27T23:00:45Z] <wmbot~bd808@tools-bastion-12> Made ZNC jump hosts to test T305487 again

bd808 changed the task status from Open to Stalled.Apr 27 2024, 11:38 PM
bd808 lowered the priority of this task from High to Medium.

I have submitted the patch that is working in our deploy upstream: https://github.com/42wim/matterbridge/pull/2138. As noted in that commit, voegelas came up with the working change in https://github.com/42wim/matterbridge/issues/1564#issuecomment-1693525232.

Lowering priority and marking as stalled while we wait for that to merge and be included in a future release that will allow us to replace the local changes from R3385:38c64944bf1d: [hack] Patch irc handler to offset BNC event reply.

bd808 changed the task status from Stalled to Open.May 24 2024, 5:25 PM

I have submitted the patch that is working in our deploy upstream: https://github.com/42wim/matterbridge/pull/2138. As noted in that commit, voegelas came up with the working change in https://github.com/42wim/matterbridge/issues/1564#issuecomment-1693525232.

Lowering priority and marking as stalled while we wait for that to merge and be included in a future release that will allow us to replace the local changes from R3385:38c64944bf1d: [hack] Patch irc handler to offset BNC event reply.

https://github.com/42wim/matterbridge/pull/2138 has been merged upstream. It looks like upstream may be getting ready to cut a new release. A new release upstream would be a nice point to undo our pinning to a patched local fork and reconnect with the main upstream.

bd808 changed the task status from Open to Stalled.Fri, Jul 5, 9:07 PM

https://github.com/42wim/matterbridge/pull/2138 has been merged upstream. It looks like upstream may be getting ready to cut a new release. A new release upstream would be a nice point to undo our pinning to a patched local fork and reconnect with the main upstream.

Marking as stalled again to remind me that I'm waiting on an upstream release (likely 1.27.0) containing the fix.