continuous timeout DEBUG messages in comitup.log

[mennamorato]

For some reason, yesterday, my /var/log/comitup.log file started filling up with this DEBUG message every 3 minutes on my RaspberryPi Zero W: (comitup v1.29)
2021-06-01 17:57:22,623 - comitup - DEBUG - connected_timeout comparing xxxxxxxx to xxxxxxxx (same SSID)

eventually there was a
2021-06-02 07:55:14,181 - comitup - INFO - Starting comitup followed by more of the same DEBUG messages.

something to worry about ? how to debug more ?
thanks

[davesteele]

The debug message is fine - it's just saying that it's checking that the connection is where it is supposed to be.

I haven't seen the restart before. There should be either a "Stopping comitup" INFO entry before it, or a Traceback in comitup.log or another. Systemd is configured to restart the service.

I have a current debug logging session on a connected one-interface system that is three days old, with no restart. I just set verbose on a connected router install (on a Pi Zero W). Prior to that, the router occasionally lost the upstream connection, but there were no restarts.

[mennamorato]

Thanks Dave, there is no "Stopping comitup" INFO entry in the log, I will attach it. I have Verbose = '1' in the .conf file.
What is strange is I have a python script that runs after CONNECTED and "ps ax | grep python3" shows it still running but it is not really running because it posts data to a cloud service (Thingspeak) and it stopped posting this morning. I have to figure out how to see print debug messages from the python script as they do not appear 'normally' in the ssh console I suspect I have to do something to make that happen. I thought possibly this problem is related to the flood of connection-timeout problems.
comitup.log

[davesteele]

Comitup uses subprocess.call() to call the external script. It waits for the script to finish before continuing. A script that doesn't return quickly could lead to weird results. Looking at your log, that does not appear to be the case here (though log entry after "External callback" oddly has the same timestamp).

Also note that the callback happens at the "CONNECTED/start" event. The connection is not actually ready until "CONNECTED/pass" - perhaps an oversight on my part. Though I'll say your connections are happening astonishingly quickly.

To reiterate, you are not seeing a flood of connection-timeout problems. The timeout call is a normal part of the state processing. In CONNECTED state, it is expected to happen on a happy system. It is an error condition only in the CONNECTING state.

Take a look in daemon.log at the time of the "Starting comitup" log entry.

To see logging to e.g. stdout, add a logging.StreamHandler to "log" in comitup.py deflog().

[mennamorato]

Arrrggg! ok my bad.. my python script does not return quickly at all and actually sits in a while(1) loop with a timeout... I will have to find another way to launch the script after comitup finishes connecting

[davesteele]

Just write a shell wrapper that calls your script with a trailing "&". You may want to store a PID to support stopping in HOTSPOT.