Zugg Software :: View topic - [2.11] #WAITSIGNAL and #WAITFOR falling through

SubAdmin Joined: 18 Nov 2001 Posts: 5182

I wanted to try replicating Malach's bad variables and instead I find this.

1. Launch CMud
2. Close Sessions window (ESC)
3. Enter at the command line

Apprentice Joined: 03 Nov 2007 Posts: 132

So I have been trying to use #WAITFOR myself and am encountering this fall through as well. I have an alias called healthsip with the following value:

T- MasterHealth
sip health
#CALL @setVariable(lastelixir,healing)
#say beforewait
#WAITFOR {^The potion heals and soothes you.$} 500
#say afterwait
#IF (!%trigger(MasterHealth)) {#T+ MasterHealth}

When my system calls health sip I would expect it to send sip health and then wait for "The potion heals and soothes you." or half a second and then I would see the "afterwait". That's not what's happening. Instead I have this:

08:44:01.781a | Lusterni |You may drink another health, mana, or bromide potion.
08:44:01.782a | Lusterni | Pattern: ^You may drink another health, mana, or bromide potion.$
08:44:01.785a | Lusterni | [2] Lusternia Trigger : start : Pattern "^You may drink another health, mana, or bromide ...
08:44:01.787a | Lusterni | [2] Var "HealthBalance" changed from "0" to "1"
08:44:01.789a | Lusterni | Expression: @CurrentHealth < @DesiredHealth && @HealthBalance
08:44:01.796a | Lusterni |sip health
08:44:01.798a | Lusterni >sip health<CR><LF>
08:44:01.801a | Lusterni |beforewait
08:44:01.804a | Lusterni |afterwait
08:44:01.862a | Lusterni | Telnet: Char.Vitals\12NL:(\d+)/100 H:(\d+)/(\d+) M:(\d+)/(\d+) E:(\d+)/(\d+) P:(\d+)/10 N:(\d+)/(\d+) W:(\d+)/(\d+) : (%1=0, %2=7590, %3=7590, %4=6000, %5=6000, %6=5700, %7=5400, %8=10, %9=32400, %10=32400, %11=27900, %12=27900)
08:44:01.864a | Lusterni | [2] Lusternia Trigger : start : Telnet "Char.Vitals\12NL:(\d+)/100 H:(\d+)/(\d+) M:(\d+)/...
08:44:01.867a | Lusterni | [2] Lusternia Trigger : stopped
08:44:02.158a | Lusterni |7590h, 6000m, 5700e, 10p, 32400en, 27900w elrx<>-
08:44:02.160a | Lusterni |You take a drink from an opal vial.
08:44:02.162a | Lusterni |The potion heals and soothes you.
08:44:02.164a | Lusterni | Pattern: {The potion heals and soothes you.|Your mind feels stronger and more alert.|Ah, the soothing bromides help strengthen your ego.}
08:44:02.167a | Lusterni | [2] Lusternia Trigger : start : Pattern "{The potion heals and soothes you.|Your mind fee...
08:44:02.168a | Lusterni | [2] Var "HealthBalance" changed from "1" to "0"
08:44:02.170a | Lusterni | [2] Lusternia Trigger : stopped

The "afterwait" line should not be showing up until 500 ms have passed or the potions heals you line shows up but it's showing up well before either of those situations leading me to believe the #WAITFOR is just being ignored.

Also, if I try to use #WAIT in the healthsip alias:

#T- MasterHealth;sip health;#CALL @setVariable(lastelixir,healing);#say beforewait
#WAIT 700
#say afterwait;#IF (!%trigger(MasterHealth)) {#T+ MasterHealth}

The sip health actually does not go through to the mud until the whole #WAIT time is expired though the #say afterwait goes through immediately:

08:57:19.945a | Lusterni |You may drink another health, mana, or bromide potion.
08:57:19.947a | Lusterni | Pattern: ^You may drink another health, mana, or bromide potion.$
08:57:19.949a | Lusterni | [2] Lusternia Trigger : start : Pattern "^You may drink another health, mana, or bromide ...
08:57:19.951a | Lusterni | [2] Var "HealthBalance" changed from "0" to "1"
08:57:19.953a | Lusterni | Expression: @CurrentHealth < @DesiredHealth && @HealthBalance
08:57:19.957a | Lusterni |sip health
08:57:19.959a | Lusterni >sip health<CR><LF>
08:57:19.962a | Lusterni |beforewait
08:57:20.664a | Lusterni |afterwait
08:57:20.667a | Lusterni | [2] Lusternia Trigger : stopped
08:57:20.672a | Lusterni |afterwait
08:57:20.674a | Lusterni | Telnet: Char.Vitals\12NL:(\d+)/100 H:(\d+)/(\d+) M:(\d+)/(\d+) E:(\d+)/(\d+) P:(\d+)/10 N:(\d+)/(\d+) W:(\d+)/(\d+) : (%1=0, %2=7590, %3=7590, %4=6000, %5=6000, %6=5700, %7=5400, %8=10, %9=32400, %10=32400, %11=27900, %12=27900)
08:57:20.676a | Lusterni | [2] Lusternia Trigger : start : Telnet "Char.Vitals\12NL:(\d+)/100 H:(\d+)/(\d+) M:(\d+)/...
08:57:20.679a | Lusterni | [2] Lusternia Trigger : stopped
08:57:20.680a | Lusterni |afterwait
08:57:20.699a | Lusterni |7590h, 6000m, 5700e, 10p, 32400en, 27900w elrx<>-
08:57:20.710a | Lusterni |You take a drink from an opal vial.
08:57:20.712a | Lusterni |The potion heals and soothes you.

Notice the big time gap that corresponds nicely with the 700 millisecond wait time that was used even though the debugger is showing that the sip health was sent to the mud prior to the #WAIT command being executed.

These all all fresh scripts in clean packages with this health sipping being the only script that's installed. I even stripped down all the rest of the script so it was as clean as possible.

Then to make sure the problem really was with these commands being called from expression triggers I did the following:

Disabled my expression trigger that would call my healthsip alias.
Created a trigger to manually call my healthsip. (#TRIGGER {TestPattern} {healthsip})
Fired that trigger

Got the following results which are exactly as I would expect them to be:

09:05:28.007a | Lusterni | [1] Lusternia Comline : start : #say TestPattern
09:05:28.010a | Lusterni |7590h, 6000m, 5700e, 10p, 32400en, 27900w elrx<>-TestPattern
09:05:28.012a | Lusterni | Pattern: TestPattern
09:05:28.014a | Lusterni | Trigger "TestPattern" compiled (Normal) : healthsip
09:05:28.016a | Lusterni | [2] Lusternia Trigger : start : Pattern "TestPattern" : healthsip
09:05:28.018a | Lusterni |sip health
09:05:28.020a | Lusterni >sip health<CR><LF>
09:05:28.023a | Lusterni |beforewait
09:05:28.024a | Lusterni | [2] Lusternia Trigger : wait 700 ms
09:05:28.029a | Lusterni | [1] Lusternia Comline : stopped
09:05:28.087a | Lusterni |beforewait
09:05:28.089a | Lusterni | Telnet: Char.Vitals\12NL:(\d+)/100 H:(\d+)/(\d+) M:(\d+)/(\d+) E:(\d+)/(\d+) P:(\d+)/10 N:(\d+)/(\d+) W:(\d+)/(\d+) : (%1=0, %2=7590, %3=7590, %4=6000, %5=6000, %6=5700, %7=5400, %8=10, %9=32400, %10=32400, %11=27900, %12=27900)
09:05:28.091a | Lusterni | [3] Lusternia Trigger : start : Telnet "Char.Vitals\12NL:(\d+)/100 H:(\d+)/(\d+) M:(\d+)/...
09:05:28.094a | Lusterni | [3] Lusternia Trigger : stopped
09:05:28.107a | Lusterni |You take a drink from an opal vial.
09:05:28.109a | Lusterni |The potion heals and soothes you.
09:05:28.110a | Lusterni | Pattern: {The potion heals and soothes you.|Your mind feels stronger and more alert.|Ah, the soothing bromides help strengthen your ego.}
09:05:28.113a | Lusterni | [3] Lusternia Trigger : start : Pattern "{The potion heals and soothes you.|Your mind fee...
09:05:28.115a | Lusterni | [3] Var "HealthBalance" changed from "1" to "0"
09:05:28.725a | Lusterni | [2] Lusternia Trigger : resumed
09:05:28.728a | Lusterni |7590h, 6000m, 5700e, 10p, 32400en, 27900w elrx<>-afterwait
09:05:28.733a | Lusterni | [2] Lusternia Trigger : terminated
09:05:29.469a | Lusterni |7590h, 6000m, 5700e, 10p, 32400en, 27900w elrx<>-afterwait

Essentially, it works as intended in every situation I tested except when being called by an expression trigger.

Posted: Mon Nov 12, 2007 5:44 pm

I'll take a look at this.

Expression Triggers do not create their own thread...they execute within whatever thread caused the variable value to change. So maybe this is causing a problem.

Posted: Tue Nov 13, 2007 11:55 pm

OK, I was right about this one. There were several problems, but the major design problem was that Expression triggers were executing within the current thread instead of starting a new thread. So, it was trying to do a #WAITSIGNAL in the *main* thread (the one doing the #LOOP).

Now, in 2.11 there was a bug where this didn't even happen, so that explains why it was falling through. When I fixed this bug, then it properly suspended the main thread waiting for the go signal. But since this was happening in the main thread, it was suspending the thread after the first loop iteration. Then, when it got the "go" signal, it would execute the next loop iteration. Then wait for the go signal again, etc. This obviously wasn't right either.

So, I modified Expression triggers to create their own thread. This finally worked as you original desired. Each Expression trigger thread was waiting for the go signal, so there were 20 threads waiting. Then, on the command line I executed '#SIGNAL go' and all of the 20 threads resumed and started executing. After a delay, all 20 threads terminated. Then I did '#SHOW @b' and it had the proper value of 20000.

So, I think this is fixed for 2.12 now. But this *does* add a bit more overhead to Expression triggers since they need to create a thread when they fire.

Wizard Joined: 14 Aug 2004 Posts: 1269

Can't expression triggers and alarms reuse threads from your threadpool? Would reduce the overhead...