No replaying of offline messages

[kkofler]

For several releases now (I am currently using matterircd 0.23.0, but this has happened with several releases now, as far as I can tell ever since #267 was supposedly "fixed"), I never get any messages that are sent while I was offline from IRC, neither in chans nor in private messages. This used to mostly work, except for #267. But when I upgraded matterircd on the server to fix #267, the messages actually stopped arriving altogether. And it always takes days if not weeks until I notice this (because I have to actually receive a message, and then actually notice that I did not see it, which means I need to go out and check the Mattermost web interface), then I try a new mattericd version that claims to have related fixes, only to figure out eventually that it is still broken. This is very annoying and I have already missed messages more than once due to this bug.

Manually requesting the scrollback as is now possible is not really a solution because I need to know that there is scrollback to check to begin with. I really need the unseen messages automatically replayed.

[kkofler]

I have run into this bug with matterircd 0.20.0, 0.22.0, and 0.23.0.

[kkofler]

0.19.4 was the last version that replayed anything for me, though with wrong sender for PMs (#267).

[hloeung]

@kkofler, do you have LastViewedSaveFile set? (e.g. LastViewedSaveFile = "matterircd-lastsaved.db')

Also, are you using any IRC bouncers (bip, znc, etc.)?

[kkofler]

@kkofler, do you have LastViewedSaveFile set? (e.g. LastViewedSaveFile = "matterircd-lastsaved.db')

No, should I?

Also, are you using any IRC bouncers (bip, znc, etc.)?

No. (I suppose I wouldn't really need this feature if I were.)

[hloeung]

No, should I?

Yes, that would definitely help with replaying of all messages when offline. Otherwise, it relies on server side's state of when you last viewed a channel - it's possible that there's a race there where new messages are updating that state before the execution of the code to replay messages not seen but I'll need to look into that and confirm.

No. (I suppose I wouldn't really need this feature if I were.)

Even with a bouncer, you can't be sure your connectivity between that and the mattermost server is always up is what I'm getting at :)

[kkofler]

Is it possible that the "server side's state of when [I] last viewed a channel" is confused because DisableAutoView = false (the default, which I have not changed)? Still, I would expect that at most to replay too many messages, not too few.

[kkofler]

In any case, I am trying LastViewedSaveFile = "/opt/matterircd/var/matterircd-lastsaved.db" now, but if nobody actually sends me a message while I am offline, it will be hard to tell whether it works.

[kkofler]

I'm also not sure why this actually needs to be saved to a file, because matterircd is running all this time, only my IRC client is offline. So it should really be enough to keep this information cached in RAM.

[kkofler]

I don't see it actually writing that file /opt/matterircd/var/matterircd-lastsaved.db though, nor do I see any errors about it in the log, except for the ones on startup:

Mar 31 00:29:48 k002922b matterircd[13847]: time="2021-03-31T00:29:48+02:00" level=warning msg="Unable to load saved lastViewedAt, using empty values: open /opt/matterircd/var/matterircd-lastsaved.db: no such file or directory" module=matterircd

[…]

Mar 31 00:29:58 k002922b matterircd[13847]: time="2021-03-31T00:29:58+02:00" level=warning msg="Unable to load saved lastViewedAt, using empty values: open /opt/matterircd/var/matterircd-lastsaved.db: no such file or directory" module=matterircd

which is no surprise because the file obviously did not exist yet.

[kkofler]

I'm afraid I still don't see this LastViewedSaveFile feature actually doing anything. The file was never written, neither while I was online nor when I logged out nor while I was offline, and so when I logged back in, matterircd complained again about the file still being missing.

[hloeung]

I'm also not sure why this actually needs to be saved to a file, because matterircd is running all this time, only my IRC client is offline. So it should really be enough to keep this information cached in RAM.

Ah yes, you're right. The state of channels is also stored in memory and only ever saved to file when that option is enabled.

I'll take a look this weekend, when I have time, to see if I can reproduce and figure out what's going on. That is unless someone doesn't beat me to it.

[hloeung]

I have run into this bug with matterircd 0.20.0, 0.22.0, and 0.23.0.

Have you tried with 0.24.0?

I've tried with the latest 0.24.1-dev and can't reproduce it. I have matterircd running just like you, disconnecting my IRC client, then waited for some messages to come in (in another matterircd+IRC instance to see). Then reconnect my IRC client and the messages since then are replayed accordingly.

[kkofler]

I will try 0.24.0. The problem is, by the time I know whether 0.24.0 works, you will likely already have the next release. (This is also why I have not filed the bug sooner. There was always a newer version to try by the time I realized the one I was running did not work.) And I did not see a relevant fix in the documented list of fixes in 0.24.0. But I will try it.

[kkofler]

We use Mattermost only sporadically, so I do not get messaged all that often. And if there was no message, I cannot miss any. ;-)

[kkofler]

I have now upgraded to 0.24.0, but I don't know when I will be able to report success or failure.

[kkofler]

What I see is that /opt/matterircd/var/matterircd-lastsaved.db is not getting created, despite this being configured as LastViewedSaveFile, so something is not working as designed.

[hloeung]

What I see is that /opt/matterircd/var/matterircd-lastsaved.db is not getting created, despite this being configured as LastViewedSaveFile, so something is not working as designed.

The file was only created after defaultSaveInterval, which defaults to 5 minutes after any new messages. I've created a PR to suppress the warning when the lastViewedAt state file doesn't exist to avoid confusion as well as to create it early on.

[kkofler]

Well, I did receive some messages (but only while I was online), the file was not created anyway.

[hloeung]

Oh of course.

Everytime you connect to matterircd using your IRC client, the lastViewedAt state is reset (or reloaded from LastViewedSaveFile) - that's done in NewUserBridge().

I think https://github.com/42wim/matterircd/pull/422, which landed recently but due to be included in 0.24.1, should help you here. Together with LastViewedSaveFile, it will save the known lastviewedAt state on logging out (usually when your IRC client disconnects).

[kkofler]

Since you "only use the stored last viewed if it's later than what the server knows" (see the comment in #422), I am doubtful that this will help, I suspect it can only lead to more missed messages compared to trusting the server only (which appears to be the fallback if the file is missing as is usually the case now).

[kkofler]

To be honest, I'd rather in some corner cases get a message twice than not get a message at all!

[kkofler]

I can confirm that matterircd 0.24.0 does not fix the issue, and neither does setting LastViewedSaveFile. I received a PM on Mattermost while I was offline, it was not replayed by matterircd.

If this "last viewed" state is per channel, how can it possibly work for private messages? Private messages in IRC are not chans that are joined or parted, how do you know which ones are open? (The private 1:1 chat might not even be "open" in Mattermost, e.g., in this case, when I checked the web interface, it was not. But in most cases where I had the issue so far, it was open when I checked the web interface, so that detail does not seem to matter.)

[hloeung]

I received a PM on Mattermost while I was offline, it was not replayed by matterircd.

If this "last viewed" state is per channel, how can it possibly work for private messages? Private messages in IRC are not chans that are joined or parted, how do you know which ones are open?

I believe you want JoinDM = true per matterircd.toml.example.

(The private 1:1 chat might not even be "open" in Mattermost, e.g., in this case, when I checked the web interface, it was not. ...

That's one I have not encountered before, but then again, I don't get many PMs (direct messages) as most of it is done in channel.

But in most cases where I had the issue so far, it was open when I checked the web interface,

That's the behaviour I would expect and should be picked by up by matterircd with JoinDM enabled.

[hloeung]

Also, IIUC, there is an option to automatically close of DMs in Mattermost after a certain period of time. But after a quick glance, I can't seem to find that option right now.

[kkofler]

I thought JoinDM was only about group chats and not 1:1 chats? (1:1 Mattermost DMs map directly to IRC PMs, so there is no virtual chan to join on the IRC end at least.) I can set it and see whether it helps any, but somehow I doubt it, because messages in 1:1 chats that were already open in Mattermost have not been replayed either last time I checked.

FYI, matterircd 0.19.4 definitely did replay offline DMs/PMs, only the sender was wrong (issue #267). Back then, I happily upgraded to 0.20.0 where this was supposed to be fixed, only to have to realize that it was not replaying anything at all, and all subsequent versions up to the current 0.24.0 have the same issue. At least at some point, messages in chans were not replayed either, but I cannot say for sure whether this is also still broken or has since been fixed. I can only confirm for sure that it is still not working for DMs/PMs.

What can I do to debug what is going on exactly?

[kkofler]

Maybe I should also clarify what my setup is: We have a GitLab CE instance with the bundled Mattermost instance running on a server, and a matterircd instance running on the same server, connecting to our Mattermost instance. (I am currently the only user of that matterircd instance, the rest of the team uses Mattermost directly.) That matterircd instance usually just keeps running, only sometimes (e.g., when changing settings) it has to be restarted (and at the beginning, I thought the lost messages only happened when matterircd was restarted, but now I know that it just never replays offline messages no matter whether matterircd and/or Mattermost were restarted or not). Normally, only my local IRC client, the only software involved that does not run on our server (but on my computer), gets shut down when I go to sleep and restarted when I wake up, reconnecting to the same, usually still running, matterircd instance. What I expect (and what, as I understand it, is supposed to work) is to get those messages (both private and in chans) replayed that I received in Mattermost while my IRC client was disconnected.

[kkofler]

And today, without having changed anything in the configuration (nor having upgraded matterircd) since last time where it did not work (where I was already running 0.24.0), I got a message replayed. So there seems to be some non-reproducible factor.

[hloeung]

Since you get infrequent messages, might I suggest enabling both Debug and Trace to try capture what's happening and why some messages are missed and others replayed?

Also, OOI, what is the Mattermost server version you're connecting to?

[kkofler]

Since you get infrequent messages, might I suggest enabling both Debug and Trace to try capture what's happening and why some messages are missed and others replayed?

Done. I see some logging output. I hope this will allow us to debug what is going on.

Also, OOI, what is the Mattermost server version you're connecting to?

Mattermost 5.26.2 (bundled with GitLab Community Edition 13.4.3).

[kkofler]

Once again a message was not replayed. I received it on 2021-06-16 13:06:52 CEST (11:06:52 UTC). At 20:07:14 CEST (18:07:14 UTC), the last viewed at time for the private message "chan" is as follows: getLastViewedAt 3kcjfd6uqpfu8dsm45ery9a14a: 1623841651744, which would be 13:07:31.744 CEST (11:07:31.744 UTC), so around 39-40 seconds after the message was sent. But I obviously did not view the conversation at that time, I was completely offline.

Does getLastViewedAt really get only the channel ID as the parameter and no user ID? (From the trace output, it seems so!) Then that is fundamentally broken and cannot possibly work. The last viewed time is obviously per user. The user who sent the message likely viewed it at the indicated time, but I did not.

[hloeung]

So do you have JoinDM enabled? If not, can you try with it enabled? It isn't just for group messages but also direct 1:1 / PMs.

Direct and group messages are like virtual channels. They have a channel ID and the name is usually "user1-user2", IIUC.

The last viewed time is not for the channel or all users of that channel, but when "you" last viewed that channel. Again, IIUC.

[kkofler]

So do you have JoinDM enabled?

Yes. I enabled it on April 8 (and yes, I restarted matterircd after I changed the settings), it was disabled before.

The last viewed time is not for the channel or all users of that channel, but when "you" last viewed that channel. Again, IIUC.

Well, that is clearly how it should be, but then the given timestamp is clearly wrong.

[kkofler]

Ah, forget it! Checking my logs again, this message did actually arrive, and in fact I was actually online when it was sent. Sorry for the false alarm, I am going to report back if and when there is actually an undelivered message again.

[kkofler]

(There hasn't been one for a while, but that is expected because there wasn't any message sent while I was offline to begin with.)

[kkofler]

Good news: replaying did work today! But I cannot tell yet whether it always works.

[42wim]

going to close this, there are really few things out there that will always work :)