Matterbridge: [irc] reconnecting problem ?

[danrmiller]

Describe the bug
Users are reporting that messages stop getting relayed between irc and mattermost until matterbridge is restarted.

To Reproduce
This happens intermittently every several days.

Expected behavior
I don't know if this log is relevant. If it isn't I'll close the issue, or maybe you have some suggestions where I should look. This message "error:websocket: unexpected reserved bits" is the only thing that jumps out to me in the logs around the timeframe of the outage. The log makes it seem like it reconnects but it doesn't seem that way to the users.

Screenshots/debug logs

[608876] ERROR matterclient: error:websocket: unexpected reserved bits 0x30
[608876] DEBUG matterclient: WsClient: making connection: wss://mattermost:443/api/v4/websocket
[608876] DEBUG matterclient: WsClient: connected
[608876] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"hello", Data:map[string]interface {}{"server_version":"4.6.0.4.6.0.e4f00a3e29ee754f7240ee4c5cd73edf.false"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea140), Sequence:0, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[608876] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"status_change", Data:map[string]interface {}{"user_id":"5ppgc3yw4ifrjrowjji8iutwae", "status":"online"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea1c0), Sequence:2, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[608876] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"status_change", Data:map[string]interface {}{"status":"online", "user_id":"5ppgc3yw4ifrjrowjji8iutwae"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea200), Sequence:1, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[608876] ERROR matterclient: error:websocket: unexpected reserved bits 0x70
[608876] DEBUG matterclient: WsClient: making connection: wss://mattermost:443/api/v4/websocket
[608876] DEBUG matterclient: WsClient: connected
[608876] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"hello", Data:map[string]interface {}{"server_version":"4.6.0.4.6.0.e4f00a3e29ee754f7240ee4c5cd73edf.false"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea140), Sequence:0, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}

Environment (please complete the following information):

• OS: Ubuntu 16.04.5 LTS
• Matterbridge version: 1.13.1 1d39c77

[42wim]

Hm that's strange, because it receives the hello event from mattermost. So it's connected.
Are there any other matterclient messages after the last line?

[danrmiller]

[608887] DEBUG matterclient: WS PING
[608887] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:1, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", Create
At:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.Translat
eFunc)(nil), Locale:""}
[608887] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:1, Data:map[string]interface {}{"node_id":"", "server_time":1.551807440441e+12, "text":"pong", "version":"4.6.0"}, Error:(*model.AppError)(nil)}
[608887] DEBUG matterclient: WS PONG received
[608947] DEBUG matterclient: WS PING
[608947] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[608947] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2, Data:map[string]interface {}{"text":"pong", "version":"4.6.0", "node_id":"", "server_time":1.5518075005e+12}, Error:(*model.AppError)(nil)}
[608947] DEBUG matterclient: WS PONG received
[609007] DEBUG matterclient: WS PING
[609007] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:3, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[609007] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:3, Data:map[string]interface {}{"version":"4.6.0", "node_id":"", "server_time":1.551807560574e+12, "text":"pong"}, Error:(*model.AppError)(nil)}
[609007] DEBUG matterclient: WS PONG received
[609067] DEBUG matterclient: WS PING
[609067] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:4, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[609067] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:4, Data:map[string]interface {}{"node_id":"", "server_time":1.551807620756e+12, "text":"pong", "version":"4.6.0"}, Error:(*model.AppError)(nil)}
[609067] DEBUG matterclient: WS PONG received
[609127] DEBUG matterclient: WS PING
[609127] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:5, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[609127] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:5, Data:map[string]interface {}{"node_id":"", "server_time":1.551807680824e+12, "text":"pong", "version":"4.6.0"}, Error:(*model.AppError)(nil)}
[609127] DEBUG matterclient: WS PONG received
[609176] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"status_change", Data:map[string]interface {}{"status":"away", "user_id":"5ppgc3yw4ifrjrowjji8iutwae"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea1c0), Sequence:1, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[609176] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"status_change", Data:map[string]interface {}{"status":"away", "user_id":"5ppgc3yw4ifrjrowjji8iutwae"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea200), Sequence:2, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[609188] DEBUG matterclient: WS PING
[609188] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:6, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[609188] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:6, Data:map[string]interface {}{"node_id":"", "server_time":1.551807740882e+12, "text":"pong", "version":"4.6.0"}, Error:(*model.AppError)(nil)}
[609188] DEBUG matterclient: WS PONG received
[609236] ERROR matterclient: error:websocket: unexpected reserved bits 0x30
[609236] DEBUG matterclient: WsClient: making connection: wss://mattermost:443/api/v4/websocket
[609236] DEBUG matterclient: WsClient: connected
[609236] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"hello", Data:map[string]interface {}{"server_version":"4.6.0.4.6.0.e4f00a3e29ee754f7240ee4c5cd73edf.false"}, Broadcast:(*model.WebsocketBroadcast)(0xc0005ea140), Sequence:0, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[609248] DEBUG matterclient: WS PING
[609248] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:1, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}

[danrmiller]

I'm very sorry for giving you a wild goose chase. Perhaps it is the irc side not reconnecting.
Prior to those matterclient messages the irc side disconnects and then no more irc messages appear, only the matterclient ones I pasted earlier from then on.

[547680] ERROR irc:          disconnect: error: timed out waiting for a requested PING response
[547680]  INFO irc:          reconnecting in 30 seconds...
[547713]  INFO bridge:       irc.myircnetwork: joining #myircchannel (ID: #myircchannel.myircnetwork)

[42wim]

Ok, and the irc doesn't get reconnected after a while?

[danrmiller]

Nope.

[42wim]

So that message is the last message you see from the irc bridge until you restarted?

[danrmiller]

Correct.

[42wim]

Ok, that's very strange, because when I look at the code path, everything points to the fact that the IRC bridge successfully connected. The event at 547713 shows that it successfully joined the channel.

The only way to get more insight is to crank the irc debuglevel
Could you run with -debug and add DebugLevel=1 to your [irc.ircserver] config ?

This will show a lot more debug info, which will hopefully point to the issue.

And report back with that debug log if the reconnect fails again.

[danrmiller]

I don't see much more info with the new debug level. The irc side gets disconnected, appears to reconnect, and the matterbridge debug log shows messages from the mattermost side, but they never get to irc, and no irc messages get to mattermost. The matterbridge debug log doesn't show the irc side messages, only mattermost, after the disconnection.

[932231] ERROR irc:          disconnect: error: timed out waiting for a requested PING response
[932231]  INFO irc:          reconnecting in 30 seconds...
[932253] DEBUG matterclient: WS PING
[932253] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2659, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", Cr
eateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.Tra
nslateFunc)(nil), Locale:""}
[932253] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2659, Data:map[string]interface {}{"server_time":1.552752442686e+12, "te
xt":"pong", "version":"4.6.0", "node_id":""}, Error:(*model.AppError)(nil)}
[932253] DEBUG matterclient: WS PONG received
[932261] DEBUG irc:          "CLIENT_INIT :irc.ircserver:6697"

Then we have the DEBUG messages of the normal irc protocol joining the server including MOTD. Then:

[932272]  INFO bridge:       irc.ircserver: joining #channel1 (ID: #channel1irc.ircserver)
[932272]  INFO bridge:       irc.ircserver:: joining #channel2 (ID: #channel2irc.ircserver)
[932274] DEBUG irc:          "CLIENT_CONNECTED :irc.ircserver:6697"
[932274]  INFO bridge:       irc.ircserver:: joining #channel3 (ID: #channel3irc.ircserver)
[932313] DEBUG matterclient: WS PING
[932313] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2660, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[932313] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2660, Data:map[string]interface {}{"server_time":1.552752502914e+12, "text":"pong", "version":"4.6.0", "node_id":""}, Error:(*model.AppError)(nil)}
[932313] DEBUG matterclient: WS PONG received
[932372]  INFO bridge:       irc.ircserver: joining #channel4 (ID: #channel4irc.ircserver)
[932373] DEBUG matterclient: WS PING
[932373] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2661, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", CreateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.TranslateFunc)(nil), Locale:""}
[932373] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2661, Data:map[string]interface {}{"node_id":"", "server_time":1.552752562993e+12, "text":"pong", "version":"4.6.0"}, Error:(*model.AppError)(nil)}
[932373] DEBUG matterclient: WS PONG received
[932380]  INFO bridge:       irc.ircserver: joining #channel5 (ID: #channel5irc.ircserver)
[932381] DEBUG irc:          "CLIENT_DISCONNECTED :irc.ircserver:6697"
[932381]  INFO bridge:       irc.ircserver: joining #channel6 (ID: #channel6irc.ircserver)
[932433] DEBUG matterclient: WS PING
[932433] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2662, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", Cr
eateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.Tra
nslateFunc)(nil), Locale:""}
[932433] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2662, Data:map[string]interface {}{"server_time":1.552752623071e+12, "te
xt":"pong", "version":"4.6.0", "node_id":""}, Error:(*model.AppError)(nil)}
[932433] DEBUG matterclient: WS PONG received
[932482] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"status_change", Data:map[string]interface {}{"user_id":"5ppgc3yw4ifrjrowjji8iutwae", "status"
:"away"}, Broadcast:(*model.WebsocketBroadcast)(0xc000408cc0), Sequence:7132, precomputedJSON:(*model.precomputedWebSocketEventJSON)(nil)}
[932493] DEBUG matterclient: WS PING
[932493] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2663, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", Cr
eateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.Tra
nslateFunc)(nil), Locale:""}
[932493] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2663, Data:map[string]interface {}{"text":"pong", "version":"4.6.0", "no
de_id":"", "server_time":1.552752683109e+12}, Error:(*model.AppError)(nil)}
[932493] DEBUG matterclient: WS PONG received
[932553] DEBUG matterclient: WS PING
[932553] DEBUG matterclient: sendWsRequest &model.WebSocketRequest{Seq:2664, Action:"ping", Data:map[string]interface {}(nil), Session:model.Session{Id:"", Token:"", Cr
eateAt:0, ExpiresAt:0, LastActivityAt:0, UserId:"", DeviceId:"", Roles:"", IsOAuth:false, Props:model.StringMap(nil), TeamMembers:[]*model.TeamMember(nil)}, T:(i18n.Tra
nslateFunc)(nil), Locale:""}
[932553] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:2664, Data:map[string]interface {}{"server_time":1.552752743163e+12, "text":"pong", "version":"4.6.0", "node_id":""}, Error:(*model.AppError)(nil)}
[932553] DEBUG matterclient: WS PONG received

After this only pings and pongs and messages from mattermost side but nothing indicating any error.
I wonder if this is relevant from above:

[932381] DEBUG irc: "CLIENT_DISCONNECTED :irc.ircserver:6697"

[chotaire]

I have seen similar behavior when an IRC connection got disconnected.

[42wim]

Should be fixed in master now.
Binaries can be found here: https://bintray.com/42wim/nightly/Matterbridge/v1.14.2-10-g380c386#files

[chotaire]

Tested as fixed in v1.14.2-10-g380c386.

[qaisjp]

Tested as fixed in 380c38674c19d741b344c627a2db7f8f34d223d3.