Some messages not relayed from IRC to Mattermost

[crhalpin]

Rarely, a message sent from IRC will not be relayed to Mattermost.

I'm using matterircd 0.25.1 on FreeBSD 13.1-RELEASE and talking to a Mattermost 7.3.0 server. Attached is an edited debug log where a message was not relayed, then the same message was sent a second time and was relayed. The text of the message was changed to [REDACTED] in the logs and the usernames were edited.

mm_log.txt

[42wim]

that's a hard one, maybe we can more info by enabling trace, could you enable trace=true ? (and try to reproduce it)

[crhalpin]

I've enabled trace=true and will follow up after it happens again. It may be a while... After the first time I noticed it happening I added debug=true and it took over a week to see it.

[42wim]

could you also try to rebuild from master? Mattermost 7.x wasn't really supported and was using an old library (falling back on mattermost 5 methods), I've just added a commit to have it actually use the recent code.

[crhalpin]

I'm now running from master with debug=true and trace=true. We shall see how it goes! Thank you.

[42wim]

Going to close this for now, reopen if still an issue

[crhalpin]

The issue did recur. Trace log attached. Message content was replaced with [MESSAGE], nothing else was changed.

mm_log.txt

(Also, I don't seem to have the permissions to re-open this issue. :/ )

[crhalpin]

I'm still seeing this with v0.27.0. Trace + Debug log is attached. Message content was replaced with [MESSAGE], nothing else was changed. The first [MESSAGE] was not delivered to MM. The second one was.

Remote MM is 7.8.0.

Is there any other information I can provide to help debug this?
mm_log.txt

[42wim]

@crhalpin ok so I've just added a change to master, can you rebuild from master ?
We returned a wrong error in the path that your message could pass, this is fixed and I've added some extra trace logs.

[crhalpin]

Awesome, thank you! I've rebuilt from master and will keep an eye on this.

[crhalpin]

So war the issue has not recurred. I think it's resolved!

[crhalpin]

The issue recurred, though I'm not sure it's actually from the same underlying cause as before... debug/trace log is attached. The message that wasn't relayed was "You too, thanks!"

The relevant part seems to be:

2023-06-01T17:37:25.83117 matterircd: time="2023-06-01T12:37:25-05:00" level=debug msg="Executed &irc.Message{Prefix:(*irc.Prefix)(nil), Command:"PRIVMSG", Params:[]string{"mali"}, Trailing:"You too, thanks!", EmptyTrailing:false} &url.Error{Op:"Post", URL:"https://ecru.scout.wisc.edu/api/v4/channels/direct", Err:(*http.httpError)(0xc0004c8df8)}" prefix=matterircd
2023-06-01T17:37:25.83128 matterircd: time="2023-06-01T12:37:25-05:00" level=error msg="handler error for am95aynzq7nfpn1wmr763g59je: Post "https://ecru.scout.wisc.edu/api/v4/channels/direct": context deadline exceeded (Client.Timeout exceeded while awaiting headers)" prefix=matterircd

If the timeout was reported back to my IRC client in some way then I totally missed it. My experience as a user was just a silent failure that I only noticed because the message I sent via my IRC client didn't also appear in the web interface.

mm_log.txt