Mote strange behavior

[sparky]

What would cause an event to take place as scheduled in the Log but not actually perform what's intended at the mote.  This has happened periodically with my Sprinkler, Door Bell, and Light Switch Mote..

Here's an example;

Code Select Expand

[11-30-18_08:08:00.004] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:5 event:switchMote0OFF_AM...
[11-30-18_08:08:00.006] [LOG]    NODEACTION: {"nodeId":5,"action":"BTN0:0"}
[11-30-18_08:08:00.006] [LOG]    **** SCHEDULING EVENT - nodeId:5 event:switchMote0OFF_AM to run in ~23h59m
[11-30-18_08:08:00.011] [LOG]       [5] DB-Updates:1
[11-30-18_08:08:00.033] [LOG]    >: ACK:OK

But the attached pictures shows the light is still on.  From what I have read RSSI of -58db is a pretty good.

[Felix]

RF collisions and maybe maybe a serial port race condition.
Do you have a LOT of events that fire at the same time?

[sparky]

Felix,

Other than the polling for my thermostat, garage mote w/weather shield, and sump pump, the only event close to the light switch is my door bell mote that turns off at 8:00PM.  As mentioned above this is periodic behavior and has worked fine since posting but now and again it will act up along with other motes as mentioned. 

Here is some events before and after the event in question;

Code Select Expand

[11-30-18_08:07:27.317] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:99 event:thermostatPoll...
[11-30-18_08:07:27.318] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:3 event:garagePoll...
[11-30-18_08:07:27.319] [LOG]    **** SCHEDULING EVENT - nodeId:99 event:thermostatPoll to run in ~30s
[11-30-18_08:07:27.320] [LOG]    **** SCHEDULING EVENT - nodeId:3 event:garagePoll to run in ~30s
[11-30-18_08:07:27.327] [LOG]       [99] DB-Updates:1
[11-30-18_08:07:27.331] [LOG]       [3] DB-Updates:1
[11-30-18_08:07:29.281] [LOG]    >: [99] F:7200 TARGET:73 HOLD:ON TSTATE:HEATING FSTATE:AUTO MODE:HEAT
[11-30-18_08:07:29.283] [LOG]    post: /home/pi/gateway/data/db/0099_F.bin[1543583249,72]
[11-30-18_08:07:29.288] [LOG]       [99] DB-Updates:1
[11-30-18_08:07:42.368] [LOG]    >: [6] CM:50   [RSSI:-40]
[11-30-18_08:07:42.369] [LOG]    post: /home/pi/gateway/data/db/0006_CM.bin[1543583262,50]
[11-30-18_08:07:42.371] [LOG]    post: /home/pi/gateway/data/db/0006_RSSI.bin[1543583262,-40]
[11-30-18_08:07:42.374] [LOG]       [6] DB-Updates:1
[11-30-18_08:07:57.334] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:99 event:thermostatPoll...
[11-30-18_08:07:57.335] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:3 event:garagePoll...
[11-30-18_08:07:57.336] [LOG]    **** SCHEDULING EVENT - nodeId:99 event:thermostatPoll to run in ~30s
[11-30-18_08:07:57.341] [LOG]    **** SCHEDULING EVENT - nodeId:3 event:garagePoll to run in ~30s
[11-30-18_08:07:57.349] [LOG]       [99] DB-Updates:1
[11-30-18_08:07:57.352] [LOG]       [3] DB-Updates:1
[11-30-18_08:08:00.004] [LOG]    **** RUNNING SCHEDULED EVENT - nodeId:5 event:switchMote0OFF_AM...
[11-30-18_08:08:00.006] [LOG]    NODEACTION: {"nodeId":5,"action":"BTN0:0"}
[11-30-18_08:08:00.006] [LOG]    **** SCHEDULING EVENT - nodeId:5 event:switchMote0OFF_AM to run in ~23h59m
[11-30-18_08:08:00.011] [LOG]       [5] DB-Updates:1
[11-30-18_08:08:00.033] [LOG]    >: ACK:OK
[11-30-18_08:08:01.073] [LOG]    >: [3] F:43.9 H:54 P:29.83   [RSSI:-49]
[11-30-18_08:08:01.075] [LOG]    post: /home/pi/gateway/data/db/0003_F.bin[1543583281,43.9]
[11-30-18_08:08:01.076] [LOG]    post: /home/pi/gateway/data/db/0003_H.bin[1543583281,54]
[11-30-18_08:08:01.077] [LOG]    post: /home/pi/gateway/data/db/0003_P.bin[1543583281,29.83]
[11-30-18_08:08:01.078] [LOG]    post: /home/pi/gateway/data/db/0003_RSSI.bin[1543583281,-49]
[11-30-18_08:08:01.082] [LOG]       [3] DB-Updates:1
[11-30-18_08:08:05.073] [LOG]    >: [6] CM:50   [RSSI:-40]
[11-30-18_08:08:05.075] [LOG]    post: /home/pi/gateway/data/db/0006_CM.bin[1543583285,50]
[11-30-18_08:08:05.077] [LOG]    post: /home/pi/gateway/data/db/0006_RSSI.bin[1543583285,-40]
[11-30-18_08:08:05.080] [LOG]       [6] DB-Updates:1
[11-30-18_08:08:10.855] [LOG]    >: [99] F:7200 TARGET:73 HOLD:ON TSTATE:HEATING FSTATE:AUTO MODE:HEAT
[11-30-18_08:08:10.857] [LOG]    post: /home/pi/gateway/data/db/0099_F.bin[1543583290,72]
[11-30-18_08:08:10.862] [LOG]       [99] DB-Updates:1
[11-30-18_08:08:27.059] [LOG]    >: [6] CM:50   [RSSI:-40]
[11-30-18_08:08:27.061] [LOG]    post: /home/pi/gateway/data/db/0006_CM.bin[1543583307,50]
[11-30-18_08:08:27.062] [LOG]    post: /home/pi/gateway/data/db/0006_RSSI.bin[1543583307,-40]
[11-30-18_08:08:27.065] [LOG]       [6] DB-Updates:1

[Felix]

There was a polling event fix, so if you're not running latest code I would upgrade. But there will be release 9.0 soon, so maybe worth the wait. Im trying to make sure there are no new bugs, and I have to make a video, no time 

[sparky]

Thanks for the response Felix,

Yes, I'm running the latest version you have.  I was wondering what baud rate you are running on your motes.  I know a few versions back you changed something allowing a slower baud rate.  I'm still running at 115200 and was wondering if lowering my baud rate would help anything?

Thanks again and I look forward to more great work from you in the new version..!

[Felix]

You mean the BAUD between the RF gateway Moteino/MightyHat and the Pi serial port?
That was changed to 19200 a while ago, I think consensus from me and other folks was that it helped with reducing any too fast marshalling of serial messages between the Pi and RF gateway.

[sparky]

Hmm, I guess I'm confused again..  I was referring to the baud rate between the Gateway and the motes..

[Felix]

That is RF baud rate, it's the 55.5k default in the RFM69 library, never changed.