Requesting variables reliably - how?

[hek]

I'll do some reading and see if I can come up with something

:thumbsup:

[mfalkvidd]

@martinhjelmare said:

Why does it take 3-4 secs to get a response from Domoticz? That sounds very slow to me.

A timeout for reading from the serial port shouldn't need to be longer than 1 second, in my opinion.

I have no idea. The Domoticz log file does not log variable requests and responses. The PiSerialGateway does not log time stamps. So troubleshooting is a bit hard. But the delay is quite consistent, 3-4 seconds. Once it took 7 seconds.

[mfalkvidd]

@mfalkvidd said:

@martinhjelmare said:

Why does it take 3-4 secs to get a response from Domoticz? That sounds very slow to me.

A timeout for reading from the serial port shouldn't need to be longer than 1 second, in my opinion.

I have no idea. The Domoticz log file does not log variable requests and responses. The PiSerialGateway does not log time stamps. So troubleshooting is a bit hard. But the delay is quite consistent, 3-4 seconds. Once it took 7 seconds.

I managed to get timestamps from the gateway:

22:03:53.597931 read: 10-10-0 s=255,c=0,t=17,pt=0,l=3:1.5
22:03:54.099184 read: 10-10-0 s=255,c=3,t=6,pt=1,l=1:0
22:03:54.636821 send: 0-0-10-10 s=255,c=3,t=6,pt=0,l=2,st=fail:M
22:03:54.637514
22:03:54.638318 read: 10-10-0 s=255,c=3,t=11,pt=0,l=20:Plant moisture w bat
22:03:55.141040 read: 10-10-0 s=255,c=3,t=12,pt=0,l=3:1.6
22:03:55.643784 read: 10-10-0 s=1,c=0,t=23,pt=0,l=0:
22:03:56.145626 read: 10-10-0 s=2,c=0,t=36,pt=0,l=0:
22:03:56.648191 read: 10-10-0 s=2,c=2,t=47,pt=0,l=0:
22:03:56.651149 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=0,st=ok:
22:03:56.655084 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=3,st=ok:30
22:03:56.655757
22:03:56.656460 read: 10-10-0 s=2,c=1,t=47,pt=2,l=2:30
22:03:58.159151 read: 10-10-0 s=0,c=1,t=1,pt=7,l=5:0.1
22:03:58.668016 read: 10-10-0 s=1,c=1,t=38,pt=7,l=5:3.441
22:03:59.169774 read: 10-10-0 s=255,c=3,t=0,pt=1,l=1:137

Serial log:

sensor started, id=10, parent=0, distance=1
send: 10-10-0-0 s=255,c=3,t=11,pt=0,l=20,sg=0,st=ok:Plant moisture w bat
send: 10-10-0-0 s=255,c=3,t=12,pt=0,l=3,sg=0,st=ok:1.6
Present battery
send: 10-10-0-0 s=1,c=0,t=23,pt=0,l=0,sg=0,st=ok:
Present moisture
send: 10-10-0-0 s=0,c=0,t=7,pt=0,l=0,sg=0,st=fail:
read: 0-0-10 s=255,c=3,t=6,pt=0,l=2,sg=0:M


Present sleep time
send: 10-10-0-0 s=2,c=0,t=36,pt=0,l=0,sg=0,st=ok:
Ask for sleep time, time is 3651
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
3727
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=fail:
3905
send: 10-10-0-0 s=2,c=2,t=47,pt=0,l=0,sg=0,st=ok:
read: 0-0-10 s=2,c=2,t=47,pt=0,l=0,sg=0:
Incoming message, time is 7024
2
47
0
Done waiting for sleep time, time is 7026
Send default sleep time
send: 10-10-0-0 s=2,c=1,t=47,pt=2,l=2,sg=0,st=ok:30
send: 10-10-0-0 s=0,c=1,t=1,pt=7,l=5,sg=0,st=ok:0.1
send: 10-10-0-0 s=1,c=1,t=38,pt=7,l=5,sg=0,st=ok:3.441
send: 10-10-0-0 s=255,c=3,t=0,pt=1,l=1,sg=0,st=ok:137

[mfalkvidd]

I forked the general discussion about reliable delivery, so we can use that thread to continue the discussion. Sorry for the inconvenience.

[mfalkvidd]

I have analyzed the log posted above and two things stand out:

1. When I request an ack, incomingMessage is called with a message length of 0. That seems strange to me. @hek do you have any insight to why this happens? Do all sketches need to handle empty messages due to ACKs as a special case in the implementation of incomingMessage? Sorry if this has already been changed in the development branch, I haven't been able to set up a working environment for that branch yet.
2. As can be seen in the serial log

Ask for sleep time, time is 3651
Incoming message, time is 7024

it takes 7.026-3.651=3.375 seconds from the request is sent until incomingMessage is called. But as can be seen in the gateway log

22:03:56.648191 read: 10-10-0 s=2,c=2,t=47,pt=0,l=0:                 # This is the request from the sensor
22:03:56.651149 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=0,st=ok:         # This is the ACK being sent to the sensor
22:03:56.655084 send: 0-0-10-10 s=2,c=2,t=47,pt=0,l=3,st=ok:30       # This is the reply being sent to the sensor - Domoticz must be blazingly fast!

both the ack and the reply are sent from the gateway almost immediately when the request is received (within 7 milliseconds). Does anyone have ideas why it takes more than three seconds before incomingMessage is called? My sketch does gw.wait almost all the time so the delay between the sensor's radio receives the message and the call to incomingMessage should be small.

[hek]

It was you, who added ack-flag to the request function. ;) Not sure I see the point in that. But generally the ack payload is identical to the message being send. And in this case, REQuest always sends an empty payload.

3 seconds sounds live an awful long time. I have no immediate explanation. I mean, it's directly communicating with the sensor.

[mfalkvidd]

@hek True :blush: Of course things become strange when I make random changes to the library. In a way I guess it makes sense to wait for the reply to the request instead of requesting an ack on the request. If I don't get a reply within some timeout, I should send the request again. No need for ack. Then that's sorted out at least, thanks!

[Yveaux]

@mfalkvidd try sniffing the network. It might reveal things you didn't expect...

[mfalkvidd]

@Yveaux yes, this is a perfect excuse to try your sniffer. (adding the link if someone else reads this and doesn't know how to find it). I read your blog post with great interest a few months ago but haven't gotten around to trying it yet.

[martinhjelmare]

Shouldn't the controller respond with a set message to the req message? Now it's responding with a req, first with empty payload then with a payload. I don't think that makes sense.

Edit: The first response must be the ack right?