debounce cnt = 2 ?

[dingausmwald]

Me again.

Just got this:

Jun 06 23:11:14 lampe-links python3[674]: av_interleaved_write_frame(): Network is unreachable
Jun 06 23:11:14 lampe-links python3[674]: Error writing trailer of udp://192.168.99.1:10001: Network is unreachable
Jun 06 23:11:17 lampe-links python3[525]: Exception in thread Thread-4:
Jun 06 23:11:17 lampe-links python3[525]: Traceback (most recent call last):
Jun 06 23:11:17 lampe-links python3[525]: File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
Jun 06 23:11:17 lampe-links python3[525]: self.run()
Jun 06 23:11:17 lampe-links python3[525]: File "/usr/lib/python3.9/threading.py", line 892, in run
Jun 06 23:11:17 lampe-links python3[525]: self._target(*self._args, **self._kwargs)
Jun 06 23:11:17 lampe-links python3[525]: File "/usr/lib/python3/dist-packages/picamera2/encoders/v4l2_encoder.py", line 201, in thread_poll
Jun 06 23:11:17 lampe-links python3[525]: self.outputframe(b, keyframe, (buf.timestamp.secs * 1000000) + buf.timestamp.usecs)
Jun 06 23:11:17 lampe-links python3[525]: File "/usr/lib/python3/dist-packages/picamera2/encoders/encoder.py", line 260, in outputframe
Jun 06 23:11:17 lampe-links python3[525]: out.outputframe(frame, keyframe, timestamp)
Jun 06 23:11:17 lampe-links python3[525]: File "/usr/lib/python3/dist-packages/picamera2/outputs/ffmpegoutput.py", line 84, in outputframe
Jun 06 23:11:17 lampe-links python3[525]: self.ffmpeg.stdin.write(frame)
Jun 06 23:11:17 lampe-links python3[525]: BrokenPipeError: [Errno 32] Broken pipe
Jun 06 23:12:50 lampe-links python3[525]: 23:12:50 - ERROR - MQTT broker was disconnected: errorcode=1
Jun 06 23:12:50 lampe-links python3[525]: 23:12:50 - ERROR - - by router , WIFI access point channel has changed?
Jun 06 23:12:50 lampe-links python3[525]: 23:12:50 - ERROR - MQTT broker was disconnected: errorcode=1
Jun 06 23:12:50 lampe-links python3[525]: 23:12:50 - ERROR - - by router , WIFI access point channel has changed?
Jun 06 23:12:50 lampe-links python3[525]: 23:12:50 - INFO - disconnect debounce cnt = 2
Jun 06 23:12:50 lampe-links python3[525]: 23:12:50 - ERROR - connction broken - exit
Jun 06 23:13:32 lampe-links python3[525]: 23:13:32 - INFO - picam2ctrl MQTT Goodbye!

network went down. Why there is a counter that counts 2 and exits? I was expecting a indefinite reconnect attempt.

[irimitenkan]

I was expecting a indefinite reconnect attempt.

I disagree. You can try to change the debounce counter in MQTTClient.py line 79:
DEBOUNCE_THRESHOLD = 2and set it to your desired value.
My experience here is that will cause an endless loop but without any connection results.

For me the better solution is to restart the complete service again automatically after about 60s, see in picam2ctrl.service

# wait 60s for possible WiFi reconnection
RestartSec=60

[dingausmwald]

Hm. Maybe thats the wrong approach, but still the service does not restart properly when my network goes down. I even set StartLimitBurst=0 but it hangs and won't restart. AI says its because child threads are still running and self.client_down() should be called before every exit() in mqttclient.py, but i do not know for sure.

Jun 17 02:31:17 lampe-links python3[530]: 02:31:17 - ERROR - timed out: connection to MQTT Broker 192.168.99.1 has failed & exit ()
Jun 17 05:17:53 lampe-links python3[691]: av_interleaved_write_frame(): Network is unreachable
Jun 17 05:17:53 lampe-links python3[691]: Error writing trailer of udp://192.168.99.1:10001: Network is unreachable
Jun 17 05:18:31 lampe-links python3[530]: Exception in thread Thread-3:
Jun 17 05:18:32 lampe-links python3[530]: Traceback (most recent call last):
Jun 17 05:18:32 lampe-links python3[530]:   File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
Jun 17 05:18:32 lampe-links python3[530]:     self.run()
Jun 17 05:18:32 lampe-links python3[530]:   File "/usr/lib/python3.9/threading.py", line 892, in run
Jun 17 05:18:32 lampe-links python3[530]:     self._target(*self._args, **self._kwargs)
Jun 17 05:18:32 lampe-links python3[530]:   File "/usr/lib/python3/dist-packages/picamera2/encoders/v4l2_encoder.py", line 201, in thread_poll
Jun 17 05:18:32 lampe-links python3[530]:     self.outputframe(b, keyframe, (buf.timestamp.secs * 1000000) + buf.timestamp.usecs)
Jun 17 05:18:32 lampe-links python3[530]:   File "/usr/lib/python3/dist-packages/picamera2/encoders/encoder.py", line 260, in outputframe
Jun 17 05:18:32 lampe-links python3[530]:     out.outputframe(frame, keyframe, timestamp)
Jun 17 05:18:32 lampe-links python3[530]:   File "/usr/lib/python3/dist-packages/picamera2/outputs/ffmpegoutput.py", line 85, in outputframe
Jun 17 05:18:32 lampe-links python3[530]:     self.ffmpeg.stdin.flush()  # forces every frame to get timestamped individually
Jun 17 05:18:32 lampe-links python3[530]: BrokenPipeError: [Errno 32] Broken pipe

[dingausmwald]

maybe the problem is that the udp stream is still running so there is no reconnect for me. Service is stuck.

[irimitenkan]

maybe the problem is that the udp stream is still running so there is no reconnect for me. Service is stuck.

As you can see in your trace a network disconnection during an active video stream will cause

1. a mqtt disconnection
2. an exception in the picamera2 api (Network is unreachable)

The only possible improvement from my point of view is a better exception handling when a stream is active: catch the error and shutdown the thread in a clean way. Since the broken connection was detected it is better to shutdown the complete user service, wait about 60s & restart the user service:

I'm using the same MQTT client implementation for my CO2Sensor and it is quite running stable since weeks / 24h even with network disconnections:

Jun 28 09:25:30 mrpi python3[33046]: 09:25:30 - INFO - Starting up MQTT Service co2sensor
Jun 28 09:25:21 mrpi python3[33046]: cfgfile = ./config.json
Jun 28 09:25:21 mrpi systemd[565]: Started co2sensor.service - CO2Sensor MQTT client.
Jun 28 09:25:21 mrpi systemd[565]: co2sensor.service: Consumed 36.523s CPU time.
Jun 28 09:25:21 mrpi systemd[565]: Stopped co2sensor.service - CO2Sensor MQTT client.
Jun 28 09:25:21 mrpi systemd[565]: co2sensor.service: Scheduled restart job, restart counter is at 19.
Jun 28 09:24:21 mrpi systemd[565]: co2sensor.service: Consumed 36.523s CPU time.
Jun 28 09:24:21 mrpi python3[31812]: 09:24:21 - INFO - co2sensor MQTT Goodbye!
Jun 28 09:23:21 mrpi python3[31812]: 09:23:21 - ERROR - connction broken - exit
Jun 28 09:23:21 mrpi python3[31812]: 09:23:21 - INFO - disconnect debounce cnt = 2
Jun 28 09:23:21 mrpi python3[31812]: 09:23:21 - ERROR - - by router , WIFI access point channel has changed?
Jun 28 09:23:21 mrpi python3[31812]: 09:23:21 - ERROR - MQTT broker was disconnected: errorcode=16
Jun 28 09:23:21 mrpi python3[31812]: 09:23:21 - ERROR - - by router , WIFI access point channel has changed?
Jun 28 09:23:21 mrpi python3[31812]: 09:23:21 - ERROR - MQTT broker was disconnected: errorcode=16
Jun 27 13:27:15 mrpi python3[31812]: 13:27:15 - INFO - Starting up MQTT Service co2sensor
Jun 27 13:27:09 mrpi python3[31812]: cfgfile = ./config.json
Jun 27 13:27:08 mrpi systemd[565]: Started co2sensor.service - CO2Sensor MQTT client.
Jun 27 13:27:08 mrpi systemd[565]: co2sensor.service: Consumed 4.668s CPU time.
Jun 27 13:27:08 mrpi systemd[565]: Stopped co2sensor.service - CO2Sensor MQTT client.
Jun 27 13:27:08 mrpi systemd[565]: co2sensor.service: Scheduled restart job, restart counter is at 18.
Jun 27 13:26:08 mrpi systemd[565]: co2sensor.service: Consumed 4.668s CPU time.
Jun 27 13:26:08 mrpi python3[31619]: 13:26:08 - INFO - co2sensor MQTT Goodbye!
Jun 27 13:25:08 mrpi python3[31619]: 13:25:08 - ERROR - connction broken - exit
Jun 27 13:25:08 mrpi python3[31619]: 13:25:08 - INFO - disconnect debounce cnt = 2
Jun 27 13:25:08 mrpi python3[31619]: 13:25:08 - ERROR - - by router , WIFI access point channel has changed?
Jun 27 13:25:08 mrpi python3[31619]: 13:25:08 - ERROR - MQTT broker was disconnected: errorcode=16
Jun 27 13:25:08 mrpi python3[31619]: 13:25:08 - ERROR - - by router , WIFI access point channel has changed?
Jun 27 13:25:08 mrpi python3[31619]: 13:25:08 - ERROR - MQTT broker was disconnected: errorcode=16
Jun 27 11:12:05 mrpi python3[31619]: 11:12:05 - INFO - Starting up MQTT Service co2sensor
Jun 27 11:11:58 mrpi python3[31619]: cfgfile = ./config.json
Jun 27 11:11:57 mrpi systemd[565]: Started co2sensor.service - CO2Sensor MQTT client.
Jun 27 11:11:57 mrpi systemd[565]: co2sensor.service: Consumed 7.377s CPU time.
Jun 27 11:11:57 mrpi systemd[565]: Stopped co2sensor.service - CO2Sensor MQTT client.
Jun 27 11:11:57 mrpi systemd[565]: co2sensor.service: Scheduled restart job, restart counter is at 17.
Jun 27 11:10:57 mrpi systemd[565]: co2sensor.service: Consumed 7.377s CPU time.
Jun 27 11:10:57 mrpi python3[31395]: 11:10:57 - INFO - co2sensor MQTT Goodbye!
Jun 27 11:09:57 mrpi python3[31395]: 11:09:57 - ERROR - connction broken - exit
Jun 27 11:09:57 mrpi python3[31395]: 11:09:57 - INFO - disconnect debounce cnt = 2

I don't know the root cause of the disconnection problem,but I have a massive raspberry WIFI reconnection problem when my WIFI router is configured with AUTO channel. Then I even have to reboot my RPI every 1-3 days to get ssh access again.