Watchdog timeout did NOT restart, killing it! USB and RTSP Cameras

[majurgens]

0. Reviewed guide and contributing documents? (Yes/No): Yes (this is long time running/configured motion system)
1. version [x.y.z, hash, other]: 4.4.0
2. installed as a package or compiled from sources [deb, rpm, git, other]: RPM package
3. standalone or part of third party [motion, MotionEyeOS, other]: Standalone
4. video stream source [V4L (card or USB), net cam (mjpeg, rtsp, other), mmal]: USB and RTSP
5. hardware [x86, ARM, other]: x86 Intel i7-12700
6. operating system [16.04, Stretch, etc, FreeBSD, other]: Fedora 36

Apparently random thread deaths from both USB and RTSP cameras. Configured to write images only (no video file creation).
This log https://www.edcint.co.nz/tmp/expire_14/motion_20220614.log contains a couple of instances of thread deaths, all the config (at the end of the log) and I am now running at log level 8 to try and capture more detail for any future instances.

[tosiara]

Where is /export/shared/TEMP/NOBACKUP/motion_local/ located? Is that a flash or a network storage?

[majurgens]

Local hard drives with a BTRFS file system running RAID1

[tosiara]

Ok, could you also check kernel messages or syslog at the time when watchdog timeout occurs? Are there any issues?

[majurgens]

Ok, could you also check kernel messages or syslog at the time when watchdog timeout occurs? Are there any issues?

I did that before creating the issue - I could not see any matching system-level messages on or around the same times and the failures.

[tosiara]

could you share your fresh motion.log, dmesg and syslog output with reproduced issue? you can do that privately, if you like. see privacy

[Mr-Dave]

Try to just increase the timeouts?

[majurgens]

I think you are asking me to submit those files next time the problem happens rather than giving you those files for the previous times?

[tosiara]

if you still have the old ones from Jun 12 11:25:32 - that is also fine

[majurgens]

I have the pretty boring messages file https://www.edcint.co.nz/tmp/expire_14/messages_20220612.log
dmesg has been cleared since the machine has been rebooted

[majurgens]

Ok, it happened again. Messages files boring and looks the same as the previous instance

[0:motion] [ERR] [ALL] [Jun 27 11:27:22] motion_watchdog: Thread 2 - Watchdog timeout. Trying to do a graceful restart
[0:motion] [ERR] [ALL] [Jun 27 11:27:32] motion_watchdog: Thread 2 - Watchdog timeout did NOT restart, killing it!
[0:motion] [ERR] [ALL] [Jun 27 11:27:43] motion_watchdog: Thread 1 - Watchdog timeout. Trying to do a graceful restart
[0:motion] [ERR] [ALL] [Jun 27 11:27:53] motion_watchdog: Thread 1 - Watchdog timeout did NOT restart, killing it!

See full log at https://www.edcint.co.nz/tmp/expire_14/messages-20220619.log

Also Kernel 5.17.11-300.fc36.x86_64
Load was high https://www.edcint.co.nz/tmp/expire_14/Load%20Screenshot%202022-06-27%20205459.jpg however this is a 12 core, 20 thread CPU so should not be a major problem

I looked at the load for the last instance on 12th Jun and load was maybe max 10

[tosiara]

The provided logs ends Jun 19 00:00:00 and does not seem to cover the issue

[majurgens]

Sorry, that was not even a motion log
Try this one https://www.edcint.co.nz/tmp/expire_14/motion.log-20220619.log

[tosiara]

But do you have syslog for that time frame? Jun 27 11:27:22

[majurgens]

But do you have syslog for that time frame? Jun 27 11:27:22

Nothing in the syslog. But there is system load again

[tosiara]

If the system load spikes 10x times compared to average and you get motion thread lock at that time, it is important to understand, what causes that high load. I'd suspect RAID i/o

[majurgens]

There is a backup that is occurring at this time (and the last time) on a BTRFS RAID 1 set. I have increased the watchdog_timeout to 90 to see what happens

[majurgens]

It happened again
https://www.edcint.co.nz/tmp/expire_14/motion_20220628.log

What I now don't understand is: I set the watchdog timeout to 90 - you can see this in the config BUT the individual threads seem to be getting set to 10 seconds?

[0:motion] [INF] [ALL] [Jun 28 08:44:57] watchdog_tmo 30
[0:motion] [INF] [ALL] [Jun 28 08:44:57] watchdog_kill 90
[0:motion] [INF] [ALL] [Jun 28 08:44:57] watchdog_kill 10
[0:motion] [INF] [ALL] [Jun 28 08:44:57] watchdog_kill 10
[0:motion] [INF] [ALL] [Jun 28 08:44:57] watchdog_kill 10
[0:motion] [ERR] [ALL] [Jun 28 15:08:13] motion_watchdog: Thread 1 - Watchdog timeout. Trying to do a graceful restart
[0:motion] [ERR] [ALL] [Jun 28 15:38:37] motion_watchdog: Thread 2 - Watchdog timeout. Trying to do a graceful restart
[0:motion] [ERR] [ALL] [Jun 28 15:38:47] motion_watchdog: Thread 2 - Watchdog timeout did NOT restart, killing it!
[0:motion] [INF] [ALL] [Jun 28 18:26:50] watchdog_tmo 30
[0:motion] [INF] [ALL] [Jun 28 18:26:50] watchdog_kill 90
[0:motion] [INF] [ALL] [Jun 28 18:26:50] watchdog_kill 10
[0:motion] [INF] [ALL] [Jun 28 18:26:50] watchdog_kill 10
[0:motion] [INF] [ALL] [Jun 28 18:26:50] watchdog_kill 10

Where is the 10 coming from? Its not in any config file I have