The Curious Incident of the Disappearing Item in Production-Time
Background
When our customer was moving to version 4.7.7, and installing it widely, a new and weird bug appeared.
Every now and again, all the POSs in one of the store servers gave “Item Not Found” for each scan, save the first one. There was no specific server, store, or time that could be blamed for this behavior. It happened in most stores, although it did not happen again in the same store.
To resolve it, you could use IIS-Reset, or Clear-Persistence, or a client restart, or all of the above, or none. No apparent pattern could be found in the reason for the bug or the method to resolve it. Actually, it looked like it resolved itself after some time…
Working the Bug
The information we did have was system logs that included an “ItemDataCartridge is NULL” log line for every incident, but nothing else.
To solve the problem, I worked my way very carefully through the code, noting every situation that might cause this specific behavior — namely, producing ONLY the mentioned log, and returning the “ItemNotOnFile” ResultCode.
After a while, I found an “IsValid” property on the PID (PosItemData) that was called each time this object was retrieved from the items cache list. Because it was called even when it should not have been, it was evident that if it returned false each time, the resulting behavior would be the same as the bug.
I looked into this “IsValid” implementation, and this is (more or less) what I saw:
get { ... return expired > System.Environment.TickCount; }
So I looked into the place where “expired” is set, and saw:
expired = System.Environment.TickCount + ActiveTimeout;
Looks suspicious? I thought so.
“TickCount,” as far as I remembered, is an Int32. Int32 has a max value that, when you add a positive int to it, becomes negative. When that happens, “IsValid” will always return false, and Bob’s your uncle!
So what I did now — and pay close attention, because this is the whole trick — is I placed the cursor (a.k.a. the “caret,” which is the little “
” cursor) between the “System.Environment.Tic” and the “kCount,” and pressed F1. And for those of you that do not have a working help file, here is the relevant quote:
“A 32-bit signed integer containing the amount of time in milliseconds that has passed since the last time the computer was started. …TickCount will increment from zero to Int32.MaxValue for approximately 24.9 days, then jump to Int32.MinValue, which is a negative number…”
The Conclusion
The bug was this:
1) ActiveTimeout is an Int32 that equals 24 minutes in milliseconds (1,440,000).
2) The “expiration” field is calculated, for every lookup in the transaction after the first one (for reasons I won’t get into right now), as the current TickCount + ActiveTimeout.
3) For this reason, when a POS server runs for 24 days, 21 hours, and 30 minutes (approximately), adding these 24 minutes to the TickCount value — now very close to Int32.MaxValue — will ALWAYS result in a negative value.
4) And because, as mentioned before, this calculation is always evaluated (even when the lookup is done through the database), it will always return false, and the lookup will always fail.
The grand-total effect is: in each store, one of the POS servers stops selling after 24.9 days, for 24 minutes.
And one final thing I’d like to point out: the programmer who originally wrote this feature declared the “expired” variable as a long. This is interesting, because if the calculation had been done in the scope of an int64, this problem would never have occurred. Unfortunately, the actual participants in the calculation were all int32-typed, which means that no matter what type of variable is used to hold the result, the math is done in an Int32 scope.
P.S. This was fixed, basically, by replacing “TickCount” with “DateTime.” This type also has a “MaxValue,” but Microsoft operating systems do not support it. We might have a problem moving to Linux, though…