Matterbridge crashing with panic: runtime error: invalid memory address or nil pointer dereference :/

[stnzzz]

Hello, I upgraded our Mattermost and Matterbridge and now Matterbridge crashes immediately after receiving a Mattermost message. It's bridging between IRC channels and Mattermost and the problem already occured before upgrading Mattermost from version 4.x to 5.2.1 so most likely it's not related to Mattermost version. The IRC daemon (ngircd) was also upgraded, but the problem already occured with old version.

I tested with the development snapshots and matterbridge-v1.11.0-4-ga69ef84-linux-amd64 seems to be stable, but anything newer beginning from matterbridge-v1.11.1-4-g5106286-linux-amd64 is suffering of the problem so it's something that has changed between those versions.

The system is a Debian 9.5 box with Go 1.8.1.

Here's an anonymized log of Matterbridge starting, logging into the server, receiving one single message and crashing. Run here as root to eliminate permision issues, normally as a regular user.

I can provide more debug information if needed. Any ideas what would be the problem here?

root@MatterMost:/opt/matterbridge/bin# ./matterbridge-v1.11.1-4-g5106286-linux-amd64 -debug [0000] INFO main: Enabling debug [0000] INFO main: Running version 1.11.2-dev 5106286 [0000] INFO main: WARNING: THIS IS A DEVELOPMENT VERSION. Things may break. [0000] INFO gateway: Parsing gateway IRC-Housut [0000] INFO gateway: Parsing gateway IRC-helpdesk [0000] INFO gateway: Parsing gateway IRC-Yleinen [0000] INFO gateway: Parsing gateway IRC-8ball [0000] INFO gateway: Parsing gateway IRC-Datacenter [0000] INFO gateway: Starting bridge: irc.company [0000] INFO irc: Connecting irc.company.fi:6667 [0000] DEBUG irc: "CLIENT_INIT :irc.company.fi:6667" [0000] DEBUG irc: ":irc.company.fi CAP LS :multi-prefix" [0001] DEBUG irc: ":irc.company.fi CAP B ACK :multi-prefix" [0001] DEBUG irc: ":irc.company.fi 001 B :Welcome to the Internet Relay Network B!~B@88.148.137.25" [0001] DEBUG irc: "CLIENT_GENERAL_UPDATED" [0001] DEBUG irc: Registering callbacks [0001] INFO irc: Connection succeeded [0001] INFO bridge: irc.company: joining #8-ball (ID: #8-ballirc.company) [0001] INFO bridge: irc.company: joining #datacenter (ID: #datacenterirc.company) [0001] INFO bridge: irc.company: joining #housut (ID: #housutirc.company) [0001] INFO bridge: irc.company: joining #helpdesk (ID: #helpdeskirc.company) [0001] INFO bridge: irc.company: joining #yleinen (ID: #yleinenirc.company) [0001] INFO gateway: Starting bridge: mattermost.uli-api [0001] INFO mattermost: Connecting using login/password (sending and receiving) [0001] INFO mattermost: Connecting helpdesk@companyname.com (team: companyname) on chat.companyname.com [0001] INFO matterclient: Found version 5.2.0.5.2.1.10f7b99372a387c04d14f1949f6f0abd.false [0001] DEBUG matterclient: trying login companyname helpdesk@companyname.com chat.companyname.com [0001] DEBUG matterclient: initUser(): found our team companyname (id: h4z1unws5f8qznte9oswzfmkue) [0001] DEBUG matterclient: WsClient: making connection: wss://chat.companyname.com/api/v4/websocket [0001] DEBUG matterclient: WsClient: connected [0001] INFO mattermost: Connection succeeded [0001] DEBUG matterclient: StatusLoop: [0001] DEBUG matterclient: WS PING [0001] 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:""} [0001] INFO bridge: mattermost.uli-api: joining housut (ID: housutmattermost.uli-api) [0001] DEBUG matterclient: Not joining 994hnpbq3jfn7p9479rqdbjn9a already joined. [0001] INFO bridge: mattermost.uli-api: joining town-square (ID: town-squaremattermost.uli-api) [0001] DEBUG mattermost: Choosing login/password based receiving [0001] DEBUG matterclient: Not joining oj9di9h6xiy78j16i78p3ocumw already joined. [0001] INFO bridge: mattermost.uli-api: joining datacenter (ID: datacentermattermost.uli-api) [0001] DEBUG matterclient: Not joining qow4tmwzo78r38btn6gia4mwdr already joined. [0001] INFO gateway: Starting bridge: mattermost.uli [0001] INFO mattermost: Connecting using webhookurl (sending) and webhookbindaddress (receiving) [0001] INFO bridge: mattermost.uli: joining helpdesk (ID: helpdeskmattermost.uli) [0001] INFO bridge: mattermost.uli: joining 8-ball (ID: 8-ballmattermost.uli) [0001] INFO main: Gateway(s) started succesfully. Now relaying messages 2018/08/29 13:31:10 Listening on http://0.0.0.0:9999... [0001] DEBUG mattermost: Choosing webhooks based receiving [0001] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"hello", Data:map[string]interface {}{"server_version":"5.2.0.5.2.1.10f7b99372a387c04d14f1949f6f0abd.false"}, Broadcast:(model.WebsocketBroadcast)(0xc420299d00), Sequence:0} [0001] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"status_change", Data:map[string]interface {}{"status":"online", "user_id":"x9mnb4sxgbbyxgwkhq4iifkzqh"}, Broadcast:(model.WebsocketBroadcast)(0xc420299d40), Sequence:1} [0001] DEBUG matterclient: WsReceiver response: model.WebSocketResponse{Status:"OK", SeqReply:1, Data:map[string]interface {}{"server_time":1.535538670525e+12, "text":"pong", "version":"5.2.0", "node_id":""}, Error:(model.AppError)(nil)} [0001] DEBUG matterclient: WS PONG received [0002] DEBUG irc: handleJoinPart: empty Params? girc.Event{Source:(girc.Source)(0xc4204e0090), Tags:girc.Tags(nil), Timestamp:time.Time{wall:0xbed9bb5bcf8f6317, ext:2022964656, loc:(time.Location)(0x160e580)}, Command:"JOIN", Params:[]string(nil), Trailing:"#8-ball", EmptyTrailing:false, Sensitive:false, Echo:false} [0002] DEBUG irc: handleJoinPart: empty Params? girc.Event{Source:(girc.Source)(0xc4207ebf80), Tags:girc.Tags(nil), Timestamp:time.Time{wall:0xbed9bb5bcf908edd, ext:2023030262, loc:(time.Location)(0x160e580)}, Command:"JOIN", Params:[]string(nil), Trailing:"#datacenter", EmptyTrailing:false, Sensitive:false, Echo:false} [0003] DEBUG irc: handleJoinPart: empty Params? girc.Event{Source:(girc.Source)(0xc4204e04e0), Tags:girc.Tags(nil), Timestamp:time.Time{wall:0xbed9bb5bcf90e273, ext:2023051658, loc:(time.Location)(0x160e580)}, Command:"JOIN", Params:[]string(nil), Trailing:"#housut", EmptyTrailing:false, Sensitive:false, Echo:false} [0005] DEBUG irc: handleJoinPart: empty Params? girc.Event{Source:(girc.Source)(0xc4204e0900), Tags:girc.Tags(nil), Timestamp:time.Time{wall:0xbed9bb5c3b72f6b2, ext:3759288511, loc:(time.Location)(0x160e580)}, Command:"JOIN", Params:[]string(nil), Trailing:"#helpdesk", EmptyTrailing:false, Sensitive:false, Echo:false} [0006] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"typing", Data:map[string]interface {}{"parent_id":"", "user_id":"ulifcpdztqnt1ngb9z61gr"}, Broadcast:(model.WebsocketBroadcast)(0xc42040e900), Sequence:2} [0007] DEBUG matterclient: WsReceiver event: model.WebSocketEvent{Event:"posted", Data:map[string]interface {}{"channel_display_name":"Muutostiedotteet", "channel_name":"town-square", "channel_type":"O", "post":"{\"id\":\"km6diehn5b88fb5dnbw3cbrqya\",\"create_at\":1535538676678,\"update_at\":1535538676678,\"edit_at\":0,\"delete_at\":0,\"is_pinned\":false,\"user_id\":\"ulifcpdztqnt1ngb9z61gr\",\"channel_id\":\"oj9di9h6xiy78j16i78p3ocumw\",\"root_id\":\"\",\"parent_id\":\"\",\"original_id\":\"\",\"message\":\"piip\",\"type\":\"\",\"props\":{},\"hashtags\":\"\",\"pending_post_id\":\"ulifcpdztqnt1ngb9z61gr:1535538676650\"}", "sender_name":"eerik.lastname-companyname.fi", "team_id":"h4z1unws5f8qznte9oswzfmkue"}, Broadcast:(model.WebsocketBroadcast)(0xc42040e940), Sequence:3} [0007] DEBUG mattermost: map[string]interface {}{"channel_name":"town-square", "channel_type":"O", "post":"{\"id\":\"km6diehn5b88fb5dnbw3cbrqya\",\"create_at\":1535538676678,\"update_at\":1535538676678,\"edit_at\":0,\"delete_at\":0,\"is_pinned\":false,\"user_id\":\"ulifcpdztqnt1ngb9z61gr\",\"channel_id\":\"oj9di9h6xiy78j16i78p3ocumw\",\"root_id\":\"\",\"parent_id\":\"\",\"original_id\":\"\",\"message\":\"piip\",\"type\":\"\",\"props\":{},\"hashtags\":\"\",\"pending_post_id\":\"ulifcpdztqnt1ngb9z61gr:1535538676650\"}", "sender_name":"eerik.lastname-companyname.fi", "team_id":"h4z1unws5f8qznte9oswzfmkue", "channel_display_name":"Muutostiedotteet"} [0007] DEBUG mattermost: == Receiving event &matterclient.Message{Raw:(model.WebSocketEvent)(0xc4204e0cc0), Post:(model.Post)(0xc4202110e0), Team:"companyname", Channel:"town-square", Username:"eerik.lastname-companyname.fi", Text:"piip", Type:"", UserID:"ulifcpdztqnt1ngb9z61gr"} [0007] DEBUG mattermost: <= Sending message from s_tanZzz on mattermost.uli-api to gateway [0007] DEBUG mattermost: <= Message is &config.Message{Text:"piip", Channel:"town-square", Username:"s_tanZzz", UserID:"ulifcpdztqnt1ngb9z61gr", Avatar:"", Account:"mattermost.uli-api", Event:"", Protocol:"", Gateway:"", Timestamp:time.Time{wall:0x0, ext:0, loc:(time.Location)(nil)}, ID:"km6diehn5b88fb5dnbw3cbrqya", Extra:map[string][]interface {}{}} [0007] DEBUG gateway: => Sending config.Message{Text:"piip", Channel:"town-square", Username:"s_tanZzz", UserID:"ulifcpdztqnt1ngb9z61gr", Avatar:"", Account:"mattermost.uli-api", Event:"", Protocol:"", Gateway:"IRC-Yleinen", Timestamp:time.Time{wall:0xbed9bb5d41524cbd, ext:7784069178, loc:(time.Location)(0x160e580)}, ID:"km6diehn5b88fb5dnbw3cbrqya", Extra:map[string][]interface {}{}} from mattermost.uli-api (town-square) to irc.company (#yleinen) [0007] DEBUG irc: => Receiving config.Message{Text:"piip", Channel:"#yleinen", Username:" ", UserID:"ulifcpdztqnt1ngb9z61gr", Avatar:"", Account:"mattermost.uli-api", Event:"", Protocol:"", Gateway:"IRC-Yleinen", Timestamp:time.Time{wall:0xbed9bb5d41524cbd, ext:7784069178, loc:(time.Location)(0x160e580)}, ID:"", Extra:map[string][]interface {}{}} [0007] DEBUG irc: Sending to channel #yleinen [0007] DEBUG mattermost: Receiving from matterhook matterhook.IMessage{BotID:"", BotName:"", Token:"5ycidckt978o8gjiy8a5q6ww3y", TeamID:"h4z1unws5f8qznte9oswzfmkue", TeamDomain:"companyname", ChannelID:"oj9di9h6xiy78j16i78p3ocumw", ChannelName:"town-square", Timestamp:"1535538676", UserID:"ulifcpdztqnt1ngb9z61gr", UserName:"eerik.lastname-companyname.fi", PostId:"km6diehn5b88fb5dnbw3cbrqya", RawText:"", ServiceId:"", Text:"piip", TriggerWord:"", FileIDs:""} panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x98f5af]

goroutine 107 [running]: github.com/42wim/matterbridge/matterclient.(MMClient).GetUser(0x0, 0xc4206839fd, 0x1a, 0x0) /home/travis/gopath/src/github.com/42wim/matterbridge/matterclient/matterclient.go:745 +0x2f github.com/42wim/matterbridge/matterclient.(MMClient).GetNickName(0x0, 0xc4206839fd, 0x1a, 0x1a, 0x162d4a0) /home/travis/gopath/src/github.com/42wim/matterbridge/matterclient/matterclient.go:777 +0x3f github.com/42wim/matterbridge/bridge/mattermost.(Bmattermost).handleMatter(0xc42040ec00) /home/travis/gopath/src/github.com/42wim/matterbridge/bridge/mattermost/mattermost.go:188 +0x373 created by github.com/42wim/matterbridge/bridge/mattermost.(Bmattermost).Connect /home/travis/gopath/src/github.com/42wim/matterbridge/bridge/mattermost/mattermost.go:60 +0x273

[42wim]

Yes, was because of commit https://github.com/42wim/matterbridge/commit/cb7278eb503498da4e1bcaf24b330d696832e57b which tried to call matterclient also if you only use webhooks.

Should be fixed now, I'm going to release a 1.11.3 which includes this fix (or you can use the dev build when it's done building)

[stnzzz]

Great, thanks. :)

[stnzzz]

Damn, actually it's not working so some other reason I guess. We actually use both, api and webhooks for different channels.

[2018-08-31T15:45:36+03:00] INFO main: Running version 1.11.3-dev .. [0001] INFO main: Gateway(s) started succesfully. Now relaying messages 2018/08/31 15:45:38 Listening on http://0.0.0.0:9999... panic: runtime error: invalid memory address or nil pointer dereference [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x9dee5f]

goroutine 109 [running]: github.com/42wim/matterbridge/matterclient.(MMClient).GetUser(0x0, 0xc420686c39, 0x1a, 0x0) /opt/matterbridge/src/github.com/42wim/matterbridge/matterclient/matterclient.go:745 +0x2f github.com/42wim/matterbridge/matterclient.(MMClient).GetNickName(0x0, 0xc420686c39, 0x1a, 0x1a, 0x168f120) /opt/matterbridge/src/github.com/42wim/matterbridge/matterclient/matterclient.go:777 +0x3f github.com/42wim/matterbridge/bridge/mattermost.(Bmattermost).handleMatter(0xc4203c28c0) /opt/matterbridge/src/github.com/42wim/matterbridge/bridge/mattermost/mattermost.go:188 +0x22e created by github.com/42wim/matterbridge/bridge/mattermost.(Bmattermost).Connect /opt/matterbridge/src/github.com/42wim/matterbridge/bridge/mattermost/mattermost.go:60 +0x2d1

[42wim]

You're not running the release with the fix. It's looks like you're still running the old code

[stnzzz]

Didn't you say 1.11.3 is fixed? 1.11.3-dev this says when starting. I installed it with "go get github.com/42wim/matterbridge" just before running. I will check the dev snapshot.

[stnzzz]

Ok seems like this nightly one is stable: [2018-08-31T16:20:20+03:00] INFO main: Running version 1.11.4-dev 1fe81b7

Works now, thanks. :)

[42wim]

go get doesn't update you need to run go get -u

[stnzzz]

Ok. :)