This forum is a read-only archive of the Gammon Software forum (2000–2026). No new posts can be made. Search the archive.

MUSHclient may disconnect before all output has been received

Posted by Twisol on Thu 20 Aug 2009 08:23 AM — 34 posts, 127,422 views.

Twisol USA #0
I'm currently using MUSHclient v4.43. The problem is what when you disconnect from Achaea, it sends some "goodbye" text right before you're disconnected. The next time I connect (during the same MUSHclient session), that "goodbye" text is still clogging the pipes, and it's output along with the title screen:


You grow still and begin to silently pray for preservation of your soul while you are out of the land.
2614h, 3078m, 13905e, 17178w, 45% exk-
--- Disconnected on Wednesday, August 19, 2009, 9:33 PM ---
--- Connected for 0 days, 2 hours, 3 minutes, 15 seconds. ---

--- Connected on Thursday, August 20, 2009, 12:28 AM ---


You feel your insides clench as your soul is frozen.
You have played 4095 games.

Goodbye for now!
Rapture Runtime Environment v2.1.3 -- (c) 2007 -- Iron Realms Entertainment
Multi-User License: 100-0000-000

           ******************************************

                 Achaea, Dreams of Divine Lands

                 "Your fate and fame shall be
               an echo and a light unto eternity."

           ******************************************

           Achaea's IP address is 64.127.116.163
           For general questions e-mail support@achaea.com.
           151 adventurers are currently in the realms.

           1. Enter the game.
           2. Create a new character.
           3. Quit.

Enter an option or enter your character's name. 

Password correct. Welcome to Achaea.


I haven't looked at the source, but it seems to me like maybe MUSHclient isn't doing a final check of the socket before it closes it? Or something else.
Nick Gammon Australia Forum Administrator #1
Final check? It looks a bit like the "socket closed" event has arrived before the final text, however it is interesting that it appears to arrive 4 hours later. Couldn't sleep huh? Playing games at 12:28 am? I know what that's like. ;) With me it is more like 3 am.

I'm not sure if this is a MUSHclient issue or a Winsock one. Just to test for me, can you try to do this later ... but with telnet or some other client. Just reproduce the situation, and see what happens.
Twisol USA #2
Telnet log:


Rapture Runtime Environment v2.1.3 -- (c) 2007 -- Iron Realms Entertainment
Multi-User License: 100-0000-000

           ******************************************

                 Achaea, Dreams of Divine Lands

                 "Your fate and fame shall be
               an echo and a light unto eternity."

           ******************************************

           Achaea's IP address is 64.127.116.163
           For general questions e-mail support@achaea.com.
           123 adventurers are currently in the realms.

           1. Enter the game.
           2. Create a new character.
           3. Quit.

Enter an option or enter your character's name. What is your password? Password
correct. Welcome to Achaea.
Your last login was from domain: censored

Your moss tattoo tingles slightly.
There are elections or referendums that you have not yet voted in.
Type ELECTIONS or REFERENDUMS to list the elections or referendums that you may
participate in.

*------------------( Announcements from the Administration )------------------*
-> A Mayan crown bonus sale is in effect! See Announce #3033.
*-----------------------------------------------------------------------------*
 (Type ADMINMESSAGE to view this again at any time.)

Glade of Isolation.
A comforting feeling of privacy pervades the area. Wings flaring, a pegasus toss
es his regal head impatiently.
You see exits leading north, northeast, east, south, west, and northwest.
2614h, 3078m, 13905e, 17190w ex-
-=[ Help us grow by voting for us at TopMudSites! http://www.achaea.com/vote ]=-
2614h, 3078m, 13905e, 17190w ex-
----[ Sylvans House announcement ]----
Just a friendly reminder...be sure to check your messages when you've been out o
f the realms. You never know who's written to you while you've slept! MSGS will
show your list of messages, MSG READ (message number) to read a particular messa
ge. STAT will also show if you've got new messages. (HELP MESSAGES for a full li
st of what you can do with them)
--------------------------------------
2614h, 3078m, 13905e, 17190w ex-You grow still and begin to silently pray for pr
eservation of your soul while you are out of the land.
2614h, 3078m, 13905e, 17190w ex-
----[ Oakstone announcement ]----
With continued mass extermination and widespread arson, replanting should cease
until further notice. See oakstone news 2693.    We are also looking for a new H
igh Fion.  If you are interested please send the Hierophants a message.  Combat
Ability is important, but leadership is more important.  We need to reactivate a
n under utilized defense.
---------------------------------
2614h, 3078m, 13905e, 17190w ex-
You feel your insides clench as your soul is frozen.
You have played 4097 games.

Goodbye for now!


Connection to host lost.

Press any key to continue...


It also works as expected with IRE's Nexus (1) and Fmud (2) clients.

(1) http://www.achaea.com/nexus
(2) http://www.achaea.com/flash


EDIT: Also, telnet is horrible. Never subjugate me to that tortute again. ;_;
Amended on Thu 20 Aug 2009 08:55 AM by Twisol
Nick Gammon Australia Forum Administrator #3
Hmm, well in my tests on my local server, I don't get that anomaly. However I have changed the code slightly in 4.44 to attempt to do one last "packet receive" in the process of closing the socket. Perhaps that will help.

I don't really see how the server does it ... does it close the socket (hence the close message) and then send out one final message? Sounds unlikely. But in that case how come the close event arrives at MUSHclient before the last message?
Rakon USA #4
I'm unsure on how this happens when playing Achaea.
However, for the entire time I've used MUSHclient to play Achaea, I've never seen that 'final goodbye' on logout. However, I DO see it when connecting via straight telnet, or the nexus client as stated before.

Been using MUSH since pre V3.2 :P so, it's a bug that's been there a while.
Twisol USA #5
Rakon said:

Been using MUSH since pre V3.2 :P so, it's a bug that's been there a while.


Yeah, for the longest time I had completely forgotten about it. It's been like this for a while.
Larkin #6
Do you use MCCP? From what I recall, this problem was caused by the compression of the text.
Twisol USA #7
Interesting. Yes, it seems to show up fine after I disable compression.


EDIT: I had someone else test with compression enabled/disabled on other clients, like zMUD, GMUD, and SimpleMU, and I'm told they all work on all counts. It seems, then, that this MUSHclient bug has something to do with how MCCP is handled at EOF?
Amended on Mon 24 Aug 2009 07:53 PM by Twisol
Nick Gammon Australia Forum Administrator #8
Well that narrows it down, but after staring at the code that handles EOF on decompression, I can't see the problem. Also, it works for me under SmaugFUSS, which uses MCCP.
Nick Gammon Australia Forum Administrator #9
Twisol said:

Interesting. Yes, it seems to show up fine after I disable compression.


EDIT: I had someone else test with compression enabled/disabled on other clients, like zMUD, GMUD, and SimpleMU, and I'm told they all work on all counts. It seems, then, that this MUSHclient bug has something to do with how MCCP is handled at EOF?


Back to this for a bit, this is unsolved AFAIK and it is interesting to read Worstje's commments here:

http://www.gammon.com.au/forum/?id=10026

Referring to the MCCP implementation he says:

Worstje said:

Oh, one thing though... Make sure you flush the stream when you know output won't be immediately following anymore, for example after you echo'd a prompt. Otherwise it can be partially stuck in the decompression buffer for a while leading to an odd playing experience where lines sometimes don't show up or take ages to show up. :)


When I first investigated this bug I thought maybe the MCCP buffer was not flushed, particularly as you report that the problem only occurs with MCCP enabled. However on *decompression* I made sure that the Z_SYNC_FLUSH flag was set, which forces as much decompression as possible to occur. Also the zLib library says as follows:

zLib docs said:

In this implementation, inflate() always flushes as much output as possible to the output buffer, and always uses the faster approach on the first call.


So, decompression should be working OK. But what about the server end? Reading Worstje's comment above makes me think that perhaps the fault is at the Achaea end. After all, testing with my local SmaugFuss server does not reproduce the problem, so we have the fact the MUSHclient works OK with Smaug, works OK with compression off, but loses a bit of data with Achaea (data which shows up later).

Now you said you "are told" that zMUD, GMUD, and SimpleMU work with Achaea and MCCP turned on. However for one thing, Wikipedia claims that GMUD does not support MCCP (this might be old), so I wonder quite how accurate these claims are. Do these clients *really* support MCCP, and was it *really* turned on? It may be hard to tell without inspecting the packets in some way.

http://en.wikipedia.org/wiki/Comparison_of_MUD_clients

Also it is possible a single test may not show the problem up. If the server does not set the "flush" parameter when compressing for MCCP, then depending on what is left over in the buffer you may lose a small amount, a large amount, or nothing.
Amended on Thu 28 Jan 2010 07:17 PM by Nick Gammon
Nick Gammon Australia Forum Administrator #10
Regarding the subject line "MUSHclient may disconnect before all output has been received" - let's remember that the disconnection is initiated by the server in your example (since it says "Goodbye for now!"). I presume you typed "quit", although you don't seem to be echoing output.

Thus it isn't factually correct to say "MUSHclient disconnects" - it is the server that disconnects in this case. And it doesn't make sense to suggest the server first disconnects, and then sends more output (which MUSHclient somehow doesn't receive). After all, the server cannot disconnect, and then send data.
Amended on Thu 28 Jan 2010 07:32 PM by Nick Gammon
Nick Gammon Australia Forum Administrator #11
A search for this issue brings up this interesting post from the zMud forums, subject "Achaea-MCCP Compression Error, and Logoff."

Quote:

Also, when I log off, I never get the ending, the part that says Thank you for playing, you have played x number of times.


Now this is an old post (around 2005) but it seems the problem is not totally all related to MUSHclient.

Also Zugg replies:

Zugg said:

The logoff problem is a known issue in zMUD. If the MUD places pain uncompressed text in the same packet as compressed text, then the uncompressed text doesn't get displayed and processed before it gets the logoff message.


Now this is an interesting clue. Perhaps Achaea turns compression off (Zugg seems to be suggesting this is the case) during the logoff procedure, and the final messages may arrive uncompressed. I'll have to check if MUSHclient gracefully handles the switchback from compressed to uncompressed in a single packet.
Nick Gammon Australia Forum Administrator #12
Well, it should handle it. In doc.cpp are these lines:


    // if end of stream, turn decompression off
    if (iCompressResult == Z_STREAM_END)
      {    // we can stop decompressing
      m_bCompress = false;
      // put remaining stuff back into buff
      memcpy (buff, m_zCompress.next_in, m_zCompress.avail_in);
      count = m_zCompress.avail_in;
      }   // end of Z_STREAM_END


That looks for the Z_STREAM_END return code (end of compression), puts the rest of the buffer back, and then loops back to process it uncompressed.
Twisol USA #13
I'll point one of the admins to this page, see if maybe we can figure out what's going on. Thanks for looking more into it!

EDIT: It also occurs to me that I didn't see the text when I quit from Mudlet* recently, either.


* (I was on Linux, it made more sense!)

EDIT 2: It may also be worth noting that in 4.45 (which I'm still running currently), the lines mentioned in the original post don't appear at all after reconnecting, which implies that the original socket flush fix is doing something.
Amended on Thu 28 Jan 2010 09:39 PM by Twisol
Twisol USA #14
I don't know what voodoo you did, Nick, but 4.48 doesn't have this problem... I upgraded straight from 4.46, so I don't know if 4.47 was also clear, unfortunately.
Nick Gammon Australia Forum Administrator #15
Glad to hear it works. :)
Oldjudge #16
Hello,

not to be pedantic, but 4.48 seems not to use compression on Achaea (possibly due to the telnet rewrite) and therefore the message appears.

Oldjudge
Worstje Netherlands #17
One mans bugfix is another mans bug...

Sorry, couldn't resist. :)
Nick Gammon Australia Forum Administrator #18
Oops, I accidentally disabled that when I was testing that MCCP v1 worked. Fixed in version 4.49.
Twisol USA #19
Nick, if I could make a suggestion, perhaps instead "officially" releasing these preview versions, you could tag them on GitHub so interested parties can download from there?
Nick Gammon Australia Forum Administrator #20
I was going to push a version for you to test shortly.
Twisol USA #21
Excellent! I only brought it up because it seems that these are more preview versions than releases intended for general use, and releasing a new version every time a few features are added didn't seem terribly optimal.
Twisol USA #22
I finally got the source to behave, and when I tested, the original problem still remains. So much for that! =/

EDIT: A new problem I just noticed is that when entering my password, the input was echoed, rather than suppressed as it normally is during the same password entry. Something up with the ECHO subnegotiation?
Amended on Mon 08 Feb 2010 06:23 PM by Twisol
Nick Gammon Australia Forum Administrator #23
First, you mean echoed in the output window? Second, there is an option to disable that in Commands configuration (Ignore "echo off" messages).

It worked OK for me when I tried it with Smaug. If you still think it is wrong please do a packet debug and check what arrived.

I got:


50 61 73 73 77 6f 72 64 3a 20 ff fb 01
P  a  s  s  w  o  r  d  :     IAC WILL 01

Twisol USA #24
No, I mean... I had local echo enabled both times. The password entry is protected by ECHO OFF or whatever. On 4.48, the password is correctly hidden, whereas on my compiled 4.49, the password is still echoed visibly. I -want- it to be hidden, since it's a password entry, but the unreleased version seems to disregard the echo-off message (again, under the same settings as my standard 4.48, I copied the compiled EXE into my MUSHclient folder and ran it there)

Packet debug on 4.48 (correct version)
What is your pas   57 68 61 74 20 69 73 20 79 6f 75 72 20 70 61 73
sword? ÿùÿû.       73 77 6f 72 64 3f 20 ff f9 ff fb 01

Sent  packet: removed bytecount at Monday, February 08, 2010, 1:06:34 PM

removed password for post

Incoming packet: 5 (719 bytes) at Monday, February 08, 2010, 1:06:34 PM

ÿü.Password corr   ff fc 01 50 61 73 73 77 6f 72 64 20 63 6f 72 72
ect. Welcome to    65 63 74 2e 20 57 65 6c 63 6f 6d 65 20 74 6f 20
Achaea...Your la   41 63 68 61 65 61 2e 0d 0a 59 6f 75 72 20 6c 61
Amended on Mon 08 Feb 2010 08:20 PM by Twisol
Nick Gammon Australia Forum Administrator #25
Well it doesn't do it for me. Look:


Enter your character's name, or type new: nick
Password: 
Reconnecting.
Limbo


Note password not echoed.
Nick Gammon Australia Forum Administrator #26
Twisol said:

I finally got the source to behave, and when I tested, the original problem still remains. So much for that! =/


What changes did you have to make, if any?
Nick Gammon Australia Forum Administrator #27
If it still does it try putting a breakpoint in on the relevant lines.
Twisol USA #28
Nick Gammon said:

Well it doesn't do it for me. Look:


Enter your character's name, or type new: nick
Password: 
Reconnecting.
Limbo


Note password not echoed.


The fact remains that it does, inexplicably, echo for me.

Nick Gammon said:

Twisol said:

I finally got the source to behave, and when I tested, the original problem still remains. So much for that! =/


What changes did you have to make, if any?

Just compilation/linker changes, nothing that would affect the behavior of the program directly.

Nick Gammon said:

If it still does it try putting a breakpoint in on the relevant line.

I wouldn't know what the "relevant lines" are, unfortunately. I just have the symptoms and a general idea of what's going on, and I didn't change the source behaviorally.
Nick Gammon Australia Forum Administrator #29
Well, it is to do with telnet echo option, so the first place I would breakpoint is here:


    case TELOPT_ECHO:    // line 297 in telnet_phases.cpp
          if (!m_bNoEchoOff)  // put breakpoint here
              {
              m_bNoEcho = true;
              TRACE ("Echo turned off\n");
              }
          break; // end of TELOPT_ECHO


That at least confirms you get the IAC WILL 1 (which I saw in your packet debug). And then you should see the line "m_bNoEcho = true;" executed.

Then, once you see the password prompt, but before typing it in, put a breakpoint in doc.cpp:


void CMUSHclientDoc::SendMsg(CString strText,   // line 1101 in doc.cpp
                             const bool bEchoIt,
                             const bool bQueueIt,
                             const bool bLogIt)
  {

  // cannot change what we are sending in OnPluginSent
  if (m_bPluginProcessingSent)
    return;

  bool bEcho = bEchoIt;

  // test to see if world has suppressed echoing
 
  if (m_bNoEcho)   // put breakpoint here 
     bEcho = false;


Now when you hit <enter> to send the password you should see the "bEcho = false;" executed.

A little further down in doc.cpp the bEcho is tested:


  if (bEchoIt)  // line 1272 in doc.cpp
    DisplayMsg (str, str.GetLength (), USER_INPUT | (bLogIt ? LOG_LINE : 0));


These line numbers are valid as at the current commit as I am writing this: 9ac78a6b548da633a78adeb25ca9e3887736d31b
Amended on Tue 09 Feb 2010 12:01 AM by Nick Gammon
Nick Gammon Australia Forum Administrator #30
Well I can reproduce your problem, not quite sure why:


MUD: Enter an option or enter your character's name. \ff\f9\ff\fe\19\ff\fd\c8\ff\fdV\ff\fc\19\ff\faV\ff\f0

Me: 1

MUD: What is the name you are known by in Achaea? > \ff\f9 

Me: name deleted

MUD: What is your password? \ff\f9 

Me: password deleted

MUD: \ff\fb\01\ff\fc\01Password correct. Welcome to Achaea.


Notice the sequence of events: It asks the password followed by IAC GA.

I reply (echoed).

It then sends IAC WILL 01 (turn echo off).
Then in the same packet it sends IAC WONT 01 (turn echo on).
It then sends "Password correct."

So in that packet sequence, it is turning echo off at the wrong moment.
Amended on Tue 09 Feb 2010 12:26 AM by Nick Gammon
Nick Gammon Australia Forum Administrator #31
OK, I think I have worked it out.

Version 4.48:


Enter an option or enter your character's name. <IAC><GA>
<IAC><DONT><EOR><IAC><DONT><200><IAC><DONT><MCCP>
1
<IAC><WONT><EOR><IAC><WONT><200><IAC><WONT><MCCP>
What is the name you are known by in Achaea? > <IAC><GA>
<IAC><DONT><EOR><IAC><DONT><200><IAC><DONT><MCCP>
name
What is your password? <IAC><GA>
<IAC><WILL><1>
password
<IAC><WONT><1>Password correct. Welcome to Achaea.



That works with Achaea, note that it sends <IAC><WILL><1> after asking for the password, so it isn't echoed.


Version 4.49:


Enter an option or enter your character's name. <IAC><GA>
<IAC><DONT><EOR><IAC><DONT><200><IAC><DO><MCCP>
<IAC><WONT><EOR><IAC><WONT><200><IAC><SB><MCCP><IAC><SE>
1
What is the name you are known by in Achaea? > <IAC><GA>
name
What is your password? <IAC><GA>
password
<IAC><WILL><1><IAC><WONT><1>Password correct. Welcome to Achaea.


This one doesn't work, it turns echo off too late.

However spot the difference? Version 4.48 doesn't turn on MCCP (because of the bug someone noted). So it is all done uncompressed.

Try this, turn compression off, and the password is suppressed correctly.

Try an earlier version of MUSHclient (before all the telnet negotiation changes) and see what happens if compression is on.
Amended on Tue 09 Feb 2010 01:27 AM by Nick Gammon
Nick Gammon Australia Forum Administrator #32
Well I carefully stepped through it with the debugger. Although the problem point is around when compression is turned on, I don't believe MUSHclient is faulty here.

I confirmed we were in compressed mode by the time it asked for the name (and waited for a reply) (as you can see from the packet debug, where it asks for the name after sending <IAC><SB><MCCP><IAC><SE>), so it is not as if the transition from uncompressed to compressed is causing the problem per se.

This seems to me to relate to the other problem with Achaea, where you don't see the final "goodbye" message after disconnecting. I speculated at the time they might not be flushing the compressed data, and this seems to me to be the same thing. Note what happens in decompressed mode:


What is your password? <IAC><GA>
<IAC><WILL><1>


So that final 3 bytes could still be in the compressed buffer at the server end. The zLib documentation recommends *against* flushing the buffer all the time, as that would cause a performance hit.

OTOH, they must flush the buffer when prompting for input, or you would probably miss every 2nd prompt.

My guess is, they flush the buffer after <IAC> <GA>, to make sure the player sees the prompt. So it would look like this:


What is your password? <IAC><GA> <flush>
<IAC><WILL><1>


In other words, they didn't flush after the <IAC><WILL><1>.

Also, the bug (see page 1 of this thread) where you don't see:


You feel your insides clench as your soul is frozen.
You have played 4095 games.

Goodbye for now!


... could be explained the same way. They aren't sending <IAC><GA> so they aren't flushing that final message.

I suggest a polite message to the Achaea admins along the lines of:

  • Please flush the zlib buffer after sending <IAC><WILL><1> after requesting the password.
  • Please flush the buffer after the final "Goodbye for now!" message.


That should fix your problems.
Amended on Tue 09 Feb 2010 01:56 AM by Nick Gammon
Twisol USA #33
That sounds very plausible. Thanks again, Nick!