Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Support]: Occasional 2 minute delay in Frigate shutdown/restart #8227

Open
leccelecce opened this issue Oct 18, 2023 · 8 comments
Open

[Support]: Occasional 2 minute delay in Frigate shutdown/restart #8227

leccelecce opened this issue Oct 18, 2023 · 8 comments
Labels
beta Related to the current beta version of frigate pinned support triage

Comments

@leccelecce
Copy link
Contributor

leccelecce commented Oct 18, 2023 •
edited

Describe the problem you are having

Occasionally, it seems one or more of my cameras can block Frigate from shutting down cleanly. Looking at the logs, I can see shutdown entries for each camera "Terminating the existing ffmpeg process..." followed by "Waiting for ffmpeg to exit gracefully..." except for one camera, which never logs either message.

Nothing happens for 2 minutes, then Frigate is killed, which looks to be based on the timeout in docker/main/rootfs/etc/s6-overlay/s6-rc.d/frigate/timeout-kill.

I've attached a full log below - to note:

revotech3 logs a "Terminating..." message, but never logs the second "Waiting..." one, suggesting it might be hanging or never reaching the communicate() call here

frigate/frigate/video.py

Line 129 in cd35481

ffmpeg_process.communicate(timeout=30)

revotech1 doesn't log any message at all, suggesting it's not attempting to stop the process.

I can't readily reproduce this, otherwise I'd try and dive in the container and get a stack trace or ps -ef dump while it's hanging to see which processes are still around.

If this is not straightforward to investigate further, I'm happy to send a PR to add some debug logging (I tend to run in debug anyway) to log out the status of the

Version

0.13.0-DCAFCC1

Frigate config file

n/a

Relevant log output

2023-10-18 21:04:25.576940965  [2023-10-18 21:04:25] peewee_migrate.logs            INFO    : Starting migrations
2023-10-18 21:04:25.593300533  [2023-10-18 21:04:25] peewee_migrate.logs            INFO    : There is nothing to migrate
2023-10-18 21:04:25.605513365  [2023-10-18 21:04:25] frigate.app                    INFO    : Recording process started: 306
2023-10-18 21:04:25.610369585  [2023-10-18 21:04:25] frigate.app                    INFO    : go2rtc process pid: 89
2023-10-18 21:04:25.635981014  [2023-10-18 21:04:25] detector.coral                 INFO    : Starting detection process: 316
2023-10-18 21:04:25.652675153  [2023-10-18 21:04:25] frigate.app                    INFO    : Output process started: 318
2023-10-18 21:04:27.040992622  [INFO] Starting go2rtc healthcheck service...
2023-10-18 21:04:28.293628144  [2023-10-18 21:04:25] frigate.detectors.plugins.edgetpu_tfl INFO    : Attempting to load TPU as usb
2023-10-18 21:04:28.307999350  [2023-10-18 21:04:25] frigate.app                    INFO    : Camera processor started for hikcam4: 327
2023-10-18 21:04:28.312144474  [2023-10-18 21:04:28] frigate.detectors.plugins.edgetpu_tfl INFO    : TPU found
2023-10-18 21:04:28.312279878  [2023-10-18 21:04:25] frigate.app                    INFO    : Camera processor started for hikcam2: 330
2023-10-18 21:04:28.312282482  [2023-10-18 21:04:25] frigate.app                    INFO    : Camera processor started for revotech1: 332
2023-10-18 21:04:28.312362418  [2023-10-18 21:04:25] frigate.app                    INFO    : Camera processor started for revotech3: 333
2023-10-18 21:04:28.312428527  [2023-10-18 21:04:25] frigate.app                    INFO    : Camera processor started for revotech2: 337
2023-10-18 21:04:28.312490756  [2023-10-18 21:04:25] frigate.app                    INFO    : Capture process started for hikcam4: 339
2023-10-18 21:04:28.312555033  [2023-10-18 21:04:25] frigate.app                    INFO    : Capture process started for hikcam2: 344
2023-10-18 21:04:28.312617941  [2023-10-18 21:04:25] frigate.app                    INFO    : Capture process started for revotech1: 347
2023-10-18 21:04:28.312693965  [2023-10-18 21:04:25] frigate.app                    INFO    : Capture process started for revotech3: 360
2023-10-18 21:04:28.312750548  [2023-10-18 21:04:25] frigate.app                    INFO    : Capture process started for revotech2: 369
2023-10-18 21:04:30.855733066  [2023-10-18 21:04:30] frigate.video                  ERROR   : hikcam4: Unable to read frames from ffmpeg process.
2023-10-18 21:04:30.856133499  [2023-10-18 21:04:30] frigate.video                  ERROR   : hikcam4: ffmpeg process is not running. exiting capture                                                   thread...
2023-10-18 21:04:30.898370575  [2023-10-18 21:04:30] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:04:30.898979540  [2023-10-18 21:04:30] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:04:45.754905243  [2023-10-18 21:04:45] watchdog.hikcam4               ERROR   : Ffmpeg process crashed unexpectedly for hikcam4.
2023-10-18 21:04:45.754911953  [2023-10-18 21:04:45] watchdog.hikcam4               ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:04:45.754914022  [2023-10-18 21:04:45] ffmpeg.hikcam4.detect          ERROR   : rtsp://127.0.0.1:8554/hikcam4_resized: Invalid data foun                                                  d when processing input
2023-10-18 21:04:45.796647240  [2023-10-18 21:04:45] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:04:45.796651744  [2023-10-18 21:04:45] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:04:45.796653454  [2023-10-18 21:04:45] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
2023-10-18 21:04:50.935950598  [2023-10-18 21:04:50] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:04:50.937244781  [2023-10-18 21:04:50] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:04:55.809415166  [2023-10-18 21:04:55] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:04:55.809606340  [2023-10-18 21:04:55] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:04:55.809848484  [2023-10-18 21:04:55] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
2023-10-18 21:05:00.980634365  [2023-10-18 21:05:00] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:05:00.980645490  [2023-10-18 21:05:00] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:05:05.835710763  [2023-10-18 21:05:05] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:05:05.835861446  [2023-10-18 21:05:05] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:05:05.835864223  [2023-10-18 21:05:05] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
2023-10-18 21:05:07.150205778  [2023-10-18 21:05:07] frigate.comms.dispatcher       INFO    : Turning off detection for revotech2
2023-10-18 21:05:07.715141810  [2023-10-18 21:05:07] frigate.comms.dispatcher       INFO    : Turning off recordings for revotech2
2023-10-18 21:05:09.429790973  [2023-10-18 21:05:09] frigate.comms.dispatcher       INFO    : Turning off detection for revotech1
2023-10-18 21:05:09.965697770  [2023-10-18 21:05:09] frigate.comms.dispatcher       INFO    : Turning off recordings for revotech1
2023-10-18 21:05:10.978243163  [2023-10-18 21:05:10] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:05:10.978514772  [2023-10-18 21:05:10] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:05:15.856487687  [2023-10-18 21:05:15] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:05:15.856728358  [2023-10-18 21:05:15] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:05:15.856732246  [2023-10-18 21:05:15] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
2023-10-18 21:05:20.985312337  [2023-10-18 21:05:20] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:05:20.985317714  [2023-10-18 21:05:20] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:05:25.863169416  [2023-10-18 21:05:25] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:05:25.863394417  [2023-10-18 21:05:25] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:05:25.863526637  [2023-10-18 21:05:25] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
2023-10-18 21:05:31.006672968  [2023-10-18 21:05:31] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:05:31.008448728  [2023-10-18 21:05:31] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:05:35.893760598  [2023-10-18 21:05:35] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:05:35.893769974  [2023-10-18 21:05:35] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:05:35.893775624  [2023-10-18 21:05:35] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
2023-10-18 21:05:41.038805070  [2023-10-18 21:05:41] frigate.video                  ERROR   : revotech2: Unable to read frames from ffmpeg process.
2023-10-18 21:05:41.038924854  [2023-10-18 21:05:41] frigate.video                  ERROR   : revotech2: ffmpeg process is not running. exiting captur                                                  e thread...
2023-10-18 21:05:45.911339299  [2023-10-18 21:05:45] watchdog.revotech2             ERROR   : Ffmpeg process crashed unexpectedly for revotech2.
2023-10-18 21:05:45.911531719  [2023-10-18 21:05:45] watchdog.revotech2             ERROR   : The following ffmpeg logs include the last 100 lines pri                                                  or to exit.
2023-10-18 21:05:45.911722641  [2023-10-18 21:05:45] ffmpeg.revotech2.detect        ERROR   : rtsp://127.0.0.1:8554/revotech2_resized: Invalid data fo                                                  und when processing input
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service nginx: stopping
s6-rc: info: service go2rtc-healthcheck: stopping
2023-10-18 21:05:53.228571976  [INFO] The go2rtc-healthcheck service exited with code 256 (by signal 15)
s6-rc: info: service go2rtc-healthcheck successfully stopped
2023-10-18 21:05:53.319347064  [INFO] Service NGINX exited with code 0 (by signal 0)
s6-rc: info: service nginx successfully stopped
s6-rc: info: service nginx-log: stopping
s6-rc: info: service frigate: stopping
2023-10-18 21:05:53.325628018  [2023-10-18 21:05:53] frigate.app                    INFO    : Stopping...
s6-rc: info: service nginx-log successfully stopped
2023-10-18 21:05:53.326430414  [2023-10-18 21:05:53] detector.coral                 INFO    : Signal to exit detection process...
2023-10-18 21:05:53.326627526  [2023-10-18 21:05:53] root                           INFO    : Waiting for detection process to exit gracefully...
2023-10-18 21:05:53.326793272  [2023-10-18 21:05:53] frigate.ptz.autotrack          INFO    : Exiting autotracker...
2023-10-18 21:05:53.327204688  [2023-10-18 21:05:53] frigate.storage                INFO    : Exiting storage maintainer...
2023-10-18 21:05:53.327353580  [2023-10-18 21:05:53] frigate.record.cleanup         INFO    : Exiting recording cleanup...
2023-10-18 21:05:53.328330334  [2023-10-18 21:05:53] frigate.events.cleanup         INFO    : Exiting event cleanup...
2023-10-18 21:05:53.357243580  [2023-10-18 21:05:53] frigate.stats                  INFO    : Exiting stats emitter...
2023-10-18 21:05:53.388330504  [2023-10-18 21:05:53] frigate.watchdog               INFO    : Exiting watchdog...
2023-10-18 21:05:53.528949506  [2023-10-18 21:05:53] detector.coral                 INFO    : Exited detection process...
2023-10-18 21:05:53.530573050  [2023-10-18 21:05:53] frigate.object_processing      INFO    : Exiting object processor...
2023-10-18 21:05:53.553560633  [2023-10-18 21:05:53] root                           INFO    : Detection process has exited...
2023-10-18 21:05:53.684891574  [2023-10-18 21:05:53] frigate.comms.ws               INFO    : Exiting websocket client...
2023-10-18 21:05:54.050581691  [2023-10-18 21:05:54] frigate.events.maintainer      INFO    : Exiting event processor...
2023-10-18 21:05:54.274527943  [2023-10-18 21:05:54] peewee.sqliteq                 INFO    : writer received shutdown request, exiting.
2023-10-18 21:05:54.287609494  [2023-10-18 21:05:54] watchdog.hikcam2               INFO    : Terminating the existing ffmpeg process...
2023-10-18 21:05:54.288821714  [2023-10-18 21:05:54] watchdog.hikcam4               INFO    : Terminating the existing ffmpeg process...
2023-10-18 21:05:54.288830635  [2023-10-18 21:05:54] watchdog.hikcam4               INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 21:05:54.288836368  [2023-10-18 21:05:54] watchdog.revotech2             INFO    : Terminating the existing ffmpeg process...
2023-10-18 21:05:54.288988377  [2023-10-18 21:05:54] watchdog.revotech2             INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 21:05:54.289339974  [2023-10-18 21:05:54] watchdog.hikcam2               INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 21:05:54.289348568  [2023-10-18 21:05:54] watchdog.revotech3             INFO    : Terminating the existing ffmpeg process...
2023-10-18 21:07:53.402276513  [INFO] Service Frigate exited with code 256 (by signal 9)
s6-rc: info: service frigate successfully stopped
s6-rc: info: service go2rtc: stopping
s6-rc: info: service frigate-log: stopping
2023-10-18 21:07:53.407744785  exit with signal: terminated
s6-rc: info: service frigate-log successfully stopped
2023-10-18 21:07:53.419453954  [INFO] The go2rtc service exited with code 0 (by signal 0)
s6-rc: info: service go2rtc successfully stopped
s6-rc: info: service go2rtc-log: stopping
s6-rc: info: service go2rtc-log successfully stopped
s6-rc: info: service log-prepare: stopping
s6-rc: info: service s6rc-fdholder: stopping
s6-rc: info: service log-prepare successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service s6rc-fdholder successfully stopped
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped

FFprobe output from your camera

Stream 0:
Return Code: 0

Video:

Codec: H.264 / AVC / MPEG-4 AVC / MPEG-4 part 10
Resolution: 2304x1296
FPS: 20/1

Frigate stats

No response

Operating system

Debian

Install method

Docker Compose

Coral version

USB

Network connection

Wired

Camera make and model

various

Any other information that may be helpful

For comparison, here is a "healthy" exit which takes a few seconds.

2023-10-18 23:14:33.629124376  [2023-10-18 23:14:33] frigate.app                    INFO    : Stopping...
2023-10-18 23:14:33.630967716  [2023-10-18 23:14:33] detector.coral                 INFO    : Signal to exit detection process...
s6-rc: info: service nginx-log successfully stopped
2023-10-18 23:14:33.632325844  [2023-10-18 23:14:33] root                           INFO    : Waiting for detection process to exit gracefully...
2023-10-18 23:14:33.633176411  [2023-10-18 23:14:33] frigate.watchdog               INFO    : Exiting watchdog...
2023-10-18 23:14:33.633183786  [2023-10-18 23:14:33] frigate.ptz.autotrack          INFO    : Exiting autotracker...
2023-10-18 23:14:33.633188752  [2023-10-18 23:14:33] frigate.events.cleanup         INFO    : Exiting event cleanup...
2023-10-18 23:14:33.634320827  [2023-10-18 23:14:33] frigate.stats                  INFO    : Exiting stats emitter...
2023-10-18 23:14:33.634359351  [2023-10-18 23:14:33] frigate.record.cleanup         INFO    : Exiting recording cleanup...
2023-10-18 23:14:33.634818374  [2023-10-18 23:14:33] frigate.storage                INFO    : Exiting storage maintainer...
2023-10-18 23:14:33.733353838  [2023-10-18 23:14:33] detector.coral                 INFO    : Exited detection process...
2023-10-18 23:14:33.751535381  [2023-10-18 23:14:33] frigate.object_processing      INFO    : Exiting object processor...
2023-10-18 23:14:33.754628289  [2023-10-18 23:14:33] root                           INFO    : Detection process has exited...
2023-10-18 23:14:33.916876168  [2023-10-18 23:14:33] frigate.comms.ws               INFO    : Exiting websocket client...
2023-10-18 23:14:34.254228255  [2023-10-18 23:14:34] frigate.events.maintainer      INFO    : Exiting event processor...
2023-10-18 23:14:34.339834872  [2023-10-18 23:14:34] peewee.sqliteq                 INFO    : writer received shutdown request, exiting.
2023-10-18 23:14:34.345585284  [2023-10-18 23:14:34] watchdog.hikcam4               INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.347471488  [2023-10-18 23:14:34] watchdog.revotech2             INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.347477840  [2023-10-18 23:14:34] watchdog.revotech2             INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.347481794  [2023-10-18 23:14:34] watchdog.revotech2             INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.347485250  [2023-10-18 23:14:34] watchdog.hikcam2               INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.347488577  [2023-10-18 23:14:34] watchdog.revotech2             INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.347491957  [2023-10-18 23:14:34] watchdog.hikcam2               INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.347495398  [2023-10-18 23:14:34] watchdog.revotech1             INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.347498447  [2023-10-18 23:14:34] watchdog.revotech1             INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.347501682  [2023-10-18 23:14:34] watchdog.revotech3             INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.347565661  [2023-10-18 23:14:34] watchdog.revotech3             INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.348052025  [2023-10-18 23:14:34] watchdog.hikcam4               INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.403249196  [2023-10-18 23:14:34] watchdog.hikcam2               INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.403388525  [2023-10-18 23:14:34] watchdog.hikcam2               INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.412566412  [2023-10-18 23:14:34] watchdog.hikcam4               INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.412658999  [2023-10-18 23:14:34] watchdog.hikcam4               INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:34.417653170  [2023-10-18 23:14:34] frigate.video                  INFO    : revotech2: exiting subprocess
2023-10-18 23:14:34.468912880  [2023-10-18 23:14:34] frigate.video                  INFO    : revotech1: exiting subprocess
2023-10-18 23:14:34.476102269  [2023-10-18 23:14:34] watchdog.revotech1             INFO    : Terminating the existing ffmpeg process...
2023-10-18 23:14:34.476191932  [2023-10-18 23:14:34] watchdog.revotech1             INFO    : Waiting for ffmpeg to exit gracefully...
2023-10-18 23:14:35.304910336  [2023-10-18 23:14:35] frigate.video                  INFO    : hikcam2: exiting subprocess
2023-10-18 23:14:35.416981563  [2023-10-18 23:14:35] frigate.output                 INFO    : exiting output process...
2023-10-18 23:14:39.421036140  /usr/lib/python3.9/multiprocessing/resource_tracker.py:216: UserWarning: resource_tracker: There appear to be 18 leaked shared_memory objects to clean up at shutdown
2023-10-18 23:14:39.421039135    warnings.warn('resource_tracker: There appear to be %d '
2023-10-18 23:14:39.424203455  [INFO] Service Frigate exited with code 0 (by signal 0)
@NickM-27 NickM-27 added the beta Related to the current beta version of frigate label Oct 18, 2023
@leccelecce
Copy link
Contributor Author

One possibility: if Frigate hasn't shutdown within 30s, could something like https://docs.python.org/3.11/library/faulthandler.html#faulthandler.dump_traceback_later be used to dump a full stack trace?

@blakeblackshear
Copy link
Owner

I have seen this too.

@leccelecce
Copy link
Contributor Author

Another case today on 0.13.0-beta5 / 0.13.0-AA93D4F

2023-12-03 19:43:59.166445352  192.168.10.52 - - [03/Dec/2023:19:43:59 +0000] "POST /api/config/save?save_option=restart HTTP/1.1" 200 103 "http://frigate.local.lan:5000/config" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36" "-"
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service nginx: stopping
s6-rc: info: service go2rtc-healthcheck: stopping
2023-12-03 19:43:59.174041819  [INFO] The go2rtc-healthcheck service exited with code 256 (by signal 15)
s6-rc: info: service go2rtc-healthcheck successfully stopped
2023-12-03 19:43:59.232733213  [INFO] Service NGINX exited with code 0 (by signal 0)
s6-rc: info: service nginx successfully stopped
s6-rc: info: service nginx-log: stopping
s6-rc: info: service frigate: stopping
2023-12-03 19:43:59.239490202  [2023-12-03 19:43:59] frigate.app                    INFO    : Stopping...
2023-12-03 19:43:59.241296399  [2023-12-03 19:43:59] detector.coral                 INFO    : Signal to exit detection process...
s6-rc: info: service nginx-log successfully stopped
2023-12-03 19:43:59.260609463  [2023-12-03 19:43:59] root                           INFO    : Waiting for detection process to exit gracefully...
2023-12-03 19:43:59.260812153  [2023-12-03 19:43:59] frigate.events.cleanup         INFO    : Exiting event cleanup...
2023-12-03 19:43:59.260906119  [2023-12-03 19:43:59] frigate.storage                INFO    : Exiting storage maintainer...
2023-12-03 19:43:59.261087329  [2023-12-03 19:43:59] frigate.watchdog               INFO    : Exiting watchdog...
2023-12-03 19:43:59.261412784  [2023-12-03 19:43:59] frigate.ptz.autotrack          INFO    : Exiting autotracker...
2023-12-03 19:43:59.262043627  [2023-12-03 19:43:59] frigate.record.cleanup         INFO    : Exiting recording cleanup...
2023-12-03 19:43:59.262191489  [2023-12-03 19:43:59] frigate.stats                  INFO    : Exiting stats emitter...
2023-12-03 19:43:59.268644534  [2023-12-03 19:43:59] frigate.object_processing      INFO    : Exiting object processor...
2023-12-03 19:43:59.779215897  [2023-12-03 19:43:59] detector.coral                 INFO    : Exited detection process...
2023-12-03 19:43:59.809844405  [2023-12-03 19:43:59] root                           INFO    : Detection process has exited...
2023-12-03 19:43:59.963618010  [2023-12-03 19:43:59] frigate.comms.ws               INFO    : Exiting websocket client...
2023-12-03 19:43:59.976752861  [2023-12-03 19:43:59] frigate.events.maintainer      INFO    : Exiting event processor...
2023-12-03 19:44:00.548013662  [2023-12-03 19:44:00] peewee.sqliteq                 INFO    : writer received shutdown request, exiting.
2023-12-03 19:44:00.555360334  [2023-12-03 19:44:00] watchdog.hikcam5               INFO    : Terminating the existing ffmpeg process...
2023-12-03 19:44:00.555370593  [2023-12-03 19:44:00] watchdog.hikcam5               INFO    : Waiting for ffmpeg to exit gracefully...
2023-12-03 19:44:00.555376276  [2023-12-03 19:44:00] watchdog.revotech2             INFO    : Terminating the existing ffmpeg process...
2023-12-03 19:44:00.555381230  [2023-12-03 19:44:00] watchdog.revotech2             INFO    : Waiting for ffmpeg to exit gracefully...
2023-12-03 19:44:00.555385958  [2023-12-03 19:44:00] watchdog.revotech1             INFO    : Terminating the existing ffmpeg process...
2023-12-03 19:44:00.555390366  [2023-12-03 19:44:00] watchdog.revotech1             INFO    : Waiting for ffmpeg to exit gracefully...
2023-12-03 19:44:00.555989089  [2023-12-03 19:44:00] watchdog.hikcam2               INFO    : Terminating the existing ffmpeg process...
2023-12-03 19:44:00.556463657  [2023-12-03 19:44:00] watchdog.revotech3             INFO    : Terminating the existing ffmpeg process...
2023-12-03 19:44:00.556745533  [2023-12-03 19:44:00] watchdog.revotech3             INFO    : Waiting for ffmpeg to exit gracefully...
2023-12-03 19:44:00.557016093  [2023-12-03 19:44:00] watchdog.hikcam2               INFO    : Waiting for ffmpeg to exit gracefully...
2023-12-03 19:44:00.557941902  [2023-12-03 19:44:00] frigate.record.maintainer      INFO    : Exiting recording maintenance...
2023-12-03 19:45:59.302596293  [INFO] Service Frigate exited with code 256 (by signal 9)
s6-rc: info: service frigate successfully stopped
s6-rc: info: service go2rtc: stopping
s6-rc: info: service frigate-log: stopping
2023-12-03 19:45:59.307903973  exit with signal: terminated
s6-rc: info: service frigate-log successfully stopped
2023-12-03 19:45:59.312167423  [INFO] The go2rtc service exited with code 0 (by signal 0)
s6-rc: info: service go2rtc successfully stopped
s6-rc: info: service go2rtc-log: stopping
s6-rc: info: service go2rtc-log successfully stopped
s6-rc: info: service log-prepare: stopping
s6-rc: info: service s6rc-fdholder: stopping
s6-rc: info: service log-prepare successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service s6rc-fdholder successfully stopped
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped

@NickM-27 NickM-27 mentioned this issue Dec 6, 2023
Closed
@leccelecce
Copy link
Contributor Author

I think I managed to catch this using pystack:

root@e721ba5834ba:/opt/frigate# ps -ef
UID          PID    PPID  C STIME TTY          TIME CMD
root           1       0  0 00:31 ?        00:00:00 /package/admin/s6/command/s6-svscan -d4 -- /run/service
root          14       1  0 00:31 ?        00:00:00 s6-supervise s6-linux-init-shutdownd
root          15      14  0 00:31 ?        00:00:00 /package/admin/s6-linux-init/command/s6-linux-init-shutdownd -c /run/s6/basedir -g 3000 -C -B
root          23       1  0 00:31 ?        00:00:00 s6-supervise s6rc-oneshot-runner
root          24       1  0 00:31 ?        00:00:00 s6-supervise go2rtc
root          25       1  0 00:31 ?        00:00:00 s6-supervise frigate-log
root          26       1  0 00:31 ?        00:00:00 s6-supervise s6rc-fdholder
root          27       1  0 00:31 ?        00:00:00 s6-supervise go2rtc-healthcheck
root          28       1  0 00:31 ?        00:00:00 s6-supervise nginx
root          29       1  0 00:31 ?        00:00:00 s6-supervise nginx-log
root          30       1  0 00:31 ?        00:00:00 s6-supervise frigate
root          31       1  0 00:31 ?        00:00:00 s6-supervise go2rtc-log
root          40      26  0 00:31 ?        00:00:00 /package/admin/s6-2.11.3.2/command/s6-fdholderd -1 -i data/rules
root          41      23  0 00:31 ?        00:00:00 /package/admin/s6/command/s6-ipcserverd -1 -- /package/admin/s6/command/s6-ipcserver-access -v0 -E -l0 -i data/rules -- /package/admin/s6/command/s6
nobody        80      31  0 00:31 ?        00:00:00 s6-log -b -- T 1 n0 s10000000 T /dev/shm/logs/go2rtc
nobody        81      25  0 00:31 ?        00:00:00 s6-log -b -- T 1 n0 s10000000 T /dev/shm/logs/frigate
root          88      24 23 00:31 ?        04:43:33 /usr/local/go2rtc/bin/go2rtc -config=/dev/shm/go2rtc.yaml
root         111      30  1 00:31 ?        00:21:26 python3 -u -m frigate
root         300     111  2 00:31 ?        00:29:46 [frigate.recordi] <defunct>
root         309     111  0 00:31 ?        00:02:43 /usr/bin/python3 -c from multiprocessing.resource_tracker import main;main(61)
root         313     111  1 00:31 ?        00:13:43 frigate.output
root         321     111  3 00:31 ?        00:48:15 frigate.process:hikcam2
root         323     111  1 00:31 ?        00:18:25 [frigate.process] <defunct>
root         327     111  1 00:31 ?        00:15:18 frigate.process:revotech3
root         329     111  1 00:31 ?        00:13:23 frigate.process:revotech2
root         333     111  2 00:31 ?        00:24:37 [frigate.capture] <defunct>
root         352     111  0 00:31 ?        00:09:28 [frigate.capture] <defunct>
root      219211      15  0 20:48 ?        00:00:00 s6-rc -v2 -bda change
root      219229  219211  0 20:48 ?        00:00:00 /package/admin/s6-2.11.3.2/command/s6-svlisten1 -D -- /run/s6-rc/servicedirs/frigate /package/admin/s6-2.11.3.2/command/s6-svc -d -- /run/s6-rc/serv
root      219231  219229  0 20:48 ?        00:00:00 /package/admin/s6/command/s6-ftrigrd
root      219490       0  0 20:49 pts/0    00:00:00 /bin/bash
root      219534  219490  0 20:50 pts/0    00:00:00 ps -ef

pystack remote 111 output seems to show only a single thread left in the process:

Traceback for thread 111 (python3) [] (most recent call last):
    (Python) File "/usr/lib/python3.9/multiprocessing/util.py", line 357, in _exit_function
        p.join()
    (Python) File "/usr/lib/python3.9/multiprocessing/process.py", line 149, in join
        res = self._popen.wait(timeout)
    (Python) File "/usr/lib/python3.9/multiprocessing/popen_fork.py", line 43, in wait
        return self.poll(os.WNOHANG if timeout == 0.0 else 0)
    (Python) File "/usr/lib/python3.9/multiprocessing/popen_fork.py", line 27, in poll
        pid, sts = os.waitpid(self.pid, flag)

Not sure if that helps much.

@leccelecce
Copy link
Contributor Author

I've updated my pystack script with --locals and --native to try and capture a bit more next time in case the above isn't sufficient.

@NickM-27
Copy link
Sponsor Collaborator

looks like there are a couple python sub processes processes open, that additional info will likely be helpful

@leccelecce
Copy link
Contributor Author

Had a reoccurence, pystack output this time with --locals and --native flags is below.

Unfortunately other than showing that the hanging code seems to be Python C code that's trying to run a finalizer I'm not sure if it's much more helpful.

Traceback for thread 113 (python3) [] (most recent call last):
    (C) File "???", line 0, in _start (/usr/bin/python3.9)
    (C) File "???", line 0, in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6)
    (C) File "???", line 0, in Py_BytesMain (/usr/bin/python3.9)
    (C) File "???", line 0, in Py_RunMain (/usr/bin/python3.9)
    (C) File "???", line 0, in Py_FinalizeEx (/usr/bin/python3.9)
    (Python) File "/usr/lib/python3.9/multiprocessing/util.py", line 357, in _exit_function
        p.join()
      Arguments:
        current_process: <function at 0x7fb6db6cb040>
        active_children: <function at 0x7fb6db6cb0d0>
        _run_finalizers: <function at 0x7fb6db6b3430>
        debug: <function at 0x7fb6db6c0d30>
        info: <function at 0x7fb6db6c0dc0>
      Locals:
        p: <Process at 0x7fb6b21b7280>
    (Python) File "/usr/lib/python3.9/multiprocessing/process.py", line 149, in join
        res = self._popen.wait(timeout)
      Arguments:
        timeout: None
        self: <Process at 0x7fb6b21b7280>
    (Python) File "/usr/lib/python3.9/multiprocessing/popen_fork.py", line 43, in wait
        return self.poll(os.WNOHANG if timeout == 0.0 else 0)
      Arguments:
        timeout: None
        self: <Popen at 0x7fb6b21b72b0>
    (Python) File "/usr/lib/python3.9/multiprocessing/popen_fork.py", line 27, in poll
        pid, sts = os.waitpid(self.pid, flag)
      Arguments:
        flag: 0
        self: <Popen at 0x7fb6b21b72b0>
    (C) File "???", line 0, in wait4 (/lib/x86_64-linux-gnu/libc.so.6)

Output of ps -ef (from host, not within container, so PIDs don't match but 12177 below is 113 in the above).

root       12043   12023  0 23:42 ?        00:00:00 /package/admin/s6/command/s6-svscan -d4 -- /run/service
root       12085   12043  0 23:42 ?        00:00:00 s6-supervise s6-linux-init-shutdownd
root       12087   12085  0 23:42 ?        00:00:00 /package/admin/s6-linux-init/command/s6-linux-init-shutdownd -c /run/s6/basedir -g 3000 -C -B
root       12094   12043  0 23:42 ?        00:00:00 s6-supervise s6rc-oneshot-runner
root       12095   12043  0 23:42 ?        00:00:00 s6-supervise go2rtc
root       12096   12043  0 23:42 ?        00:00:00 s6-supervise frigate-log
root       12097   12043  0 23:42 ?        00:00:00 s6-supervise s6rc-fdholder
root       12098   12043  0 23:42 ?        00:00:00 s6-supervise go2rtc-healthcheck
root       12099   12043  0 23:42 ?        00:00:00 s6-supervise nginx
root       12100   12043  0 23:42 ?        00:00:00 s6-supervise nginx-log
root       12101   12043  0 23:42 ?        00:00:00 s6-supervise frigate
root       12102   12043  0 23:42 ?        00:00:00 s6-supervise go2rtc-log
root       12111   12097  0 23:42 ?        00:00:00 /package/admin/s6-2.11.3.2/command/s6-fdholderd -1 -i data/rules
root       12112   12094  0 23:42 ?        00:00:00 /package/admin/s6/command/s6-ipcserverd -1 -- /package/admin/s6/command/s6-ipcserver-access -v0 -E -l0 -i da
nobody     12151   12102  0 23:42 ?        00:00:00 s6-log -b -- T 1 n0 s10000000 T /dev/shm/logs/go2rtc
nobody     12152   12096  0 23:42 ?        00:00:00 s6-log -b -- T 1 n0 s10000000 T /dev/shm/logs/frigate
root       12159   12095  4 23:42 ?        00:00:07 /usr/local/go2rtc/bin/go2rtc -config=/dev/shm/go2rtc.yaml
root       12177   12101  2 23:42 ?        00:00:03 python3 -u -m frigate
root       12367   12177  0 23:42 ?        00:00:00 [frigate.logger] <defunct>
root       12383   12177  0 23:42 ?        00:00:00 /usr/bin/python3 -c from multiprocessing.resource_tracker import main;main(61)
root       12386   12177  0 23:42 ?        00:00:00 [frigate.output] <defunct>
root       12398   12177  1 23:42 ?        00:00:02 frigate.process:hikcam2
root       12404   12177  1 23:42 ?        00:00:02 frigate.process:revotech3
root       12420   12177  0 23:42 ?        00:00:00 frigate.process:revotech2
root       12422   12177  0 23:42 ?        00:00:00 [frigate.capture] <defunct>
root       12430   12177  0 23:42 ?        00:00:00 [frigate.capture] <defunct>
root       12790   12087  0 23:43 ?        00:00:00 s6-rc -v2 -bda change
root       12808   12790  0 23:43 ?        00:00:00 /package/admin/s6-2.11.3.2/command/s6-svlisten1 -D -- /run/s6-rc/servicedirs/frigate /package/admin/s6-2.11.
root       12810   12808  0 23:43 ?        00:00:00 /package/admin/s6/command/s6-ftrigrd

@leccelecce
Copy link
Contributor Author

Still occurring in 0.14 dev builds so will have another go at getting some more debug data.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
beta Related to the current beta version of frigate pinned support triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@blakeblackshear @NickM-27 @leccelecce