Small offset in date() time and console time?

Hello

Working with timers, and I’m experiencing a small offset between the date() generated time and the time logged in the console:

2015-02-16 11:38:20 UTC+1 [Agent] { "min": 38, "hour": 10, "yday": 46, "year": 2015, "wday": 1, "time": 1424083096, "sec": 16, "month": 1, "usec": 0, "day": 16 }

As you can see in this log, the date() object have 16 secs, but the console log timestamp says 20 secs (4 secs difference). The offset is not static. Is there a way to programatically deal with this offset? I can see that the imp acts on the time given in the console timestamp, but I can only compute info from the date() object. Mostly curiosity.

Best, bobby

Interesting, not seen that before. Can you include the code that’s printing this? Is it actually the agent reading and printing it, or is this a date sent from the imp to the agent that’s then being printed?

I did a little testing - see below.

Agent code:
`device.on(“print”, function (table) {

server.log("Agent secs (when sent from device): " + date().sec);
server.log("Time sent from device: " + http.jsonencode(table));

});`

Device code:
server.log("Device secs: " + date().sec); agent.send("print", date());

From boot
Feedback 1:
2015-02-17 10:12:14 UTC+1 [Agent] Agent secs (when sent from device): 14 2015-02-17 10:12:14 UTC+1 [Agent] Time sent from device: { "min": 12, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164330, "sec": 10, "month": 1, "usec": 0, "day": 17 } 2015-02-17 10:12:14 UTC+1 [Device] Device secs: 10

Feedback 2:
2015-02-17 10:16:18 UTC+1 [Agent] Agent secs (when sent from device): 18 2015-02-17 10:16:18 UTC+1 [Agent] Time sent from device: { "min": 16, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164577, "sec": 17, "month": 1, "usec": 0, "day": 17 } 2015-02-17 10:16:18 UTC+1 [Device] Device secs: 17

Feedback 3:
2015-02-17 10:17:36 UTC+1 [Agent] Agent secs (when sent from device): 36 2015-02-17 10:17:36 UTC+1 [Agent] Time sent from device: { "min": 17, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164656, "sec": 36, "month": 1, "usec": 0, "day": 17 } 2015-02-17 10:17:36 UTC+1 [Device] Device secs: 36

Feedback 4:
2015-02-17 10:18:36 UTC+1 [Agent] Agent secs (when sent from device): 36 2015-02-17 10:18:36 UTC+1 [Agent] Time sent from device: { "min": 18, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164715, "sec": 35, "month": 1, "usec": 0, "day": 17 } 2015-02-17 10:18:36 UTC+1 [Device] Device secs: 35

From http request (device running)
Feedback 1:
2015-02-17 10:20:31 UTC+1 [Agent] Agent secs (when sent from device): 31 2015-02-17 10:20:31 UTC+1 [Agent] Time sent from device: { "min": 20, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164826, "sec": 26, "month": 1, "usec": 0, "day": 17 } 2015-02-17 10:20:31 UTC+1 [Device] Device secs: 26

Feedback 2:
2015-02-17 10:21:22 UTC+1 [Device] Device secs: 19 2015-02-17 10:21:22 UTC+1 [Agent] Agent secs (when sent from device): 22 2015-02-17 10:21:22 UTC+1 [Agent] Time sent from device: { "min": 21, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164879, "sec": 19, "month": 1, "usec": 0, "day": 17 }

Feedback 3:
2015-02-17 10:22:07 UTC+1 [Device] Device secs: 3 2015-02-17 10:22:07 UTC+1 [Agent] Agent secs (when sent from device): 7 2015-02-17 10:22:07 UTC+1 [Agent] Time sent from device: { "min": 22, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164923, "sec": 3, "month": 1, "usec": 0, "day": 17 }

Feedback 4:
2015-02-17 10:22:27 UTC+1 [Device] Device secs: 24 2015-02-17 10:22:28 UTC+1 [Agent] Agent secs (when sent from device): 28 2015-02-17 10:22:28 UTC+1 [Agent] Time sent from device: { "min": 22, "hour": 9, "yday": 47, "year": 2015, "wday": 2, "time": 1424164944, "sec": 24, "month": 1, "usec": 0, "day": 17 }

I’m not really sure what to conclude on this. But overall it seems like the device is running a little before the agent - but then again, not at a fixed difference. Also the difference seems to be smaller when doing the test at boot (about 1 sec), and greater when device is running and sending a http request (3-4 secs).

I also tried this with a completely clean model (the above test ran in a setup function in a larger program), but seems to be the “exact” same thing.

Clean model code

Agent:
`function requestHandler(request, response) {

device.send(“time”, true);
response.send(200, “OK”);

}

http.onrequest(requestHandler);

device.on(“print”, function(data) {

server.log("Agent secs (when sent from device): " + date().sec);
server.log("Time sent from agent: " + http.jsonencode(data));

});`

Device:
`function start() {

server.log(date().sec);
agent.send("print", date());

}

start();

agent.on(“time”, function(x) {

server.log(date().sec);
agent.send("print", date());

});`

Hmm. I can’t replicate this at all (I mean, I usually get the same time to the second, sometimes it’s 1 second behind as obviously there is going to be some delay with sending it and printing it on the agent side).

The only thing I can think that would cause this delay would be the agent being busy when the request was sent - eg if the http handler was doing something more meaty that caused it to be busy for some number of seconds, then though the device would have sent the time back to the agent almost immediately, the device.on() handler wouldn’t fire until the http handler had exited.