Bug - Fixed Browser suppresses some "modern chat" messages in Relay Browser

[jolson42]

I've mentioned this in a previous thread some months ago, and it wasn't resolved, but I didn't notice the problem occurring for a while. But it's been happening a lot over the last few days, so...

I chat in the relay browser only, but from time to time it's clear that chat messages are not being delivered. Usually I notice people responding to thin air, and when I log in with my multi, I confirm that chat messages are missing. Now, I never use Mafia's chat window, because I like the immediacy of having chat attached to the browser, and I know that having both open causes messages to be delivered to one and not the other.
But today I did some poking around, exiting chat on the relay, and opening Mafia's chat, and sure enough the missing messages were there. I am certain that I didn't open Mafia chat until checking for those missing messages, so surely they shouldn't have been waiting for me upon arrival, unless Mafia chat is activating itself?
I assume this is unintended behaviour, but if not, is there any way of totally disabling Mafia's chat? I can't find anything in the chat preferences that would cause this.

 

[Bale]

I assume this is unintended behaviour, but if not, is there any way of totally disabling Mafia's chat? I can't find anything in the chat preferences that would cause this.

Go to Preferences -> Look & Feel - Main Interface

Under the heads of "Startup as Window" or "Startup in Tabs" is there an entry called "Loathing Chat"?

 

[lostcalpolydude]

I have seen messages show up in mafia's chat logs that didn't show up in relay browser chat. During one of the twitch events I kept the log files open and refreshed them to make sure I wasn't missing anything for channels where it was important enough to me. I don't understand mafia's chat code well enough to try to track it down though.

 

[heeheehee]

If I had to take a stab in the dark regarding what's happening, the browser is timing out requests, even though Mafia is dispatching them faithfully. If you don't explicitly have the Mafia chat GUI open, then messages get added to the chat manager (which handles stuff like logging) by RelayRequest, i.e. requests that come from the relay browser.

I have no idea if it's even possible to fix this, if it is indeed the result of lag, like I'm guessing it is.

 

[lostcalpolydude]

I've had one person tell me that they are using KoL's older chat because it doesn't have the same issue in mafia. I don't know if that's useful information.

 

[heeheehee]

Older chat can request the same message multiple times (two tabs of lchat will play nicely with each other, whereas two tabs of mchat will lead to conflicts and sad times). That could be relevant.

 

[jolson42]

Bale, I have no startup windows. My tabs are Adventure, CLI, Gear, Items and Maximizer. So yeah, no chat opening that way. Now, I was assuming that the issue was of mafia chat stealing messages from browser chat, like if you have two vanilla chat tabs open, but from the discussion here, it sounds more like that wouldn't help, and browser chat would still lose messages...

lostcalpolydude, when you say older chat, if you mean no tabs, I don't think I have the strength of will to try that.
The logs thing sounds like a good idea to keep track of important stuff though. I'll keep that in mind!

 

[Veracity]

I am certain that I didn't open Mafia chat until checking for those missing messages, so surely they shouldn't have been waiting for me upon arrival, unless Mafia chat is activating itself?

Bad assumption. Well, depending on what you mean by "Mafia chat".

Have you ever asked for a Fax from Faxbot? That is done by sending a PM to the bot and waiting until a PM comes back from it. You'll notice that we do NOT require the KoLmafia chat GUI to be open; you can have chat open in the Relay Browser and we will notice the response.

Similarly, have you ever noticed that KoLmafia saves logs of all of chat channels you are listening to in the "chats" directory? It does this even if you have only the Relay Browser chat open.

When you use the Relay Browser, every message that the browser wants to sent to KoL passes through KoLmfia on the way, and every response that KoL makes to the Browser similarly passes through KoLmafia. This includes chat messages; every interaction in the browser chat pane passes through KoLmafia.

Therefore, there is obviously code that sends received chat messages to KoLmafia's chat manager. Not that I can say exactly how it works; the internals of KoLmafia's ChatManager/ChatPoller/etc. are mysterious to me. But, I expect that it processes every chat message, saves it in its own internal chat buffer, and relays it right on down to the browser. So, when you initialize the chat GUI, it has all the chat messages that have arrived waiting for you.

So, if by "Mafia chat opening itself in background" you mean "the mafia chat GUI is opening itself", no. If you mean "Mafia has a Chat Poller running which is looking at every message that passes through chat", yes.

But when you say this "causes missed messages", you are making a huge logical leap. You are saying, basically, that although KoLmafia processes all chat messages that go through the Relay Browser chat, it somehow does not send some of them on down to the browser.

I would be shocked and astonished if that were true. The Browser opens a new connection for every single request that it makes to KoL - through KoLmafia - and if it does not get a response, you'd expect to see timeouts or "the server is not responding" messages or something of the sort in the Browser.

Is it possible that KoLmafia is responding to the Browser's request for every message, but is somehow losing the content? I suppose so.

However, is it possible that KoLmafia is obediently relaying every message on down to the Browser, but code running in the Browser - Javascript associated with the chat pane, or something - is not displaying everything? Why, yes - that is certainly possible. Which is to say, "correlation does not equal causation": although Mafia is processing all chat messages, I do not assume that that is CAUSING messages to not display in the Browser.

Somebody would need to really dive in and understand how chat messages get sent through the Chat Managaer on their way to being relayed down to the Browser; since they go into the chat log (and appear later when you open the Chat GUI), they are obviously being seen. Is there any way that an empty (or stripped down) response can be sent down to the browser?

A question for you: what kind of messages seem to be not shown?

I assume this is unintended behaviour, but if not, is there any way of totally disabling Mafia's chat? I can't find anything in the chat preferences that would cause this.

You are saying you would like to disable chat logs and the ability to request monsters from Faxbot. I think that figuring out what's really going on would be a better solution.

 

[Veracity]

Slight followup:

RelayRequest.handleChat() is called whenever the browser gives us something that we categorize as a "chat request". KoLmafia will make this or that request to KoL, depending on what of chat you are running, and will format a "chatText" to send on down to the browser. We don't actually open the ChatManager. We don't even call the ChatPoller, except for "old chat".

So, yes - we will respond to every single chat request that the browser asks for.

I notice that for new "tabbed chat", we submit a request to get the messages, process the result - which adds things to the chat log and such - and then pass the response straight down to the browser. Whereas for old chat, we ask the Chat Poller to get a list of messages for us, which we format and send down to the browser. So if anything is going to lose messages, I would expect it to be old chat, not new chat.

This will take study.

 

[Veracity]

Final followup for tonight: Revision 14502 refactors RelayRequest.handleChat to make it a lot clearer what is happening.

Tabbed chat works like this:

If the Browser asks for newchatmessages.php (wanting to see if anybody else has said something), we ask KoL for that and get the response. We process the response text - adding messages to the chat log and so on - and then pass the response untouched down to the browser.

If the Browser asks for submitnewchat.php (you just typed something), we send it to KoL and wait for the response. We process the response text - adding messages to the chat log and so on - and then pass the response text untouched down to the browser.

I don't see any way in which KoLmafia can "lose" chat messages that KoL sends down but still secret them away in its own chat history. It sends to the browser exactly what it gets from KoL.

 

[jolson42]

Ok, that's a lot to process!
First of all, sorry if I've caused any offence to any you mafia devs; that was absolutely not intended, and I truly appreciate what you do here!
When I made that first post, I had assumed that the situation was like when you have two instances of the native chat pane running; messages go to one or the other, rather than both.
As for what sort of messages go missing, I don't see any pattern. I know that they can be my messages, or ones posted by others. When I post messages that go missing, I know that other players can see them, and they just don't show up for me, confirmed by watching chat on a multi logged into vanilla KoL.
Right now, I have no idea whether I'm losing private messages, because obviously I can't watch those on a multi. I've turned on chat logging, so next time I notice it happening in public chat, I'll do some private messaging and check the logs. (or, of course, just talk to my multi. duh)
And for good measure, I'll be brave and try an older version of chat as well, to see whether it is affected too.
Now, it feels like more messages go missing during things like twitch streams, but that may just be that more people are talking, so the effect is more noticeable.

 

[Bale]

Final followup for tonight: Revision 14502 refactors RelayRequest.handleChat to make it a lot clearer what is happening.

Veracity, It sounds like you're starting to get curious about this. This is a dangerous project to tackle a week before we're hoping to put out a new point release when it is not on your list of bugs to crush before we release.

 

[xKiv]

Some incoherent thoughts:
- when I last (perhaps a year ago?) tried having both native and mafia chat GUI open, mafia was often "eating" PMs (as in, all PMs would show in mafia's GUI, but only some would show in native chat). Normal messages were fine.
- (this might be third-hand misremembered speculation) I think I read somewhere (probably /hardcore) something about tabbed chat being different from the previous version, in that it requests messages "since last request", while older chat reqeusted messages "since $timestamp"?
As in, if there are messages A B C D posted, and one process requests new messages just after A and just after D, and process 2 requests new messages just after B and C:
old version:
process 1 gets A, and then B C D (because it asked for all new messages since A)
process 2 gets A B, then C
new version (each new message is only delivered once):
process 1 gets A
process 2 gets B
process 2 gets C
process 1 gets D
I have no idea if this is any close to actuality, but it would explain missing messages, especially if opening vanilla kol in two tabs with chat in each also makes messages go only to one of them.

 

[lostcalpolydude]

Now, it feels like more messages go missing during things like twitch streams

KoL slows down chat processing server-side during twitch events.

My speculation (based on not understanding how it works) is that the relay browser makes a request, and there's nothing new. Then it makes another request, finally gets a message with a timestamp from before the previous request, and throws it out because that should be a duplicate. This could be completely wrong of course.

 

[Veracity]

This is a dangerous project to tackle a week before we're hoping to put out a new point release when it is not on your list of bugs to crush before we release.

Good point.

when I last (perhaps a year ago?) tried having both native and mafia chat GUI open, mafia was often "eating" PMs (as in, all PMs would show in mafia's GUI, but only some would show in native chat). Normal messages were fine.

Running native chat and Mafia's chat GUI simultaneously is still black magic to me; I can see how native chat requested messages would get copied to the GUI chat, but not the other way. As Bale points out, I don't have time to figure that out, right now.

- (this might be third-hand misremembered speculation) I think I read somewhere (probably /hardcore) something about tabbed chat being different from the previous version, in that it requests messages "since last request", while older chat reqeusted messages "since $timestamp"?

This is correct.

When you request old chat messages, you include a "lasttime" form field in the request, which is the timestamp of the last message you've processed. We take the response, parse the (multiple) messages it contains, noting the timestamp, and pass down an HTML comment with "lastseen" specifying the timestamp of the last one. The next time the Browser polls, it passes that right back in the "lasttime" form filed.

Getting messages from new chat has no way for you to specify WHICH messages; you just get back a JSON structure with all the messages since the last time you requested messages. We process messages from that JSON, but do not manipulate it in any way before passing it down to the browser.

As in, if there are messages A B C D posted, and one process requests new messages just after A and just after D, and process 2 requests new messages just after B and C:
old version:
process 1 gets A, and then B C D (because it asked for all new messages since A)
process 2 gets A B, then C
new version (each new message is only delivered once):
process 1 gets A
process 2 gets B
process 2 gets C
process 1 gets D

Yes, this is correct.

I have no idea if this is any close to actuality, but it would explain missing messages, especially if opening vanilla kol in two tabs with chat in each also makes messages go only to one of them.

Exactly.

Now, if we have multiple threads fetching chat - one in the KoLmafia chat GUI, and one relayed from the browser (a RelayRequest), that is exactly what we expect to see: each process would get only a subset of the messages. However, all the messages should get funneled through our internal chat history, so they will all show up in the GUI chat. The same does not happen in the other direction; messages received by the GUI chat don't go back down to the native chat.

This is the time-consuming can of worms that Bale is encouraging me to not open right now.

My speculation (based on not understanding how it works) is that the relay browser makes a request, and there's nothing new. Then it makes another request, finally gets a message with a timestamp from before the previous request, and throws it out because that should be a duplicate. This could be completely wrong of course.

The part about "making a request and getting nothing, followed by making a request and getting something" is correct. However, the "throwing out messages because a timestamp is too old" is incorrect - for new chat, at least, which is where the issue we're discussing occurs. We ask for "everything since the last time we asked" and the messages come back with time stamps, but we do not throw any of them away because of that: we process ALL of them through our internal chat history and, for requests coming from the relay browser, we pass the response text we received back to the browser with no modification; we do not prune or filter the messages in any way.

I'm happy to talk about this more, but I have no time for a "project" right now.

 

[heeheehee]

My speculation (based on not understanding how it works) is that the relay browser makes a request, and there's nothing new. Then it makes another request, finally gets a message with a timestamp from before the previous request, and throws it out because that should be a duplicate. This could be completely wrong of course.

This speculation is actually doubly wrong because mchat.php doesn't actually set the timer for requesting new messages until the last request completed (either finished normally or was killed client-side due to a timeout).

I looked a bit into this, and mchat.php times out requests after 5s. That doesn't *seem* too likely, but it's still my best guess as to what's going on.

 

[Veracity]

This speculation is actually doubly wrong because mchat.php doesn't actually set the timer for requesting new messages until the last request completed (either finished normally or was killed client-side due to a timeout).

I looked a bit into this, and mchat.php times out requests after 5s. That doesn't *seem* too likely, but it's still my best guess as to what's going on.

What is mchat.php? The string "mchat" appears literally nowhere in the KoLmafia source.

 

[lostcalpolydude]

What is mchat.php? The string "mchat" appears literally nowhere in the KoLmafia source.

That's KoL's URL to enter modern chat. Older chat, or loathing chat I guess, is lchat.php. Ancient chat is chat.php.

 

[Veracity]

Hah. GenericRequest.php:

		this.isChatRequest =
			this.formURLString.startsWith( "chat.php" ) ||
			this.formURLString.startsWith( "newchatmessages.php" ) ||
			this.formURLString.startsWith( "submitnewchat.php" );

The only chat URLs that RelayRequest.java looks at are newchatmessages.php and submitnewchat.php.

 

[Grotfang]

Now, if we have multiple threads fetching chat - one in the KoLmafia chat GUI, and one relayed from the browser (a RelayRequest), that is exactly what we expect to see: each process would get only a subset of the messages. However, all the messages should get funneled through our internal chat history, so they will all show up in the GUI chat. The same does not happen in the other direction; messages received by the GUI chat don't go back down to the native chat.

This is the time-consuming can of worms that Bale is encouraging me to not open right now.

Yeah... I started writing some code to try and fix this a while ago, but my degree intensifying coincided with a burnout from KoL and I didn't get very far (and haven't been around much since). What's being described sounds like the issue I was trying to fix way back when and is exactly what Veracity is describing.