Zugg Software :: View topic - [2.11] #VAR creating a duplicate variable, causing crashes

Apprentice Joined: 03 Nov 2007 Posts: 132

Hmm, okay but in the opening post, the example I posted was after the variable was already in existence. TestVar was already a variable when those two alarm threads created it again, resulting in the duplicate variables.

So after all that I'm back to my original problem! When using #VAR to *update* variables there seem to be some situations where the variable can actually be created again regardless of whether it was already in existence long before the threads that create the duplicates run. However, when just using varname=varvalue syntax, this problem does not occur in my testing.

I do have a better understanding of threading now and being aware of what in my scripting will create a new thread and what won't etc. so I feel more confident in what I'm doing but this does appear to still be a bug.

Posted: Mon Nov 12, 2007 7:36 pm

Apprentice Joined: 03 Nov 2007 Posts: 132

Ahh. Okay that makes sense then. Thank you!

Apprentice Joined: 03 Nov 2007 Posts: 132

This is still happening in 2.12. It seems it can happen to any variable regardless of what setting calls it.

To restate the problem: Variables that are already in existence are sometimes being recreated (and duplicated) when the #VAR command is used to update them. This does not happen all the time but I can't pinpoint anything in particular that is always causing it. Here are some debugger lines showing it:

11:20:03.401a | k Lusterni | [16] Var "SalveTry" changed from "0" to "1"

**This is set by an alias called by a trigger***

Note: The SalveTry variable clearly exists here and it was changed from 0 to 1

Then later down in the same sequence of settings I get this line:

11:20:03.761a | k Lusterni | [SalveTryThread] Var "SalveTry" changed from "" to "0"

***This is set by a background thread****

Here are a few more examples:

11:41:07.526a | k Lusterni | [7] Var "CurrentMana" changed from "6000" to "5750"

***This is set by an ATCP Trigger***

Then later:

11:41:08.282a | k Lusterni | [7] Var "CurrentMana" changed from "" to "5750"

***This is set by the same ATCP Trigger***
--

11:39:38.749a | k Lusterni | [7] Var "MaxMana" changed from "0" to "6000"

***This is set by an ATCP Trigger***

Then later:

11:41:08.305a | k Lusterni | [7] Var "MaxMana" changed from "" to "6000"

***This is set by the same ATCP Trigger***

--

These result in duplicate variables to be created outside the package entirely in the current window settings and also causes access violation errors.

I do not know what is causing the settings to not recognize that the variable is already in existence but it's making for an unstable program.

Posted: Sat Nov 17, 2007 8:44 pm

I'm going to need more details on your exact ATCP trigger that is doing this. That seems the best place to start. Somehow the context for that trigger is getting messed up.

Apprentice Joined: 03 Nov 2007 Posts: 132

It is not just my ATCP trigger though. The first example was called by a completely different trigger and background thread. It was just the last two that were caused by the ATCP trigger. This is happening with all my variables that can be set in a trigger thread. I can include the ATCP trigger but ...that really doesn't seem to be the source of the problem as it happens even when the ATCP trigger is disabled.

SubAdmin Joined: 18 Nov 2001 Posts: 5187

Can you describe where the variables are in relation to the triggers and aliases that set them? Same package? Same module? Same class?

Also has anyone had this same problem yet in either 2.11 or 2.12?

Apprentice Joined: 03 Nov 2007 Posts: 132

All the variables are in the same package as the triggers and aliases that set them. Some are in the same class as well but some are not.

EDIT: As a note, variables are doing this with the variable=value syntax as well

SubAdmin Joined: 18 Nov 2001 Posts: 5187

I just ran a test of this on my system by doing this at the command line in an untitled session

Apprentice Joined: 03 Nov 2007 Posts: 132

The lines aren't complicated:

Here's the CurrentHealth 1: CurrentHealth=%2

Earlier I had it as #VAR CurrentHealth %2

Same thing.

This is happening pretty much as soon as I have a lot of my settings interacting with each other on a large scale and then I get the crashing and errors when the duplicates are being accessed.

EDIT: I'm starting to suspect this has something to do with accessing the variable as well as some variables that are not even being written to but are being accessed by an expression can sometimes end up with duplicates as well.

Anyway, I can send try to send my package to support and see if the same problem is happening elsewhere. Maybe it is just my computer as it apparently doesn't really like these 2.x versions of cmud.

Wizard Joined: 17 Jun 2006 Posts: 1201

Mine doesn't either Malach. I'm running Windows XP Pro with an AMD Athlon 64 3800+ processor and 1 GB RAM.

Apprentice Joined: 03 Nov 2007 Posts: 132

Okay, my new method of running cmud does not fix the duplicate variable problem. I would paste the debugger results but the program locked up so I couldn't access it. Basically what happened was one of these duplicate variables were created. Then another alias was trying to call that variable and it popped this. Kept popping when I clicked on continue. Same access violation.

date/time : 2007-11-17, 16:34:59, 530ms
computer name : #####
user name : ####
operating system : Windows NT New build 6000
system language : English
system up time : 4 hours 32 minutes
program up time : 14 minutes 25 seconds
processors : 4x Intel(R) Core(TM)2 Quad CPU @ 2.40GHz
physical memory : 978/2030 MB (free/total)
free disk space : (C:) 168.06 GB
display mode : 1024x768, 32 bit
process id : $1798
allocated memory : 60.28 MB
executable : cMUD.exe
exec. date/time : 2007-11-17 01:08
version : 2.12.0.0
madExcept version : 3.0b
contact name : ######
contact email : ######
callstack crc : $402e7cbb, $18ed16ba, $18ed16ba
exception number : 6
exception class : EAccessViolation
exception message : Access violation at address 00D4422D in module 'cMUD.exe'. Read of address 00000089.

Main ($17d0):
00d4422d +009d cMUD.exe PrefDat 10450 +11 PkgData.UpdateTriggerOrder
00ca5f22 +08e2 cMUD.exe MAIN 7435 +166 TMUDForm.HandleTrigger
00ca512e +000e cMUD.exe MAIN 7095 +1 TMUDForm.UserOutNewLine
00a1f1ad +0039 cMUD.exe term 8805 +3 TTerm.DoTriggerLine
00a1dc70 +0200 cMUD.exe term 8383 +34 HandleNewLine
00a1e457 +06d7 cMUD.exe term 8507 +104 TTerm.PutText
00a1ea11 +0049 cMUD.exe term 8613 +2 TTerm.Add
00c91d15 +00b1 cMUD.exe MAIN 1567 +8 TMUDForm.OutputStr
00c9513a +0066 cMUD.exe MAIN 2339 +4 SendBuf
00c95e79 +0b4d cMUD.exe MAIN 2604 +222 TMUDForm.ProcessMUDBuffer
00c91ded +002d cMUD.exe MAIN 1588 +1 TMUDForm.ParseOut
00c91eec +0048 cMUD.exe MAIN 1611 +4 TMUDForm.EchoStr
00c96763 +0117 cMUD.exe MAIN 2784 +21 TMUDForm.EchoPas
00c9661d +0049 cMUD.exe MAIN 2757 +4 TMUDForm.EchoInfo
00ccb594 +44b8 cMUD.exe MAIN 17362 +715 HandleCase
00cd1ef7 +007f cMUD.exe MAIN 18465 +11 TMUDForm.ExecCommand
00c544b0 +0034 cMUD.exe CodeThread 1173 +2 TRunCodeThread.DoExecCommand
0047d901 +0101 cMUD.exe Classes 9339 +22 CheckSynchronize
0052e72f +06df cMUD.exe Forms 6671 +144 TApplication.WndProc
0047fef8 +0014 cMUD.exe Classes 10966 +8 StdWndProc
75a33c85 +000a USER32.dll DispatchMessageA
0052ee84 +00ac cMUD.exe Forms 6873 +13 TApplication.ProcessMessage
0052eecb +000f cMUD.exe Forms 6892 +1 TApplication.HandleMessage
0052f166 +00a6 cMUD.exe Forms 6976 +16 TApplication.Run
00dc86e8 +0088 cMUD.exe CMUD 344 +18 initialization
75bc3831 +0010 kernel32.dll BaseThreadInitThunk
7710a9bb +004b ntdll.dll LdrInitializeThunk

error details:
bug report

Should it be showing my operating system as Windows NT when it's Windows Vista?

Posted: Mon Nov 19, 2007 5:43 pm

Can you describe your settings structure a bit more? Are you using #WAIT commands to create multiple parallel threads? I don't see how this could fail unless you are using threads in some complex way.

Other than Vijilante's method of dragging stuff to another package, the only other way I could see for duplicate variables to be created is:

1) If you use #UNVAR to delete the variable, but somehow it's not really getting fully deleted. So let me know if you are using #UNVAR in a background thread. Or,

2) If you are using #T- to disable something and you accidentally disable a variable (instead of a class or trigger). So you might check to see if your variable names are the same as some class or trigger you are disabling.

Once you get duplicate variables, then you are going to have lots of problems with crashes and stuff. Basically, you end up with 2 pointers to the same portion of memory, and when one pointer is removed, the other one now points to invalid memory and is going to cause access violations.

So we need to go back to how these duplicate variables are getting created in the first place. A simple trigger with a #VAR statement isn't going to do it. Somehow you must be causing other threads to run at the same time and have multiple threads trying to create the same variable at the same time, or something like that.

Btw, it will always show "Windows NT" for NT, XP, and Vista. All of those are "NT" at the core, even though Microsoft has given them different "public" names like "XP" and "Vista". It's the build number (6000 for Vista) that really determines the version.

Apprentice Joined: 03 Nov 2007 Posts: 132

I don't use #UNVAR anywhere. The only place I use T- is disabling explicitly named expression triggers and classes. (things called MasterHealthExpression for example) I have other threads running in parallel but *none* of my triggers, aliases, or anything else actually create a global variable at any time. All my global variables are created ahead of time and are already in existence.

All of my settings only update variables currently in existence. I do use #WAIT in several situations rather than another alarm but again rarely am I even updating a global variable in these threads much less creating one.

My settings have changed quite a bit from the first time I noticed this problem till now. I initially was using a lot of alarms. Now I am using threads and #WAITFOR more and no alarms. The only thing that has stayed consistent is my usage of several experession triggers. Today I will disable the expression triggers and see if I can get the same problems but I imagine I will.

Now, when I initially created these settings I dragged them from the main window settings into a seperate package but that was a one time deal and about a week ago at this point so it seems unlikely that that is the cause as he was doing the dragging when the triggers were actually active.

Posted: Mon Nov 19, 2007 7:28 pm

OK, well, see what more you can learn by disabling various triggers. I really need to get it narrowed down to something more specific since I can't reproduce this here. It has to be some complex interaction with one of the scripts running in the background.

My guess is that one of the background threads are having a bug regarding the scope and/or context and somehow cannot "see" the existing variable, so it tries to create a new variable of the same name. So maybe one script is changing the context in the middle of when the background script is doing the #VAR command (or var=value command). Do you use #CLASS or #MODULE in your scripts to manually change the context? Or, are you clicking on different windows when this happens (clicking on a window changes the current context).

Apprentice Joined: 03 Nov 2007 Posts: 132

I will try to get it more specific but it is happening so frequently with such a variety of variables that's it's hard to pin down. I have had it happen with variables that are actually being updated in a background trigger thread and I've had it happen with variables that are simply being read in an expression. It's very obscure. I don't use #CLASS or #MODULE and I'm not clicking in other windows when it happens. I only have one window running at any given time.

I'll see what more I can do tonight.

Posted: Tue Nov 20, 2007 12:15 am

In your original post, you showed a trigger like this:

Apprentice Joined: 03 Nov 2007 Posts: 132

Yeah I don't actually even use any while statements in my regular scripting. It was just in testing that was the fastest way to get the problem to appear on my system.

I've been testing for most of the afternoon now and my only conclusion is there isn't a cause I can easily see. It's not expression triggers or ATCP triggers or ATCP itself (though those have some odd behavior that may be contributing to it)

I am also going to say that it's not two threads trying to write to the same variable at the same time that's causing it as quite often the variable that is duplicated is only being written to by one thread. Using #SECTION hasn't helped the problem any really. However it defintiely has something to do with multiple threads running. What I have noticed is that it seems like one thread starts and goes through a script where variables are being updated and then another thread starts or is resumed right in the middle of that script and that's when my problems happen. I'll be doing more testing but I'm getting a bit burnt out on it.

Apprentice Joined: 03 Nov 2007 Posts: 132

Okay I am making progress. The latest version of my primary expression trigger had a "trying" variable associated with it in order to get it to fire. It would disable itself, fire the command, have a wait, re-enable itself, then change the trying variable back to the proper value for it to fire again.

This worked fine but what it would cause is two threads for the *same* setting to be running. I would have two exptrig threads with the same id (not the same thread number) running in parallel for a period of time and the duplicate variable problems seem to happen during this period. This is consistent with my problems in earlier versions when I was using alarms instead and I would sometimes have several threads with the same named alarm running.

I made a change to my expression trigger where I took out the "trying" variable and had it immediately disable itself and then start an alarm that would do the actual commands and such. The alarm would disable itself once the conditions no longer called for it's commands to be needed and would also re-enable the expression trigger at this time. In this setup the same setting never has two threads going at once.

I haven't had a duplicate variable since and further several other weird problems I'd been having such as total lock ups, out of memory errors, and argument still on stack errors have gone away as well. I will keep testing it to see if this was the actual problem but it looks promising so far.

Posted: Tue Nov 20, 2007 1:47 am

That's very interesting. I wonder what was causing the duplicate exptrig threads? Can you try this again and post a debugger log showing the duplicate triggers being created? But at least that helps point me in the direction of something related to expression triggers.

Also, v2.13 *has* made some changes that might also be improving this. In 2.12 (and previous versions), the "current window context" is a global value. For example, when you click on a window, the global context is set to the window that you clicked on. The #CLASS command changes this global context variable. This global context variable is used to perform the searching for settings, and is used to determine the current class when using a syntax like @./varname.

Because this is a global variable, if one background thread changes it somehow, then another thread that is also running at the same time will suddenly see the context change. This is related to some problems Vijilante posted about alarms that would change behavior if you clicked on different windows.

Even though you said that you just had one window and were not using the #class command, it's possible that this global variable was getting changed by something else in the middle of running a trigger. In v2.13 I have tried to remove this global variable and use the context setting that is stored in the thread. So this shouldn't be as big of a problem in 2.13.

However, I'm not sure this explains your problem, so I'm going to take another look at expression triggers to see what I can learn.

But definitely post the debugger log output if you can.

Apprentice Joined: 03 Nov 2007 Posts: 132

The duplicate exptrig threads come about simply because the expression trigger fires anytime one of the variables in the expression changes and the expression is true. It doesn't need a pattern and doesn't seem to check to see whether another instance of that trigger is already running so it can happen quite frequently if you use a lot of expression triggers. I just did a test where I had about 200 threads of the same expression trigger running at the same time heh. Anyway here is one debugger log showing it happening:

03:26:24.596p | f CleanLus | Expression: @AfflictionList && @CureTry == 0
03:26:24.612p | c CleanLus | [193] ExpTrig : start : Expression "CureExpression" : #say Cure Expression #T- Cu...
03:26:24.624p | a CleanLus |Cure Expression
03:26:24.646p | k CleanLus | [193] Var "CureTry" changed from "0" to "1"
03:26:24.659p | d CleanLus | [193] ExpTrig : wait 200 ms
03:26:24.859p | e CleanLus | [193] ExpTrig : resumed
03:26:25.463p | a CleanLus #Telnet 200: Char.Vitals<LF>NL:0/100 H:6900/6900 M:5750/6000 E:5400/5400 P:9/10 N:32400/32400 W:27867/27900
03:26:25.476p | k CleanLus | [9] Var "CurrentMana" changed from "6000" to "5750"
03:26:25.567p | a CleanLus #Telnet 200: Char.Vitals<LF>NL:0/100 H:6900/6900 M:5500/6000 E:5400/5400 P:9/10 N:32400/32400 W:27792/27900
03:26:25.579p | k CleanLus | [9] Var "CurrentMana" changed from "5750" to "5500"
03:26:25.675p | e CleanLus | [193] ExpTrig : resumed
03:26:25.682p | a CleanLus #Telnet 200: Char.Vitals<LF>NL:0/100 H:6900/6900 M:5250/6000 E:5400/5400 P:9/10 N:32400/32400 W:27717/27900
03:26:25.693p | k CleanLus | [193] Var "CureTry" changed from "1" to "0"
03:26:25.698p | f CleanLus | Expression: @AfflictionList && @CureTry == 0
03:26:25.706p | k CleanLus | [9] Var "CurrentHealth" changed from "" to "6900"
03:26:25.711p | c CleanLus | [195] ExpTrig : start : Expression "CureExpression" : #say Cure Expression #T- Cu...
03:26:25.761p | k CleanLus | [195] Var "CureTry" changed from "0" to "1"
03:26:25.766p | d CleanLus | [195] ExpTrig : wait 200 ms
ATCP DATA CUT OUT FOR CLEANLINESS OF LOG
03:26:25.923p | d CleanLus | [187] ExpTrig : terminated
03:26:25.937p | d CleanLus | [189] ExpTrig : terminated
03:26:25.950p | d CleanLus | [191] ExpTrig : terminated

I removed a few things for log readability but I think this kind of points of what's happening.

The first bolded part is the exptrig starting on thread 193. I then bolded where it waits and then resumes itself for the next two bolds. The 4th bolded part is showing the ATCP trigger setting the existing CurrentMana variable to the new value and the next bolded part shows the same. The next part shows the same expression trigger starting on thread 195 and going through its script. Then we see thread 9, which is the ATCP trigger, recreating the CurrentHealth variable which is already in existence and only updated in the same instances where the CurrentMana ones would be updated so if it didn't exist, it would already have come up before then. Then we see threads 187, 189, and 191 terminating, all for the same expression trigger, none of which are threads started in the portion of the log we're looking that. So at one time we had six instances of the same expression trigger running.

I have no real idea, but I suspect from experience that the duplicate variables are only being created when the variable actually changes in value. So I doubt the variable in this log would have been duplicated if the mana value had stayed the same.

Anyway, I still haven't gotten any duplicate variables with my new way of doing the expression trigger so I strongly suspect these duplicate instances of the same trigger is the culprit.

Posted: Tue Nov 20, 2007 3:35 am

Wow, 200 Expression threads? Yikes. Are you able to post the entire expression trigger? I'm not sure I can do anything to optimize the expression trigger or to prevent it from firing if it's already active. In a lot of cases, you really want the expression trigger to fire everytime the expression changes. But I can see where this might be a problem if the expression trigger depends upon multiple variables. I'll have to think more about that.

But I think your analysis of the debug log is pretty good. I still can't figure out how it would create a new variable, but this gives me a bit more information to help me find the problem.

Apprentice Joined: 03 Nov 2007 Posts: 132

I deleted it when I changed it over to my new method but it looked something like: (@AfflictionList && @CureTry == 0) {#T- CureExpression;CureTry = 1;#WAIT 200;#CALL @CureAttempt();#WAIT 500;#T+ CureExpression;CureTry = 0}

Though that was just the most recent iteration of it and I had done a variety of other syntaxes, though none that would completely eliminate the trigger being called again. I can see what would cause all the nested threads though running in parallel. I had thought that it would create a new thread but then the old thread would close itself down soon after but the new thread becomes a subthread of the old thread and the old thread won't close itself until its subthread has finished as well. Or something like that.

Posted: Tue Nov 20, 2007 5:18 pm

Yeah, your expression trigger fires when @CureTry changes values, and then in the script for the trigger you are changing CureTry twice! So that's certainly going to cause problems. Obviously I need to change it so that the expression trigger doesn't re-trigger if the variables are changed within the script of the trigger itself.

Also, Expression Triggers need to be fast! Since they are called immediately whenever the dependent variable(s) change, they are called more than any other type of trigger or script in CMUD. I can see where having the #WAIT would cause lots and lots of these triggers to be created. Definitely not a good way to handle it.

One feature that I'm going to consider adding is a command to "queue" a call to an #EVENT. Sort of like how the Windows Message queue works, but if you call #QEVENT more than once, it will still just call the event once. So you could call #QEVENT within the expression trigger, and then when CMUD has a chance (and isn't running another script), it would fire the event that was queued. So even if your expression trigger fired 10 times in a row, the event would just get called once. Not sure if I'll be able to do this for the public release or not.

Anyway, thanks for sharing the expression trigger. I'll try that and see if I can get the duplicate variables to be created, but I can definitely see where that particular expression trigger would really cause a lot of problems.

Apprentice Joined: 03 Nov 2007 Posts: 132

Yeah I have changed all my expression triggers to do nothing except disable themselves and enable something else which will actually handle doing something of note. Works better.