thelounge / thelounge

πŸ’¬ β€Ž Modern, responsive, cross-platform, self-hosted web IRC client
https://thelounge.chat
MIT License
5.68k stars 687 forks source link

znc.in/playback doesn't request messages #4464

Open ghost opened 2 years ago

ghost commented 2 years ago

The Issue

To sorta TL;DR the chatlogs below:

  1. thelounge CAP REQs znc.in/playback
    1. this tells ergo to not automatically send playback in any other way
  2. thelounge is only capable of using this feature if you have sqlite enabled and no messages get returned from the call to the provider

The Solution

The Lounge should either:

IRC context

irc://irc.ergo.chat/#ergo > \ hmm > \ autoreplay stuff only works if you didn't explicit disconnect, I guess? > \<@slingamn> xnaas: you mean like with QUIT? that shouldn't affect anything > \ Well...it sure seems to πŸ˜… > \<@slingamn> are you using client ids? > \ yes > \<@slingamn> are you always-on? > \ yes > \<@slingamn> then it should work > \ Doesn't seem to πŸ˜… > \<@slingamn> is this on your server or here? > \ Tested on my server. > \<@slingamn> can you confirm that the device id is being recognized, e.g. by checking /ns clients list? > \ Indeed: ![img](https://web.archive.org/web/20220206204122if_/https://xnaas.info/tmp/qF8.webp) > \<@slingamn> oh > \<@slingamn> TL > \<@slingamn> requesting znc.in/playback disables all autoreplay > \ hmm...but the missed lines show if, say, I reboot thelounge > \ just not if you /disconnect > \<@slingamn> it's probably a bug in TL's impl of znc.in/playback > \ (and then connect again, obviously :P ) > \ awesome > \<@slingamn> you can get raw logs from the ergo side > \<@slingamn> and see in which cases it is sending the playback message > \<@slingamn> if you don't want to bother debugging TL you can probably just tell it to stop requesting znc.in/playback > \<@slingamn> i should add something about this to the FAQ, it's come up before > \ Don't think that's something possible without editing source code > \ at least, I only know how to request CAPs, not the opposite πŸ˜… > \<@slingamn> ah you might be right > \ https://ircv3.net/specs/extensions/capability-negotiation.html#the-cap-del-subcommand > \-ErgoBot- Client Capability Negotiation - IRCv3 > \ maybe > \ [410]DEL Invalid CAP subcommand > \ guess not :P > \ So if a client requests znc.in/playback...what's *supposed* to be the workflow that happens? > \<@slingamn> it sends the playback message, there are a few different possible forms of it > \<@slingamn> but the semantics are "play me messages starting from time X" > \<@slingamn> where X is the last time the client knows that it was receiving messages > \ ok, so *most likely* thelounge is just not sending that request after explicitly disconnecting > \<@slingamn> yeah > \ makes sense > \<@slingamn> like it erases its stored timestamp or whatever > \ probably an intentional design decision, but I'll verify that to be true or not another weekend :D > \ (could be a bug tho) > \ Will also see about getting a way to *not* request the CAP to begin with since it sounds like it'd be better to not use it with ergo? > \<@slingamn> hmmmmmmmmm > \<@slingamn> well so > \<@slingamn> znc.in/playback is cool because if your client supports it, you don't even have to set a device id > \ ah > \[...] > \ to go back to playback and such...another fun question/scenario > \ say you're moving ergo to another box and don't have permanent sql storage > \ just in-RAM stuff > \ You spin up ergo on the new box after copying over ircd.db and ircd.yaml > \ you connect first and start saying stuff > \ should someone connecting later get the messages? > \ (this is the situation that originally triggered my testing with the playback and thelounge, since a user connected later and didn't get the 2 messages I'd sent before they connected "for the first time" to this "new ergo") > \<@slingamn> yeah they should get it > \<@slingamn> the "last seen" timestamps are stored in ircd.db > \<@slingamn> so is always-on status > \<@slingamn> i can test that locally to confirm, i'll do that now > \ Perhaps another bug with thelounge and znc.in/playback Β―\\\_(ツ)_/Β― β€” would require a lot of effort to do some full testing on the 'moving servers' workflow heh > \<@slingamn> yeah, works locally > \<@slingamn> so it doesn't really matter from ergo's perspective whether the server was "moved" > \ makes logical sense > \<@slingamn> all that's really visible from the ergo side is whether the process was restarted > \<@slingamn> so i tested it across a process restart and it works > \ aight, so prolly TL then > \<@slingamn> yeah > \ best route would seem to be to just not use znc.in/playback as getting patches in it outside of my scope haha > \ but that doesn't look like an option for me either
irc://irc.libera.chat/#thelounge > \ Is there any way to tell thelounge to *not* request znc.in/playback? > \ xnaas: I think you have to set a separate login > \ a separate "client identifier" > \ xnaas: try a different bouncer that lets you set separate history refill per client id (specified in login info), like soju > \ I don't use any bouncer > \ I'm connecting to an ergo server directly > \ wat > \ which has bouncer shit built-in > \ including supporting znc playback > \ the client requests bouncer stuff? > \ thelounge requests znc.in/playback yes > \ I wanted to disable the CAP REQ for znc.in/playback from thelounge to test something, but thinking it might not be possible without source code edits.. > \ Basically, it seems like thelounge is not requesting playback if you /disconnect from a server and then /connect again. > \ ah I didn't know you were using ergo > \ another situation in which thelounge did not request znc playback was after the ergo server was rebooted (and down for a bit, was moved to another box) > \[...] > \<+bookworm> xnaas: TL only requests playback if it doesn't already have messages from the message storage (sqlite) > \<+bookworm> it will always enable the cap if the server advertises it, but that doesn't mean that it's actually using > \ I'm confused by the first message and it's relevance to what I was experiencing. Let me know if I need to cla > \ (though it's 01:30 and I will probably sleep Soonβ„’) > \<+bookworm> https://github.com/thelounge/thelounge/blob/26a38b12abeb61fce10f412872a044c6fcf619da/src/models/chan.js#L247 > \<+bookworm> literally, if you have sqlite enabled and it returns messages the playback cap will be ignored. If it doesn't, it'll try to fetch new messages > \<+bookworm> so it depends if your client already had messages in the store or not > \<+bookworm> (which seems a strange place to have the cap really... it also doesn't load scrollback if sqlite is disabled which makes no sense at all) > \ What I'm reading from what you typed is that it doesn't request playback...? > \ That doesn't sound right πŸ˜… > \<+bookworm> if sqlite is enabled but returns exactly 0 messages and it has the cap then it does, else no > \<+bookworm> don't shoot the messenger, I didn't write the code > \ Well that seems...not useful, heh > \<+bookworm> no > \ I most definitely want the messages I missed. > \<+bookworm> yes > \<+bookworm> that's the point isn't it? > \* xnaas will have to open 1 or 2 issues later > \<+bookworm> can ergo do it transparently to TL? then I'd do that > \<+bookworm> znc has actually a better way than playback > \ Only if I could disable the znc.in/playback CAP REQ > \ Then ergo could do it a better way > \ but requesting the CAP overrides the other way > \<+bookworm> called clientbuffer, that was what _Snuupy was trying to tell you > \<+bookworm> ergo has CHATHISTORY, no? > \<+bookworm> and that TL doesn't support yet > \* xnaas doesn't have or want ZNC involved in any way :P > \ No, it's an auto replay thing that's entirely separate. I've seen it work fine in both weechat and hexchat. > \ And the only CAP weechat seems to REQ is SASL > \ Regardless, I guess I'll open a couple of issues later when I wake up. Cat already has one of my arms. πŸ™ƒ > \<+bookworm> TL didn't make it an option as it usually doesn't get advertised by the server unless you have znc. Seems strange of ergo to use the vendored cap > \<+bookworm> do that and say hi to your cat from me > \ She sleepin' 😴 > \ I'm not qualified to give a definitive answer, but my understanding was that it's included because it is something that is functional and if thelounge was just saying "give me messages since X" on reconnect then it'd be working perfectly πŸ˜… > \<+bookworm> well there are some edgecases if you also have a storage provider active but in theory yes > \<+bookworm> you also need to store the last time you've seen a message so that you aren't requesting things from the beginning of time > \<+bookworm> else you're gonna have a bad time, depending on your buffer size > \ Also, I get why TL was only grabbing missed messages on a restart. It connected faster than it could get data from my massive SQLite logs πŸ˜… > \<+bookworm> yup > \ Amusing. :D -- anyway, goodnight and thanks for the insight. Will be useful for creating issues tomorrow. \o/
xPaw commented 2 years ago

Should be a simple fix here: https://github.com/thelounge/thelounge/blob/66455f2c40fd1a7b40120c4c5fddfb714fa5e955/src/models/chan.js#L239

If client.messageProvider is false, call requestZncPlayback if the cap is enabled (after the network.irc check).

brunnre8 commented 2 years ago

If client.messageProvider is false,

~~It should do so even if we have a message provider. After all you can have znc in use and sqlite enabled for things like search and messages on restart still. However there may have been a downtime between TL terminating and starting back up where znc was happily logging. playback allows you to ask for a timeframe since a last received message, we should use that to query not yet received messages.~~

Mea culpa misread the code, ignore

ghost commented 2 years ago

Not fixed with #4549 that I can tell.

ghost commented 2 years ago

The Lounge (built on https://github.com/thelounge/thelounge/commit/5f7acbf9948446289054527ee9385f938a116386, which includes the linked PR) still fails to automatically get missed channel logs on server reconnect. Hexchat working as expected.

07:25:25 <xnaas> Oh no. Never got to test #4549 😬
07:25:44 <+bookworm> no worries, I did
07:26:06 <+bookworm> and considering that I could read your convo in #ergo with slingamm I'd say it's fixed
07:27:40 <xnaas> πŸ€”

Not sure if I'm missing something.

brunnre8 commented 2 years ago

What's your exact config? Raw debug logs of the IRC traffic?

It loaded fine for me (been looking at the raw traffic with and without SQLite enabled)

ghost commented 2 years ago

I'm not sure what all to supply, so apologies for the extreme verbosity of this.

config.js ```js "use strict"; module.exports = { // ## Server settings public: false, host: undefined, port: 9000, bind: undefined, reverseProxy: true, maxHistory: 10000, https: { enable: false, key: "", certificate: "", ca: "", }, theme: "morning", prefetch: true, disableMediaPreview: false, prefetchStorage: true, prefetchMaxImageSize: 92160, prefetchMaxSearchSize: 300, fileUpload: { enable: true, maxFileSize: 92160, }, transports: ["polling", "websocket"], leaveMessage: "So long, and thanks for all the fish", defaults: { name: "ASAK", host: "chat.actionsack.com", port: 6697, password: "", tls: true, rejectUnauthorized: true, nick: "asak%%", username: "asak", realname: "asak", join: "#thesack", }, lockNetwork: false, messageStorage: ["sqlite", "text"], useHexIp: false, webirc: null, identd: { enable: false, port: 113, }, oidentd: null, ldap: { enable: false, }, // ## Debugging settings // The `debug` object contains several settings to enable debugging in The // Lounge. Use them to learn more about an issue you are noticing but be aware // this may produce more logging or may affect connection performance so it is // not recommended to use them by default. // All values in the `debug` object are set to `false`. debug: { // ### `debug.ircFramework` // // When set to true, this enables extra debugging output provided by // [`irc-framework`](https://github.com/kiwiirc/irc-framework), the // underlying IRC library for Node.js used by The Lounge. ircFramework: false, // ### `debug.raw` // When set to `true`, this enables logging of raw IRC messages into each // server window, displayed on the client. raw: true, }, }; ```
The Lounge Server Settings Window (screenshot) ![img0](https://user-images.githubusercontent.com/8271327/166314550-61af0bd2-f217-424a-93af-a22ae9804b9c.png) I have tried both with and without an `@some_device_id`.
raw logs on connect ```14:39:44 Network created, connecting to [chat.actionsack.com:6697](http://chat.actionsack.com:6697/)... 14:39:44 Connected to the network. 14:39:44 *** CAP LS 302 14:39:44 *** NICK BitchAccount 14:39:44 *** USER BitchAccount 0 * BitchAccount 14:39:44 *** :chat.actionsack.com CAP * LS :account-notify account-tag away-notify batch cap-notify chghost draft/account-registration=before-connect draft/channel-rename draft/chathistory draft/event-playback draft/extended-monitor draft/languages=1,en draft/multiline=max-bytes=4096,max-lines=100 draft/relaymsg=/ echo-message ergo.chat/nope extended-join invite-notify labeled-response message-tags multi-prefix sasl=PLAIN,EXTERNAL server-time setname userhost-in-names znc.in/playback znc.in/self-message 14:39:44 *** CAP REQ :account-notify account-tag away-notify batch cap-notify chghost echo-message extended-join invite-notify message-tags multi-prefix sasl server-time setname userhost-in-names znc.in/playback znc.in/self-message 14:39:44 *** @time=2022-05-02T19:39:44.176Z :chat.actionsack.com CAP * ACK :account-notify account-tag away-notify batch cap-notify chghost echo-message extended-join invite-notify message-tags multi-prefix sasl server-time setname userhost-in-names znc.in/playback znc.in/self-message 14:39:44 *** AUTHENTICATE PLAIN 14:39:44 *** AUTHENTICATE + 14:39:44 *** AUTHENTICATE 14:39:44 *** ZNC *playback PLAY #spam 1651520235 14:39:44 *** @time=2022-05-02T19:39:44.182Z :chat.actionsack.com 900 * * BitchAccount :You are now logged in as BitchAccount 14:39:44 *** CAP END 14:39:44 Logged in as: BitchAccount 14:39:44 *** @time=2022-05-02T19:39:44.182Z :chat.actionsack.com 903 * :Authentication successful 14:39:44 *** @time=2022-05-02T19:39:44.184Z :chat.actionsack.com 451 * :You need to register before you can use that command 14:39:44 [451]* You need to register before you can use that command 14:39:44 *** @account=BitchAccount;time=2022-05-02T19:39:44.185Z :BitchAccount!~asak@BitchAccount AWAY 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 001 BitchAccount :Welcome to the asak IRC Network BitchAccount 14:39:44 *** PING 1651520384187 14:39:44 Enabled capabilities: account-notify, account-tag, away-notify, batch, cap-notify, chghost, echo-message, extended-join, invite-notify, message-tags, multi-prefix, sasl, server-time, setname, userhost-in-names, [znc.in/playback](http://znc.in/playback), [znc.in/self-message](http://znc.in/self-message) 14:39:44 You're now known as BitchAccount 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 002 BitchAccount :Your host is chat.actionsack.com, running version ergo-v2.9.1 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 003 BitchAccount :This server was created Sat, 02 Apr 2022 04:22:08 UTC 14:39:44 [003]This server was created Sat, 02 Apr 2022 04:22:08 UTC 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 004 BitchAccount chat.actionsack.com ergo-v2.9.1 BERTZios CEIMRUabefhiklmnoqstuv Iabefhkloqv 14:39:44 [004]chat.actionsack.com ergo-v2.9.1 BERTZios CEIMRUabefhiklmnoqstuv Iabefhkloqv 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 005 BitchAccount AWAYLEN=390 BOT=B CASEMAPPING=ascii CHANLIMIT=#:100 CHANMODES=Ibe,k,fl,CEMRUimnstu CHANNELLEN=64 CHANTYPES=# ELIST=U EXCEPTS EXTBAN=,m FORWARD=f INVEX KICKLEN=390 :are supported by this server 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 005 BitchAccount MAXLIST=beI:60 MAXTARGETS=4 MODES MONITOR=100 NETWORK=asak NICKLEN=32 PREFIX=(qaohv)~&@%+ STATUSMSG=~&@%+ TARGMAX=NAMES:1,LIST:1,KICK:,WHOIS:1,USERHOST:10,PRIVMSG:4,TAGMSG:4,NOTICE:4,MONITOR:100 TOPICLEN=390 UTF8MAPPING=rfc8265 UTF8ONLY WHOX :are supported by this server 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 005 BitchAccount draft/CHATHISTORY=100 :are supported by this server 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 251 BitchAccount :There are 13 users and 3 invisible on 1 server(s) 14:39:44 [251]There are 13 users and 3 invisible on 1 server(s) 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 252 BitchAccount 1 :IRC Operators online 14:39:44 [252]1 IRC Operators online 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 253 BitchAccount 0 :unregistered connections 14:39:44 [253]0 unregistered connections 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 254 BitchAccount 9 :channels formed 14:39:44 [254]9 channels formed 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 255 BitchAccount :I have 16 clients and 0 servers 14:39:44 [255]I have 16 clients and 0 servers 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 265 BitchAccount 16 20 :Current local users 16, max 20 14:39:44 [265]16 20 Current local users 16, max 20 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 266 BitchAccount 16 20 :Current global users 16, max 20 14:39:44 [266]16 20 Current global users 16, max 20 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 375 BitchAccount :- chat.actionsack.com Message of the day - 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 372 BitchAccount :- Welcome to the Action Sack! 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 372 BitchAccount :- Owner: xnaas 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 372 BitchAccount :- INFO: actionsack.com 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 372 BitchAccount :- Main Chan: #thesack 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 376 BitchAccount :End of MOTD command 14:39:44 *** Welcome to the Action Sack! Owner: xnaas INFO: [actionsack.com](http://actionsack.com/) Main Chan: #thesack 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 221 BitchAccount +Zi 14:39:44 *** Your user mode is +Zi 14:39:44 *** @time=2022-05-02T19:39:44.185Z :BitchAccount!~asak@BitchAccount JOIN #spam BitchAccount BitchAccount 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 332 BitchAccount #spam :S P A M 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 333 BitchAccount #spam xnaas!~asak@God 1614192924 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 353 BitchAccount = #spam :+Aegisfate!~asak@mike dulanic!~asak@dulanic.com +nC!~asak@gambling.addict Sackbot!~asak@slave.of.xnaas ~xnaas!~asak@xnaas.info Chex!~asak@northnook.ca %feek!~asak@feek.org +Tasian!~asak@tall.asian BitchAccount!~asak@BitchAccount 14:39:44 *** @time=2022-05-02T19:39:44.185Z :chat.actionsack.com 366 BitchAccount #spam :End of NAMES list 14:39:44 *** @time=2022-05-02T19:39:44.187Z :chat.actionsack.com PONG chat.actionsack.com 1651520384187 14:39:45 *** JOIN #spam 14:40:14 *** PING 1651520414198 14:40:14 *** @time=2022-05-02T19:40:14.199Z :chat.actionsack.com PONG chat.actionsack.com 1651520414198 ```

14:39:44 ** ZNC playback PLAY #spam 1651520235

It looks like it's trying something...but I don't get anything in The Lounge.

ghost commented 2 years ago

After that last test, I killed the docker container, sent some more messages in #spam then started up the container again. I don't see any attempt at getting playback this time.

more raw log spam ``` 14:52:16 Network created, connecting to [chat.actionsack.com:6697](http://chat.actionsack.com:6697/)... 14:52:16 Connected to the network. 14:52:16 *** CAP LS 302 14:52:16 *** NICK BitchAccount 14:52:16 *** USER BitchAccount 0 * BitchAccount 14:52:16 *** :chat.actionsack.com CAP * LS :account-notify account-tag away-notify batch cap-notify chghost draft/account-registration=before-connect draft/channel-rename draft/chathistory draft/event-playback draft/extended-monitor draft/languages=1,en draft/multiline=max-bytes=4096,max-lines=100 draft/relaymsg=/ echo-message ergo.chat/nope extended-join invite-notify labeled-response message-tags multi-prefix sasl=PLAIN,EXTERNAL server-time setname userhost-in-names znc.in/playback znc.in/self-message 14:52:16 *** CAP REQ :account-notify account-tag away-notify batch cap-notify chghost echo-message extended-join invite-notify message-tags multi-prefix sasl server-time setname userhost-in-names znc.in/playback znc.in/self-message 14:52:16 *** @time=2022-05-02T19:52:16.215Z :chat.actionsack.com CAP * ACK :account-notify account-tag away-notify batch cap-notify chghost echo-message extended-join invite-notify message-tags multi-prefix sasl server-time setname userhost-in-names znc.in/playback znc.in/self-message 14:52:16 *** AUTHENTICATE PLAIN 14:52:16 *** AUTHENTICATE + 14:52:16 *** AUTHENTICATE 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 900 * * BitchAccount :You are now logged in as BitchAccount 14:52:16 *** CAP END 14:52:16 Logged in as: BitchAccount 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 903 * :Authentication successful 14:52:16 *** @account=BitchAccount;time=2022-05-02T19:52:16.221Z :BitchAccount!~asak@BitchAccount AWAY 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 001 BitchAccount :Welcome to the asak IRC Network BitchAccount 14:52:16 *** PING 1651521136224 14:52:16 Enabled capabilities: account-notify, account-tag, away-notify, batch, cap-notify, chghost, echo-message, extended-join, invite-notify, message-tags, multi-prefix, sasl, server-time, setname, userhost-in-names, [znc.in/playback](http://znc.in/playback), [znc.in/self-message](http://znc.in/self-message) 14:52:16 You're now known as BitchAccount 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 002 BitchAccount :Your host is chat.actionsack.com, running version ergo-v2.9.1 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 003 BitchAccount :This server was created Sat, 02 Apr 2022 04:22:08 UTC 14:52:16 [003]This server was created Sat, 02 Apr 2022 04:22:08 UTC 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 004 BitchAccount chat.actionsack.com ergo-v2.9.1 BERTZios CEIMRUabefhiklmnoqstuv Iabefhkloqv 14:52:16 [004]chat.actionsack.com ergo-v2.9.1 BERTZios CEIMRUabefhiklmnoqstuv Iabefhkloqv 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 005 BitchAccount AWAYLEN=390 BOT=B CASEMAPPING=ascii CHANLIMIT=#:100 CHANMODES=Ibe,k,fl,CEMRUimnstu CHANNELLEN=64 CHANTYPES=# ELIST=U EXCEPTS EXTBAN=,m FORWARD=f INVEX KICKLEN=390 :are supported by this server 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 005 BitchAccount MAXLIST=beI:60 MAXTARGETS=4 MODES MONITOR=100 NETWORK=asak NICKLEN=32 PREFIX=(qaohv)~&@%+ STATUSMSG=~&@%+ TARGMAX=NAMES:1,LIST:1,KICK:,WHOIS:1,USERHOST:10,PRIVMSG:4,TAGMSG:4,NOTICE:4,MONITOR:100 TOPICLEN=390 UTF8MAPPING=rfc8265 UTF8ONLY WHOX :are supported by this server 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 005 BitchAccount draft/CHATHISTORY=100 :are supported by this server 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 251 BitchAccount :There are 13 users and 3 invisible on 1 server(s) 14:52:16 [251]There are 13 users and 3 invisible on 1 server(s) 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 252 BitchAccount 1 :IRC Operators online 14:52:16 [252]1 IRC Operators online 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 253 BitchAccount 0 :unregistered connections 14:52:16 [253]0 unregistered connections 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 254 BitchAccount 9 :channels formed 14:52:16 [254]9 channels formed 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 255 BitchAccount :I have 16 clients and 0 servers 14:52:16 [255]I have 16 clients and 0 servers 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 265 BitchAccount 16 20 :Current local users 16, max 20 14:52:16 [265]16 20 Current local users 16, max 20 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 266 BitchAccount 16 20 :Current global users 16, max 20 14:52:16 [266]16 20 Current global users 16, max 20 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 375 BitchAccount :- chat.actionsack.com Message of the day - 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 372 BitchAccount :- Welcome to the Action Sack! 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 372 BitchAccount :- Owner: xnaas 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 372 BitchAccount :- INFO: actionsack.com 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 372 BitchAccount :- Main Chan: #thesack 14:52:16 *** @time=2022-05-02T19:52:16.221Z :chat.actionsack.com 376 BitchAccount :End of MOTD command 14:52:16 *** Welcome to the Action Sack! Owner: xnaas INFO: [actionsack.com](http://actionsack.com/) Main Chan: #thesack 14:52:16 *** @time=2022-05-02T19:52:16.222Z :chat.actionsack.com 221 BitchAccount +Zi 14:52:16 *** Your user mode is +Zi 14:52:16 *** @time=2022-05-02T19:52:16.222Z :BitchAccount!~asak@BitchAccount JOIN #spam BitchAccount BitchAccount 14:52:16 *** @time=2022-05-02T19:52:16.222Z :chat.actionsack.com 332 BitchAccount #spam :S P A M 14:52:16 *** @time=2022-05-02T19:52:16.222Z :chat.actionsack.com 333 BitchAccount #spam xnaas!~asak@God 1614192924 14:52:16 *** @time=2022-05-02T19:52:16.222Z :chat.actionsack.com 353 BitchAccount = #spam :+Aegisfate!~asak@mike dulanic!~asak@dulanic.com +nC!~asak@gambling.addict Sackbot!~asak@slave.of.xnaas ~xnaas!~asak@xnaas.info Chex!~asak@northnook.ca %feek!~asak@feek.org +Tasian!~asak@tall.asian BitchAccount!~asak@BitchAccount 14:52:16 *** @time=2022-05-02T19:52:16.222Z :chat.actionsack.com 366 BitchAccount #spam :End of NAMES list 14:52:16 *** @time=2022-05-02T19:52:16.224Z :chat.actionsack.com PONG chat.actionsack.com 1651521136224 14:52:17 *** JOIN #spam 14:52:46 *** PING 1651521166238 14:52:46 *** @time=2022-05-02T19:52:46.239Z :chat.actionsack.com PONG chat.actionsack.com 1651521166238 14:53:16 *** PING 1651521196246 14:53:16 *** @time=2022-05-02T19:53:16.247Z :chat.actionsack.com PONG chat.actionsack.com 1651521196246 ```

This is the last run for the docker image being built: https://github.com/xnaas/docker-thelounge/runs/6262528859 -- I notice my version still shows as 4.3.1 in the GUI for this test container...thought it says something different when building from master? Maybe I'm misremembering.

ghost commented 2 years ago
<+bookworm> xnaas: can't reproduce on ergo, works for me
<xnaas> I'll try there as well, but it's the same software πŸ˜…
<xnaas> bookworm: what is your SASL auth set to?
<xnaas> does your username contain or not contain an @whatever
<xnaas> account**
<xnaas> yeah, definitely not working for me
<xnaas> joining the channel the very first time requests playback
<xnaas> but never again after that

I registered a new account there and was able to get the logs from #chat the very first time I joined, but after that, logs are never attempted to be grabbed on a reconnect.


Edit:

<+bookworm> SASL isn't enabled but that's also not part of that code path
<xnaas> So it would seem we're testing different things. πŸ˜…
<xnaas> This is a registered account there you're testing with?
<+bookworm> no
<xnaas> Then we've found a difference. 😬
<+bookworm> yes, but that's not part of that codepath
<xnaas> Yes, but that probably changes how ergo interacts with the client πŸ˜…
<+bookworm> playback is pull not push, TL needs to initiate it and you should see that in the debug logs
<+bookworm> I've a hunch but it needs to wait until tomorrow morning 
<+bookworm> thanks for testing 
<xnaas> I'm wondering if it's an order of operations, thing.
<xnaas> The one time I saw it actually request playback in raw logs, that was before thelounge ran JOIN against the channel.
<xnaas> Indeed. If I manually rejoin the channel, the missing logs are requested as expected.

Seems like an order of operations issue.

proton-ab commented 1 year ago

This is caused by re-connection to server going to separate code path here: https://github.com/thelounge/thelounge/blob/a7b85db9906b63632fa946dee7b9385c90d82cc0/server/plugins/irc-events/join.ts#L29 which does not call for ZNC playback. The reason it does not is that the function which does it (Chan.loadMessages) also loads messages from message store provider, which would duplicate all past entries. The logic needs to be split in Chan model and then the code path above updated so that it requests playback.

Also worth of note is that we should likely print stuff like channel modes again in such cases and in case where server reports ZNC playback capability we should also likely not inject "{me} joined {channel}" by wrapping new Msg with something like if (!network.irc.network.cap.isEnabled("znc.in/playback") || !self) {

Other thing to note is that ZNC playback module takes time as epoch seconds with optional milliseconds as floating point, but we send it as milliseconds which is coerced to seconds only, losing precision and possibly fetching duplicate messages in the process.

And yet another thing - in Chan.loadMessages we do not provide ending time for playback module, which means that current time is used. While this is fine, it does result in duplicated messages if message store (such as SQLite) takes over a second to load message for given channel, during which time we delay calling playback yet we accept messages from IRC.