Now this is weird. To say the least.
Over the weekend I tickled the sourcecode very slightly - I added a single new function to do fuzzy matching inside the code rather than externally (as mentioned in my last post). It's not working yet, this is just the hook that lets me develop it. Four lines changed in the code, none of them difficult, or with anything unusual about them.
When I released last night I started getting bug reports from the placefinder. It was blowing up in a line that multiplied a score by 100. When I adjusted that to stop it happening, the same happened in another line that multipled a different value by 100.
I got up early this morning as this was driving me bonkers and got down to work on it. The errors were coming out of the parsing part of the code - which hasn't been touched since September 2004. The adjustments I'd made to the code weren't the sort to have introduced any memory corruption bugs (plus the fact it was doing exactly the same on the development and server machine, and was utterly consistent), so what the heck was happening?
A bit of experiment showed that:
print 2 * 95
worked just as it should, as did
print 2 * 101
but try to do anything between 95 and 100 and it died. It wasn't the multiplication that did it, just the same happened with addition etc.
I
know that it won't help, but I fruitlessly search for 94s and 95s, 100s and 99s in the code.
When I was first developing the CanalplanAC interpreter, which is far and away the most complicated thing I've ever written, I took the trouble to build a dedicated debugging and tracing feature into it,
and left all the calls in the code - but they are excluded normally by some macro hackery.
So I changed a constant, rebuilt from clean, and this time, before typing
x = 2 * 95
I typed
trace "EF"
'E' means trace expressions, and 'F' means trace syntactical flow.
In another console I did the same with
x = 2 * 10
and I compared the outputs. Each generated a page that looked like this (the full trace for a successful evaluation and assignment of 20 to x)
syntax.c (147) Read_Everything Read: x = 2 * 10 as 1
syntax.c (162) Read_Everything Identifier token is: x
syntax.c (187) Read_Everything Parsing [SET/GOSUB]
syntax.c (188) Read_Everything Syntax table reads: %IK#
syntax.c (190) Read_Everything Using syntax table entry %
syntax.c (190) Read_Everything Using syntax table entry I
syntax.c (853) Match_Simple Read identifier - Identifier token is: x
syntax.c (190) Read_Everything Using syntax table entry K
syntax.c (301) Read_Everything Next token read: Token is operator: =
syntax.c (530) Read_Everything Keyword changed to [IMPLICIT SET]
syntax.c (190) Read_Everything Using syntax table entry #
syntax.c (285) Read_Everything Spliced to syntax table: #%A~X
syntax.c (190) Read_Everything Using syntax table entry %
syntax.c (190) Read_Everything Using syntax table entry A
token.c (389) Syntactic_Unit First token: Identifier token is: x
token.c (421) Pull_Expression Expression token: Token is operator: =
syntax.c (747) Match_Simple Item is an expression: x
syntax.c (190) Read_Everything Using syntax table entry ~
syntax.c (190) Read_Everything Using syntax table entry X
NUMBER: 2
token.c (389) Syntactic_Unit First token: Integer constant is: 2
token.c (421) Pull_Expression Expression token: Token is operator: *
NUMBER: 10
token.c (421) Pull_Expression Expression token: Integer constant is: 10
token.c (421) Pull_Expression Expression token: empty token
syntax.c (731) Match_Simple Item is an expression: 2 * 10
syntax.c (595) Read_Everything ?Separator empty token
syntax.c (606) Read_Everything End of line: x = 2 * 10
syntax.c (607) Read_Everything Lastpushed: 0, depth: 0
syntax.c (634) Read_Everything About to resolve procedure calls
expression.c (313) Real_Evaluate Caching this expression
expression.c (336) Real_Evaluate Getting token from expression into new storage
expression.c (354) Real_Evaluate Evaluating - Identifier token is: x
variables.c (148) Create_Global_Variable Creating global variable x
variables.c (97) hashdup Making item of size 10 to hold string 'x' - allocated at 0x86bc5b8
variables.c (103) hashdup The name item points at 0x86bc5c0
variables.c (105) hashdup Copied in
variables.c (152) Create_Global_Variable Done!
expression.c (958) Push_Variable_Onto_Valstack Pushing variable called x onto the stack
expression.c (959) Push_Variable_Onto_Valstack It holds [NULL]
expression.c (336) Real_Evaluate Getting token from expression into new storage
expression.c (354) Real_Evaluate Evaluating - empty token
expression.c (560) Real_Evaluate Returning from Evaluate
expression.c (1069) Drop_Valstk Dropping value stack
expression.c (188) Evaluate_String - EXPRESSION TO EVALUATE IS 2 * 10
expression.c (313) Real_Evaluate Caching this expression
expression.c (336) Real_Evaluate Getting token from expression into new storage
NUMBER: 2
expression.c (354) Real_Evaluate Evaluating - Integer constant is: 2
expression.c (921) Push_Value_Onto_Valstack Pushing value of 2 onto the stack
expression.c (336) Real_Evaluate Getting token from expression into new storage
expression.c (354) Real_Evaluate Evaluating - Token is operator: *
expression.c (336) Real_Evaluate Getting token from expression into new storage
NUMBER: 10
expression.c (354) Real_Evaluate Evaluating - Integer constant is: 10
expression.c (921) Push_Value_Onto_Valstack Pushing value of 10 onto the stack
expression.c (336) Real_Evaluate Getting token from expression into new storage
expression.c (354) Real_Evaluate Evaluating - empty token
expression.c (557) Real_Evaluate End-loop. Have popped *
expression.c (1018) Pull_Top_Value_Off_Stack Result was a new value 10
expression.c (1018) Pull_Top_Value_Off_Stack Result was a new value 2
expression.c (663) Operate_On_Stack Calculating 2 * 10
expression.c (665) Operate_On_Stack Evaluates to 20
expression.c (921) Push_Value_Onto_Valstack Pushing value of 20 onto the stack
expression.c (560) Real_Evaluate Returning from Evaluate
expression.c (1018) Pull_Top_Value_Off_Stack Result was a new value 20
expression.c (210) Evaluate_String -END OF EXPRESSION- returning 20
expression.c (1069) Drop_Valstk Dropping value stack
The faulty calculation stopped dead with an error after the line I've marked in red.
Armed with this it was easy to see what was happening. The code was wrong, it was as simple as that - a test that should only have been performed when checking an "operator" was being performed for numbers as well. CanalplanAC stores all symbols in what is called a "union" - where different sorts of things are stored in the same space.
Now the first lesson. The time and effort I put into writing the trace module and embedding trace statements in the code this has paid off just today. This part of the code runs like clockwork, and I've never looked at it for ages. It's like debugging someone else's code, not mine now. Without the debugging this problem would have taken
days to find.
Lesson two - you are not clever enough to use "fall-through" in C, even if you think you are. Even if it's one of the accepted reasons for doing it, and you comment it. It will
still bite you on the arse.
When I added the new function I increased the size of the table that holds function names, and this in turn changed the values of the operators by one. This meant that the largest operator now had a value of 100.
Would you believe it, but for the last two years Canalplan has been incapable of evaluating any expression that ended with a literal number between 94 and 99? Well it has. And at no time at all has anyone tried to do this. There aren't any of them, anywhere in the code. But there are several 100s.
Lesson three - nobody ever tests their code enough.
And on that cheery note, I'm off to work.