Backend waking up and immediately going back to sleep before recording starts

[cornflake]

I had a couple of recordings fail recently, the last one last night at 23:00. Looking at the SystemD and mythbackend logs, it looks like the backend woke up properly at 22:58, but went back to sleep 13 seconds later, missing the recording completely until woken up by a frontend connecting at 08:10 the next morning.

SystemD journal

Code: Select all

Jun 22 21:01:33 Lenovo systemd[1]: Starting Suspend...
Jun 22 21:01:33 Lenovo systemd-sleep[1911]: Suspending system...
Jun 22 22:58:00 Lenovo kernel: Filesystems sync: 0.442 seconds
Jun 22 22:58:00 Lenovo kernel: Freezing user space processes ... (elapsed 0.023 seconds) done.
Jun 22 22:58:00 Lenovo systemd-sleep[1911]: System resumed.
Jun 22 22:58:13 Lenovo kernel: ACPI: Low-level resume complete
Jun 22 22:58:13 Lenovo kernel: ACPI: Preparing to enter system sleep state S3
Jun 22 22:58:13 Lenovo kernel: Disabling non-boot CPUs ...
Jun 22 22:58:13 Lenovo kernel: Enabling non-boot CPUs ...
Jun 22 22:58:13 Lenovo kernel: Freezing remaining freezable tasks ... (elapsed 0.000 seconds) done.
Jun 22 22:58:13 Lenovo kernel: OOM killer disabled.
Jun 22 22:58:13 Lenovo kernel: PM: Restoring platform NVS memory
Jun 22 22:58:13 Lenovo kernel: PM: Saving platform NVS memory
Jun 22 22:58:13 Lenovo kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Jun 22 22:58:13 Lenovo kernel: sd 2:0:0:0: [sda] Stopping disk
Jun 22 22:58:13 Lenovo kernel: sd 2:0:0:0: [sda] Synchronizing SCSI cache
Jun 22 22:58:13 Lenovo kernel: smpboot: Booting Node 0 Processor 1 APIC 0x1
Jun 22 22:58:13 Lenovo kernel: smpboot: CPU 1 is now offline
Jun 22 22:58:13 Lenovo kernel: x86: Booting SMP configuration:
Jun 22 22:58:13 Lenovo sudo[1941]:   mythtv : PWD=/ ; USER=root ; COMMAND=/etc/myth_set_alarm 2021-06-22 22:58:00
Jun 22 22:58:13 Lenovo sudo[1941]: pam_unix(sudo:session): session closed for user root
Jun 22 22:58:13 Lenovo sudo[1941]: pam_unix(sudo:session): session opened for user root by (uid=477)
Jun 22 22:58:13 Lenovo sudo[1944]:   mythtv : PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl suspend
Jun 22 22:58:13 Lenovo sudo[1944]: pam_unix(sudo:session): session closed for user root
Jun 22 22:58:13 Lenovo sudo[1944]: pam_unix(sudo:session): session opened for user root by (uid=477)
Jun 22 22:58:13 Lenovo systemd[1]: Finished Suspend.
Jun 22 22:58:13 Lenovo systemd[1]: Reached target Sleep.
Jun 22 22:58:13 Lenovo systemd[1]: Reached target Suspend.
Jun 22 22:58:13 Lenovo systemd[1]: session-c128.scope: Succeeded.
Jun 22 22:58:13 Lenovo systemd[1]: session-c129.scope: Succeeded.
Jun 22 22:58:13 Lenovo systemd[1]: Started Session c128 of user root.
Jun 22 22:58:13 Lenovo systemd[1]: Started Session c129 of user root.
Jun 22 22:58:13 Lenovo systemd[1]: Starting Suspend...
Jun 22 22:58:13 Lenovo systemd[1]: Stopped target Sleep.
Jun 22 22:58:13 Lenovo systemd[1]: Stopped target Suspend.
Jun 22 22:58:13 Lenovo systemd[1]: systemd-suspend.service: Succeeded.
Jun 22 22:58:13 Lenovo systemd-logind[167]: Operation 'sleep' finished.
Jun 22 22:58:13 Lenovo systemd-sleep[1946]: Suspending system...
Jun 23 08:10:23 Lenovo kernel: ACPI: Waking up from system sleep state S3

Myth backend log

Code: Select all

2021-06-22 21:00:30.969020 N [2030/1782] RecThread recorders/recorderbase.cpp:507 (FinishRecording) - Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (1280x720 A/R: 3 59.9401fps) Audio Codec: ac3
2021-06-22 21:00:31.035223 E [2030/2030] CoreContext mainserver.cpp:1199 (customEvent) - MainServer: PREVIEW_SUCCESS but no receivers.
2021-06-22 21:00:31.061686 I [2030/2044] TVRecEvent recordinginfo.cpp:1238 (FinishedRecording) - Finished recording LEGO Masters "Hats Incredible!": channel 10809
2021-06-22 21:00:31.061832 I [2030/2030] CoreContext scheduler.cpp:729 (UpdateRecStatus) - Updating status for "LEGO Masters":"Hats Incredible!" on cardid [1] (Recording => Recorded)
2021-06-22 21:00:31.133290 I [2030/2048] Scheduler scheduler.cpp:2356 (HandleReschedule) - Reschedule requested for CHECK -3 1247 0 UpdateRecStatus2 | LEGO Masters | Hats Incredible! | The teams create wearable hats made entirely of LEGO bricks, then model their designs on the runway. | EP032757510014
2021-06-22 21:00:31.300686 I [2030/2048] Scheduler scheduler.cpp:2472 (HandleReschedule) - Scheduled 43 items in 0.1 = 0.04 match + 0.09 check + 0.02 place
2021-06-22 21:00:49.186214 I [2030/1830] MythSocketThread(80) mainserver.cpp:7930 (connectionClosed) - Playback sock(7f06e40e1670) 'Lenovo' disconnected
2021-06-22 21:00:50.664853 I [2030/1824] MythSocketThread(76) mainserver.cpp:7930 (connectionClosed) - Playback sock(556ce86ae9e0) 'Lenovo' disconnected
2021-06-22 21:00:50.665137 I [2030/1826] MythSocketThread(78) mainserver.cpp:7930 (connectionClosed) - Monitor sock(556ce86cc970) 'Lenovo' disconnected
2021-06-22 21:00:52.693035 I [2030/1873] ProcessRequest mainserver.cpp:1780 (HandleAnnounce) - MainServer: MainServer::ANN Playback
2021-06-22 21:00:52.693053 I [2030/1873] ProcessRequest mainserver.cpp:1785 (HandleAnnounce) - MainServer: adding: Lenovo(556ce8745310) as a client (events: 0)
2021-06-22 21:00:52.693734 I [2030/1873] ProcessRequest mainserver.cpp:1780 (HandleAnnounce) - MainServer: MainServer::ANN Monitor
2021-06-22 21:00:52.693742 I [2030/1873] ProcessRequest mainserver.cpp:1785 (HandleAnnounce) - MainServer: adding: Lenovo(7f06dc0020c0) as a client (events: 1)
2021-06-22 21:01:07.292470 I [2030/1882] MythSocketThread(54) mainserver.cpp:7930 (connectionClosed) - Playback sock(556ce8745310) 'Lenovo' disconnected
2021-06-22 21:01:07.292807 I [2030/1884] MythSocketThread(56) mainserver.cpp:7930 (connectionClosed) - Monitor sock(7f06dc0020c0) 'Lenovo' disconnected
2021-06-22 21:01:16.538747 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds.
2021-06-22 21:01:31.609098 N [2030/2048] Scheduler scheduler.cpp:3435 (ShutdownServer) - Running the command to set the next scheduled wakeup time :-
                                sudo /etc/myth_set_alarm "2021-06-22 22:58:00"
2021-06-22 21:01:33.322128 N [2030/2048] Scheduler scheduler.cpp:3466 (ShutdownServer) - Running the command to shutdown this computer :-
                                sudo /usr/bin/systemctl suspend
2021-06-22 21:01:33.712733 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds.
2021-06-22 22:58:03.272965 I [2030/2048] Scheduler mythdbcon.cpp:431 (PurgeIdleConnections) - New DB connection, total: 9
2021-06-22 22:58:13.389999 I [2030/2048] Scheduler scheduler.cpp:3325 (CheckShutdownServer) - CheckShutdownServer returned - OK to shutdown
2021-06-22 22:58:13.390110 N [2030/2048] Scheduler scheduler.cpp:3435 (ShutdownServer) - Running the command to set the next scheduled wakeup time :-
                                sudo /etc/myth_set_alarm "2021-06-22 22:58:00"
2021-06-22 22:58:13.440957 N [2030/2048] Scheduler scheduler.cpp:3466 (ShutdownServer) - Running the command to shutdown this computer :-
                                sudo /usr/bin/systemctl suspend
2021-06-23 08:10:25.989326 I [2030/2049] Expire mythdbcon.cpp:431 (PurgeIdleConnections) - New DB connection, total: 9
2021-06-23 08:10:36.182668 N [2030/2049] Expire autoexpire.cpp:261 (CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 20.0 GB w/freq: 15 min
2021-06-23 08:10:36.410615 I [2030/2048] Scheduler mythdbcon.cpp:431 (PurgeIdleConnections) - New DB connection, total: 9
2021-06-23 08:10:36.692370 I [2030/2030] CoreContext mythdbcon.cpp:431 (PurgeIdleConnections) - New DB connection, total: 9
2021-06-23 08:10:36.854940 C [2030/2030] CoreContext programinfo.cpp:347 (ProgramInfo) - ProgramInfo(): Failed to find recorded entry for 0.
2021-06-23 08:10:37.365553 I [2030/2044] TVRecEvent tv_rec.cpp:1091 (HandleStateChange) - TVRec[1]: Changing from None to RecordingOnly
2021-06-23 08:10:37.365605 I [2030/2044] TVRecEvent mythdbcon.cpp:431 (PurgeIdleConnections) - New DB connection, total: 9
2021-06-23 08:10:37.366597 I [2030/2044] TVRecEvent tv_rec.cpp:3682 (TuningFrequency) - TVRec[1]: TuningFrequency
2021-06-23 08:10:37.383119 I [2030/2044] TVRecEvent recorders/hdhrstreamhandler.cpp:385 (Connect) - HDHRSH[1](131C257E): Added 3 devices from 131C257E
2021-06-23 08:10:37.399830 I [2030/2044] TVRecEvent recorders/hdhrstreamhandler.cpp:403 (Connect) - HDHRSH[1](131C257E): Connected to device(131C257E-0)
2021-06-23 08:10:37.488081 E [2030/2044] TVRecEvent tv_rec.cpp:3976 (TuningSignalCheck) - TVRec[1]: TuningSignalCheck: SignalMonitor timed out
2021-06-23 08:10:37.488183 I [2030/2030] CoreContext scheduler.cpp:729 (UpdateRecStatus) - Updating status for Conan on cardid [1] (Pending => Recorder Failed)
2021-06-23 08:10:37.539503 I [2030/2044] TVRecEvent tv_rec.cpp:1091 (HandleStateChange) - TVRec[1]: Changing from RecordingOnly to None
2021-06-23 08:10:37.692924 I [2030/2048] Scheduler scheduler.cpp:3325 (CheckShutdownServer) - CheckShutdownServer returned - OK to shutdown
2021-06-23 08:10:37.692942 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds.
2021-06-23 08:10:37.693064 I [2030/2048] Scheduler scheduler.cpp:2356 (HandleReschedule) - Reschedule requested for PLACE PrepareToRecord
2021-06-23 08:10:37.693080 I [2030/2048] Scheduler scheduler.cpp:2356 (HandleReschedule) - Reschedule requested for CHECK -9 1228 0 UpdateRecStatus2 | Conan |  |  | EP038114690057
2021-06-23 08:10:37.740532 I [2030/2048] Scheduler scheduler.cpp:2472 (HandleReschedule) - Scheduled 42 items in 0.0 = 0.00 match + 0.00 check + 0.02 place

[dnalorernst]

Does this help?
Thread: Myth Shutdown Shortly After Waking
viewtopic.php?f=36&t=3917#p19110

[kmdewaal]

Reading the logs I think the following is happening.
The mythbackend log shows that mythbackend initiates a shutdown at 21:01:33 which has to happen 15 seconds later:

Code: Select all

2021-06-22 21:01:33.712733 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds

Then the SystemD journal shows that the system does a shutdown immediately, also at 21:01:33, instead of 15 seconds later:

Code: Select all

Jun 22 21:01:33 Lenovo systemd[1]: Starting Suspend...

Because the suspend happens immediately instead of after 15 seconds the system is suspended when the mythbackend shutdown is still running.
When the system is resumed at 22:58:00 it is restored to the state where the mythbackend shutdown is still running and this causes it to suspend again. After the resume the time is 22:58:13 so that the scheduled wakeup time of 22:58:00 is now in the past so it will never happen anymore.

[cornflake]

I see what you mean. Now, would this be a bug? It seems that the HandleIdleShutdown function is being called twice, once at 21:01:16.538747, waiting 15 seconds and calling the suspend correctly at 21:01:33.322128, but then calling the HandleIdleShutdown again at 21:01:33.712733, right as the server is entering sleep.

Code: Select all

2021-06-22 21:01:16.538747 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds.
2021-06-22 21:01:31.609098 N [2030/2048] Scheduler scheduler.cpp:3435 (ShutdownServer) - Running the command to set the next scheduled wakeup time :-
                                sudo /etc/myth_set_alarm "2021-06-22 22:58:00"
2021-06-22 21:01:33.322128 N [2030/2048] Scheduler scheduler.cpp:3466 (ShutdownServer) - Running the command to shutdown this computer :-
                                sudo /usr/bin/systemctl suspend
2021-06-22 21:01:33.712733 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds.

Reading the logs I think the following is happening.
The mythbackend log shows that mythbackend initiates a shutdown at 21:01:33 which has to happen 15 seconds later:

Code: Select all

2021-06-22 21:01:33.712733 N [2030/2048] Scheduler scheduler.cpp:3268 (HandleIdleShutdown) - I'm idle now... shutdown will occur in 15 seconds

Then the SystemD journal shows that the system does a shutdown immediately, also at 21:01:33, instead of 15 seconds later:

Code: Select all

Jun 22 21:01:33 Lenovo systemd[1]: Starting Suspend...

Because the suspend happens immediately instead of after 15 seconds the system is suspended when the mythbackend shutdown is still running.
When the system is resumed at 22:58:00 it is restored to the state where the mythbackend shutdown is still running and this causes it to suspend again. After the resume the time is 22:58:13 so that the scheduled wakeup time of 22:58:00 is now in the past so it will never happen anymore.

[paulh]

There is also this in the log

Code: Select all

2021-06-23 08:10:37.488183 I [2030/2030] CoreContext scheduler.cpp:729 (UpdateRecStatus) - Updating status for Conan on cardid [1] (Pending => Recorder Failed)

It looks to me like the backend woke up at the right time and tried to start a recordings but failed. It then went idle again so initiated a shutdown again?