Unexpected device-agent communication patterns

Agent Code
1

Unexpected device-agent communication patterns:
I have received some unexpected device-agent communication, and I am wondering if anyone can explain what’s going on. In the following code, the device posts a message to server.log, then sends data to the agent, and loops every five seconds. The agent receives the data, and also posts a message to server.log. What’s unexpected is that sometimes (but not all the time), the agent message is posted in server.log before the device message. Why would that be, and what can I do to make sure the server.log messages from the device and agent are posted in chronological order? Thanks for any comments.

Here is the device code, the agent code, and server.log (note the second set of messages are out of order) :
Device Code:
function loop() {
server.log(“This is the device”)
agent.send(“data”,“unused”)
imp.wakeup(5.0,loop)
}
loop()

Agent Code:
function receivedata(unused) {
server.log(“This is the Agent”); server.log(" ")
}
device.on(“data”,receivedata)
Server.log:
2015-12-06 16:24:49 UTC-6 [Device] This is the device
2015-12-06 16:24:49 UTC-6 [Agent] This is the Agent
2015-12-06 16:24:49 UTC-6 [Agent]
2015-12-06 16:24:54 UTC-6 [Agent] This is the Agent
2015-12-06 16:24:54 UTC-6 [Agent]
2015-12-06 16:24:54 UTC-6 [Device] This is the device
2015-12-06 16:24:59 UTC-6 [Device] This is the device
2015-12-06 16:24:59 UTC-6 [Agent] This is the Agent
2015-12-06 16:24:59 UTC-6 [Agent]

2

Welcome to the vagaries of the Internet. Remember that the Agent and Device are executing in completely different places. server.log("This is the device’) is certainly being executed before the agent receives the message, but buffering and propagation delays can lead to stuff appearing to happen out of order.

If you really want the stuff to be in order, don’t use server.log in the Device. Send the message with agent.send() and use agent code to post the message with server.log.

3

And you’ll see that the groups of messages are presented in the same time window, eg. 16:24:54. There’s probably just milliseconds between the postings of the three messages.

Logs get fired off and pass through several entities before they appear in your IDE’s log window, and the (tiny) lag you’re seeing is am inevitable result of that. Like @coverdriven says, the best way around this is to relay device-posted logs via the agent, then you have a single dispatch queue and route to the logging server.

4

Thanks coverdriven and smittytone for your comments. I hadn’t realized that propagation delays would make that much difference. A single dispatch queue makes sense to me. Thanks again.