Possible Bug – Remote Stations – Special Station Auto-Refresh

[Robert]

I have an OpenSprinklerPi (reported as App version 2.2.0, Firmware 2.1.9 (4), Hardware OSPi) acting as master and a OpenSprinkler (reported as App version 2.2.0, Firmware 2.1.9 (4), Hardware 3.2 – AC) acting as the remote extender. I have turned on the “Special Station Auto-Refresh” option on the Pi. At first things appeared good, but then I noticed stations shutting off when they shouldn’t be. I thought perhaps there was a network issue, but checking I couldn’t find any network problems. I then proceeded to install tshark on the Pi to do packet captures. If I’m capturing from the Pi itself, packet loss can’t be an issue without it showing up in the capture.

The following is one of the captures pointing to a problem:
(Complete capture segment is listed at the end if you need it)

The starting line of interest is: 1049 4404.988509274 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=5&en=1&t=400 HTTP/1.0

Here we see it call and set station 5 on for 400 seconds. Timestap is 4404 – so around about 4804 if there hasn’t been another call, the station will shut off. We see on line 1050 that the remote responded with a 200 so it should have accepted the command (and I saw the web interface indicate the new time, so it worked).

The calls that followed after this were:
1060 4407.064225428 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=7&en=0&t=400 HTTP/1.0
1073 4599.990633680 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=0&en=0&t=400 HTTP/1.0
1084 4602.050993450 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=2&en=0&t=400 HTTP/1.0
1095 4604.161371216 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=4&en=0&t=400 HTTP/1.0
1106 4606.226640553 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=6&en=0&t=400 HTTP/1.0
1119 4800.096142681 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=0&en=0&t=400 HTTP/1.0
1126 4803.149174223 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=3&en=0&t=400 HTTP/1.0
1133 4806.346671803 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=6&en=0&t=400 HTTP/1.0

So we don’t see station 5 called again. The order here isn’t apparent to me, but we see stations 0 and 6 called twice, so one would think it had completed it’s group. It seems to start at 0 and call the evens, and then start at 0 and call the odds – though it never called 1 in that sequence for some reason. Given it never called 5 again before 400 seconds were up, station 5 eventually ran out of time and shut down.

We see that it’s calling with a time set when it’s disabling the station (I suppose that doesn’t matter), and it’s calling with the time of 400 which is apparently a calculation you’re using, though I’m not sure why (why not just call it with the actual time remaining? – that way if communication is lost, it still shuts off at the right time instead of going too short or too long). I would think calling with the correct time would solve a number of possible issues – it would also make the time show correctly on the remote unit for how long the station is actually supposed to be running for – as it is now, I have to refer to the master for the actual time.

Why the unit is failing to make the correct “refresh” call in time to prevent the station from shutting off is the key question though as far as I can tell. It should have, but simply didn’t. Number of stations involved here are 16. 1-8 are local and 9-16 are remote (0-7 sid values for the remote).

Now I don’t write C++, and I know little of libc and related things in general, but I think the applicable piece of code is this:

if(iopts[IOPT_SPE_AUTO_REFRESH]) {
// handle refresh of RF and remote stations
// we refresh the station whose index is the current time modulo MAX_NUM_STATIONS
static byte last_sid = 0;
byte sid = now() % MAX_NUM_STATIONS;
if (sid != last_sid) { // avoid refreshing the same station twice in a roll
last_sid = sid;
bid=sid>>3;
s=sid&0x07;
switch_special_station(sid, (station_bits[bid]>>s)&0x01);
}
(which is found in OpenSprinkler::apply_all_station_bits() in OpenSprinkler.cpp). I think the key here is “byte sid = now() % MAX_NUM_STATIONS;”. If I’m reading that right, you’re dividing the current time (probably in seconds) by the number of stations and taking the remainder to determine which station to call. This would seem to be based on the assumption that this section of code will be reached _AT LEAST_ once each second. If for some reason it took longer, that could explain the results I saw. Could you just carve out a variable to store the last station and roll through them in order maybe? If it’s not getting called each second (or sooner) then it’s going to end up being sort of random as to when each station is called with no guarantee that some will be called at all within the appropriate time.

Personally, I’d find it a very useful feature enhancement if it were to call with the correct time set as well rather than just the 400 it’s using.

Thoughts? Am I in the right place here or did I totally miss it?

Thanks!

Gene

1046 4404.984516869 192.168.113.253 → 192.168.113.252 TCP 74 32902 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2929933772 TSecr=0 WS=128
1047 4404.988191087 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32902 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1048 4404.988320570 192.168.113.253 → 192.168.113.252 TCP 54 32902 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1049 4404.988509274 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=5&en=1&t=400 HTTP/1.0
1050 4405.001608812 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1051 4405.001702200 192.168.113.253 → 192.168.113.252 TCP 54 32902 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1052 4405.006347228 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1053 4405.006392229 192.168.113.253 → 192.168.113.252 TCP 54 32902 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1054 4407.000436802 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32902 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1055 4407.000663632 192.168.113.253 → 192.168.113.252 TCP 54 32902 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1056 4407.002601707 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32902 [ACK] Seq=231 Ack=98 Win=2047 Len=0
1057 4407.047554801 192.168.113.253 → 192.168.113.252 TCP 74 32904 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2929935835 TSecr=0 WS=128
1058 4407.063891929 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32904 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1059 4407.064054329 192.168.113.253 → 192.168.113.252 TCP 54 32904 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1060 4407.064225428 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=7&en=0&t=400 HTTP/1.0
1061 4407.076967403 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1062 4407.077058343 192.168.113.253 → 192.168.113.252 TCP 54 32904 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1063 4407.084395998 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1064 4407.084446468 192.168.113.253 → 192.168.113.252 TCP 54 32904 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1065 4409.071965476 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32904 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1066 4409.072153762 192.168.113.253 → 192.168.113.252 TCP 54 32904 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1067 4409.077890070 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32904 [ACK] Seq=231 Ack=98 Win=2047 Len=0
1068 4599.956499577 192.168.113.253 → 192.168.113.252 TCP 74 32906 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930128739 TSecr=0 WS=128
1069 4599.958697745 48:3f:da:5f:64:55 → Broadcast ARP 60 Who has 192.168.113.253? Tell 192.168.113.252
1070 4599.958758059 Raspberr_ea:d6:99 → 48:3f:da:5f:64:55 ARP 42 192.168.113.253 is at b8:27:eb:ea:d6:99
1071 4599.990308882 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32906 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1072 4599.990447426 192.168.113.253 → 192.168.113.252 TCP 54 32906 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1073 4599.990633680 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=0&en=0&t=400 HTTP/1.0
1074 4599.998079294 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1075 4599.998170285 192.168.113.253 → 192.168.113.252 TCP 54 32906 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1076 4600.002896471 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1077 4600.002937357 192.168.113.253 → 192.168.113.252 TCP 54 32906 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1078 4601.998578526 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32906 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1079 4601.998792749 192.168.113.253 → 192.168.113.252 TCP 54 32906 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1080 4602.003471642 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32906 [ACK] Seq=231 Ack=98 Win=2047 Len=0
1081 4602.045936008 192.168.113.253 → 192.168.113.252 TCP 74 32908 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930130828 TSecr=0 WS=128
1082 4602.050687454 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32908 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1083 4602.050816311 192.168.113.253 → 192.168.113.252 TCP 54 32908 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1084 4602.050993450 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=2&en=0&t=400 HTTP/1.0
1085 4602.058156193 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1086 4602.058253747 192.168.113.253 → 192.168.113.252 TCP 54 32908 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1087 4602.061164845 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1088 4602.061208596 192.168.113.253 → 192.168.113.252 TCP 54 32908 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1089 4604.058230681 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32908 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1090 4604.058425528 192.168.113.253 → 192.168.113.252 TCP 54 32908 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1091 4604.064916018 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32908 [ACK] Seq=231 Ack=98 Win=2047 Len=0
1092 4604.156179970 192.168.113.253 → 192.168.113.252 TCP 74 32910 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930132939 TSecr=0 WS=128
1093 4604.161059648 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32910 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1094 4604.161185119 192.168.113.253 → 192.168.113.252 TCP 54 32910 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1095 4604.161371216 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=4&en=0&t=400 HTTP/1.0
1096 4604.172452837 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1097 4604.172543984 192.168.113.253 → 192.168.113.252 TCP 54 32910 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1098 4604.174852466 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1099 4604.174904759 192.168.113.253 → 192.168.113.252 TCP 54 32910 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1100 4606.170485097 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32910 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1101 4606.170755467 192.168.113.253 → 192.168.113.252 TCP 54 32910 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1102 4606.173232233 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32910 [ACK] Seq=231 Ack=98 Win=2047 Len=0
1103 4606.217722621 192.168.113.253 → 192.168.113.252 TCP 74 32912 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930135000 TSecr=0 WS=128
1104 4606.226317005 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32912 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1105 4606.226456070 192.168.113.253 → 192.168.113.252 TCP 54 32912 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1106 4606.226640553 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=6&en=0&t=400 HTTP/1.0
1107 4606.237980251 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1108 4606.238065044 192.168.113.253 → 192.168.113.252 TCP 54 32912 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1109 4606.247337983 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1110 4606.247385640 192.168.113.253 → 192.168.113.252 TCP 54 32912 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1111 4608.238903872 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32912 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1112 4608.239128616 192.168.113.253 → 192.168.113.252 TCP 54 32912 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1113 4608.241019017 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32912 [ACK] Seq=231 Ack=98 Win=2047 Len=0
1114 4672.491802088 48:3f:da:5f:64:55 → Broadcast ARP 60 Who has 192.168.113.1? Tell 192.168.113.252
1115 4672.492099541 48:3f:da:5f:64:55 → Broadcast ARP 60 Who has 192.168.113.1? Tell 192.168.113.252
1116 4799.988105465 192.168.113.253 → 192.168.113.252 TCP 74 32914 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930328767 TSecr=0 WS=128
1117 4800.095792364 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32914 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1118 4800.095951168 192.168.113.253 → 192.168.113.252 TCP 54 32914 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1119 4800.096142681 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=0&en=0&t=400 HTTP/1.0
1120 4800.208909595 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32914 [ACK] Seq=1 Ack=97 Win=2048 Len=0
1121 4803.099351534 192.168.113.253 → 192.168.113.252 TCP 54 32914 → 80 [FIN, ACK] Seq=97 Ack=1 Win=29200 Len=0
1122 4803.101454218 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32914 [RST, ACK] Seq=1 Ack=98 Win=24584 Len=0
1123 4803.146152204 192.168.113.253 → 192.168.113.252 TCP 74 32916 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930331925 TSecr=0 WS=128
1124 4803.148854427 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32916 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1125 4803.148992763 192.168.113.253 → 192.168.113.252 TCP 54 32916 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1126 4803.149174223 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=3&en=0&t=400 HTTP/1.0
1127 4803.209157255 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32916 [ACK] Seq=1 Ack=97 Win=2048 Len=0
1128 4806.152380033 192.168.113.253 → 192.168.113.252 TCP 54 32916 → 80 [FIN, ACK] Seq=97 Ack=1 Win=29200 Len=0
1129 4806.240925310 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32916 [RST, ACK] Seq=1 Ack=98 Win=24584 Len=0
1130 4806.250792107 192.168.113.253 → 192.168.113.252 TCP 74 32918 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=2930335030 TSecr=0 WS=128
1131 4806.346323986 192.168.113.252 → 192.168.113.253 TCP 62 80 → 32918 [SYN, ACK] Seq=0 Ack=1 Win=2144 Len=0 MSS=536 SACK_PERM=1
1132 4806.346477113 192.168.113.253 → 192.168.113.252 TCP 54 32918 → 80 [ACK] Seq=1 Ack=1 Win=29200 Len=0
1133 4806.346671803 192.168.113.253 → 192.168.113.252 HTTP 150 GET /cm?pw=<password_hash>&sid=6&en=0&t=400 HTTP/1.0
1134 4806.585211966 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32918 [ACK] Seq=1 Ack=97 Win=2048 Len=0
1135 4808.135006078 192.168.113.252 → 192.168.113.253 TCP 271 HTTP/1.0 200 OK [TCP segment of a reassembled PDU]
1136 4808.135110663 192.168.113.253 → 192.168.113.252 TCP 54 32918 → 80 [ACK] Seq=97 Ack=218 Win=30016 Len=0
1137 4808.137188919 192.168.113.252 → 192.168.113.253 HTTP 66 HTTP/1.0 200 OK (application/json)
1138 4808.137234857 192.168.113.253 → 192.168.113.252 TCP 54 32918 → 80 [ACK] Seq=97 Ack=230 Win=30016 Len=0
1139 4810.136919880 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32918 [FIN, ACK] Seq=230 Ack=97 Win=2048 Len=0
1140 4810.137149935 192.168.113.253 → 192.168.113.252 TCP 54 32918 → 80 [FIN, ACK] Seq=97 Ack=231 Win=30016 Len=0
1141 4810.139680749 192.168.113.252 → 192.168.113.253 TCP 60 80 → 32918 [ACK] Seq=231 Ack=98 Win=2047 Len=0

[Robert]

I should probably add that the API documentation for cm appears to need updating. It states “An error code will return if you try to open the master station (as the master cannot be operated independently), or open a station that’s either already running or in the queue waiting to run.” After watching this refresh using cm the way it does I tested it for myself. Attempting to open a station that is currently running on the remote simply resets the time – it doesn’t return an error. I’m guessing the functionality was changed some time back from what it originally was.

[Ray]

“This would seem to be based on the assumption that this section of code will be reached _AT LEAST_ once each second. If for some reason it took longer, that could explain the results I saw. ” ==> yes this is correct, and is likely the cause of the issue you are seeing. When the remote station feature was implemented, I was assuming only a very small number of zones are set up as remote zones and didn’t anticipate a situation where a lot of zones are set up as remote. So you are right that if one HTTP call takes longer than a second, then it would miss that cycle and would have to wait for the next cycle. The reason each remote zone was given 2*MAX_NUM_ZONES (in your case, 2*200=400) seconds of run time each time is so that it will get two chances before the remote zone shuts off. In any case, I think there is already a pull request in Github to address this issue so I will take a look as soon as possible. This can be easily addressed without much difficulty.

Next, the question regarding “why not give the remote zone the correct run time” — this is harder to do because of the way remote zone is implemented: it is at very low level, in OpenSprinkler::apple_all_station_bits function. It’s done this way so that the remote zone is guaranteed to trigger independent of how the scheduler is implemented. At that low level, it does not know what is the scheduled run time, all it knows is whether it should turn on the zone or turn it off.

And about the API document, yes will correct that part about /cm command.

[Robert]

Created a pull request with the station refresh fix as well as setting the correct duration on the remote stations both during the initial call and also with the refresh option (tracks the finish time so duration can be calculated from finish – current time).

[Author]

Posts