|
JQuilici Adept
Joined: 21 Sep 2005 Posts: 250 Location: Austin, TX
|
Posted: Mon Mar 31, 2008 9:26 pm
[2.21] Lockup when MXP elements received |
I originally thought this was the same bug as in this thread. However, based on Zugg's posts there, I now think it is a separate problem. My posts from that thread are yanked and placed below:
I am seeing a lockup trying to connect to MozartMUD (mozartmud.com:4500), immediately after MXP is enabled. I have a reproducible test case, detailed below, which can be invoked at character creation time:
Note: I have performed this test on two separate installs on two separate machines. Both were virgin installs of 2.21 (new directory, all data files in the install directory, no imports of anything), to reduce any crossover from zMud or previous CMUDs, but I do not have a virgin machine (which has never had zMUD/CMUD installed) to completely eliminate the possibility.
Procedure
- Run CMUD
- Create a new session named 'Mozart'. Set the hostname to mozartmud.com and the port to 4500. Save changes.
- Open the Mozart session.
- After the welcome screen, you will see:
Code: |
By what name do you wish to be known? |
Enter 'Fluglehorn' - I know the name is not taken.
You will see:
Code: |
Did I get that right, Fluglehorn (Y/N)? |
Confirm by typing 'y'.
You will see:
Code: |
New character.
Choose a password for Fluglehorn: |
Type 'zzzz'. We'll never finish character creation, so don't sweat it. If the auto-login trigger dialog appears at this point, just cancel it.
You will see:
Code: |
Please retype password: |
Type 'zzzz' again (or just hit return to re-send it).
You will see:
Code: |
Enable MXP (Mud Extension Protocol)? (Y=Yes, N=No): |
Type 'y'.
CMUD will lock up and go to 100% CPU (or 50% on my dual-core machine). I have to kill it from the Task Manager.
A similar lockup occurs when logging in an existing character. I have no way of getting at the stack, or otherwise figuring out what it's up to. However, I CAN say that I have not yet enabled MCCP (that's the next question expected in character creation), so that isn't the culprit in my case.
Further info. #DEBUGFILE doesn't give anything terribly useful - I suspect that the final buffer isn't flushed to the file by the time I kill CMUD, so the debug file just cuts off wherever. So I ran the procedure above with Packetyzer running on the connection. Here is the final data packet from the server, and the ACK back from CMUD:
Code: |
Packetyzer Trace:
Frame 1 (778 bytes on wire, 778 bytes captured)
Frame is marked: False
Arrival Time: Mar 31, 2008 16:06:45.264846000
Time delta from previous packet: -23.758085000 seconds
Time since reference or first frame: 1964.081015000 seconds
Frame Number: 1
Packet Length: 778 bytes
Capture Length: 778 bytes
Protocols in frame: eth:ip:tcp:data
Ethernet II, Src: 00:18:39:cd:11:ca, Dst: 00:12:3f:00:65:05
Destination: 00:12:3f:00:65:05 (Dell_00:65:05)
Source: 00:18:39:cd:11:ca (00:18:39:cd:11:ca)
Source or Destination Address: 00:12:3f:00:65:05 (Dell_00:65:05)
Source or Destination Address: 00:18:39:cd:11:ca (00:18:39:cd:11:ca)
Type: IP (0x0800)
Internet Protocol, Src Addr: 69.220.173.202 (69.220.173.202), Dst Addr: 192.168.1.120 (192.168.1.120)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
0000 00.. = Differentiated Services Codepoint: Default (0x00)
.... ..0. = ECN-Capable Transport (ECT): 0
.... ...0 = ECN-CE: 0
Total Length: 764
Identification: 0x6bd3 (27603)
Flags: 0x04 (Don't Fragment)
0... = Reserved bit: Not set
.1.. = Don't fragment: Set
..0. = More fragments: Not set
Fragment offset: 0
Time to live: 49
Protocol: TCP (0x06)
Header checksum: 0x2562 (correct)
Source: 69.220.173.202 (69.220.173.202)
Source or Destination Address: 69.220.173.202 (69.220.173.202)
Destination: 192.168.1.120 (192.168.1.120)
Source or Destination Address: 192.168.1.120 (192.168.1.120)
Transmission Control Protocol, Src Port: 4500 (4500), Dst Port: 3726 (3726), Seq: 1729, Ack: 59, Len: 724
Source port: 4500 (4500)
Destination port: 3726 (3726)
Source or Destination Port: 4500
Source or Destination Port: 3726
TCP Segment Len: 724
Sequence number: 1729 (relative sequence number)
Next sequence number: 2453 (relative sequence number)
Acknowledgement number: 59 (relative ack number)
Header length: 20 bytes
Flags: 0x0018 (PSH, ACK)
0... .... = Congestion Window Reduced (CWR): Not set
.0.. .... = ECN-Echo: Not set
..0. .... = Urgent: Not set
...1 .... = Acknowledgment: Set
.... 1... = Push: Set
.... .0.. = Reset: Not set
.... ..0. = Syn: Not set
.... ...0 = Fin: Not set
Window size: 5840
Checksum: 0x5b80 (correct)
SEQ/ACK analysis
TCP Analysis Flags
This frame is a (suspected) out-of-order segment
This is a TCP duplicate ack
Duplicate ACK #: 1
Duplicate to the ACK in frame: 109
Data (724 bytes)
0000: 00 12 3F 00 65 05 00 18 39 CD 11 CA 08 00 45 00 ..?.e...9.....E.
0010: 02 FC 6B D3 40 00 31 06 25 62 45 DC AD CA C0 A8 ..k.@.1.%bE.....
0020: 01 78 11 94 0E 8E A5 72 D1 A5 A8 FB 70 FC 50 18 .x.....r....p.P.
0030: 16 D0 5B 80 00 00 1B 5B 31 7A 3C 21 45 4C 45 4D ..[....[1z<!ELEM
0040: 45 4E 54 20 72 6E 61 6D 65 20 46 4C 41 47 3D 22 ENT rname FLAG="
0050: 52 6F 6F 6D 4E 61 6D 65 22 3E 0A 0D 1B 5B 31 7A RoomName">...[1z
0060: 3C 21 45 4C 45 4D 45 4E 54 20 72 64 65 73 63 20 <!ELEMENT rdesc
0070: 46 4C 41 47 3D 22 52 6F 6F 6D 44 65 73 63 22 3E FLAG="RoomDesc">
0080: 0A 0D 1B 5B 31 7A 3C 21 45 4C 45 4D 45 4E 54 20 ...[1z<!ELEMENT
0090: 72 65 78 69 74 20 46 4C 41 47 3D 22 52 6F 6F 6D rexit FLAG="Room
00A0: 45 78 69 74 22 3E 0A 0D 1B 5B 31 7A 3C 21 45 4C Exit">...[1z<!EL
00B0: 45 4D 45 4E 54 20 70 72 6D 70 74 20 46 4C 41 47 EMENT prmpt FLAG
00C0: 3D 22 50 72 6F 6D 70 74 22 3E 0A 0D 1B 5B 31 7A ="Prompt">...[1z
00D0: 3C 21 45 4C 45 4D 45 4E 54 20 68 70 20 46 4C 41 <!ELEMENT hp FLA
00E0: 47 3D 22 53 65 74 20 68 70 22 3E 0A 0D 1B 5B 31 G="Set hp">...[1
00F0: 7A 3C 21 45 4C 45 4D 45 4E 54 20 6D 61 78 68 70 z<!ELEMENT maxhp
0100: 20 46 4C 41 47 3D 22 53 65 74 20 6D 61 78 68 70 FLAG="Set maxhp
0110: 22 3E 0A 0D 1B 5B 31 7A 3C 21 45 4C 45 4D 45 4E ">...[1z<!ELEMEN
0120: 54 20 6D 76 20 46 4C 41 47 3D 22 53 65 74 20 6D T mv FLAG="Set m
0130: 76 22 3E 0A 0D 1B 5B 31 7A 3C 21 45 4C 45 4D 45 v">...[1z<!ELEME
0140: 4E 54 20 6D 61 78 6D 76 20 46 4C 41 47 3D 22 53 NT maxmv FLAG="S
0150: 65 74 20 6D 61 78 6D 76 22 3E 0A 0D 1B 5B 31 7A et maxmv">...[1z
0160: 3C 21 45 4C 45 4D 45 4E 54 20 6D 61 6E 61 20 46 <!ELEMENT mana F
0170: 4C 41 47 3D 22 53 65 74 20 6D 61 6E 61 22 3E 0A LAG="Set mana">.
0180: 0D 1B 5B 31 7A 3C 21 45 4C 45 4D 45 4E 54 20 6D ..[1z<!ELEMENT m
0190: 61 78 6D 61 6E 61 20 46 4C 41 47 3D 22 53 65 74 axmana FLAG="Set
01A0: 20 6D 61 78 6D 61 6E 61 22 3E 0A 0D 1B 5B 31 7A maxmana">...[1z
01B0: 3C 21 45 4C 45 4D 45 4E 54 20 65 78 20 22 3C 73 <!ELEMENT ex "<s
01C0: 65 6E 64 20 68 72 65 66 3D 27 26 74 65 78 74 3B end href='&text;
01D0: 27 3E 22 3E 0A 0D 1B 5B 31 7A 3C 21 45 4C 45 4D '>">...[1z<!ELEM
01E0: 45 4E 54 20 67 6F 74 6F 20 22 3C 73 65 6E 64 20 ENT goto "<send
01F0: 68 72 65 66 3D 27 67 6F 74 6F 20 26 74 65 78 74 href='goto &text
0200: 3B 27 3E 22 3E 0A 0D 1B 5B 31 7A 3C 21 45 4C 45 ;'>">...[1z<!ELE
0210: 4D 45 4E 54 20 72 65 61 64 20 22 3C 73 65 6E 64 MENT read "<send
0220: 20 68 72 65 66 3D 27 72 65 61 64 20 26 74 65 78 href='read &tex
0230: 74 3B 27 3E 22 3E 0A 0D 1B 5B 31 7A 3C 21 45 4C t;'>">...[1z<!EL
0240: 45 4D 45 4E 54 20 68 65 6C 70 20 22 3C 73 65 6E EMENT help "<sen
0250: 64 20 68 72 65 66 3D 27 68 65 6C 70 20 26 74 65 d href='help &te
0260: 78 74 3B 27 3E 22 3E 0A 0D 1B 5B 31 7A 3C 56 45 xt;'>">...[1z<VE
0270: 52 53 49 4F 4E 3E 0A 0D 0A 0D 1B 5B 31 7A 45 6E RSION>.....[1zEn
0280: 61 62 6C 65 20 4D 43 43 50 20 28 4D 75 64 20 43 able MCCP (Mud C
0290: 6C 69 65 6E 74 20 43 6F 6D 70 72 65 73 73 69 6F lient Compressio
02A0: 6E 20 50 72 6F 74 6F 63 6F 6C 29 3F 20 28 3C 73 n Protocol)? (<s
02B0: 65 6E 64 20 68 72 65 66 3D 22 79 22 3E 59 3D 59 end href="y">Y=Y
02C0: 65 73 3C 2F 73 65 6E 64 3E 2C 20 3C 73 65 6E 64 es</send>, <send
02D0: 20 68 72 65 66 3D 22 6E 22 3E 4E 3D 4E 6F 3C 2F href="n">N=No</
02E0: 73 65 6E 64 3E 2C 20 3C 73 65 6E 64 20 68 72 65 send>, <send hre
02F0: 66 3D 22 62 22 3E 42 3D 42 61 63 6B 3C 2F 73 65 f="b">B=Back</se
0300: 6E 64 3E 29 3A 20 1B 5B 32 7A nd>): .[2z
Frame 2 (54 bytes on wire, 54 bytes captured)
Frame is marked: False
Arrival Time: Mar 31, 2008 16:06:45.444226000
Time delta from previous packet: 0.179380000 seconds
Time since reference or first frame: 1964.260395000 seconds
Frame Number: 2
Packet Length: 54 bytes
Capture Length: 54 bytes
Protocols in frame: eth:ip:tcp
Ethernet II, Src: 00:12:3f:00:65:05, Dst: 00:18:39:cd:11:ca
Destination: 00:18:39:cd:11:ca (00:18:39:cd:11:ca)
Source: 00:12:3f:00:65:05 (Dell_00:65:05)
Source or Destination Address: 00:18:39:cd:11:ca (00:18:39:cd:11:ca)
Source or Destination Address: 00:12:3f:00:65:05 (Dell_00:65:05)
Type: IP (0x0800)
Internet Protocol, Src Addr: 192.168.1.120 (192.168.1.120), Dst Addr: 69.220.173.202 (69.220.173.202)
Version: 4
Header length: 20 bytes
Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00)
0000 00.. = Differentiated Services Codepoint: Default (0x00)
.... ..0. = ECN-Capable Transport (ECT): 0
.... ...0 = ECN-CE: 0
Total Length: 40
Identification: 0xda98 (55960)
Flags: 0x04 (Don't Fragment)
0... = Reserved bit: Not set
.1.. = Don't fragment: Set
..0. = More fragments: Not set
Fragment offset: 0
Time to live: 128
Protocol: TCP (0x06)
Header checksum: 0x6a70 (correct)
Source: 192.168.1.120 (192.168.1.120)
Source or Destination Address: 192.168.1.120 (192.168.1.120)
Destination: 69.220.173.202 (69.220.173.202)
Source or Destination Address: 69.220.173.202 (69.220.173.202)
Transmission Control Protocol, Src Port: 3726 (3726), Dst Port: 4500 (4500), Seq: 59, Ack: 2453, Len: 0
Source port: 3726 (3726)
Destination port: 4500 (4500)
Source or Destination Port: 3726
Source or Destination Port: 4500
TCP Segment Len: 0
Sequence number: 59 (relative sequence number)
Acknowledgement number: 2453 (relative ack number)
Header length: 20 bytes
Flags: 0x0010 (ACK)
0... .... = Congestion Window Reduced (CWR): Not set
.0.. .... = ECN-Echo: Not set
..0. .... = Urgent: Not set
...1 .... = Acknowledgment: Set
.... 0... = Push: Not set
.... .0.. = Reset: Not set
.... ..0. = Syn: Not set
.... ...0 = Fin: Not set
Window size: 64546
Checksum: 0x49e4 (correct)
SEQ/ACK analysis
TCP Analysis Flags
This frame is a (suspected) out-of-order segment
This is a TCP duplicate ack
Duplicate ACK #: 1
Duplicate to the ACK in frame: 5
0000: 00 18 39 CD 11 CA 00 12 3F 00 65 05 08 00 45 00 ..9.....?.e...E.
0010: 00 28 DA 98 40 00 80 06 6A 70 C0 A8 01 78 45 DC .(..@...jp...xE.
0020: AD CA 0E 8E 11 94 A8 FB 70 FC A5 72 D4 79 50 10 ........p..r.yP.
0030: FC 22 49 E4 00 00 ."I...
|
Nothing else after that, and I waited a good 30 secs before killing it from the Task Manager. Looks like CMUD went belly-up right after getting a pile of MXP elements from the server (and the MCCP question, which I never see on the screen).
Final note: If you run my procedure, and type 'n' at the MXP question...no hang. It goes on to the MCCP question, which you can safely answer 'y'. |
|
_________________ Come visit Mozart Mud...and tell an imm that Aerith sent you! |
|
|
|
Zugg MASTER
Joined: 25 Sep 2000 Posts: 23379 Location: Colorado, USA
|
Posted: Mon Mar 31, 2008 9:54 pm |
OK, I looked into the problem with MozartMUD, and it looks like they are also sending an incorrect telnet option. This is similar to the bug with Dark Skies, but instead of it being the "valid" v1 of the MCCP protocol (with the documented issue of not terminating the option sequence), MozartMUD is sending the incorrect sequence:
IAC SB 91 SE
In other words, it looks like someone was reading the MCCP v1 spec and somehow decided that this was the proper way to "enable" any protocol. This is a completely bogus code. I don't know if some other MUD client is incorrectly recognizing this sequence to enable MXP or not. zMUD/CMUD do not "enable" the MXP protocol at all. zMUD/CMUD simply use the normal DO/DONT WILL/WONT sequences.
In any case, the above is invalid text for a Telnet connection. Whenever you use IAC SB to start a suboption negotiation, you must ALWAYS end the sequence with IAC SE as in the Telnet RFC. As you can see, the above text is missing the IAC before the trailing SE.
You should notify MozartMUD about this problem since it might cause problems with their MUD and other telnet clients.
The reason this worked in previous versions of CMUD (and zMUD) and that when implementing the v1 MCCP bad code, zMUD/CMUD was allowing any suboption to terminate with just SE instead of IAC SE. I guess I will do this in the next version too so that people can play these bad MUDs. But see, this is what happens when you start allowing exceptions to the proper protocols. You get lazy MUDs, or MUDs that just don't understand the protocols, sending out invalid text. And when MUD clients accept this bad text, it just encourages more MUDs to do it instead of fixing their code properly.
So please report this to Mozart and see if they will fix their code base. Or, if you discover why they are sending this particular code, let me know. Like I said, maybe some other MUD client is handling MXP improperly and they added this since it didn't break zMUD/CMUD in the past. |
|
|
|
Zugg MASTER
Joined: 25 Sep 2000 Posts: 23379 Location: Colorado, USA
|
Posted: Mon Mar 31, 2008 9:59 pm |
Btw, the reason that is is *VERY BAD* to kludge CMUD to allow this kind of invalid Telnet text is that it will cause problems for Telnet servers that use the protocol property and actually need to send a chr(240) (SE) in the data stream. Telnet supports sending IAC IAC in order to place a chr(255) into the data stream. So that is why you need IAC SE to mark the end. My terminating the sequence with just SE, it prevents that character from being within the suboption data itself.
So, since MXP doesn't ever use the chr(240) in it's suboption negotiation, I am going to restrict this "fix" so that it only allows the invalid sequence for options 85 (v1 MCCP) and 91 (MXP). Otherwise this might cause problems on IRE MUDs that use suboptions extensively to send data. |
|
|
|
JQuilici Adept
Joined: 21 Sep 2005 Posts: 250 Location: Austin, TX
|
Posted: Mon Mar 31, 2008 10:34 pm |
Yes, I definitely see the problem. I'll see if I can get a server-side fix as well...maybe they'll let me implement it if they're too busy otherwise.
I have a horrid suspicion, though, that the same problem will rear its head on MSP (telnet option 90) with Mozart or some other MUD - I can't tell until I get past the MXP crash. Perhaps option 90 should be enabled for the kludge as well? Or make it a configuration checkbox somewhere? |
|
_________________ Come visit Mozart Mud...and tell an imm that Aerith sent you! |
|
|
|
Zugg MASTER
Joined: 25 Sep 2000 Posts: 23379 Location: Colorado, USA
|
Posted: Tue Apr 01, 2008 4:55 pm |
Yeah, I'll add MSP to the list too.
|
|
|
|
|
|
|
You cannot post new topics in this forum You cannot reply to topics in this forum You cannot edit your posts in this forum You cannot delete your posts in this forum You cannot vote in polls in this forum
|
|