Register forum user name Search FAQ

Gammon Forum

Notice: Any messages purporting to come from this site telling you that your password has expired, or that you need to verify your details, confirm your email, resolve issues, making threats, or asking for money, are spam. We do not email users with any such messages. If you have lost your password you can obtain a new one by using the password reset link.

Due to spam on this forum, all posts now need moderator approval.

 Entire forum ➜ MUSHclient ➜ Bug reports ➜ Full lines received within a packet, Note(), and triggers

Full lines received within a packet, Note(), and triggers

It is now over 60 days since the last post. This thread is closed.     Refresh page


Pages: 1  2 3  4  5  

Posted by Nick Gammon   Australia  (23,140 posts)  Bio   Forum Administrator
Date Reply #15 on Tue 30 Jun 2015 08:47 PM (UTC)
Message
I'm not sure this can be easily fixed (apart from the suggested change of delaying the note for a short time).

Lines in the output window are one of three types: MUD output / Note / User input.

These types are established at the start of the line, and then the line gets added to until a newline, or a line type change. So, for example, doing a note finishes the current MUD output line (if any) and switches to "note type".

There also appears to be quite a bit of code that makes sure that the line type is preserved over line breaks, so for example, if a note spans two lines, the second line is still a note.

What your Note in the GMCP callback has done is finished the "MUD output" line and switched it to a Note line. Then when the rest of the text is processed it is still a Note line. Note lines are not evaluated for triggers.

I think the simplest solution is to use the DoAfterSpecial call, to delay outputting the note. We can regard it as a (design) limitation that you don't attempt to do displays during telnet subnegotiation sequences.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

Posted by Galaban   (19 posts)  Bio
Date Reply #16 on Tue 30 Jun 2015 09:00 PM (UTC)
Message
I'm almost certainly wrong, but it looks like CMUSHclientDoc::StartNewLine is setting the ->flags for the current line to the value that is being passed in.

Right around here (line 2556):

    m_pCurrentLine = new CLine (++m_total_lines, 
                                m_nWrapColumn,
                                iFlags,       // style flags
                                iForeColour,  
                                iBackColour,
                                m_bUTF_8);

    m_pCurrentLine->flags = flags;
    pos = m_LineList.AddTail (m_pCurrentLine);


What's happening is that the Note() is sending 1 into the StartNewLine() function, indicating that the current line is a Note. However, this code above is interpreting it as the next line is a Note.

We return from that function, maintaining that m_pCurrentLine pointer for the next round of text that comes in. That's causing it to get flagged as a note.

I don't know why it works for regular note-before-mud-input-text combos, but I'm sure there's some reason.

Maybe that will help out...

Thanks,
Galaban
Top

Posted by Galaban   (19 posts)  Bio
Date Reply #17 on Tue 30 Jun 2015 09:01 PM (UTC)
Message
Aah, that makes sense for multi-line notes... Hmm.

This is definitely a tricky bug.
Top

Posted by Nick Gammon   Australia  (23,140 posts)  Bio   Forum Administrator
Date Reply #18 on Tue 30 Jun 2015 11:41 PM (UTC)
Message
I'm not really defending the code, but the way I recall doing it, there always had to be a current line (otherwise m_pCurrentLine would be NULL at the very start of a new world).

Thus, there was a current line before we were sure what sort of line it would be. And the decision to make the current line a certain type would happen at the start of that line. Not when the line was created, but when we start putting stuff into it.

So, for example, for a Note, it first checks if we have a current Note line, in which case the Note is appended to it.

But for MUD output, if the line is not already MUD output, then it terminates it, and starts a new line, and marks it MUD output.

Now, in the case in question, we have MUD output, so the line is started as a MUD output line. And indeed it is MUD output. However it then process the GMCP stuff which (perhaps to the surprise of the function) now terminates that line and converts it to a Note line. But now when we get the "real" output we have passed the decision point for setting the line type, so it stays a Note line.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

Posted by Manacle   (28 posts)  Bio
Date Reply #19 on Wed 01 Jul 2015 12:25 AM (UTC)

Amended on Wed 01 Jul 2015 12:35 AM (UTC) by Manacle

Message
In fact, it doesn't really seem to be a bug. It seems that the code as it is is taking reasonable measures and giving a fairly consistent, if surprising, reaction to exceptional circumstances.

The issue we're having is that we're jumping the gun in processing some control information. If we know that there may be additional information in the line, perhaps the easiest way to handle this is to just alter the GMCP plugin we're using to allow that line to be processed completely before it broadcasts information about the updated GMCP table.

Is there a way to elegantly add a delay until the current line is done processing (does that sentence even make sense in the context of how MushClient processes lines?) Because I think the way this is being handled by the client makes sense and is reasonably consistent, I prefer to frame this issue as a (very subtle) bug in the current GMCP plugin. I really don't want to have to remember to do this: (Delay("Note ...")) every time I respond to a GMCP broadcast.

What I'd really like to do is to do this to this line:
BroadcastPlugin(1,message)

to
DoAfterSpecial(.1,BroadcastPlugin(1,message))


but of course I'd rather do this immediately rather than after a 10th of a second (it's quite possible to receive several GMCP messages in that timeframe).
Top

Posted by Nick Gammon   Australia  (23,140 posts)  Bio   Forum Administrator
Date Reply #20 on Wed 01 Jul 2015 01:32 AM (UTC)
Message
Not a direct answer but see "How MUSHclient processes text arriving from the MUD":

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

Quote:

Is there a way to elegantly add a delay until the current line is done processing ...


The plugin callback OnPluginLineReceived might do that for you. I think at that point the line would be assembled but the triggers not yet processed. You could try that. Have the plugin push various GMCP messages into a queue, and empty that queue when OnPluginLineReceived is called.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

Posted by Manacle   (28 posts)  Bio
Date Reply #21 on Wed 01 Jul 2015 03:18 AM (UTC)
Message
Sadly, this ends up in the same position that the trigger fix posted above finds itself. It works fine if this issue DOES crop up, but if GMCP is received on its own, the queue isn't emptied until the next actual line is processed.
Top

Posted by Manacle   (28 posts)  Bio
Date Reply #22 on Wed 01 Jul 2015 05:19 AM (UTC)
Message
If I wanted to add in some hack that at least attempted to deal with this, is it possible that this might work in many cases? I can see in doc.cpp that received lines are handled by a state machine with no character memory, so...

Can I assume that at least (most of the time, after any initial negotiations are done) that I'm not THAT likely to have many telnet subnegotiation codes on the same line?

If so, then can I assume that if I see the character sequence (note that \c9 is the code for GMCP) below start on a packet received from the MUD:
\ff\fa\c9(.+)\ff\f0, where .+ doesn't include the sequence \ff\f0 itself unless there are an even number of \ff characters
followed by a character that is not an IAC (\ff - UNLESS this IAC character is escaped by itself) that, for the most part, I'm seeing a GMCP message followed by an output line in the same packet?

I'm assuming that if I see an ESC (\1b) after subnegotiation that this will end up being an ANSI code and I should at least hope that I'll have a line after it, or should I also check for the ';' character and make sure I have non-IAB data afterward (ie, is it common for the MUD to send ANSI information without actual output data afterward?)

My plan is to use OnPluginPacketReceived (I assume I'll have to think about what happens if I encounter a partial packet) to examine the incoming packets to check for this situation. If I can make the assumptions I listed above, it shouldn't be too difficult to catch most instances of this failure. I don't intend to change the packet information, but I intend to enable queueing behavior in the GMCP plugin we're using when I detect this situation (otherwise, I'll have it behave normally). Assuming my above assumptions are (more or less) true, this should fix most instances of this unexpected behavior while having its very worst failure case result in a delay in broadcasting some GMCP data until one additional line comes in from the MUD.

Am I missing some intricacy in the communication between the game and the client that might trip me up?
Top

Posted by Nick Gammon   Australia  (23,140 posts)  Bio   Forum Administrator
Date Reply #23 on Wed 01 Jul 2015 05:38 AM (UTC)
Message
I'm not sure what all that complexity gets you. Probably most of the GMCP messages would be followed fairly promptly by other ones. MUDs are generally not quiet places. What would be the problem with just the DoAfterSpecial with a short delay? You will see the tick message within a 10th of a second or so.

I'm going to regard this as a documentation problem, and amend the documentation for the OnPluginTelnetSubnegotiation callback to warn you to not do notes. I notice, interestingly, that the GMCP debug mode seems to do just that (does a note) so if there were major problems wouldn't this have cropped up already? Or maybe not many people turn the debugging mode on.

There are other ways you can probably screw around with the way the client handles data, for example doing a Simulate to put more data into the incoming stream, in places it isn't expected.

If I was rewriting the client today, there are quite a few things I would do differently, based on experience, but I'm reluctant to touch things like that, because of all the comments, and commented-out code, that indicates that doing it this way is actually solving other problems.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

Posted by Galaban   (19 posts)  Bio
Date Reply #24 on Wed 01 Jul 2015 09:32 AM (UTC)

Amended on Wed 01 Jul 2015 10:24 AM (UTC) by Galaban

Message
Regarding the Workaround

My first workaround was a DoAfterSpecial call. However. I found that this was... really quite aweful.

What happened was that we would get a -->TICK<-- message (part of that very packet we're trying to process) and then we would process it several lines later. It looked like the plugin was simply unresponsive or that it wasn't tied to the tick message. This may seem alright, but it just looked unprofessional.

That's why I did the temporary, one-shot trigger. Yes, it delays it one line. However, that one line always comes in the same packet.

Even if we get a line of GMCP data "on it's own", we get a new line with it. That's how Aardwolf was coded.

Now, again, this hacky workaround will cause multi-line triggers to fail. It has great potential to mess things up. However, it is better than delaying the output by 0.1 seconds (which is almost always several lines of mud output).
Top

Posted by Galaban   (19 posts)  Bio
Date Reply #25 on Wed 01 Jul 2015 09:41 AM (UTC)

Amended on Wed 01 Jul 2015 10:24 AM (UTC) by Galaban

Message
Regarding the "bug" discussion

Manacle said:

In fact, it doesn't really seem to be a bug. It seems that the code as it is is taking reasonable measures and giving a fairly consistent, if surprising, reaction to exceptional circumstances.


I disagree.

I see this as an architectural bug. Note text should be counted as Note text and mud text as mud text. Remember, what we're talking about here is that if I fire a Note() on a TelnetSubnegotiation, the next trigger will fail to fire.

At what point can I reasonably expect a trigger to not fire?

Don't get me wrong. I've looked at the code and I understand how it was designed and the assumptions that were made. But just because the assumptions make sense does not mean that the results are accurate. I believe that this can and should be fixed.

This is a bug. Triggers are not firing.

What other situation causes this? Does this happen when we echo the input? What about when we turn on tracing? Will all triggers stop firing if I use "gmcpdebug 1"? All of these are using the DisplayMsg function and altering the flags of the next line.

If this won't be fixed, triggers in Mushclient will be viewed as unreliable. Just listen to how it sounds: "If you use a Note(), Tell() or AnsiNote(), it might cause the next line of mud input to be ignored by triggers". Doesn't sound too good.

Look, I already have my workaround and it's solid. I just believe that this bug is much bigger than my little "moons" plugin. And I believe it needs fixed.
Top

Posted by Galaban   (19 posts)  Bio
Date Reply #26 on Wed 01 Jul 2015 10:21 AM (UTC)

Amended on Wed 01 Jul 2015 10:25 AM (UTC) by Galaban

Message
The fix:


  unsigned char save_flags = m_pCurrentLine->flags;

  DisplayMsg (strFullMsg, strFullMsg.GetLength (), COMMENT);

  // Reset the next output line to make sure that our comment above doesn't cause
  // any mud input to be treated as a comment.
  m_pCurrentLine->flags = save_flags;


This would only need to be done in CMUSHclientDoc::Tell and CMUSHclientDoc::Trace. However, it might be worth evaluating other places where we force a COMMENT, such as CMUSHclientDoc::CheckTimerList:


    if (!strExtraOutput.IsEmpty ())
       DisplayMsg (strExtraOutput, strExtraOutput.GetLength (), COMMENT);


I tested it and it solved the problem.
Top

Posted by Nick Gammon   Australia  (23,140 posts)  Bio   Forum Administrator
Date Reply #27 on Wed 01 Jul 2015 09:02 PM (UTC)
Message
Galaban said:

Ooh, that's nice output. How do we get that line info?


Select something on the line, then go to Display -> Text Attributes -> Line Info.

Quote:

I tested it and it solved the problem.


Not quite. It solved that particular problem with that exact test setup. The problem that I have is to make sure it doesn't introduce other problems, which it does. After applying the suggested changes, I thought to myself "what if you do a Tell which doesn't terminate the line?".

What happens with your change is that we are halfway through the line, and you are supposed to be able to do multiple Tells which each add to the current line. Now by switching the line type back to MUD output, each one thinks it has to terminate the MUD output, and start Note output.

So if we change your plugin to do this:


      if (text == "comm.tick {}") then
         Tell ("---")
         Tell ("GMCP TICK")
         Note ("---")
      end 


The output window now reads:


---
GMCP TICK
---
You see the grey moon rising in the east.
---------------
--> TICK <--


Not acceptable. We have disabled the Tell functionality and degraded it to Note behaviour.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

Posted by Manacle   (28 posts)  Bio
Date Reply #28 on Wed 01 Jul 2015 09:02 PM (UTC)

Amended on Wed 01 Jul 2015 09:06 PM (UTC) by Manacle

Message
Galaban, I wasn't saying that I didn't think not firing a trigger on a line that we expected it to fire on wasn't a bug. I suppose a cleaner way of saying what I meant was that I think the bug was that the GMCP plugin we're using fires Note() calls in the middle of OnPluginTelnetSubnegotiation(). Yes, it was because of behavior that wasn't understood and (understandably) not documented. I just don't have a problem with the fact that in this very unusual circumstance that MushClient produced unexpected and undesirable results.

For the nonce, without requiring update to the hardcode, this change in the GMCP plugin also solves the problem with a minimum of behavioral change:

Replace the OnPluginTelnetSubnegotiation function with
GMCPMessageQueue = {}
function OnPluginTelnetSubnegotiation (msg_type, data)
   if msg_type ~= GMCP then
      return
   end -- if not GMCP
  
   if GMCPDebug > 0 then ColourNote ("darkorange", "", data) end

   message, params = string.match (data, "([%a.]+)%s+(.*)")
  
   if not message then
      return
   end -- if
  
   if not string.match (params, "^[%[{]") then
      params =  "[" .. params .. "]"  -- JSON hack, make msg first element of an array.
   end -- if 
   local succ,t = pcall(json.decode,params)

   if succ and type(t) == "table" then
      gmcpdata = gmcpdata or {}

      -- Create the higher level tables based on tag such as char.vitals or room.info etc.
      -- Lowest level of those will be the 'parent' for parse_gmcp
      local parent = gmcpdata
      for item in string.gmatch(message,"%a+") do

         -- reset data hacks
         if (item == "room" and message:sub(1,13) ~= "room.wrongdir") -- don't let room.wrongdir erase current room info
         or item == "comm" or item == "group" then 
            parent[item] = nil 
         end

         parent[item] = parent[item] or {}
         parent = parent[item]
      end
 
      parse_gmcp(t,nil,parent)

	--This if/print will result in bad behavior
	--for GMCP packets with embedded output lines
      if GMCPDebug > 1 then 
         print ("gmcpdata serialized: " .. serialize.save_simple(gmcpdata)) 
      end
 
      --BroadcastPlugin(1,message)
      --Doing it this way to avoid interrupting a line that contains both
      --GMCP data and normal data.  We want to process the GMCP *after* we've
      --generated the full "normal" line from the MUD.  See
      --OnPluginLineReceived(), OnPluginTick()
      table.insert(GMCPMessageQueue, message)

      -- Examples of use from here on. Can be uncommented for debug.
      --print("Testing room.info.exits table      : " .. gmcpval("room.info.exits")) -- serialized table.
      --print("Testing correct room name          : " .. gmcpval("room.info.brief")) -- single field
      --print("Testing character str stat         : " .. gmcpval("char.stats.str"))  -- single number.
      --print("Testing top-level value            : " .. gmcpval("char"))            -- all char table.
      --print("Testing bad top-level value        : " .. gmcpval("sdlkfsldf"))       -- nil (not error)
      --print("Testing bad lower level            : " .. gmcpval("blah.1.2.3"))      -- nil
      --print("Testing bad lower level inside good: " .. gmcpval("room.info.hinick")) -- nil
      --print("Testing north exit, deeper nest    : " .. gmcpval("room.info.exits.n"))
      -- End of test cases.
 
  else
      ColourNote("white","red","GMCP DATA ERROR: "..t)
  end  -- if
   
end -- function OnPluginTelnetSubnegotiation

function OnPluginLineReceived()
	--Capture here to do our best to broadcast GMCP
	--BEFORE triggers are run on embedded lines
	OnPluginTick()
end

function OnPluginTick()
	--Capture here to broadcast GMCP shortly after
	--any GMCP line, even if no output text is
	--embedded.
	if #GMCPMessageQueue > 0 then
		for i=1, #GMCPMessageQueue do
			BroadcastPlugin(1, GMCPMessageQueue[i])
		end
		
		GMCPMessageQueue = {}
	end
end


(Still prefer Galaban's C solution, but for the moment...)
This works for the moment, and it seems to avoid certain unexpected behavior that I was running into before. The situation is, particularly for moon plugins, that we need the GMCP Broadcast to happen BEFORE triggers happen on the embedded line. Otherwise, with moon plugins in particular and, more general, for all plugins that track ticks, there will be one line of input that technically came after the tick but will be matched for triggers before that tick is broadcast to other plugins. Obviously, with moon plugins, this minor discrepancy has a fairly large effect. It is for this reason that I capture both OnPluginTick() AND OnPluginLineReceived(), because OnPluginLineReceived fires before triggers are evaluated. I capture on OnPluginTuck() because I experienced behavior contrary to Galaban's; sometimes OnPluginLineReceived() alone fires too late for my tastes and was delaying GMCP broadcasts until an ADDITIONAL line was received from the MUD.

I do not know if I will run into concurrency issues.
Top

Posted by Nick Gammon   Australia  (23,140 posts)  Bio   Forum Administrator
Date Reply #29 on Wed 01 Jul 2015 09:13 PM (UTC)
Message
Isn't the ---TICK--- line just debugging? You can do other stuff, just don't display things immediately.

- Nick Gammon

www.gammon.com.au, www.mushclient.com
Top

The dates and times for posts above are shown in Universal Co-ordinated Time (UTC).

To show them in your local time you can join the forum, and then set the 'time correction' field in your profile to the number of hours difference between your location and UTC time.


152,218 views.

This is page 2, subject is 5 pages long:  [Previous page]  1  2 3  4  5  [Next page]

It is now over 60 days since the last post. This thread is closed.     Refresh page

Go to topic:           Search the forum


[Go to top] top

Information and images on this site are licensed under the Creative Commons Attribution 3.0 Australia License unless stated otherwise.