Two variables return the same value (periodically)

From time to time I see the same value gets returned from two variables. For example, I have two tmp36 hooked up, one inside and one outside, both return expected values normally, but this morning at 0559 BST they both returned the same value:

“{u’coreInfo’: {u’last_handshake_at’: u’2014-06-18T19:38:41.148Z’, u’connected’: True}, u’cmd’: u’VarReturn’, u’name’: u’in_temp’, u’result’: 809}”

“{u’coreInfo’: {u’last_handshake_at’: u’2014-06-18T19:38:41.148Z’, u’connected’: True}, u’cmd’: u’VarReturn’, u’name’: u’out_temp’, u’result’: 809}”

The previous values were consistent, at 0554 BST:

“{u’coreInfo’: {u’last_handshake_at’: u’2014-06-18T19:38:41.148Z’, u’connected’: True}, u’cmd’: u’VarReturn’, u’name’: u’in_temp’, u’result’: 810}”

“{u’coreInfo’: {u’last_handshake_at’: u’2014-06-18T19:38:41.148Z’, u’connected’: True}, u’cmd’: u’VarReturn’, u’name’: u’out_temp’, u’result’: 739}”

The subsequent values are consistent as well, at 0604 BST:

“{u’coreInfo’: {u’last_handshake_at’: u’2014-06-18T19:38:41.148Z’, u’connected’: True}, u’cmd’: u’VarReturn’, u’name’: u’in_temp’, u’result’: 809}”

“{u’coreInfo’: {u’last_handshake_at’: u’2014-06-18T19:38:41.148Z’, u’connected’: True}, u’cmd’: u’VarReturn’, u’name’: u’out_temp’, u’result’: 747}”

In the graph the blue line is “in_temp” and the black line is “out_temp”. I see this problem maybe once a day, and its not always the same variables.

I initialise the variable

int in_temp = 0;
int out_temp = 0;

In setup() I have:

  Spark.variable("in_temp", &in_temp, INT);
  Spark.variable("out_temp", &out_temp, INT);

and in main() I have:

  in_temp = analogRead(A7);
  out_temp = analogRead(A6);

I have nothing else which touches these variables.

I thought initially my sensors were reporting badly, but then I noticed that each time I had a spike two of variables I was recording had the same value, so then i thought my code which logs the data was causing the issue, so I started logging the results from the API to compare against what I had in my database. Have I stumbled across a bug in the API or the spark firmware, is there a way to look historically at what values my sparkcore is reporting, should I hook up a serial line to the sparkcore and record the values?

I would datalog on a microsd out Serial printout to my machine and verify.

Seems like we might have something interesting going on here :wink:

Ooh, cool! I know there used to be an issue where analogreads close to eachother could cause what feels like 'interference'.

If you also published your variable values with a spark.publish, then your messages would follow a different path in the cloud than spark.variable, and that would also help distinguish if this is a cloud problem, or a core problem. :slight_smile:

Thanks,
David

1 Like

@Dave would reflashing my code help if there have been new firmware releases? Its not been reflashed in a maybe 2 weeks. I’ll also setup some serial output logging and also spark.publish my variables and record them well.

Hi @pfarmer,

It might help! Just make sure you add a space or something to your code to force it to re-compile before flashing. :slight_smile:

Thanks,
David

OK, so some more data, I attached my sparkcore via USB to a laptop and added some serial debugging to my code.

At 01:25 I saw a spike on an analog input, as shown in the image:

The responses I got from the API were (first the spike):

{u'last_handshake_at': u'2014-06-20T21:06:45.486Z', u'connected': True}, u'cmd': u'VarReturn', 'name': u'photocell', u'result': 790}

and then the response it matches:

{u'coreInfo': {u'last_handshake_at': u'2014-06-20T21:06:45.486Z', u'connected': True}, u'cmd': u'VarReturn', u'name': u'out_temp', u'result': 790}

The serial data from around the time, the second column is “out_temp” and the forth column is “photocell” (not including the date time column)

2014-06-22T01:25:26.324212 867, 788, 115, 3, 2
2014-06-22T01:25:26.828319 867, 788, 118, 2, 12
2014-06-22T01:25:27.338241 867, 789, 122, 3, 1
2014-06-22T01:25:27.842144 871, 790, 124, 6, 2
2014-06-22T01:25:28.370326 868, 789, 118, 4, 1
2014-06-22T01:25:28.874326 867, 790, 125, 3, 0
2014-06-22T01:25:29.378326 867, 789, 122, 2, 1
2014-06-22T01:25:29.882325 870, 792, 114, 4, 1
2014-06-22T01:25:30.416093 868, 789, 116, 2, 1
2014-06-22T01:25:30.914366 867, 790, 117, 2, 1
2014-06-22T01:25:31.418343 868, 788, 123, 2, 0
2014-06-22T01:25:31.928195 872, 791, 124, 4, 12

Having checked my data for the photocell it never goes above about 250. I did also setup a publish on each of my variables, but for some reason the data only got published once, when the spark was reflashed, and then no new values got published.

Hi @pfarmer,

Yay for bugs! :slight_smile: Any chance you can share your test code so I can try to reproduce it here?

The Spark.publish is rate limited to 60 per minute, at a burst of up to 4 per second. If your rate goes past that it will be throttled slightly.

Thanks!
David

Ok, so on Saturday I added a delay(500); between each analogread, cycle time for main is now about 2.5 seconds.

On Sunday morning I saw another anomaly on an analog reading (in this instance the photocell variable).

{u'coreInfo': {u'last_handshake_at': u'2014-06-27T10:30:33.285Z', u'connected': True}, u'cmd': u'VarReturn', u'name': u'photocell', u'result': 769}

The photocell reading should have been between about 189 - 193, but instead got the same value as “out_temp” which was correct for the time.

{u'coreInfo': {u'last_handshake_at': u'2014-06-27T10:30:33.285Z', u'connected': True}, u'cmd': u'VarReturn', u'name': u'out_temp', u'result': 769}

The serial output from the core around the time was:

2014-06-29T05:58:07.398580 811, 770, 577, 191, 2956
2014-06-29T05:58:09.930599 810, 769, 565, 191, 2954   
2014-06-29T05:58:12.462310 811, 769, 574, 191, 2954
2014-06-29T05:58:14.989912 812, 770, 578, 192, 2953
2014-06-29T05:58:17.520775 811, 770, 571, 191, 2950
2014-06-29T05:58:20.053979 811, 770, 568, 191, 2951
2014-06-29T05:58:22.585975 810, 770, 568, 191, 2950

The reading appears to have come from one of these analogreads:

2014-06-29T05:58:09.930599 810, 769, 565, 191, 2954   
2014-06-29T05:58:12.462310 811, 769, 574, 191, 2954 

@Dave is it possible to trace what exactly my core is sending to the cloud?

Thanks,

Peter

Hi @pfarmer,

Thanks for the follow-up! So the delay between reads rules out ADC issues, and I’m guessing your circuit is good, so that leaves protocol / cloud issues potentially.

Hmmm… Can you give me an idea of what kind of latency, and what kind of frequency you’re using when you’re polling the values from the API? I’m guessing something like 4-5 variables every 1-2 seconds, with 125-500ms lag, does that sound right? It’ll help me setup a test harness to try and reproduce this in isolation.

The CoAP protocol allows for lots of simultaneous requests open to your core, but it’s possible something could be overflowing if you were say asking for all of them tens of times a second via the cloud.

Thanks!
David

Boom, reproduced on my end! Yes!

Edit: Okay, awesome. I was able to reproduce this, meaning I will be able to identify / fix the issue. Thank you for reporting it, and I’ll work on it this week and report back. :slight_smile:

Thanks,
David

3 Likes

Well done! Pleased I reported the issue now!

My requests are every 5 minutes, and no more than perhaps 2 in parallel, I suspect you found the issue so quickly by making a massive amount of queries in the short space in time?

Edit: latency on a complete requests is between 0.8 and 1.5 seconds.

Thanks for the effort!

Peter

2 Likes

Just FYI, we were discussing this today. I just added an issue for those who want to track:

1 Like