gmcp "hangs" when dealing with a lot of items

[Simon Vermeersch]

When dealing with a lot of individual items, your connection can look like its stuck: you don't receive any information back from the server and can't send anything.

I found the problem on Achaea, and it only works when using gmcp. An easy way to simulate it would be the following:
OUTR ALL KOLA (or whatever plant you have tons of)
SPLIT KOLA INTO GROUPS OF 1 (do this till all your kola is split into individual items)
COMBINE ALL KOLA

This last step will cause the connection to hang. This is on an empty profile with only gmcp enabled.

To confirm that this is a Mudlet-specific bug and not an Achaean one, I tried with another client (tintin++). With gmcp enabled there (and the Char, Room and Char.Items modules enabled), the combining worked.

My Mudlet version is one compiled from git from a week or two ago, on Archlinux.

[Heiko (koehnheiko)]

From what I have seen this looks like a server problem (stack overflow due to too deep recursion). In any case the server severely mangles the last part of the GMCP package.

[Vadim Peretokin (vperetokin)]

Re-opening the issue as this has turned into an exploit to disconnect Mudlet users from a game.

The admins have looked back into it and mentioned this:

Sent By: Iosai on 09/28/17:51
Just FYI, we looked into that GMCP issue a bit and although we could stand to combine some GMCP reports in instances like that, it appears to be an issue with Mudlet as we tested on some alternative clients and didn't see that problem occurring. Is that something you could look into on Mudlet's end?

[Vadim Peretokin (vperetokin)]

It's clear that JSON decoding is receiving a corrupted string:

[ERROR:] object:<event handler function> function:<mmhrv_resetroom>
         <[string "local currentroom..."]:3: attempt to index field 'Info' (a nil value)>
[ERROR:] object:<JSON decoder error:> function:<json_to_value>
         <Lua error:InvalidJSONInput: lexical error: invalid char in json text.
                   { "location": "inv",.Items.Update { "location": "in
                     (right here) ------^
 at lua-yajl2-linux.c line 310>
[ERROR:] object:<JSON decoder error:> function:<json_to_value>
         <Lua error:InvalidJSONInput: parse error: trailing garbage
                { "locatttrib": "gt" } }
                     (right here) ------^
 at lua-yajl2-linux.c line 310>
[ERROR:] object:<JSON decoder error:> function:<json_to_value>
         <Lua error:InvalidJSONInput: lexical error: invalid char in json text.
          183408", "name": "a stem of4"location": "inv", "item": { "id
                     (right here) ------^
 at lua-yajl2-linux.c line 310>
[ERROR:] object:<JSON decoder error:> function:<json_to_value>
         <Lua error:InvalidJSONInput: lexical error: invalid string in json text.
                     { "locatttrib": 9trib": "gt" } }
                     (right here) ------^
 at lua-yajl2-linux.c line 310>
[ERROR:] object:<JSON decoder error:> function:<json_to_value>
         <Lua error:InvalidJSONInput: parse error: object key and value must be separated by a
colon (':')
           "a9 of 1090 galingale stems", "attrib": "gt" } }
                     (right here) ------^
 at lua-yajl2-linux.c line 310>
[ERROR:] object:<JSON decoder error:> function:<json_to_value>

[Vadim Peretokin (vperetokin)]

Here is output of a successful consolidation of 1000 items: http://pastebin.com/V2BZURwA

Here's a corrupted consolidation of 2000 items: http://www.pastebin.ca/2459518

[Vadim Peretokin (vperetokin)]

In http://www.pastebin.ca/2459518, it seems to break down right after "a group of 1132 galingale stems" (as you'll observe, the count goes up since the start of the output).

Data to setGMCPVariables itself gets corrupted as well - the only level above that is processTelnetCommand.

[Vadim Peretokin (vperetokin)]

void cTelnet::processTelnetCommand( const string & command )
{
    qDebug() << "processTelnetCommand: " <<command.c_str();

processTelnetCommand: ���Char.Items.Remove { "location": "inv", "item": { "id": "176385", "name": "a stem of galingale", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Update { "location": "inv", "item": { "id": "70005", "name": "a group of 1108 galingale stems", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Remove { "location": "inv", "item": { "id": "176393", "name": "a stem of galingale", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Update { "location": "inv", "item": { "id": "70005", "name": "a group of 1109 galingale stems", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Remove { "location": "inv", "item": { "id": "176397", "name": "a stem of galingale", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Update { "location": "inv", "item": { "id": "70005", "name": "a group of 1110 galingale stems", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Remove { "location": "inv", "item": { "id": "1767alingale stems", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201
processTelnetCommand: ���Char.Items.Remove { "location": "inv", "item": { "id": "176349", "name": "a stem of galingale", "attrib":51", "044624ngale stems", "attrib": "gt" } }��
SERVER sends telnet signal: "250" + 201

Even processTelnetCommand itself gets corrupted data. So either the zlib decompression is going wrong, or we're receiving corrupted data.

[Vadim Peretokin (vperetokin)]

Wireshark is showing a peculiar difference in packet sizes during this: observe how all packets max out at 1430 and then the one with number 35 is markedly different. All of them are part of the same communication as you can see according to time.

[Vadim Peretokin (vperetokin)]

So at the moment, data coming right out of decompression is corrupted (see https://bugs.launchpad.net/mudlet/+bug/918419/comments/6), and the packets we receive break down in uniformity (see https://bugs.launchpad.net/mudlet/+bug/918419/comments/7).

Attached is a Mudlet replay demonstrating the issue.

[Heiko (koehnheiko)]

I've started work on this. Fix is coming soon.

[Martin Tee (phasma77)]

Either way, if some kind of mitigation for this could be implemented game-side. In Aetolia, for example, I bugged this with the request that multiple items of the same type be consolidated before death and the workaround was added within hours. If the other games could do this...

[David (manaknightwolf1)]

This is a huge issue in Aetolia currently and cause lockup, drop outs and freezing in pk

[Stephen Lyons (slysven)]

I'm getting some mojibake (after the "processTelnetCommand: " in lines containing that and also at the end of the same lines) when viewing posting: "Vadim Peretokin (vperetokin) wrote on 2013-09-29". Maybe its not an issue but just the side effect of cut and pasting raw telnet byte sequences with characters with the high bit set (>127) but is that the case or is something actually wrong there?

[Vadim Peretokin (vperetokin)]

Any updates on the fix?

What would also be a good design solution for fixing this?

[Ahmed Charles (ahmedcharles)]

This doesn't seem to hang mudlet for me, it just puts it in some weird corrupted state. I'll need to investigate more.

[Ahmed Charles (ahmedcharles)]

This is a bug with mudlet's decompression code for MCCP. Working on the fix.

[Ahmed Charles (ahmedcharles)]

https://github.com/Mudlet/Mudlet/pull/101

Pull request with fix.