Proximity sensor - log flood

Moderators: grovkillen, Stuntteam, TD-er

Post Reply
Message
Author
mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Proximity sensor - log flood

#1 Post by mackowiakp » 30 Sep 2019, 18:24

I use a cheap distance sensor as a push-on switch. So I don't measure distances but I generate an event if I bring my hand close to the sensor. I noticed that sometimes (not always) nodeMCU generates a huge number of logs, as below. Is this normal or does the processor overload it? The processor load is 35-40%. I also attach the sensor configuration. Maybe I'm making a mistake?

Code: Select all

4408785: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4408856: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4408985: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4409056: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4409185: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4409278: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4409385: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4409456: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4409585: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4409657: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4410085: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4410156: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4410285: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4410356: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4410485: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4410556: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
4410685: ULTRASONIC : TaskNr: 5 Error: Echo too late, maximum distance exceeded
4410756: ULTRASONIC : TaskNr: 5 Error: Echo pulse error, Echopin not low on trigger
Switch.png
Switch.png (61.12 KiB) Viewed 10289 times

User avatar
grovkillen
Core team member
Posts: 3621
Joined: 19 Jan 2017, 12:56
Location: Hudiksvall, Sweden
Contact:

Re: Proximity sensor - log flood

#2 Post by grovkillen » 30 Sep 2019, 18:38

Have you tried a different GPIO etc?
ESP Easy Flasher [flash tool and wifi setup at flash time]
ESP Easy Webdumper [easy screendumping of your units]
ESP Easy Netscan [find units]
Official shop: https://firstbyte.shop/
Sponsor ESP Easy, we need you :idea: :idea: :idea:

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#3 Post by mackowiakp » 30 Sep 2019, 19:01

I did not try another GPIO`s, mainly because all are in use. But generally it works properly and such logs flood is not distributing me anything. But unit reboots sometimes. After the last improvement of WiFi and ADC issue by TD-er, all my nodeMCU works pretty nice, without reboots. I dont know in case of this one device is it flash fragmentation related problem or this logs flood, which occurs from time to time (not always).
I noticed that the devices left alone, after the final configuration, e.g. adding rules, reload themselves for 2-3 days, and then work properly. In one post TD-er stated that flash de-fragmentation occurs at the start of easyESP. But that one device with proximity sensor has been working for several days and reboot itself 2-3 times a day.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: Proximity sensor - log flood

#4 Post by TD-er » 30 Sep 2019, 21:32

Flash (de)fragmentation only can have an effect when something has been written to the filesystem.
If you don't change any settings, nothing will be written to the filesystem and fragmentation is also not changed.
Fragmentation on the filesystem also hardly has any impact on the read performance. It only matters when writing to the filesystem.
N.B. update of the firmware itself is also not writing to the filesystem, since both work on a different part of the flash. (similar to partitions on a hard drive)

GPIO-2 must be pulled up in order to properly boot the ESP.
This means there is some pull up resistor on that pin.
Maybe that has an effect on the sensor you're using?

I don't know exactly how the ultrasonic sensor does handle the interrupt signals from the echo pin. It could be using some ISR code and then we may need to have a look at it to see if all code has the proper iram attributes on it. Otherwise it may cause all kind of crashes.

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#5 Post by mackowiakp » 01 Oct 2019, 17:23

Flash (de)fragmentation only can have an effect when something has been written to the filesystem.
I have several nodeMCU, of which I haven't changed anything in 6 of them for a long time, except for a software upgrade. From what I noticed, some operation is performed on "config" part of flash . This would be indicated, for example, by changing the order of files in "Tools" -> "File browser". And this happens after self hardware/software watchdog reboot.
GPIO-2 must be pulled up in order to properly boot the ESP.
This means there is some pull up resistor on that pin.
Maybe that has an effect on the sensor you're using?
I have installed such a resistor. This is because the nodeMCU has a proximity sensor (as a switch) and 4x20 LCD display connected. Both of these modules have inputs/outputs dedicated to the 5V logic. That's why I used a 4 channel bi-directional voltage level shiftier 5 <-> 3.3V. It has installed on-board pull-up resistors on both 5 and 3.3 V sides on all inputs/outputs.
I don't know exactly how the ultrasonic sensor does handle the interrupt signals from the echo pin. It could be using some ISR code and then we may need to have a look at it to see if all code has the proper iram attributes on it. Otherwise it may cause all kind of crashes.
So I'll take a test. I will disable the sending of "Error" logs in the source code and see what the effects will be. These error logs mentioned in the first post do not make sense (and they are not really errors) if you use the proximity sensor in the "state" mode, i.e. as a switch.
I would be grateful if somebody could help me try to change the source code of the plugin sensor so as to disable the sending of error information for the test. Of course, all other messages must remain. Probably one or two lines must be "commented". But witch one?

But I think it is also related to WiFi. I think so because I have my own watchdog made with the rule. And if there was no transmission for 15 minutes, the device performs reboot. And during this 15 min I have on display information "No data". Its because they are downloaded from the Domoticz database via SendToHTTP. If no response comes from the server, it indicates a WiFi hang and hence the "No Data" message is displayed

User avatar
grovkillen
Core team member
Posts: 3621
Joined: 19 Jan 2017, 12:56
Location: Hudiksvall, Sweden
Contact:

Re: Proximity sensor - log flood

#6 Post by grovkillen » 01 Oct 2019, 18:22

I suggest you experiment on a unit with only the sensor. It's never a good idea to search for bugs on units with multiple hardware connected + special rules. You introduce too much unknown variables. Try to do tests methodical.
ESP Easy Flasher [flash tool and wifi setup at flash time]
ESP Easy Webdumper [easy screendumping of your units]
ESP Easy Netscan [find units]
Official shop: https://firstbyte.shop/
Sponsor ESP Easy, we need you :idea: :idea: :idea:

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#7 Post by mackowiakp » 01 Oct 2019, 18:36

Right. As the first step I set all log levels in "Advanced" section to "none". As I understand it is near the same like disabling error logs in source code. Now nothing is display as a log.The future will tell us (part of) the truth ....

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#8 Post by mackowiakp » 05 Oct 2019, 15:26

So, these are my observations. In all cases I use FW ESP_Easy_mega-20190926_normal_ESP8266_4M1M. The one with first WiFi/ADC improvements. All log level set to "none" to eliminate logs string sending to any destination. Serial port disabled.
Connected devices:
- 4x24 LCD display with brightness controlled by PWM via GPIO13 (D7)
- DS18b20 temp sensor
- HC-SR04 proximity sensor (configured as a switch)
- analog air quality sensor connected to ADC
- quad dummy device
- generic system uptime sensor.

In all cases I use SendToHTTP command to "press" virtual switch in Domoticz (from timer dependent rule). It activates LUA script which query Domoticz DB about values of sensors connected to other nodeMCU`s and place this values to dummy sensor of tested unit and after then display on 4x20 LCD. In each stage I enabled sensors one by one to see when reboot problem accrues.
I use PWM instead LCD dim command because its more flexible and in some cases LCDCMD,dim caused reboot.

Stage 1:
enabled 4x20 LCD, generic uptime sensor, quad dummy sensor and SendToHTTP rule to load parameters from Domoticz DB to dummy. Works without reboots.
Stage 2:
additionally enabled DS18b20 temp sensor. Works without reboots.
Stage 3:
enabled proximity sensor. Reboots occurs 2 times per day but after two days, the situation calmed down. However, the order of files in "Tools" -> "Filebrowser" has been changed (automatically).
Stage 4:
Enabled ADC (oversampling disabled). The unit reboots 4-5 times per day. As a reason is "Software watchdog".

In the case of this unit we have several very frequent events. PWM, proximity trigger/echo, WiFi/ADC readouts. Can this events interfere to each other?

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: Proximity sensor - log flood

#9 Post by TD-er » 05 Oct 2019, 16:57

enabled proximity sensor. Reboots occurs 2 times per day but after two days, the situation calmed down. However, the order of files in "Tools" -> "Filebrowser" has been changed (automatically).
The order of files is not something that is well defined.
I'm not even sure it will be the same order if nothing has been written to the file system.

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#10 Post by mackowiakp » 05 Oct 2019, 17:44

OK, but file order on filesystem is a matter of any operation on it. It could not be any writing to particular file but somethink like FSCK. In the meaning of functionality.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: Proximity sensor - log flood

#11 Post by TD-er » 05 Oct 2019, 19:24

mackowiakp wrote: 05 Oct 2019, 17:44 OK, but file order on filesystem is a matter of any operation on it. It could not be any writing to particular file but somethink like FSCK. In the meaning of functionality.
Not sure if I understand exactly what you're saying.
If you're stating that reading it twice without change should result in the same output twice, then I agree.
But... there is also caching of the filesystem and a call to garbage collection at boot involved.
So it may very well be that the order of displayed files change even though there has nothing be written to the filesystem inbetween.

For example:
- File order: 1 , 2, 3, 4
- Write something, order: 1, 3, 2, 4
- Reboot => clean caches => file order: 1, 2, 4, 3
- Nothing written, no reboot => file order: 1, 2, 4, 3 (the same)

What does happen here?
If you write something (doesn't matter what or where), all writes will be done to a different page and the old one is marked for deletion.
If there are no free pages available for write, the garbage collector is scanning to see if there is a block which has all its pages marked for deletion.
Typically this is a block of 32 pages of 256 bytes.
If such a block is found, it is actually deleted (setting all bytes to 0xFF again), meaning there are 32 pages marked as free.
Such a change will result in re-balancing the tree of the cached data and this may result in a different order in which files on the filesystem are found.

So even though you do not save anything to the filesystem, a reboot may lead to a different ordering of the files.
Eventually the ordering will become "stable" if there is no block to be found with all its pages marked for deletion. (garbage collector will only free 3 of these blocks in one run)

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#12 Post by mackowiakp » 05 Oct 2019, 20:36

OKAY. I understand. I just wanted to share my thoughts.

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: Proximity sensor - log flood

#13 Post by TD-er » 05 Oct 2019, 21:19

mackowiakp wrote: 05 Oct 2019, 20:36 OKAY. I understand. I just wanted to share my thoughts.
And that's more than welcome.
Just to make sure you don't keep focusing on the observations that have nothing to do with what you're trying to find.
Keeping track of 'noise' will make it really hard to pinpoint the real cause.

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#14 Post by mackowiakp » 06 Oct 2019, 10:58

So, another observation that I think may be important in this case. As I wrote, nodeMCU sends a request to the SendToHTTP server that "presses" on the virtual button in Domoticz. This causes (via the LUA script) 4 queries to the Domoticz database and then sending four TaskValueSet`s to nodeMCU. The transmitted values ​​are saved in the dummy sensor. Then the same script sends TaskRun to activate the dummy sensor action (show all values to the system). So 5 HTTP requests are sent sequentially one by one from the server to nodeMCU, every minute, every 2 sec after the full minute. In the Domoticz logs I found an entry's that this task of sending HTTP requests was sometimes (not always but sometimes, rarely) performed over 10 seconds. Because this happens very rarely, I can't tell if the data has actually been sent to dummy sensor and TaskRun was running. But comparing the time of registering such a logs with the uptime of nodeMCU, one can conclude that this is when reboot occurs. The reason - hardware or software watchdog. This is probably due to limited processor capabilities. However, the problem does not occur if I have ADC disabled. Oversampling is never enabled. Is any workaround possible?

TD-er
Core team member
Posts: 8643
Joined: 01 Sep 2017, 22:13
Location: the Netherlands
Contact:

Re: Proximity sensor - log flood

#15 Post by TD-er » 06 Oct 2019, 23:16

First of all, could you maybe use a bit more formatting in your posts?
It is quite hard to read now as it is a single line of text.

I think the sendtohttp command has to be looked at a bit more.
First of all, it does not wait for an acknowledgement, so it may perhaps already attempt a new connection while the receiving end is still under the impression it is handling the previous one.
Also it does not have a proper timeout set in the WiFiclient it is using.

Both are perfect and well proven recipes for watchdog reboots.
The reboots do occur a bit less often on core 2.6.0 with sendtohttp, since there was a recent fix in wificlient handling when it does not get any response while attempting the connection.

What you could do, is send the timestamp to log using logentry command and send these logs to a log server.
This is merely for debugging of course, but it may help tracking down when things happen.

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#16 Post by mackowiakp » 07 Oct 2019, 11:25

Chanaged to 2.6.0 sdk 2.2.2. Will see what happen

mackowiakp
Normal user
Posts: 527
Joined: 07 Jun 2018, 06:47
Location: Gdynia/Poland

Re: Proximity sensor - log flood

#17 Post by mackowiakp » 09 Oct 2019, 19:44

You are right. 2.6.0 based FW works without self reboots so far. Pretty nice :D

Post Reply

Who is online

Users browsing this forum: No registered users and 21 guests