3
\$\begingroup\$

I will come to a question further down, but first a little background

We are struggling with reproducing a nasty bug that we have been getting reports for.

The symptoms clearly show that the RTC (a DS1305) is skipping from November 30 to April 1, the same year (e.g. backwards).

We have received enough reports as to not being able to write it off as a hardware fault or solar flare or other unlikely one-time-error. However all attempts at reproducing this behavior in-house have failed. Even with the exact same hardware and settings as was used by our customer when the error did occur.

Since it doesn't always happen, nor for all devices, it doesn't feel like a software bug. At least not acting on it's own.

Question

Any ideas for how to go about reproducing this kind of behavior, fault-finding methods, what to look for, etc.

Any one else have any experience with this kind of error?

We are aware of one other with a very similar symptom, however unclear if this is related at all.

I know there is a lot of details missing. I can't disclose any source, and simply stating everything I know will be a little to much to type; I can fill you in if you post concrete questions.

Update

Finally! We have been able to reproduce this erratic behaviour in the lab!

Pressed for time as we are, all our attempts at reproducing was started one or a few days prior to 30/11 to see how it went, and all passed over to 1/12 just fine. It was after that we noticed that all customer devices were started during october.

We can't really work with waiting over a month for reproducing, so we came up with a work-around that to my surprise actually seems to work.

By speeding up the clock!

We have replaced the standard 32.768kHz osc with a 1Mhz signal, and can now reproduce in about a day.

I'll keep you posted as to what we will discover about this.

Thank you all for excellent brainstorming. I appreciate it a lot.

Now, I'm off trying to further trim the reproduction time, and dig out more facts about it.

Solved

I have posted the root cause of this as the accepted answer.

Summary: month value used was not a valid BCD value.

Improve this question
\$\endgroup\$
14
  • 4
    \$\begingroup\$ I do find it odd/interesting that these are sorta binary inverses of each other. 11->1011, 4->0100 and 30->11110, 1->00001. \$\endgroup\$ – Kellenjb Mar 5 '12 at 16:18
  • \$\begingroup\$ @Kellenjb wow that's a keen observation \$\endgroup\$ – vicatcu Mar 5 '12 at 16:23
  • 1
    \$\begingroup\$ @kaos I know it is given to you in that format, but I could see internally to the rtc it being stored differently. My other thought was if you convert it in your own code. \$\endgroup\$ – Kellenjb Mar 6 '12 at 12:37
  • 1
    \$\begingroup\$ @Kaos I'm just trying to brainstorm for ideas, and I have found odd things like that are more often then not an area to look into. I wouldn't put it past a firmware bug either, there is always the chance that your firmware hits some rare case that is hard to reproduce in the lab. Given, I know nothing about your code so I have no idea how deterministic it is. \$\endgroup\$ – Kellenjb Mar 6 '12 at 13:46
  • 1
    \$\begingroup\$ Is there any control signal that could be floating, including during powersaving mode? Ie picking up stray capacitance and turning it into a set command. \$\endgroup\$ – pjc50 Mar 6 '12 at 13:57
4
\$\begingroup\$

Ok, the original question asked for methods, not the root cause, which I'll give here.

But I don't like to leave the question unanswered. No disrespect to all fine suggestions that I've received. Thanks to everyone who've contributed to us finally being able to resolve this.

It all went a lot better after we realized that the issue was related to setting the time in october, rather than some obscure bug going into december.

The culprit was a bug in the INT to BCD encoding of the month value, where the original author mistakenly added 1 to the BCD encoded value, rather to the INT value before encoding it; resulting in october being sent to the RTC as 0x0A, rather than 0x10.

The clock happily steps from 0x0A to 0x0B when going into november, and the BCD to INT routine wasn't too picky about getting invalid BCD values. It still got the 0x0B right (BCD 0x0B to INT = 0x0B, however 0x0B is not a valid BCD value...).

I have not yet confirmed how we ended up in april, that is still on my TODO for this.

I am rather confident however that I am finally on to the real root cause of this issue.

@Kellenjb: and you were right, too: it was a firmware bug :)

Update

OK, I have now confirmed that when the DS1305 goes from the invalid 0x0A month value (October) it ends up with 0x0B for November. With a naive implementation of BCD to INT (one that doesn't check the BCD input for validity), BCD 0x0B == INT 0x0B, so it still works.

It is when the DS1305 is to increment 0x0B (in seeing 0x0A go to 0x0B, one could expect 0x0C, but no) it ends up with 0x04 when going into December.

Mystery solved.
Improve this answer
\$\endgroup\$
3
  • \$\begingroup\$ Yet another reason to hate BCD clock chips. Now that you mention it, I suppose such behavior shouldn't be terribly unexpected. Except for the 12->1 transition, the upper bits of the month will only change when the LSB is set. Further, for any "legitimate" transitions, any time bit 2 changes, it will be to the state opposite bit 3. \$\endgroup\$ – supercat Mar 12 '12 at 18:24
  • \$\begingroup\$ Yeah, I'm sure that if we were to implement some BCD counting logic, that adding one to 0x0B would not end up with 0x0C. Our main issue with finding this was that we looked too hard at the November->December border, without having the baggage of coming from October (where the issue was introduced, in our case). \$\endgroup\$ – Kaos Mar 13 '12 at 8:40
  • \$\begingroup\$ There are lots of ways of doing BCD logic; the month isn't really BCD logic, though, since there are 12 valid states. I find it curious, actually, that the month seems to be stored as five bits, rather than being converted from 5 to 4 when written and from 4 to 5 when read. Though of course if I were designing a BCD chip I'd simply output a straight 48-bit count of the number of half-cycles (i.e. 65,536 ticks/second), and probably include a 32-bit alarm register with a latching equality comparator. I don't know why cheap RTC's aren't designed that way. Simpler and more useful than BCD. \$\endgroup\$ – supercat Mar 13 '12 at 14:38
1
\$\begingroup\$

  • If you have a debugger that is capable of stopping when there is a memory access to a particular address, it may be a good idea to set that and see if there is a rouge, unintended access. You may have to leave the system on for a while though. I have had pleasure of dealing with stack frames just a tad above their limit causing nerve racking problems.

  • If you don't have the one above, you can put an SPI analyzer (logic analyzer) and capture the traffic for sometime, this will give you a very good clue what may be going on.

  • I would also try to push a power spike that passes 5V and below 2.5V (Rated operating condition) and see if the problem is coming back.

  • I would look at the problem on the other side, i.e CPU, perhaps, their SPI has a problem, search for SPI issues with the particular processor you have. It is almost always least place you expect.

Improve this answer
\$\endgroup\$
4
  • \$\begingroup\$ Thanks. I like your thinking. Altough I rarely find bugs in CPU's or other third party devices. However strange a bug may seem, in my experience they are almost always caused by the person attached to your own hands.. :) \$\endgroup\$ – Kaos Mar 6 '12 at 12:45
  • \$\begingroup\$ I don't have access to a real logic analyzer, as such. What I've used is a oscilloscope with some decoding functionality to help decode the communication, but it has limited memory, so can only capture less than a second. This will be most useful once we can get the bug to manifest upon command. \$\endgroup\$ – Kaos Mar 6 '12 at 12:49
  • \$\begingroup\$ I'll look at spiking the system. But, we've seen this on completeley unrelated devices, from different customers from different parts of the world. And they were not all using the same version of the software, nor the same batch of hardware. So, any unintentional stray spikes or other random events seem unlikely to me; given that they were all affected at the same time (from what we can tell; at least rather close in time). So, there seem to be some built in issue with going from 30/11 to 1/12, but only when some certain (set of) circumstance(s) are fulfilled. I DO welcome all ideas, though. \$\endgroup\$ – Kaos Mar 6 '12 at 12:53
  • \$\begingroup\$ @Kaos: When you look at it that way (rolling from 30/11 to 4/1 instead of 12/1) it starts to look like a single bit flip. For that to be the case, there would have to be binary -> BCD conversion of the months, and that conversion could introduce delay and skew between signals, allowing a transient read of April. \$\endgroup\$ – Ben Voigt Mar 7 '12 at 17:58
0
\$\begingroup\$

How is the code processing the time from the RTC? Is the 'slip-back' precisely nine months (such that the time of day is correct)? Do you have any idea when the last time the clock would have been polled prior to the slip-back and the first time it was polled after? What is the pattern for reading the date/time? Is it read as a single seven-byte transaction starting with register zero?

It seems curious that a system with BCD months would slip from either 0x11 or 0x12, to 0x04. I do know that some RTC chips could have some weird interactions between reads and register updates, though the DS chip claims to copy the time/date to static registers before a read. Some chips have an annoying quirk where a read that takes excessively long could cause the clock to lose time (my guess would be that rather that duplicating the upper bits, they simply defer increments while a read is in progress; if an increment is still deferred when the time comes for another, the latter increment will be missed) but I doubt anything like that could be happening here, unless the last read operation was in April, and the first faulty read in November.

Addendum

Is the code doing any data conversion on the time from the chip (i.e. does the code itself store time as YYYY-MM-DD HH:MM:SS format, or number of seconds since Midnight GMT January 1, 1970, or what?) How is daylight saving time handled? Under the old DST rules, if DST is handled by setting the RTC forward and backward (as is done on some systems, including PC's, but seems really silly) I could easily foresee potential problems if a device was powered off while DST was in effect and was powered on between 11:00pm and 11:59 on October 31 (which would be stored on the RTC as times between midnight and 12:59am on November 1). I could also imagine some weird corner cases when trying to convert YYYY-MM-DD HH:MM:SS to something like linear seconds when running code on an 8-bit CPU, if one tried to use an optimized mix of 16- and 32-bit math but didn't do things quite right, but the time slip would more likely be a power-of-two multiple of some kind of units, which doesn't seem to be the case here.

Improve this answer
\$\endgroup\$
11
  • \$\begingroup\$ I have only one device which has also logged a GPS timestamp. And from that we can see that the time has also slipped (about 25hrs and 15 minutes). So I guess that the time has slipped for the other devices as well, but I have no proof, either way. \$\endgroup\$ – Kaos Mar 6 '12 at 12:57
  • \$\begingroup\$ The data I have saves a timestamp with the data. And the clock is read a number of times during that logging, before going back to sleep. The last thing it does before going to sleep is to setup the alarm for when to wake up again. All interactions with the RTC device is done in batch read/write mode. When reading the clock, start at 0. When writing to alarm 0, start at 0x87. Before each read/write, the RTC's control register is written to, 0x8f = 0x06. When it wakes up again, it may be one of two things, the time has reached the alarm that was setup, or some acceleration has been detected... \$\endgroup\$ – Kaos Mar 6 '12 at 13:03
  • \$\begingroup\$ ... that exceeds some configured limits. When the clock skips back, the alarm case will not happen (for a very long time), so the next we see in the log is for acceleration. And that can be within the next day or so, up to weeks or even months. When logging the acc data, the RTC date/time is read again, and it is from this reading we can see that we got 1/4 or some date after that in the log, instead of the expected 1/12 . \$\endgroup\$ – Kaos Mar 6 '12 at 13:06
  • \$\begingroup\$ Thanks for the tip of a possible read quirk. We can get an interrupt while reading the bytes, causing a delay in midst of reading the clock. I'll see what I can make of that. \$\endgroup\$ – Kaos Mar 6 '12 at 13:11
  • \$\begingroup\$ @Kaos: The "read quirk" I was thinking of would require if I recall that the unit be in "read" mode for a more than a second continuously. Only a problem if the processor might go to sleep or get seriously waylaid during a read. Also, it sounds like you have recorded data within the last eight months, so you can see that the clock actually skipped back, rather than simply stopping for eight months? \$\endgroup\$ – supercat Mar 6 '12 at 16:28
0
\$\begingroup\$

This is stating the obvious, but have you checked the lot numbers of the ICs in the devices with problems to see if they come from different batches at the foundry from the boxes which don't exhibit the symptoms?

Also were all your ICs procured in the same shipment from the manufacturer or are some from different orders? Any correlation between orders and failures?

Do any of the ICs come from the "grey market"? Is there a possibility that you got a few counterfeit or questionable chips mixed in with the good ones?

Finally is there any correlation between the failing devices and your manufacturing process? Were all the failing devices made in the same week or all on Friday for example?

Improve this answer
\$\endgroup\$
1
  • \$\begingroup\$ We have seen this error from a range of production runs and device manufacturing batches. So far, the only common factor we have observed is that they were all started during october. So it seems that it has to run from october to november for the error to show when crossing over to december. \$\endgroup\$ – Kaos Mar 8 '12 at 10:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.