I'm using r1820. I've also seen this in the master branch compiled from github.
This is the packet we get from the mud:
++Received from MUD: [IAC][SB]Écomm.tick {}[IAC][SE][ESC][1;34mYou see the black moon rising in the east.[ESC][0;37m[LF][CR][ESC][0;37mYou see the grey moon rising in the east.[ESC][0;37m[LF][CR]-->[ESC][1;37m TICK [ESC][0;37m<--[LF][CR][LF][CR]
The triggers
Trigger 1 (sort of): (gmcp) comm.tick
I have code that prints out a Note() when we get the GMCP data comm.tick (first thing in the packet above). That works great. (Technically it isn't a trigger, but a plugin broadcast handler that prints a note.)
Trigger 2: ^You see the black moon rising in the east\.$
This trigger sets a value and prints a note when we get this next line in the packet.
Trigger 3: ^You see the grey moon rising in the east\.$
Trigger 2 isn't firing. #1 and #3 are.
Analysis
My trigger is matching on "^You see the black moon rising in the east\.$" (I converted to regex to avoid the auto-conversion that happens internally.) This isn't matching. I tried dropping the ^ and the $ (both separately and together) and it still didn't match.
I changed the Note() call to AnsiNote(), but that had no impact (which didn't surprise me).
Finally, I tried delaying the note printing when the comm.tick comes in and that fixed it. (A DoAfterSpecial call.)
My first thought is that adding Note()s to the output alters the CurrentLine or PreviousLine pointers in some unexpected way. For some reason, it's causing the mid-packet line to not execute the triggers.
However, I have notes writing out for triggers 2 and 3 as well (for debug purposes at this point). When Trigger 2 prints out a note, it doesn't mess up the firing of Trigger 3.
So, I'm thinking that there must be something with the GMCP data or the plugin broadcast that we're getting that is causing the second trigger not to fire. I haven't figured out what it is, but it's really bugging me.
Workaround
One possibility that I have not tried is to check for the comm.tick gmcp data OnPacketReceived in the plugin, alter it to remove the data, and then broadcast the event (so that it continues to work). That might work to solve this problem. However, it might make the problem worse (if the plugin broadcast is to blame).
Another workaround is to deal with the tick in some other way. We get in -->TICK<-- line. When I used a trigger to fire off of that, everything worked fine. When I switched to using the GMCP data, it caused problems.
The workaround I chose is to delay any notes that are occurring from the comm.tick event.
This is far from ideal, however. If other plugins get the comm.tick broadcast and print a note, my triggers are hosed.
Incoming packet: 61 (104 bytes) at Monday, June 29, 2015, 6:08:29 AM
ÿúÉcomm.tick {}ÿ ff fa c9 63 6f 6d 6d 2e 74 69 63 6b 20 7b 7d ff
ð.[0;37mYou see f0 1b 5b 30 3b 33 37 6d 59 6f 75 20 73 65 65 20
the grey moon ri 74 68 65 20 67 72 65 79 20 6d 6f 6f 6e 20 72 69
sing in the east 73 69 6e 67 20 69 6e 20 74 68 65 20 65 61 73 74
..[0;37m..-->.[1 2e 1b 5b 30 3b 33 37 6d 0a 0d 2d 2d 3e 1b 5b 31
;37m TICK .[0;37 3b 33 37 6d 20 54 49 43 4b 20 1b 5b 30 3b 33 37
m<--.... 6d 3c 2d 2d 0a 0d 0a 0d
I stripped the plugin down to the basics and it's still behaving the same. The entire plugin:
<?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE muclient>
<muclient>
<plugin
name="Stripped_Moon_Plugin"
author="Galaban"
id="2e1f6126c7419c94e739611d"
language="Lua"
purpose="A plugin with a trigger and a broadcast handler"
save_state="y"
date_written="2015-06-11 12:21:04"
requires="4.81"
version="1.0"
>
<description trim="y">
<![CDATA[
A plugin with a trigger and a broadcast handler
]]>
</description>
</plugin>
<!-- Get our standard constants -->
<include name="constants.lua"/>
<!-- Triggers -->
<triggers>
<trigger
enabled="y"
match="You (.*?) the (.*?) moon (falling|rising) (.*?) the (east|west)"
regexp="y"
name="trgMoons1"
send_to="12"
sequence="100"
>
<send>Note("---------------")</send>
</trigger>
</triggers>
<!-- Aliases -->
<script>
<![CDATA[
----------------------
-- GMCP
function OnPluginBroadcast (msg, id, name, text)
if id == "3e7dedbe37e44942dd46d264" then -- gmcphandler
if (text == "comm.tick") then
Note("--GMCP TICK---")
end
end --if gmcphandler
end
]]>
</script>
</muclient>
I also ripped out all unneccesary plugins to remove the possible sources. The plugins installed:
* Aardwolf_gmcp_handler (required for the broadcast)
* My plugin above
When I use "Test Trigger", the moon rises/falls correctly fire the trigger, sending out a "--------" line. However, live data does not do it. Also, when I change the "gmcp tick" to a DoAfterSpecial, the note fires later and the trigger fires every time:
Oh, also the moon rise/fall lines are mud output. I also removed all local triggers. So there's nothing else triggering on those two events other than those two plugins.
As an improved workaround, I've added a temporary, one-shot trigger to fire off the code after the next line is received from the mud. It may possibly mess up multi-line triggers, though.:
local trgCntr = 1
function DelayCall(text)
-- Make the label semi-unique in case this gets called twice in succession
if (trgCntr > 100) then
trgCntr = 1
end
trgCntr = trgCntr + 1
-- (Make it match a full line so we're not messing up trigger test
AddTriggerEx("tmpTrgMoons"..trgCntr,
"^(.*?)$",
text, --what to execute
trigger_flag.Enabled + trigger_flag.RegularExpression + trigger_flag.OneShot + trigger_flag.KeepEvaluating + trigger_flag.Temporary,
-1, 0, "", "",sendto.script, 100)
end
with the call
DelayCall("Note('--GMCP Tick--')")
or
DelayCall("processTick()")
Yes, the packet dump I posted didn't fire on the moon rise.
The problem isn't a specific trigger or specific text, but any trigger text that is occurring after I output a Note() (or AnsiNote) on the telnet subnegotiation.
In the packet above, we get that "comm.tick" gmcp data, output a Note() for it and then fail to trigger on the moon rise.
For what it's worth, I've noticed this exact problem (I even almost had a note posted on it myself two or three days ago but got interrupted with work issues).
I notice it most in the same situation as above: I use MushClient 4.84 (wharblegarbleUPDATE but I haven't seen anything in changelogs that refers to this similar issue, so I think it's still valid, especially given the evidence of the note at the beginning of this thread).
I play Aardwolf.
I have a 3Moons plugin that Note()s a message every tick when the moons are up.
I have a script that will quickly enchant that I often run during this time.
That script often fails to trigger on solidify/illuminate/resonate messaging when the tick-based Note() happens just before the MUD responds to my solidfy cast.
At first I thought it affected only multi-line triggers, but this is not true (see below).
I've also noticed it at other times with other Note()ed output. The easiest way for me to notice? I have {channel} tags on but trigger-hidden, but if one of my notification plugins Note()s output just before I receive a {channel} message, the trigger (it's one of Fiendish's plugins, whichever one) doesn't trigger on that line so I see the tag. One can also notice this because at times I notice the default blue Note() color bleed into game lines if the timing is perfect. I can, for the most part, resolve this issue by Execute()ing something blank during the most troublesome part of the scripts, but this isn't perfect and it's obviously a hack.
I have not been able to recreate the issue with a set of triggers and timers attempting to Note() output at the same time that the game sends text in, but I have tried. It requires something (timing? Packet order?} very specific, but it affects me for better or worse ten or twenty times a day. It's so difficult to catch in log form though since it's very sparse.
Most of my Note() outputs happen on game ticks and I always use GMCP to capture game ticks. I have not specifically noticed this happen except for output that occurs on game ticks.
There's definitely an issue here in some cases matching triggers just after Note() output is sent to the window, possibly involving that Note() happening during the processing of a comm.tick GMCP message from Aardwolf.
The problem is that when you call Note(), AnsiNote() or Tell() during the OnTelnetSubnegotiation, it messes up...something.
For aardwolf purposes, you probably have a plugin that respons to the gmcp tick. If you output any Notes during that "tick" response, the next line of text will be ignored if it came in that same packet of data.
I posted a workaround a few responses back, but basically instead of using:
Note("I have a tixors")
you can use:
DelayCall("Note('I have a tixors')")
And it behaves nearly the same, but it doesn't stop the triggers from firing. It will delay the note by 1 line. Also, it will mess up any multi-line triggers you have. So, something to keep in mind... :)
Anyways, if you're looking for a workaround, that will solve it.
Actually, that does seem like it will fix my issue for the nonce.
Thank you; I'd marked this subject for later reading but basically pasted the note I had prepared earlier in case it had any useful debug information, but I think you've basically made this a nonissue for me (for the moment) in one easy to parse statement. I appreciate it; this was a pretty big item sitting on my stack and I kept pushing it down a bit because I was dreading having to work through it.
I wonder if it would be easier to modify the GMCP plugin to issue its information after the line is fully parsed, but I also wonder if that would interrupt how the standard mapper and/or channel plugins might work. Maybe a DoAfterSpecial on the GMCP plugin's broadcast line?
I've been debugging Mushclient and I've found the key...
The input from the mud that isn't matching has it's ->flags set to 1 (Note). For some reason, it's hanging onto the flag from the previous display line (which was the note from the TelnetSubnegotiation code).
I'll keep digging, but that flag should definitely be 0 and it's 1.
For future reference, this can be used as test data for "test trigger"
\ff\fa\c9comm.tick {}\ff\f0\1b[0;37mYou see the grey moon rising in the east.\1b[0;37m\0a\0d-->\1b[1;37m TICK \1b[0;37m<--\0a\0d\0a\0d
You didn't respond to this:
Quote:
Also get line information on the problem line "You see the black moon rising in the east" and see if it is classified as MUD output or Note output.
The line info for the problem line says:
Line 470 (470), Wednesday, July 01, 7:27:19 AM
Flags = End para: YES, Note: YES, User input: no, Log: no, Bookmark: no
Length = 41, last space = 35
Text = "You see the grey moon rising in the east."
So it has indeed been converted to a note rather than MUD output.
I'll look into it, but I suspect that the "line type" got changed, probably because it wasn't expecting a note to occur during the middle of handling line input.
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.
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.
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.
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.
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).
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.
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.
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?
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.
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).
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.
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);
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.
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.
I output moon status in some circumstances (ie, I output every tick during the 3 moons. I also output an additional moon messages, "The black moon has fallen completely." because the game actually outputs its falling message the tick before the moon is gone).
There are circumstances in which I have other messaging running on ticks (when I have brewed/scribed items that are going to dissolve, for instance, and in certain times I've found it useful to have a tick counter that outputs a short message every 10-30 ticks.)
For me, it's that this behavior is completely unexpected, affects a plugin that I'd like to be able to trust completely, and when unexpected results happen, they're not consistent and if I'm not careful could be almost impossible to resolve in the future unless I always keep this counter intuitive behavior on my mind.
It's also worth noting that it's easy for a plugin completely unrelated to any of mine that I may be using or testing to cause this issue without intention. That's why I'm not eager to have a solution that requires thought upon any plugins actually using GMCP but instead am looking for a solution that fixes the problem more centrally. For instance, my moons plugin was interrupting Fiendish's chat plugin every so often and causing it to miss messages.
The most damning thing is that this behavior allows plugins to inadvertently and deleteriously affect other plugins silently. A lot of work has gone into making that very difficult to do, but all this takes is one callback and one function in that callback, and ironically it's the very same function that is used most often to attempt to debug these very types of issues.
It's sort of the GMCP plugin's fault for not advertising that you shouldn't use Note() calls when responding to any information it broadcasts, but... No, that's a bit much. At least in Aardwolf... What am I supposed to do, add a timer delay to everything I do in response to GMCP if it might lead to a Note()? There's no way I can expect every single plugin that ANY of my users might run to do that, but I do have to expect that in the case of a Moons plugin, because those messages are tied firmly to the Tick() GMCP poke. This is why I'm trying so hard for a central solution.
Neat. Another instance of this cropping up is a plugin I use to append GMCP room numbers to the end of room names. For a long time, during runs, it would only output the number every second room, but it seems that this was the root of that issue to. That's also a situation, given that room movement happens every 1/8second, that it would be very easy for an insufficiently granular timer to cause more unexpected behavior.
There may be a way of fixing it, but the proposed code in reply #26 wasn't it, for reasons I explained.
One idea that springs to mind is the m_OutstandingLines list. This is currently used to save up Tells and Notes that are done before the output window exists.
Conceivably that could be leveraged to do something similar if we know we are processing some out-of-band data, like telnet data. So, if a certain flag is set, the notes are batched, and then output afterwards.
There are more subtle problems than just switching the line type when a GMCP message arrives. Imaging this for example:
You have {GMCP subnegotiation here} died.
Now if we just output notes in the GMCP subnegotiation by terminating the current line, starting a note line, and then re-starting a MUD line we will get:
There may be a way of fixing it, but the proposed code in reply #26 wasn't it, for reasons I explained.
OK, fair enough. Honestly, my goal wasn't to propose a final solution. I knew that it was probably insufficient. I was simply trying to make sure that this thread didn't die and that this bug didn't get fixed. I was trying to float an idea out there that would help keep things alive.
To me it felt like the previous posts were indicating that this wasn't going to get fixed.
Manacle said:
The most damning thing is that this behavior allows plugins to inadvertently and deleteriously affect other plugins silently.
I completely agree and this is why I don't see this as a bug on the plugins part, but as a bug in the Mushclient code. Until I actually dove into the Mushclient code, it made no sense that a Note() should cause the next line of text to fail to fire a trigger.
I apologize if I stepped on anyone's toes. It simply seemed like this was bug was being written off as "too hard" or "as designed", when it's definitely neither. While it may be hard, the payoff is significant. While it may be how it was originally designed, this behavior is broken.
Thank you for continuing to investigate this and work towards a solution.
I just want to point out that you can't necessarily do everything you might want to, in a script. For example, a plugin can't delete itself.
However in this particular case I think I have a compromise. I have tested the idea of deferring notes until the end of the current line. This seems to be working (even with the extra Tells I had in my recent post).
So basically the callback is called at the same time it always was, and can do whatever it wants - within reason. However attempts to output to the current line are pushed into a queue, and saved until "end of line" processing - which should happen when the newline for the line you are trying to trigger on arrives.
The only "gotcha" here would be if you got the tick but no newline. Do you think this is likely to happen? We can probably also empty the outstanding notes buffer on timer processing which happens every 1/10 of a second. I think that usually happens between lines, although it is possible, I think, that you might get a partial line, and then the timer kicks in, and then another partial line.
To make the solution more general, I have applied it to all places where plugin callbacks are called. This includes things like MXP tags and so on. These are probably also places where you don't want notes in the middle of a line.
The only "gotcha" here would be if you got the tick but no newline. Do you think this is likely to happen?
This would cause all sorts of problems. I see it as unlikely. I doubt that the "\n" at the end of the gmcp data is conditional. Even in muds that have telnet subnegotiation mid-line, I see it as most likely hard-coded to not be hard-coded. New lines are something I think we can rely on. I would imagine that Muds/mushs that don't send them would have other trigger issues.
I'm revisiting this thread, because I've been experiencing funny undesired behavior in MUSHclient for a while, and have suddenly realized that the change made because of this thread is the cause of my problems.
I've also found that the behavior being discouraged here, printing data to the screen during subnegotiation callbacks, is extremely useful. IMO, it's not good to require messages from the server before satisfying requests from the user. The result is that I right now offscreen have literally dozens of hidden-from-me messages piling up in this print queue not getting shown until I type "look" or "score" or something entirely unrelated, at which point my piled up prints don't just display but they get interleaved after the first line of the resulting output from the entirely unrelated command.
Unless, that is, I...
Just replace all of my print statements with DoAfterSpecial(0.1, etc. as suggested in the middle of the thread?
Which I am absolutely going to do, because that at least appears to solve my problem. So where does that leave any of this? The committed fix has broken something useful (printing gmcp), but won't this workaround just re-break the original complaint? What's the real difference between a note from subnegotiation and an arbitrarily short delayed note from subnegotiation that makes one of them bad and one good?
And I'm left wondering, couldn't MUSHclient just take all my prints and Notes that it is now refusing to show and just automatically convert them to DoAfterSpecial(0.1 for me? At least then code that used to work would continue to work.
Quote: You have {GMCP subnegotiation here} died.
I think that this is a bonkers example that should be considered a giant server bug and should not be fixed in the client at the expense of other useful operation. I cannot believe that a properly functioning server will send only half of a message, stop what it's doing mid-sentence, send a different message, and then resume sending the rest of the first message. I just can't imagine any server working that way.
Quote: I'm not sure what all that complexity gets you. Probably most of the GMCP messages would be followed fairly promptly by other ones.
I consider this an invalid assumption because I'm running into the problem right now trying to do something for Aardwolf. :\
Quote: MUDs are generally not quiet places.
Actually, I think exactly the opposite. MUDs tend to be very quiet places if you disable the needless spam.
Quote: 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.
Yes, I noticed this too. I'm reporting it now as something that has bothered me since 4.99. :\
This reminds me of quite a few threads on the Arduino Forum. There are things called ISRs (Interrupt Service Routines) which can happen asynchronously, or in other words, when you don't expect them.
Now ISRs can be tricky to debug, so people put debugging prints inside them. Unfortunately that generally makes things worse:
The processor may lock up entirely because the serial prints can't be serviced with interrupts off
The fact of printing alters the timing of the ISR
So I say: "Don't do serial prints inside an ISR". And the user replies "But I want to! It's helpful!".
Quote:
... printing data to the screen during subnegotiation callbacks, is extremely useful ...
No doubt. But you have to design it differently. You could do a table.insert of your message, and have a timer pull them out every 10th of a second, for example.
Quote:
Just replace all of my print statements with DoAfterSpecial(0.1, etc. as suggested in the middle of the thread?
The major problem is that this comment here is exactly spot on:
Quote: What am I supposed to do, add a timer delay to everything I do in response to GMCP if it might lead to a Note()? There's no way I can expect every single plugin that ANY of my users might run to do that
And this later dismissal of concern is not valid, and is based on, I think, the player misunderstanding your question.:
Galaban said:
Nick Gammon said:
The only "gotcha" here would be if you got the tick but no newline. Do you think this is likely to happen?
This would cause all sorts of problems. I see it as unlikely.
It's in fact quite easy to get GMCP without a following in-band message. (Especially now that Aardwolf has added GMCP-only channels, which makes the data easier to manage. Honestly, I'd be happy with everything coming from the server silently out of band with JSON structure and then scripts choosing which parts to show where, but that's maybe a dream for a distant future.)
So should all subnegotiation handlers be themselves DoAfterSpecialing their broadcasts or something? That's the only viable alternative I can think of, though it will mean a lot of script changes across the board if this isn't done automatically under the hood because the canonical demonstration of handling GMCP broadcasts relies on checking the sender plugin ID.
Nick Gammon said:
Quote:
... printing data to the screen during subnegotiation callbacks, is extremely useful ...
No doubt. But you have to design it differently. You could do a table.insert of your message, and have a timer pull them out every 10th of a second, for example.
Quote:
Just replace all of my print statements with DoAfterSpecial(0.1, etc. as suggested in the middle of the thread?
Which is effectively the same thing.
My question is though...
If putting a Note on the screen at a moment in time that is arbitrarily unrelated to the receipt of in-band messages breaks the handling of a subsequent in-band message, wouldn't the exact same thing happen when putting a Note on the screen at a slightly different arbitrarily unrelated moment in time?
If the answer is "No, of course not. You obviously didn't read the thread closely enough." then I think a more good change is to have one of the following:
1) notes sent from inside subnegotiations get automatically converted "DoAfterSpecial(0.1,..." for the noting and therefore continue working as written instead of requiring different syntax. (Maybe not all callbacks though! A non-subnegotiated trigger should be able to broadcast without conflict!)
or
2) broadcasts sent from inside subnegotiations get automatically converted to use "DoAfterSpecial(0.1,..." for the broadcasting, which of course then also requires forwarding the proper ID.
... notes sent from inside subnegotiations get automatically converted "DoAfterSpecial(0.1,..." for the noting ...
That's about what I figured. To me that means that the code change hasn't fixed the root problem and just created a second problem. Can the original change get reverted then until this is worked out?
In the back of my head I've got an idea rolling around about an intermediate message buffer to separate triggerables from notes, after I finish exploring SAPI.
I'm currently using a Note() in my GMCP handler's OnPluginTelnetSubnegotiation() for developing purposes however some GMCP messages seem to be "waiting (?)" for something before they finally get Note()'d.
I've been pointed to this thread and from what I've read it seems DoAfterSpecial() is the proposed solution.
Does that mean there is currently no way at all to immediately echo all GMCP?
They are waiting for the current line to be completed. The reason for deferring notes was that they could interfere with MUD output, or even convert an output line to a note line. For example, a GMCP note in the middle of an output line caused a note to be inserted, and thus the trigger match on the whole line would fail.
One technique would be to use a Notepad window if you are just trying to debug your GMCP. That won't have the limitations of deferred noting.
For example, a GMCP note in the middle of an output line caused a note to be inserted, and thus the trigger match on the whole line would fail.
Handling this alleged case (that probably never actually happens in the first place) by always buffering Notes during packet handling has created all kinds of display problems for me recently, and the current workaround using DoAfterSpecial instead of Note is very problematic at best because it completely breaks output predictability. You no longer have any good way of controlling where and when output actually shows up.
The original problem is very simple that the line handler assumes that GMCP in the middle of an output line is good and proper, and now a new problem is that it's seen as ok to arbitrarily and indefinitely block output until some unrelated packet arrives.
The right fix would be either:
1) to say "actually, no it isn't ok to wedge GMCP in the middle of an output line, and in fact this probably never actually happens because it would be a rather silly thing to do" and thus also terminate display lines at the start of any GMCP.
or
2) If and only if GMCP is received in the middle of an output line, then defer handling of the GMCP data until after the full line is completed. Do NOT arbitrarily defer handling of any and all Notes that may occur during packet handling until receipt of some subsequent and 99.999% of the time completely unrelated display line because:
a) Notes are in fact not the only valid way to generate output and this again leads to ordering problems.
b) Most GMCP packets are NOT received in the middle of output lines(!!!) and can in fact be received with no display lines forthcoming from the server at all.
Further, I imagine that if the first function were to use Simulate instead of Note then the problem would also never occur.
I don't really get why this is assumed to be fine:
Quote: What your Note in the GMCP callback has done is...switched [a completely unrelated line] to a Note line.
You no longer have any good way of controlling where and when output actually shows up.
That's the whole problem if I want "on-the-fly GMCP visualization" triggers (in the output screen). Sometimes the very thing I want is to precise when (or where) the GMCP is in relation to the rest of the MUD output. In my case, for example, I'd like the receiving of specific GMCP to turn on triggers that will process following output. Precision concerning the order and exact moment of stuff received is very valuable in this case.
Fiendish said:
[...] the line handler assumes that GMCP in the middle of an output line is ok [...] no it isn\'t [...]
I lack deep understanding of Telnet protocols or GMCP, but I must say this seems/sounds right to me.
(..) end lines at GMCP as well as newline symbols.
Is that something I could \"fix\" on my end in case it\'s not a change Nick would like to make to the client?
If yes, how?
That's an interesting question. I don't know.
I suppose we could try something like
Simulate("\r\n")
following handling of the GMCP combined with activation of a temporary trigger which removes any immediately subsequent blank line and then disables itself?
Note: This will completely eliminate the acceptability of actually receiving GMCP in the middle of an output line, which Nick seems over the years hell-bent on preserving above all else, and will split that line in half.
Aardwolf sanely never splits output lines like that, so _we_ should be fine with this. Of course always introducing a blank line that we then always have to remove is a bit...unfortunate.
For the proper general solution, Manacle's proposed GMCP plugin change in http://mushclient.com/forum/?id=12915&reply=28#reply28 seems like it would have approximately implemented my 2nd suggestion (by combining gmcp message deferral buffering with both timed and forced consumption of that buffer, you mimic only deferring when reasonable), which I think would have been a far preferable solution because it would then also mostly accomodate this insane line-splitting (except possibly at packet boundaries with very high network delays, which is part of why line-splitting is just insane). Though it of course no longer works past MUSHclient 4.98 because it doesn't stack on top of the "always defer notes forever until a new line arrives" change. :\
The only reason I did this in the first place was that there was indeed a problem to solve. I didn\'t add all this extra work for my amusement.
We were having a problem with plugins being called during the receipt of an output line, which caused triggers to not fire.
No doubt. And I want to take this moment to say two things to you.
1) Your continued effort and attention to this project is both inspiring and pleasant. I'm very glad that you continue to work on it, and I wish that building in Windows were simpler for me to do so that I could send more code to you.
2) The prior resolution of this thread unfortunately broke a lot of my existing plugin code. I'm definitely a lot less bothered by this now that Aardwolf will have a seemingly reliable workaround* ** (thanks for jogging my brain VBMeireles!)
3) I'm still worried that a solution found in a discussion buried in a forum thread leaves breakage for anyone who doesn't find the thread.
That turns off the deferred outputting of lines, when doing a plugin callback, if the current line length is zero. That is, we can assume that an existing line won't be corrupted.
** - that will unfortunately break on any server insane enough to wedge GMCP into the middle of output lines
Out-of-band messages should be able to be sent at any time, that's the whole point of them. Well, maybe not the whole point, but they should be considered separately from in-band messages.
1) Your continued effort and attention to this project is both inspiring and pleasant. I\'m very glad that you continue to work on it, and I wish that building in Windows were simpler for me to do so that I could send more code to you.
Thanks! What was the problem with building in Windows? I thought the latest Visual Studio supported MFC? But there was another issue, wasn't there?
Thanks! What was the problem with building in Windows?
For me right now the problem is mostly storage space on my laptop needed for another virtual machine that is large enough to hold the dozen or so additional gigabytes of MSVC Community Edition.
Quote: Out-of-band messages should be able to be sent at any time, that's the whole point of them. Well, maybe not the whole point, but they should be considered separately from in-band messages.
Fundamentally I agree that it's both not the point for MU*s (I see the point as being more of a differentiation between data to show and data to hide, especially for MU*s that are more likely to send whole complete messages and not stream partial data willy-nilly) and also probably the right thing to do even if probably not that useful for MU*s because MUSHclient isn't actually just a MUSH client.
In practice I'm much more likely to see problems on the MU* side. Oddly enough, I _have_ used MUSHclient extensively for work in the past when I needed to debug telnet data streams, but we weren't mixing in/out-of-band data because that only makes sense if some is for display and some isn't.
