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

[Veracity]

We handle this for non-tabbed chat by fetching "new" messages, merging them with other messages we have queued up from KoLmafia chat, and then generating a response to the browser that has all of the messages. We don't do that for tabbed chat; we merge the new messages into the internal list, but we don't merge other messages and rewrite the response.

I envision we'd do it like this:

- Keep track of the timestamp (or something) of the last message we sent down to the browser
- when the Relay Browser wants to get new messages, ask KoL for them.
- extract them from the JSON into a list.
- If there are any messages on the internal list which arrived and were processed since the last time we send messages to the browser (which we can tell by comparing the saved timestamp, or something)
-- insert them into the list of messages from the latest request
-- generate a new JSON which includes all the the (new and old) messages
-- convert the JSON into a new responseText to send down to the browser.
- send the responseText to the browser - either exactly what KoL sent us, if there are no messages we got from the GUI chat, or the munged/combined list of messages.

That's not conceptually difficult, but I have the feeling getting it "right" will be tricky. Fortunately, our JSON package, which we use only to read JSON - api.php, volcano maze, CAB - also has the ability to write JSON into a string. I've been intending to figure out how to do that, anyway, for use by the ASH to_json() function.

I'm not sure I want to be the one to do it for new chat.

This probably deserves to go into a new Feature Request, since I don't think it has anything to do with this Bug report; the OP was not running KoLmafia's chat GUI.

 

[Veracity]

Apparently I can't stop looking at this.

I notice that the browser will request "newchatmessages.php?lasttime=xxxxxx" no matter what kind of chat you have active. For the older chat, we pass that right on through to KoL. For tabbed chat, we omit the lasttime field, submit it to KoL, and pass exactly what KoL responds with down to the browser. The browser is obviously expecting to get a response that took the "lasttime" field in to account. I wonder if the messages that it is apparently not showing - even though we know that KoL sent them, since they go into the chat log - are being rejected by the browser because they somehow look "stale"?

I experimentally made the RelayRequest ask for tabbed chat messages using the lasttime that the browser specified when it polled for messages. That is what the GUI chat does too, although it uses older chat, not tabbed chat. And I noticed something interesting: I could type into the GUI chat and the browser would pick up those messages next time it polled. Unfortunately, it would put them back into the chat history list, even though they were already there, since the GUI chat had put them there, and the GUI chat would echo them again.

Still, I think this is promising. And passing the same lasttime parameter as the browser itself requested seems important.

I'm going to submit some minor code cleanups I made along the way and will pursue this more, later, with the help of Eclipse. I want to look at the ChatMessages in the History List and see if we can match a tabbed chat message that is already there.

 

[Bale]

Apparently I can't stop looking at this.

I'm not surprised. I'll just cross my fingers that nothing gets broken while you indulge yourself. Having fun is more important than a timely point release.

 

[jolson42]

Pandorolson42 is sorry for opening his box.

 

[Veracity]

I renamed this thread, since, although "Mafia chat opening itself in background, causing missed messages" was the OP's conjecture of what was happening, it turned out to have nothing to do with reality.

I believe that the issue is that the browser says "give me messages since XXX", but the Relay Browser throws away the "since XXX" part. KoL responds with a set of messages (which KoLmafia adds to the chat log) and passes them all down to the Browser, which, for reasons we don't understand, decides that it doesn't need to show some of them. Perhaps the timestamps make them look too old.

In any case, I believe that if we forward the Browser's request untouched to KoL and relay KoL's response untouched back to the Browser, that it will behave exactly as well (or not) as it does in a vanilla browser.

I could do that with an hour's work, at most, and I believe it will solve this bug report. Unfortunately, if you have KoLmafia's chat GUI open at the same time as you have modern chat open in the Relay Browser, you will see duplicated messages in the chat GUI.

I may do it anyway and fix this bug, and deal with the "make KoL's modern chat play nicely with KoLmafia's chat GUI" issue separately.

 

[fronobulax]

Unfortunately, if you have KoLmafia's chat GUI open at the same time as you have modern chat open in the Relay Browser, you will see duplicated messages in the chat GUI.

For my education, why is this a reasonable thing to do? Personally, on those rare occasions when I have two (non-KoL) chat clients running I want both of them to see everything so the described behavior is what I would expect. What is there about the KoL use case that I am missing? Thanks.

 

[Veracity]

For my education, why is this a reasonable thing to do?

As a long-term solution, it is not a "reasonable" thing. That is why there will need to be followup work which fixes it.
As a short-term solution which fixes a bug that affects everybody who runs "modern" chat in the Relay Browser. maybe so.

Personally, on those rare occasions when I have two (non-KoL) chat clients running I want both of them to see everything so the described behavior is what I would expect. What is there about the KoL use case that I am missing? Thanks.

If you are running "modern" chat, it already doesn't work. If you type things in the Relay Browser chat, they show up in the GUI chat, but not vice versa.

 

[fronobulax]

Thank you.

 

[jolson42]

Thanks for taking the time to look into this. It's a pity this glitch happens from time to time, rather than being easily reproducible... But when I see that update, I will assume everything is working properly unless I notice otherwise. So hopefully this is the last time I say anything here!

 

[Veracity]

Revision 14663 changes how the Relay Browser deals with chat messages.

- The browser always asks for newchatmessages.php and submitnewchat.php via a GET. We were submitting them via POST. It seemed to work, but, now we are a better proxy and submit them via GET.
- The browser always asks for newchatmessages.php (whether via lchat or mchat) with a "lasttime" field. We no longer suppress that for "modern" chat and dutifully forward it along.

That should fix THIS bug; we now submit exactly what the browser submits and, for tabbed chat, forward KoL's response unmodified back to to the browser. Therefore, what you see in chat in the Relay Browser should be exactly what you see in a vanilla browser.

Now, this does expose an issue in the KoLmafia chat GUI, if you happen to be running it at the same time as you are running chat in the relay browser. But, we knew that - and that is my next project.

I believe this bug is fixed - but I will mark it Waiting for Info for a while, just in case you see a problem.

 

[fronobulax]

I ran r14664 this morning. Things were fine, but I noticed a debug log.

Horrible relay failure
class java.lang.NullPointerException: null
java.lang.NullPointerException
at net.sourceforge.kolmafia.webui.RelayAgent.sendServerResponse(RelayAgent.java:583)
at net.sourceforge.kolmafia.webui.RelayAgent.performRelay(RelayAgent.java:158)
at net.sourceforge.kolmafia.webui.RelayAgent.run(RelayAgent.java:130)
Horrible relay failure

Just logging in did not reproduce the error and the character has no adventures and non adventure relay interactions did not trigger it. So it is in the land of anecdotes and nothing more.

But I mention it because the character it happened for has never visited The Altar of Literacy and so has no access to chat channels. That is such an edge case that it could have been overlooked in this or related changes. Or Not.

 

[Veracity]

The browser always asks for newchatmessages.php and submitnewchat.php via a GET. We were submitting them via POST. It seemed to work, but, now we are a better proxy and submit them via GET.

Actually, we WERE submitting them via GET. We were just kludgy about it: loading up data fields, just like we need for POST, and then converting them into the URL string just before running it. I cleaned that up, but that would not have changed the behavior. The other fix - actually passing through the lasttime field for "modern" chat - is the real fix for this problem.

 

[Veracity]

I ran r14664 this morning. Things were fine, but I noticed a debug log.

Unfortunately, that stack trace tells nothing about what might have caused this; it is asking for the outputStream of the socket and getting back a null? Horrible relay failure, indeed! - and inexplicable.

Since your character has not visited the Altar of Literacy, I guarantee that the browser is not sending up Chat requests to be relayed, which means that this stack trace is not for a Chat request, which means that nothing I submitted is even slightly relevant to it.

 

[Veracity]

By the way - just to make this clear, the reason this report is "Waiting for Info" is because I'm hoping the OP will chime and say "with the new revision, I am no longer seeing the issue I reported."

Your call to do that - but if you don't, after a week or so, I'm going to just mark this "Fixed".

Thanks.

 

[lostcalpolydude]

It can be hard to tell that messages are no longer not showing up under normal circumstances. However, there's a twitch event coming up on the 27th, and with KoL slowing down chat for those it should be much easier to tell.

 

[jolson42]

Indeed. I haven't noticed any missing messages yet, but, like I said, it's not something I can intentionally reproduce.
Twitch event for me is 3am Sunday morning... I have to work at 7am, so I may need to sleep through the event itself I think, but I can leave myself logged in to do a simple check.

 

[Veracity]

I'm marking this fixed. Like other bugs that are not reproducible at will, all we have is a lack of new reports, but I'm pretty confident I fixed the root cause; when you are running mchat in the browser, KoLmafia now submits exactly the URL that the browser submits and passes back every single message that KoL responds with - which is exactly what hapens in the vanilla browser.

 

[lostcalpolydude]

I didn't see anything weird during the twitch event, so I'm confident that you fixed it.