Messages not being relayed
Closed this issue · 10 comments
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?
This is the reconnecting issue, while reconnecting messages can not be send.
Going to close this in favor of #302
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.
logs please
it's normal there are no messages sent/received during reconnect
@hloeung , are you using matterircd behind a bouncer, like ZNC?
@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 , are you using matterircd behind a bouncer, like ZNC?
No, straight irssi connected directly to the matterircd instance.
Thanks for adding details.
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
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