Strange bug with calling Execute() from plugin (v5.07-pre)

Posted by Rollanz on Sun 28 Feb 2021 06:46 PM — 12 posts, 41,892 views.

#0
I downloaded 5.07-pre to see if it would fix a strange trigger issue, which is probably not relevant here.

I'm calling Execute from a plugin. The alias it calls does not seem to matter (more on this later). The result is a broken display like this:

Quote:

ql
Sycamore hollow. (indoors)
\ /
--- Sycamore hollow ------ 4:-1:1 ---

6460h,4628m,29545e,23020w,exckdb=,nonea,Ii,Gv,18:11:22.53s,t,T,0R,546x-


Adding a call to print() function at the right place restores the proper appearance
Quote:

ql
Sycamore hollow. (indoors)
test
test
Vines have overtaken this location. Muria of Eleusis is here, curled up by the fire. A runic totem is planted solidly in the ground. A large tapestry is here, displaying an elaborate world map. Averan stands here, her mouth pursed in a slight frown. There are 2 ebony bookshelves carved with sinuous dragons here. Lying flat on the ground is a key-shaped sigil. A solid oak bench rests here. There are 2 logosmas stockings here. A green tapestry of a stag and wolf is placed here. There are 2 birch bookshelves here. A plain green bookcase rests here. Peeking through the glass of an author's trunk, colourful tomes can be seen. A sigil in the shape of a small, rectangular monolith is on the ground. There are 3 indigo nightfire butterflies here.
test
You see a single exit leading north (closed door).
test
test
test
6460, 4628, 29545, 23020, exckdb-, 0S18:17:27.92


As a side remark: as you can see from the different in the prompt lines, the bug is preventing downstream triggers from firing (I have a trigger for gagging the prompt I receive and a script function for displaying the prompt I want).

The relevant section of the plugin is:

function OnPluginTelnetSubnegotiation (type, option)
  if type ~= ATCP then
    return
  end -- not Achaea subnegotiation
  
  local command, args = string.match (option, "^([%a.]+)%s+(.*)$")
  
  if not command then
    return
  end -- don't seem to have a command
  
  --ExecuteNoStack("handle_GMCP " .. command .. "=" .. args)
  --ExecuteNoStack("handle_GMCP2 " .. command .. "=" .. args)
  Execute("test")
  --print("subnegotiation complete")
end -- function OnPluginTelnetSubnegotiation


Having print above Execute("test") and the result is broken output. Having a print() call anywhere downstream of Execute("test") - for example, in the ^test$ alias itself fixes the output.
The content and options on the alias does not seem to matter. This is what the ^test$ alias looks like:


<aliases>
  <alias
   match="^test$"
   enabled="y"
   regexp="y"
   send_to="12"
   keep_evaluating="y"
   sequence="100"
  >
  <send>test = "success"
--print(test)</send>
  </alias>
</aliases>


Varying the options (other than Enabled, of course) did not affect this bug.

I speculate that the problem might have to do with line not ending properly? Is there a version of print function that doesn't begin a new line, which might work as a temporary fix?

Thanks in advance.
Amended on Sun 28 Feb 2021 06:50 PM by Rollanz
Australia Forum Administrator #1

Personally I wouldn’t be doing this. The OnPluginTelnetSubnegotiation function (which is called while receiving data from the MUD) is intended to gather information (eg. your hit points, your current room) which can later be used by things like the mapper. Doing a print in the middle of that re-enters the function that processes incoming input. Using Execute means you are also invoking the command-processor as well. These nested function calls may not be re-entrant, possibly leading to the problems you are having. If you want to print you could use DoAfter (with a short delay) to defer printing for 1/10 of a second.

Is there a version of print function that doesn’t begin a new line, which might work as a temporary fix?

The Tell function outputs without a newline.

#2
Hi Nick,

Reading back, I wasn't clear enough with the issue description. The calls to print() were added after the bug was observed, to help me find out where exactly the trouble was.

Originally the OnPluginTelnetSubnegotiation looked like:


function OnPluginTelnetSubnegotiation (type, option)
  if type ~= ATCP then
    return
  end -- not Achaea subnegotiation
  
  local command, args = string.match (option, "^([%a.]+)%s+(.*)$")
  
  if not command then
    return
  end -- don't seem to have a command
  
  ExecuteNoStack("handle_GMCP " .. command .. "=" .. args)

end -- function OnPluginTelnetSubnegotiation


The ExecuteNoStack function looks like:


function ExecuteNoStack(cmd)
  local s = GetOption("enable_command_stack")
  SetOption("enable_command_stack", 0)
  Execute(cmd)
  SetOption("enable_command_stack", s)
end


The handle_GMCP alias:

<aliases>
  <alias
   script="handle_GMCP"
   match="^handle_GMCP (.*?)=(.*)$"
   enabled="y"
   group="gmcp"
   omit_from_command_history="y"
   regexp="y"
   send_to="12"
   omit_from_output="y"
   sequence="100"
  >
  </alias>
</aliases>


The script function it calls looks like:

function handle_GMCP(name, line, wc)
	local command = wc[1]
	local args = wc[2]
	GMCPTrackProcess(command,args)
end


Short-circuiting the handle_GMCP() function (by commenting out everything inside) does not fix the issue, but adding a print() call does, so I didn't trace further than that.
Australia Forum Administrator #3
I'm not saying there is no bug, however it may be tortuous to find it.

Can't you skip the Execute part by going straight from OnPluginTelnetSubnegotiation to GMCPTrackProcess? It just seems to me that going via the command processor (which may be echoing the command perhaps) is added complexity.
#4
From reading past forum posts, I'm under the impression that there is no notify the world script space of new GMCP messages, which can only be received directly by plugins, without invoking a world alias. I would happily be corrected if I'm mistaken here.

I did however try to queue up the execute commands to wait for line completion.


function OnPluginLineReceived()
  --tprint(cmdQueue)
  if #cmdQueue > 0 then
    for i,v in ipairs(cmdQueue) do
      ExecuteNoStack(v)
    end
  end
  cmdQueue = {}
  return true
end


That made the output mostly as it should have been. The other problem was a mistake I made in creating my prompt trigger.

It turned out that I was checking if a line is a prompt in the send section of the trigger, and using the result in the script function associated with the trigger (this was the wrong order). I'm guessing it used to work because of a bug that was fixed in the pre-release version.
Australia Forum Administrator #5

I’m under the impression that there is no notify the world script space of new GMCP messages, which can only be received directly by plugins

Ah yes, you are right about that. If you keep your code in plugins then you can use CallPlugin.

Amended on Mon 01 Mar 2021 08:55 PM by Nick Gammon
#6
Update:

I noticed that I was still getting blank lines (despite a gagging trigger for the pattern "^$").

Most often, the blank line appears just before a message that would be accompanied by a Comm.Channel.Text GMCP message.

Example of output with the issue:
Quote:

5500h,4000m,24600e,18000w,exkdb=,nonea,Ii,Gv,00:18:31.21s,t,T,0R,531x-

Truax says in a soft-spoken voice, "Back to ELeusis we go!"
5500h,4000m,24600e,18000w,exkdb=,nonea,Ii,Gv,00:18:31.66s,t,T,0R,531x-


Example of output without the issue:
Quote:

5500h,4000m,24600e,18000w,exkdb=,nonea,Oi,Gv,00:26:25.71s,t,T,0R,531x-
Aidun says in a baritone voice, "I'll go."
5500h,4000m,24600e,18000w,exkdb=,nonea,Oi,Gv,00:26:25.77s,t,T,0R,531x-


Debugging the issue by deleting triggers and removing plugins, I traced the problem back to this plugin, specifically to Execute() again.

Observations:
- The Execute() call is inside OnPluginLineReceived()
- The actual content of the Execute doesn't seem to matter. Execute("gag "), where the alias it corresponds to is:

<aliases>
  <alias
   match="^gag (.*)$"
   enabled="y"
   regexp="y"
   send_to="12"
   omit_from_output="y"
   keep_evaluating="y"
   sequence="100"
  >
  <send>gagged = "%0"</send>
  </alias>
</aliases>

makes the blank line show up reliably as much as anything else.
- The blank line does not show up if the Execute() call is commented out altogether
- Comm.Channel.Text is unusual in that it is received before the line it corresponds to, and in that it contains ANSI control sequences, e.g.

"Comm.Channel.Text={ "channel": "says", "talker": "Truax", "text": "\u001b[0;1;36mTruax smiles and says in a soft-spoken voice, \"Come gather inside a bit further. We can sit and talk a spell.\"\u001b[0;37m" }"

- Adding a wait of 0 seconds before firing Execute removes the blank line

As far as I can tell, calling an Execute after a line has been completely received (but before it has a chance to be processed by the World) is causing this issue. Is it intended behaviour?
Australia Forum Administrator #7
It is not exactly intended behaviour, but inside the code is a rather complex set of tests intended to stop input lines from clashing with output lines (as they both show up in the output buffer).

One of the tests terminates a line if we are switching from one type to another (eg. output line to command line) so that a "dual-type" line does not appear (which doesn't make any sense).

Possibly what is happening is that calling Execute is triggering this behaviour.
#8
I played around a little with old MUSHclient commits. The blank lines started appearing in commit 4d5115b192da90ef4f01c62f31962128d937fe0a, which was a fix in response to another of my complaints (https://gammon.com.au/forum/bbshowpost.php?bbsubject_id=14454).

(I'm a little surprised because I thought this was the version I had been using from late April 2019 to when my old computer broke in mid-2020, and I don't recall seeing this until I installed MUSHclient on my new computer.)

Anyways, looks like the added code


if ((m_pCurrentLine->flags & NOTE_OR_COMMAND) != COMMENT)
  DisplayMsg ("", 0, COMMENT);


might not be playing well with the "Convert IAC EOR/GA to new line" option. The blank line disappears if uncheck that option, but that turned out not to be as useful a workaround as I had hoped because it also made my prompt trigger stop working.

I'm trying to wrap my head about how everything works (not experienced with C++), but I think I'm going to need to check if the new line from conversion sets different flags from newlines after regular output.
Australia Forum Administrator #9
I think you might be right. That code preemptively makes a newline in case the script does some outputting. I'm not certain of the best place to move this, or adjust it.

Can you not use CallPlugin, by rearranging stuff a bit?
#10
Nick Gammon said:

I think you might be right. That code preemptively makes a newline in case the script does some outputting. I'm not certain of the best place to move this, or adjust it.

Can you not use CallPlugin, by rearranging stuff a bit?


My first reaction was "no", but looking more closely at the logs it looks like the GMCP packets always come before the prompt lines, meaning I can just invoke CallPlugin on prompt lines. I suspect SetVariable/GetVariable will be faster than matching aliases too, as a side bonus.

This will probably require a bit of reorganizing as I move some things from the world into the GMCP plugin. In the meanwhile, I have a question (again. Sorry):

How should I access colour/style information inside a plugin? Is there a way to get it purely through plugin callbacks, or do I need to use triggers for it?
Australia Forum Administrator #11
From incoming lines? (If so, the fourth argument to trigger functions gives you that).

Or from existing lines in the buffer?