gmcp "hangs" when dealing with a lot of items

Bug #918419 reported by Simon Vermeersch
22
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Mudlet
Fix Released
Critical
Ahmed Charles

Bug Description

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)
Changed in mudlet:
status: New → Incomplete
importance: Undecided → Critical
Revision history for this message
Heiko (koehnheiko) wrote :

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.

Changed in mudlet:
status: Incomplete → Invalid
Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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?

Changed in mudlet:
status: Invalid → Confirmed
Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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>

Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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

Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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.

Changed in mudlet:
importance: Critical → High
importance: High → Critical
Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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.

Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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.

Revision history for this message
Vadim Peretokin (vperetokin) wrote :

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.

Revision history for this message
Heiko (koehnheiko) wrote :

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

Revision history for this message
Martin Tee (phasma77) wrote :

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...

Revision history for this message
David (manaknightwolf1) wrote :

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

Revision history for this message
Stephen Lyons (slysven) wrote :

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?

Revision history for this message
Vadim Peretokin (vperetokin) wrote :

Any updates on the fix?

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

Changed in mudlet:
milestone: none → 3.0
Changed in mudlet:
assignee: nobody → Ahmed Charles (ahmedcharles)
Revision history for this message
Ahmed Charles (ahmedcharles) wrote :

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

Revision history for this message
Ahmed Charles (ahmedcharles) wrote :

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

Revision history for this message
Ahmed Charles (ahmedcharles) wrote :
Changed in mudlet:
status: Confirmed → Fix Committed
Changed in mudlet:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.