Messages not being relayed

[hloeung]

Hi,

This might be similar to #296, using the latest matterircd built from commit a1ab35c, every now and again messages are not relayed. On typing something, it then triggers a bunch of replayed as well as:

|13:52 -!-     &users hloeung   H   0  m45ssk4t4bfwufbghxnmj89d4a@localhost [Haw Loeung]
...

Is this some kind of idle timer automatically setting myself to away mode?

[hloeung]

On reconnecting, a flood of replaying, likely also #302

[42wim]

This is the reconnecting issue, while reconnecting messages can not be send.
Going to close this in favor of #302

[hloeung]

Can we re-open this? Even with the reconnecting issue fixed, it seems with the latest matterircd there are periods where no messages are relayed / received.

[42wim]

logs please
it's normal there are no messages sent/received during reconnect

[guilhermepiccoli]

@hloeung , are you using matterircd behind a bouncer, like ZNC?

[guilhermepiccoli]

@42wim , I think we may have a high severity issue here heheh
I faced that today, running master (at commit cf161ee) - all of sudden, my IRC client stopped seeing messages (and I didn't realize until like 2h later). The mattermost server was fine and I could follow-up reading on web client. Notice that I could send messages!

I saw the following pattern after the problem started:

time="2020-08-24T18:44:14+02:00" level=debug msg="-> :matterircd 315 gpiccoli #channel :End of /WHO list." module=matterircd time="2020-08-24T18:44:14+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"WHO\", Params:[]string{\"#channel\"}, Trailing:\"\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:44:14+02:00" level=debug msg="<- PING LAG1598237454168" module=matterircd time="2020-08-24T18:44:14+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237454168" module=matterircd time="2020-08-24T18:44:14+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237454168\"}, Trailing:\"LAG1598237454168\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:44:44+02:00" level=debug msg="<- PING LAG1598237484168" module=matterircd time="2020-08-24T18:44:44+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237484168" module=matterircd time="2020-08-24T18:44:44+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237484168\"}, Trailing:\"LAG1598237484168\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:45:14+02:00" level=debug msg="<- PING LAG1598237514167" module=matterircd time="2020-08-24T18:45:14+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237514167" module=matterircd time="2020-08-24T18:45:14+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237514167\"}, Trailing:\"LAG1598237514167\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:45:44+02:00" level=debug msg="<- PING LAG1598237544167" module=matterircd time="2020-08-24T18:45:44+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237544167" module=matterircd time="2020-08-24T18:45:44+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237544167\"}, Trailing:\"LAG1598237544167\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:46:14+02:00" level=debug msg="<- PING LAG1598237574168" module=matterircd time="2020-08-24T18:46:14+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237574168" module=matterircd time="2020-08-24T18:46:14+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237574168\"}, Trailing:\"LAG1598237574168\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:46:44+02:00" level=debug msg="<- PING LAG1598237604167" module=matterircd time="2020-08-24T18:46:44+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237604167" module=matterircd time="2020-08-24T18:46:44+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237604167\"}, Trailing:\"LAG1598237604167\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="<- WHO #otherchannel" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="-> :matterircd 352 gpiccoli #otherchannel 4qkp6yeddiddjjpj4ui3cmzpfr https://mmost.server.org * bar G :0 Bar User " module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="-> :matterircd 352 gpiccoli #otherchannel zypncuty1byu8edfbr3utsk6ey localhost * gpiccoli G :0 Guilherme G. Piccoli" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="-> :matterircd 315 gpiccoli #otherchannel :End of /WHO list." module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"WHO\", Params:[]string{\"#otherchannel\"}, Trailing:\"\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="<- WHO #somechannel" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="<- PING LAG1598237634167" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="-> :matterircd PONG matterircd :LAG1598237634167" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PING\", Params:[]string{\"LAG1598237634167\"}, Trailing:\"LAG1598237634167\", EmptyTrailing:false} <nil>" module=matterircd time="2020-08-24T18:47:14+02:00" level=debug msg="-> :matterircd 352 gpiccoli #somechannel t7odu44sojy48rtrdye91barwa https://mmost.server.org * alice G :0 Alice FooBar " module=matterircd

After that, only 3 types of messages got logged: ping/pongs, /who commands to channels (a lot of them) and message that I sent, like below:

time="2020-08-24T20:17:12+02:00" level=debug msg="B: \"<- PRIVMSG foo :testing - do you receive that? EYEcatcheR\"\n" module=matterircd time="2020-08-24T20:17:12+02:00" level=debug msg="flushing buffer: &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PRIVMSG\", Params:[]string{\"foo\"}, Trailing:\"testing - do you receive that? EYEcatcheR\", EmptyTrailing:false}\n" module=matterircd time="2020-08-24T20:17:12+02:00" level=debug msg="SendDirectMessage to 15mhxss9p3rmiykm5wwqrmxxah, msg testing - do you receive that? EYEcatcheR" prefix=matterclient time="2020-08-24T20:17:13+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:\"PRIVMSG\", Params:[]string{\"foo\"}, Trailing:\"testing - do you receive that? EYEcatcheR\", EmptyTrailing:false} <nil>" module=matterircd

The above message reached his destination, although the response from the foo user I could only see in the web client.

I'm running now matterircd from August, 19th as a fallback - let me know if you need more logs, or want me to grep something in the logs. Also, I'm on freenode as usual. Thanks in advance =)

[hloeung]

@hloeung , are you using matterircd behind a bouncer, like ZNC?

No, straight irssi connected directly to the matterircd instance.

Thanks for adding details.

[guilhermepiccoli]

Hey @42wim , running master with your pong commit (built this morning), I got the following:

`time="2020-08-25T19:52:24+02:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:"MODE", Params:[]string{"#town-square"}, Trailing:"", EmptyTrailing:false} " module=matterircd
panic: send on closed channel

goroutine 40 [running]:
github.com/mattermost/mattermost-server/v5/model.(*WebSocketClient).SendMessage(...)
/home/guilherme/app/go/pkg/mod/github.com/mattermost/mattermost-server/v5@v5.25.2/model/websocket_client.go:252
github.com/42wim/matterircd/pkg/matterclient.(*Client).doCheckAlive(0xc000222540, 0xc00003cf48, 0x2)
/home/guilherme/src/matterircd/pkg/matterclient/matterclient.go:498 +0xdd
github.com/42wim/matterircd/pkg/matterclient.(*Client).checkAlive(0xc000222540, 0xd664a0, 0xc0001d8740)
/home/guilherme/src/matterircd/pkg/matterclient/matterclient.go:518 +0x129
created by github.com/42wim/matterircd/pkg/matterclient.(*Client).checkConnection
/home/guilherme/src/matterircd/pkg/matterclient/matterclient.go:530 +0x6e
`

I'm not sure if it's a patch bug or if it's a clue on some connection problem.
Thanks in advance, sorry to annoy you so much heheh

[guilhermepiccoli]

Just a heads-up on how this is evolving: using matterircd master one should not experience the "stalls" (not relayed messages), but I face multiple reconnects in 24h (more than 130) - so I'm using a version before commit 15b76.
In my case, reconnects always show in the form of the following error:

time="2020-08-26T02:39:01+02:00" level=error msg="got a listen error: &model.AppError{Id:"model.websocket_client.connect_fail.app_error", Message:"model.websocket_client.connect_fail.app_error", DetailedError:"websocket: close 1006 (abnormal closure): unexpected EOF", RequestId:"", StatusCode:500, Where:"NewWebSocketClient", IsOAuth:false, params:map[string]interface {}(nil)}" prefix=matterclient time="2020-08-26T02:39:01+02:00" level=error msg="connection not alive: NewWebSocketClient: model.websocket_client.connect_fail.app_error, websocket: close 1006 (abnormal closure): unexpected EOF" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=error msg="got a listen error: &model.AppError{Id:"model.websocket_client.connect_fail.app_error", Message:"model.websocket_client.connect_fail.app_error", DetailedError:"websocket: close 1006 (abnormal closure): unexpected EOF", RequestId:"", StatusCode:500, Where:"NewWebSocketClient", IsOAuth:false, params:map[string]interface {}(nil)}" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=info msg="reconnect: logout" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=debug msg="logout running loginCancel to exit goroutines" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=debug msg="logout as gpiccoli (team: myteam) on mmost.someserver.org" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=debug msg="closing websocket" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=debug msg="running m.Client.Logout" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=debug msg="exiting Logout()" prefix=matterclient time="2020-08-26T02:39:11+02:00" level=info msg="reconnect: login" prefix=matterclient

[hloeung]

Looks good to me too, haven't seen any periods of "stalls" / messages not being relayed via IRC. Thanks @42wim