SQLite error was (null) after watchdog timeout

[damluk]

I use motion 4.0-1 on Debian Stretch with sqlite3 backend for event logging. After some time INSERTs will stop to work. It seems to always happen after a watchdog timeout:

[1:ml1] [NTC] [EVT] [Oct 22 23:42:26] event_newfile: File of type 1 saved to: /var/lib/motion/20171022233821-1508708546-00.jpg
[1:ml1] [NTC] [EVT] [Oct 22 23:42:26] event_newfile: File of type 1 saved to: /var/lib/motion/20171022233821-1508708546-01.jpg
[1:ml1] [NTC] [EVT] [Oct 22 23:42:27] event_newfile: File of type 1 saved to: /var/lib/motion/20171022233821-1508708547-00.jpg
[1:ml1] [NTC] [EVT] [Oct 22 23:43:00] event_newfile: File of type 1 saved to: /var/lib/motion/20171022233821-1508708552-00.jpg
[0:motion] [ERR] [ALL] [Oct 22 23:43:02] main: Thread 1 - Watchdog timeout, trying to do a graceful restart
[1:ml1] [NTC] [ALL] [Oct 22 23:43:06] motion_loop: Thread exiting
[1:ml1] [NTC] [STR] [Oct 22 23:43:06] stream_stop: Closing motion-stream listen socket & active motion-stream sockets
[1:ml1] [NTC] [STR] [Oct 22 23:43:06] stream_stop: Closed motion-stream listen socket & active motion-stream sockets
[1:ml1] [NTC] [VID] [Oct 22 23:43:06] vid_close: Closing video device /dev/video0
[0:motion] [NTC] [ALL] [Oct 22 23:43:07] main: Motion thread 1 restart
[1:ml1] [NTC] [ALL] [Oct 22 23:43:07] motion_init: Camera 0 started: motion detection Enabled
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] vid_v4lx_start: Using videodevice /dev/video0 and input -1
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_get_capability: 
------------------------
cap.driver: "uvcvideo"
cap.card: "USB 2.0 Camera"
cap.bus_info: "usb-3f980000.usb-1.5"
cap.capabilities=0x84200001
------------------------
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_get_capability: - VIDEO_CAPTURE
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_get_capability: - STREAMING
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_select_input: name = "Camera 1", type 0x00000002, status 00000000
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_select_input: - CAMERA
[1:ml1] [WRN] [VID] [Oct 22 23:43:07] v4l2_select_input: Device doesn't support VIDIOC_G_STD
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format: Config palette index 17 (YU12) doesn't work.
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format: Supported palettes:
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format: (0) MJPG (Motion-JPEG)
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format: 0 - Motion-JPEG (compressed : 1) (0x47504a4d)
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format: (1) YUYV (YUYV 4:2:2)
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format: 1 - YUYV 4:2:2 (compressed : 0) (0x56595559)
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_set_pix_format Selected palette YUYV
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_do_set_pix_format: Testing palette YUYV (1920x1080)
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_do_set_pix_format: Using palette YUYV (1920x1080) bytesperlines 3840 sizeimage 4147200 colorspace 00000008
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980900, "Brightness", range -64,64 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Brightness", default -8193, current 0
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980901, "Contrast", range 0,64 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Contrast", default 57343, current 32
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980902, "Saturation", range 0,128 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Saturation", default 57343, current 60
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980903, "Hue", range -40,40 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Hue", default -8193, current 0
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980918, "Power Line Frequency", range 0,2 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Power Line Frequency", default 1, current 1
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980910, "Gamma", range 72,500 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Gamma", default 57343, current 100
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls: found control 0x00980913, "Gain", range 0,100 
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] v4l2_scan_controls:       "Gain", default 57343, current 0
[1:ml1] [NTC] [VID] [Oct 22 23:43:07] vid_v4lx_start: Using V4L2
[1:ml1] [NTC] [ALL] [Oct 22 23:43:07] image_ring_resize: Resizing pre_capture buffer to 1 items
[1:ml1] [NTC] [DBL] [Oct 22 23:43:07] motion_init: Database backend sqlite3
[1:ml1] [NTC] [DBL] [Oct 22 23:43:07] motion_init: SQLite3 using shared handle
[1:ml1] [NTC] [STR] [Oct 22 23:43:07] http_bindsock: listening on 127.0.0.1 port 8081
[1:ml1] [NTC] [ALL] [Oct 22 23:43:07] motion_init: Started motion-stream server on port 8081 (auth Disabled)
[1:ml1] [NTC] [EVT] [Oct 22 23:48:16] event_new_video Source FPS 2
[1:ml1] [NTC] [ALL] [Oct 22 23:48:16] motion_detected: Motion detected - starting event 1
[1:ml1] [ERR] [DBL] [Oct 22 23:48:16] event_sqlnewfile: SQLite error was (null)
[1:ml1] [NTC] [EVT] [Oct 22 23:48:16] event_newfile: File of type 1 saved to: /var/lib/motion/20171022234816-1508708896-00.jpg
[1:ml1] [NTC] [ALL] [Oct 22 23:49:16] motion_loop: End of event 1
[1:ml1] [NTC] [EVT] [Oct 23 01:00:02] event_new_video Source FPS 2
[1:ml1] [NTC] [ALL] [Oct 23 01:00:02] motion_detected: Motion detected - starting event 2
[1:ml1] [ERR] [DBL] [Oct 23 01:00:02] event_sqlnewfile: SQLite error was (null)
[1:ml1] [NTC] [EVT] [Oct 23 01:00:02] event_newfile: File of type 1 saved to: /var/lib/motion/20171023010001-1508713201-01.jpg
[1:ml1] [ERR] [DBL] [Oct 23 01:00:02] event_sqlnewfile: SQLite error was (null)
[1:ml1] [NTC] [EVT] [Oct 23 01:00:02] event_newfile: File of type 1 saved to: /var/lib/motion/20171023010001-1508713202-00.jpg
[1:ml1] [ERR] [DBL] [Oct 23 01:00:03] event_sqlnewfile: SQLite error was (null)

After some gdb debugging I found out, that sqlite3_exec is returning SQLITE_MISUSE because db->magic, which is checked in sqlite3SafetyCheckOk, is SQLITE_MAGIC_CLOSED.

[damluk]

Besides the sqlite error I wonder what causes the watchdog timeout. My current hypothesis is, that the main-loop thread is stuck inside motion_loop->motion_detected()->event_imagem_detect()->put_picture() due to high IOWAIT. The target_dir is a rather slow USB stick. Is that possible?

[tosiara]

Watchdog may also timeout if V4L blocked (usb or kernel issue)

[damluk]

It certainly helped to use a tmpfs as target_dir and move the files to persistent storage inside the on_event_end script asynchronously.

[liangxiufeng]

When I run the latest version of motion in Ubuntu 16.04 (not including the sql function), it reports that the watchdog times out and how can I do?

[Mr-Dave]

This issue is only related to a restart/re-initialize problem with sqlite3 after a watchdog timeout has occurred. Questions related to other watchdog events and how to prevent them from occurring should be discussed on the mailing list.

[liangxiufeng]

Oh, my question, I have sent the problem