mysensors / NodeManager

Plugin for a rapid development of battery-powered sensors
130 stars 82 forks source link

Motion sensor "crashing" other sensors #437

Closed Nalith closed 4 years ago

Nalith commented 5 years ago

Hi

I am having a strange issue where my multi-sensor device seems to stop checking my DHT22 sensor values (TEMP and HUM) when the I set the motion sensors interrupt mode to CHANGE ("motion.setInterruptMode(CHANGE);". The unit does not actually freeze as the interrupt sensors still work but the battery and DHT22 sensor just seem to stop reading and sending data through. I have even tried specifically setting the setReportIntervalMinutes value on each of the sensors. When I set the setInterruptMode back to default then this problem seems to go away. I have lowered all timeouts and sleep intervals for testing.

Below are the logs:

[Starting] Opening the serial port - COM5 [Info] Opened the serial port - COM5 0 NM:INIT:VER=1.8-dev 0 NM:INIT:INO=NodeManager-DoorSensor v0.4 0 NM:INIT:LIB VER=2.3.0 CP=RNNNA--- 0 NM:INIT:RBT p=255 20 NM:BFR:INIT 4093 NM:BFR:OK 4112 NM:PRES:CONFIG(200) p=23 t=48 4151 NM:PRES:BATTERY(14) p=30 t=38 4190 NM:PRES:DHT22(1) p=6 t=0 4225 NM:PRES:DHT22(2) p=7 t=1 4294 NM:PRES:DOOR(3) p=0 t=16 4362 NM:PRES:MOTION(4) p=1 t=16 4470 NM:MSG:RECV(200) c=0 t=23 p=CONFIG 4511 NM:PWR:ON p=7 4532 NM:MSG:RECV(14) c=0 t=30 p=BATTERY 4575 NM:PWR:ON p=7 4595 NM:MSG:RECV(1) c=0 t=6 p=DHT22 4632 NM:PWR:ON p=7 4704 NM:PWR:OFF p=6 4724 NM:PWR:OFF p=6 4745 NM:PWR:OFF p=6 4767 NM:PWR:ON p=7 4839 NM:STP:ID=1 M=1 4861 NM:BFR:INT p=3 m=1 4886 NM:BFR:INT p=2 m=1 4911 NM:PWR:OFF p=6 5005 NM:STP:HW V=3319 F=9 M=843 5040 NM:PWR:ON p=7 5566 NM:LOOP:BATTERY(14):SET t=38 v=3.91 5611 NM:MSG:SEND(14) t=38 p=3.91 5652 NM:LOOP:DHT22(1):SET t=0 v=23.30 5699 NM:LOOP:DHT22(2):SET t=1 v=53.00 5738 NM:MSG:SEND(1) t=0 p=23.30 5775 NM:MSG:SEND(2) t=1 p=53.00 5810 NM:PWR:OFF p=6 5830 NM:SLP:SLEEP s=60

5859 NM:MSG:RECV(1) c=1 t=0 p= 5892 NM:PWR:ON p=7 5912 NM:MSG:RECV(2) c=1 t=1 p= 5945 NM:PWR:ON p=7 6014 NM:PWR:OFF p=6 6035 NM:PWR:OFF p=6 8040 NM:LOOP:INT p=2 v=0 8067 NM:SLP:AWAKE 8085 NM:PWR:ON p=7 8155 NM:LOOP:MOTION(4):SET t=16 v=0 8192 NM:MSG:SEND(4) t=16 p=0 8224 NM:PWR:OFF p=6 8245 NM:SLP:SLEEP s=60

8273 NM:MSG:RECV(4) c=1 t=16 p= 8306 NM:PWR:ON p=7 8378 NM:PWR:OFF p=6 10455 NM:LOOP:INT p=2 v=1 10481 NM:SLP:AWAKE 10502 NM:PWR:ON p=7 10573 NM:LOOP:MOTION(4):SET t=16 v=1 10612 NM:MSG:SEND(4) t=16 p=1 10645 NM:PWR:OFF p=6 10668 NM:SLP:SLEEP s=60

10696 NM:MSG:RECV(4) c=1 t=16 p= 10731 NM:PWR:ON p=7 10803 NM:PWR:OFF p=6 12877 NM:LOOP:INT p=2 v=0 12904 NM:SLP:AWAKE 12924 NM:PWR:ON p=7 12996 NM:LOOP:MOTION(4):SET t=16 v=0 13035 NM:MSG:SEND(4) t=16 p=0 13068 NM:PWR:OFF p=6 13090 NM:SLP:SLEEP s=60

13119 NM:MSG:RECV(4) c=1 t=16 p= 13154 NM:PWR:ON p=7 13225 NM:PWR:OFF p=6 15300 NM:LOOP:INT p=2 v=1 15327 NM:SLP:AWAKE 15347 NM:PWR:ON p=7 15419 NM:LOOP:MOTION(4):SET t=16 v=1 15458 NM:MSG:SEND(4) t=16 p=1 15491 NM:PWR:OFF p=6 15513 NM:SLP:SLEEP s=60

15542 NM:MSG:RECV(4) c=1 t=16 p= 15577 NM:PWR:ON p=7 15648 NM:PWR:OFF p=6 17725 NM:LOOP:INT p=2 v=0 17752 NM:SLP:AWAKE 17772 NM:PWR:ON p=7 17844 NM:LOOP:MOTION(4):SET t=16 v=0 17883 NM:MSG:SEND(4) t=16 p=0 17915 NM:PWR:OFF p=6 17938 NM:SLP:SLEEP s=60

17967 NM:MSG:RECV(4) c=1 t=16 p= 18001 NM:PWR:ON p=7 18073 NM:PWR:OFF p=6 20150 NM:LOOP:INT p=2 v=1 20176 NM:SLP:AWAKE 20197 NM:PWR:ON p=7 20267 NM:LOOP:MOTION(4):SET t=16 v=1 20305 NM:MSG:SEND(4) t=16 p=1 20338 NM:PWR:OFF p=6 20361 NM:SLP:SLEEP s=60

20389 NM:MSG:RECV(4) c=1 t=16 p= 20424 NM:PWR:ON p=7 20496 NM:PWR:OFF p=6 22571 NM:SLP:AWAKE 22591 NM:PWR:ON p=7 22661 NM:PWR:OFF p=6 22683 NM:SLP:SLEEP s=60

24893 NM:LOOP:INT p=2 v=0 24920 NM:SLP:AWAKE 24940 NM:PWR:ON p=7 25012 NM:LOOP:MOTION(4):SET t=16 v=0 25051 NM:MSG:SEND(4) t=16 p=0 25083 NM:PWR:OFF p=6 25106 NM:SLP:SLEEP s=60

25135 NM:MSG:RECV(4) c=1 t=16 p= 25169 NM:PWR:ON p=7 25241 NM:PWR:OFF p=6 27318 NM:LOOP:INT p=2 v=1 27344 NM:SLP:AWAKE 27365 NM:PWR:ON p=7 27435 NM:LOOP:MOTION(4):SET t=16 v=1 27473 NM:MSG:SEND(4) t=16 p=1 27506 NM:PWR:OFF p=6 27529 NM:SLP:SLEEP s=60

27557 NM:MSG:RECV(4) c=1 t=16 p= 27592 NM:PWR:ON p=7 27664 NM:PWR:OFF p=6 29739 NM:LOOP:INT p=2 v=0 29765 NM:SLP:AWAKE 29786 NM:PWR:ON p=7 29857 NM:LOOP:MOTION(4):SET t=16 v=0 29896 NM:MSG:SEND(4) t=16 p=0 29929 NM:PWR:OFF p=6 29952 NM:SLP:SLEEP s=60

29980 NM:MSG:RECV(4) c=1 t=16 p= 30015 NM:PWR:ON p=7 30085 NM:PWR:OFF p=6 32161 NM:LOOP:INT p=2 v=1 32188 NM:SLP:AWAKE 32208 NM:PWR:ON p=7 32280 NM:LOOP:MOTION(4):SET t=16 v=1 32319 NM:MSG:SEND(4) t=16 p=1 32352 NM:PWR:OFF p=6 32374 NM:SLP:SLEEP s=60

32403 NM:MSG:RECV(4) c=1 t=16 p= 32438 NM:PWR:ON p=7 32509 NM:PWR:OFF p=6 34584 NM:LOOP:INT p=2 v=0 34611 NM:SLP:AWAKE 34631 NM:PWR:ON p=7 34703 NM:LOOP:MOTION(4):SET t=16 v=0 34742 NM:MSG:SEND(4) t=16 p=0 34775 NM:PWR:OFF p=6 34797 NM:SLP:SLEEP s=60

34828 NM:MSG:RECV(4) c=1 t=16 p= 34863 NM:PWR:ON p=7 34934 NM:PWR:OFF p=6 37009 NM:LOOP:INT p=2 v=1 37036 NM:SLP:AWAKE 37056 NM:PWR:ON p=7 37126 NM:LOOP:MOTION(4):SET t=16 v=1 37165 NM:MSG:SEND(4) t=16 p=1 37197 NM:PWR:OFF p=6 37220 NM:SLP:SLEEP s=60

37249 NM:MSG:RECV(4) c=1 t=16 p= 37283 NM:PWR:ON p=7 37355 NM:PWR:OFF p=6 39432 NM:SLP:AWAKE 39452 NM:PWR:ON p=7 39524 NM:PWR:OFF p=6 39546 NM:SLP:SLEEP s=60

41754 NM:SLP:AWAKE 41775 NM:PWR:ON p=7 41846 NM:PWR:OFF p=6 41869 NM:SLP:SLEEP s=60

44077 NM:SLP:AWAKE 44097 NM:PWR:ON p=7 44169 NM:PWR:OFF p=6 44191 NM:SLP:SLEEP s=60

46399 NM:SLP:AWAKE 46419 NM:PWR:ON p=7 46491 NM:PWR:OFF p=6 46514 NM:SLP:SLEEP s=60

Thanks

Nalith commented 5 years ago

Correction, seeing the same symptoms even with the "motion.setInterruptMode(CHANGE);" commented out:

[Starting] Opening the serial port - COM5 [Info] Opened the serial port - COM5 0 NM:INIT:VER=1.8-dev 0 NM:INIT:INO=NodeManager-DoorSensor v0.4 0 NM:INIT:LIB VER=2.3.0 CP=RNNNA--- 0 NM:INIT:RBT p=255 20 NM:BFR:INIT 6129 NM:BFR:OK 6148 NM:PRES:CONFIG(200) p=23 t=48 6187 NM:PRES:BATTERY(14) p=30 t=38 6225 NM:PRES:DHT22(1) p=6 t=0 6260 NM:PRES:DHT22(2) p=7 t=1 6330 NM:PRES:DOOR(3) p=0 t=16 6397 NM:PRES:MOTION(4) p=1 t=16 6506 NM:MSG:RECV(200) c=0 t=23 p=CONFIG 6547 NM:PWR:ON p=7 6567 NM:MSG:RECV(14) c=0 t=30 p=BATTERY 6610 NM:PWR:ON p=7 6631 NM:MSG:RECV(1) c=0 t=6 p=DHT22 6668 NM:PWR:ON p=7 6739 NM:PWR:OFF p=6 6760 NM:PWR:OFF p=6 6780 NM:PWR:OFF p=6 6803 NM:PWR:ON p=7 6871 NM:STP:ID=1 M=1 6893 NM:BFR:INT p=3 m=1 6918 NM:BFR:INT p=2 m=3 6942 NM:PWR:OFF p=6 7036 NM:STP:HW V=3309 F=9 M=843 7071 NM:PWR:ON p=7 7596 NM:LOOP:BATTERY(14):SET t=38 v=3.81 7641 NM:MSG:SEND(14) t=38 p=3.81 7682 NM:LOOP:DHT22(1):SET t=0 v=22.90 7729 NM:LOOP:DHT22(2):SET t=1 v=52.80 7768 NM:MSG:SEND(1) t=0 p=22.90 7804 NM:MSG:SEND(2) t=1 p=52.80 7839 NM:PWR:OFF p=6 7860 NM:SLP:SLEEP s=60

7888 NM:MSG:RECV(1) c=1 t=0 p= 7921 NM:PWR:ON p=7 7942 NM:MSG:RECV(2) c=1 t=1 p= 7974 NM:PWR:ON p=7 8044 NM:PWR:OFF p=6 8065 NM:PWR:OFF p=6 10070 NM:SLP:AWAKE 10090 NM:PWR:ON p=7 10616 NM:LOOP:BATTERY(14):SET t=38 v=3.94 10661 NM:MSG:SEND(14) t=38 p=3.94 10704 NM:LOOP:DHT22(1):SET t=0 v=23.00 10752 NM:LOOP:DHT22(2):SET t=1 v=52.90 10792 NM:MSG:SEND(1) t=0 p=23.00 10829 NM:MSG:SEND(2) t=1 p=52.90 10866 NM:PWR:OFF p=6 10889 NM:SLP:SLEEP s=60

10917 NM:MSG:RECV(1) c=1 t=0 p= 10952 NM:PWR:ON p=7 10973 NM:MSG:RECV(2) c=1 t=1 p= 11008 NM:PWR:ON p=7 11079 NM:PWR:OFF p=6 11102 NM:PWR:OFF p=6 13099 NM:LOOP:INT p=2 v=1 13125 NM:SLP:AWAKE 13146 NM:PWR:ON p=7 13217 NM:LOOP:MOTION(4):SET t=16 v=1 13256 NM:MSG:SEND(4) t=16 p=1 13289 NM:PWR:OFF p=6 13312 NM:SLP:SLEEP s=60

13340 NM:MSG:RECV(4) c=1 t=16 p= 13375 NM:PWR:ON p=7 13445 NM:PWR:OFF p=6 15521 NM:SLP:AWAKE 15542 NM:PWR:ON p=7 15613 NM:PWR:OFF p=6 15636 NM:SLP:SLEEP s=60

17846 NM:SLP:AWAKE 17866 NM:PWR:ON p=7 17938 NM:PWR:OFF p=6 17960 NM:SLP:SLEEP s=60

20168 NM:SLP:AWAKE 20189 NM:PWR:ON p=7 20260 NM:PWR:OFF p=6 20283 NM:SLP:SLEEP s=60

22493 NM:SLP:AWAKE 22513 NM:PWR:ON p=7 22585 NM:PWR:OFF p=6 22607 NM:SLP:SLEEP s=60

user2684 commented 5 years ago

Thanks for reporting this issue, I'll try to reproduce and I'll come back to you should I have any further question.

Nalith commented 5 years ago

Thanks. Love the NodeManager solution btw. I have logged a post of the mysensors forum (https://forum.mysensors.org/topic/9873/nodemanager-motion-door-interrupt-sensor-stopping-dht22-from-reading-value-after-a-while) with my source code, should I close that thread?

Nalith commented 5 years ago

Some more additional information, if I add setReportIntervalMinutes after nodeManager.loop() it seems to sort out the problem, been running for 12 hours without any issue, will keen an eye on it and update you accordingly.

user2684 commented 5 years ago

Hi, feel free to keep the thread on the forum there, somebody could always come out with a solution, who knows :) Can you share the sketch you are using? I'll try to reproduce it tomorrow. Thanks!

Nalith commented 5 years ago

I have attached a copy of the sketch that I was having a issue with:

My Setup:

If you toggle the door sensor a couple of times or have the motion sensor go off a couple of times it will eventually stop running the DHT sensor loop. Interrupts still work fine but not the stuff that is timer based if that makes sense?

Test.zip

user2684 commented 5 years ago

I think the issue is related to an interrupt-based sensor combined with other sensors reporting periodically on a sleeping board. The thing is, every time an interrupt occurs, there is no way without being time-aware to know how much time has been spent on sleeping which may lead to these situations. However, I see you are using an RTC which is also enabled on your sketch but I cannot see any log related to it. Any chance sharing the logs while using the RTC? thanks

Nalith commented 5 years ago

Thanks for the effort you are putting into assisting with this. I had eventually tried adding a RTC to see if that resolved the problem however it did not, all that it did was rectify the sleep time so it resumes sleep for only the remaining time and not from the original sleep time.

I have since used a different Arduino Pro Mini board only connecting a DHT22 sensor and a push button to simulate the door switch, the report and sleep interval have been configured to 30 seconds for testing. The loop works correctly without any issues however as soon as I toggle the door sensor a few times while its sleeping it seems to forget that there is a door sensor connected and does not execute the DHT22 loop when it executes the NodeManager loop (See line 116/117 in log files). I had initially thought if I reset the report at the end of the loop however it does not seem to resolve the issue. It's almost as if NodeManager internally forgets that there is a DHT22 sensor attached and just does an empty loop, all interrupts still work like a charm. A single open/close during the sleep cycle seems to work however if there are q few consecutive interrupts it seems to break. Please find attached the source + log. Let me know if you need any additional info.

NodeManager-DoorSensor.zip

Nalith commented 5 years ago

Thanks for the effort you are putting into assisting with this. I had eventually tried adding a RTC to see if that resolved the problem however it did not, all that it did was rectify the sleep time so it resumes sleep for only the remaining time and not from the original sleep time.

I have since used a different Arduino Pro Mini board only connecting a DHT22 sensor and a push button to simulate the door switch, the report and sleep interval have been configured to 30 seconds for testing. The loop works correctly without any issues however as soon as I toggle the door sensor a few times while its sleeping it seems to forget that there is a door sensor connected and does not execute the DHT22 loop when it executes the NodeManager loop (See line 116/117 in log files). I had initially thought if I reset the report at the end of the loop however it does not seem to resolve the issue. It's almost as if NodeManager internally forgets that there is a DHT22 sensor attached and just does an empty loop, all interrupts still work like a charm. A single open/close during the sleep cycle seems to work however if there are q few consecutive interrupts it seems to break. Please find attached the source + log. Let me know if you need any additional info.

NodeManager-DoorSensor.zip

Apologies, just noticed you had asked for logs/source code for when I was using the RTC module, I have already removed that from my sketch as it did not resolve the issue but could wire it back up and send through the logs if it would help resolve the issue. Please let me know if the sketch + logs sent through are not sufficient?

user2684 commented 5 years ago

@Nalith sorry for the delay, I was finally able to find some time to run a similar test but unfortunately I couldn't reproduce the issue. I had a DHT22 sensor and a motion sensor with a configuration similar to yours. I started without power manager first and got this:

0 NM:INIT:VER=1.8-dev
0 NM:INIT:INO=NodeManagerTester v1.0
0 NM:INIT:LIB VER=2.3.0 CP=RNNNA--- 
0 NM:INIT:RBT p=255
20 NM:BFR:INIT
0 NM:INIT:VER=1.8-dev
0 NM:INIT:INO=NodeManagerTester v1.0
0 NM:INIT:LIB VER=2.3.0 CP=RNNNA--- 
0 NM:INIT:RBT p=255
20 NM:BFR:INIT
4368 NM:BFR:OK
7747 NM:PRES:BATTERY(201) p=30 t=38
7786 NM:PRES:DHT22(1) p=6 t=0
7821 NM:PRES:DHT22(2) p=7 t=1
7856 NM:PRES:MOTION(3) p=1 t=16
32098 NM:STP:ID=99 M=1
32122 NM:BFR:INT p=3 m=3
32223 NM:STP:HW V=3233 F=8 M=1120
32329 NM:LOOP:BATTERY(201):SET t=38 v=3.22
32376 NM:MSG:SEND(201) t=38 p=3.22
32419 NM:LOOP:DHT22(1):SET t=0 v=21.40
32466 NM:LOOP:DHT22(2):SET t=1 v=67.90
32507 NM:MSG:SEND(1) t=0 p=21.40
32544 NM:MSG:SEND(2) t=1 p=67.90
32581 NM:SLP:SLEEP s=30

34791 NM:LOOP:INT p=3 v=1
34818 NM:SLP:AWAKE
34838 NM:LOOP:MOTION(3):SET t=16 v=1
34877 NM:MSG:SEND(3) t=16 p=1
34912 NM:SLP:SLEEP s=30

39448 NM:SLP:AWAKE
39475 NM:LOOP:DHT22(1):SET t=0 v=21.20
39522 NM:LOOP:DHT22(2):SET t=1 v=60.10
39563 NM:MSG:SEND(1) t=0 p=21.20
39600 NM:MSG:SEND(2) t=1 p=60.10
39636 NM:SLP:SLEEP s=30

I then set the power manager like in your configuration and got this:

0 NM:INIT:VER=1.8-dev
0 NM:INIT:INO=NodeManagerTester v1.0
0 NM:INIT:LIB VER=2.3.0 CP=RNNNA--- 
0 NM:INIT:RBT p=255
20 NM:BFR:INIT
0 NM:INIT:VER=1.8-dev
0 NM:INIT:INO=NodeManagerTester v1.0
0 NM:INIT:LIB VER=2.3.0 CP=RNNNA--- 
0 NM:INIT:RBT p=255
20 NM:BFR:INIT
29298 NM:BFR:OK
29319 NM:PRES:BATTERY(201) p=30 t=38
29360 NM:PRES:DHT22(1) p=6 t=0
29394 NM:PRES:DHT22(2) p=7 t=1
29429 NM:PRES:MOTION(3) p=1 t=16
31614 NM:STP:ID=99 M=1
31639 NM:PWR:ON p=7
32661 NM:PWR:OFF p=6
32681 NM:BFR:INT p=3 m=3
32780 NM:STP:HW V=3233 F=8 M=1106
32886 NM:LOOP:BATTERY(201):SET t=38 v=3.23
32933 NM:MSG:SEND(201) t=38 p=3.23
32972 NM:PWR:ON p=7
33998 NM:LOOP:DHT22(1):SET t=0 v=20.80
34045 NM:LOOP:DHT22(2):SET t=1 v=0.00
34084 NM:PWR:OFF p=6
34107 NM:MSG:SEND(1) t=0 p=20.80
34144 NM:MSG:SEND(2) t=1 p=0.00
34181 NM:SLP:SLEEP s=30

36390 NM:LOOP:INT p=3 v=1
36417 NM:SLP:AWAKE
36438 NM:LOOP:MOTION(3):SET t=16 v=1
36476 NM:MSG:SEND(3) t=16 p=1
36511 NM:SLP:SLEEP s=30

38719 NM:SLP:AWAKE
38739 NM:PWR:ON p=7
39766 NM:LOOP:DHT22(1):SET t=0 v=20.70
39811 NM:PWR:OFF p=6
39833 NM:MSG:SEND(1) t=0 p=20.70
39870 NM:SLP:SLEEP s=30

So as you can see it is working but the humidity was missing in this case. This is because there is a isnan() test in Child::_setValueNumber() and a DHT sensor if unable to poll a measure returns nan. My guess is it has something to do with power manager, maybe 1s of sleep before polling the sensor is not enough (which is anyhow weird since we sleep for getMinimumSamplingPeriod() before invoking readSensor() in the DHT class). I'll keep this open as a bug but outside the v1.8 queue for now. Thanks!

Nalith commented 5 years ago

Thanks for all your help, will keep you posted too if I manage to narrow it down more.

Nalith commented 4 years ago

Have not managed to narrow this down and don't seem to be getting the issue anymore so will close this bug for now.

user2684 commented 4 years ago

Ok thanks, feel free to re-open it should it happen again. Thx