Opened 14 years ago

Closed 7 years ago

#9712 closed Bug Report - General (Fixed)

the backend is not suspending when idle reliably

Reported by: brian@… Owned by: Peter Bennett
Priority: minor Milestone: unknown
Component: MythTV - Mythwelcome & Mythshutdown Version: 0.24-fixes
Severity: medium Keywords:
Cc: Ticket locked: no

Description

Frequently I find my backend which is configured to suspend when idle, running while there is nothing for it to be doing. Sometimes that will go on for hours and then all of a sudden it decides to suspend.

I have been running a test for the last 20-30 minutes, sampling mythshutdown -s and echoing the return to see what the backend thinks it's state is. Here is the result: 

$ while sleep 60; do echo -e "$(date): \c"; mythshutdown -s; echo $?; done
Wed Apr  6 07:41:47 EDT 2011: 0
Wed Apr  6 07:42:47 EDT 2011: 0
Wed Apr  6 07:43:48 EDT 2011: 0
Wed Apr  6 07:44:48 EDT 2011: 0
Wed Apr  6 07:45:48 EDT 2011: 0
Wed Apr  6 07:46:48 EDT 2011: 0
Wed Apr  6 07:47:48 EDT 2011: 0
Wed Apr  6 07:48:49 EDT 2011: 0
Wed Apr  6 07:49:49 EDT 2011: 0
Wed Apr  6 07:50:49 EDT 2011: 0
Wed Apr  6 07:51:49 EDT 2011: 0
Wed Apr  6 07:52:50 EDT 2011: 0
Wed Apr  6 07:53:50 EDT 2011: 0
Wed Apr  6 07:54:50 EDT 2011: 0
Wed Apr  6 07:55:50 EDT 2011: 0
Wed Apr  6 07:56:51 EDT 2011: 0
Wed Apr  6 07:57:51 EDT 2011: 0
Wed Apr  6 07:58:51 EDT 2011: 0
Wed Apr  6 07:59:51 EDT 2011: 0
Wed Apr  6 08:00:52 EDT 2011: 0
Wed Apr  6 08:01:52 EDT 2011: 0
Wed Apr  6 08:02:52 EDT 2011: 0
Wed Apr  6 08:03:52 EDT 2011: 0
Wed Apr  6 08:04:52 EDT 2011: 0
Wed Apr  6 08:05:53 EDT 2011: 0
Wed Apr  6 08:06:53 EDT 2011: 0

As you an see, the backend certainly thinks it's idle. The backend log for the same period of time: 

2011-04-06 07:41:47.780 MainServer::ANN Monitor
2011-04-06 07:41:47.781 adding: pvr as a client (events: 0)
2011-04-06 07:41:47.782 MainServer::ANN Monitor
2011-04-06 07:41:47.783 adding: pvr as a client (events: 1)
2011-04-06 07:42:48.013 MainServer::ANN Monitor
2011-04-06 07:42:48.014 adding: pvr as a client (events: 0)
2011-04-06 07:42:48.015 MainServer::ANN Monitor
2011-04-06 07:42:48.015 adding: pvr as a client (events: 1)
2011-04-06 07:43:48.248 MainServer::ANN Monitor
2011-04-06 07:43:48.249 adding: pvr as a client (events: 0)
2011-04-06 07:43:48.250 MainServer::ANN Monitor
2011-04-06 07:43:48.250 adding: pvr as a client (events: 1)
2011-04-06 07:44:48.482 MainServer::ANN Monitor
2011-04-06 07:44:48.482 adding: pvr as a client (events: 0)
2011-04-06 07:44:48.483 MainServer::ANN Monitor
2011-04-06 07:44:48.484 adding: pvr as a client (events: 1)
2011-04-06 07:45:48.713 MainServer::ANN Monitor
2011-04-06 07:45:48.714 adding: pvr as a client (events: 0)
2011-04-06 07:45:48.715 MainServer::ANN Monitor
2011-04-06 07:45:48.715 adding: pvr as a client (events: 1)
2011-04-06 07:46:48.945 MainServer::ANN Monitor
2011-04-06 07:46:48.946 adding: pvr as a client (events: 0)
2011-04-06 07:46:48.947 MainServer::ANN Monitor
2011-04-06 07:46:48.948 adding: pvr as a client (events: 1)
2011-04-06 07:47:49.179 MainServer::ANN Monitor
2011-04-06 07:47:49.180 adding: pvr as a client (events: 0)
2011-04-06 07:47:49.181 MainServer::ANN Monitor
2011-04-06 07:47:49.181 adding: pvr as a client (events: 1)
2011-04-06 07:48:49.413 MainServer::ANN Monitor
2011-04-06 07:48:49.413 adding: pvr as a client (events: 0)
2011-04-06 07:48:49.415 MainServer::ANN Monitor
2011-04-06 07:48:49.415 adding: pvr as a client (events: 1)
2011-04-06 07:49:49.645 MainServer::ANN Monitor
2011-04-06 07:49:49.645 adding: pvr as a client (events: 0)
2011-04-06 07:49:49.646 MainServer::ANN Monitor
2011-04-06 07:49:49.647 adding: pvr as a client (events: 1)
2011-04-06 07:50:49.877 MainServer::ANN Monitor
2011-04-06 07:50:49.878 adding: pvr as a client (events: 0)
2011-04-06 07:50:49.879 MainServer::ANN Monitor
2011-04-06 07:50:49.880 adding: pvr as a client (events: 1)
2011-04-06 07:51:07.869 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 07:51:50.111 MainServer::ANN Monitor
2011-04-06 07:51:50.111 adding: pvr as a client (events: 0)
2011-04-06 07:51:50.112 MainServer::ANN Monitor
2011-04-06 07:51:50.113 adding: pvr as a client (events: 1)
2011-04-06 07:52:50.345 MainServer::ANN Monitor
2011-04-06 07:52:50.346 adding: pvr as a client (events: 0)
2011-04-06 07:52:50.347 MainServer::ANN Monitor
2011-04-06 07:52:50.348 adding: pvr as a client (events: 1)
2011-04-06 07:53:50.578 MainServer::ANN Monitor
2011-04-06 07:53:50.579 adding: pvr as a client (events: 0)
2011-04-06 07:53:50.580 MainServer::ANN Monitor
2011-04-06 07:53:50.581 adding: pvr as a client (events: 1)
2011-04-06 07:54:50.813 MainServer::ANN Monitor
2011-04-06 07:54:50.814 adding: pvr as a client (events: 0)
2011-04-06 07:54:50.815 MainServer::ANN Monitor
2011-04-06 07:54:50.815 adding: pvr as a client (events: 1)
2011-04-06 07:55:51.046 MainServer::ANN Monitor
2011-04-06 07:55:51.046 adding: pvr as a client (events: 0)
2011-04-06 07:55:51.048 MainServer::ANN Monitor
2011-04-06 07:55:51.048 adding: pvr as a client (events: 1)
2011-04-06 07:56:51.279 MainServer::ANN Monitor
2011-04-06 07:56:51.279 adding: pvr as a client (events: 0)
2011-04-06 07:56:51.280 MainServer::ANN Monitor
2011-04-06 07:56:51.281 adding: pvr as a client (events: 1)
2011-04-06 07:57:51.513 MainServer::ANN Monitor
2011-04-06 07:57:51.513 adding: pvr as a client (events: 0)
2011-04-06 07:57:51.516 MainServer::ANN Monitor
2011-04-06 07:57:51.517 adding: pvr as a client (events: 1)
2011-04-06 07:58:51.748 MainServer::ANN Monitor
2011-04-06 07:58:51.748 adding: pvr as a client (events: 0)
2011-04-06 07:58:51.749 MainServer::ANN Monitor
2011-04-06 07:58:51.750 adding: pvr as a client (events: 1)
2011-04-06 07:59:51.980 MainServer::ANN Monitor
2011-04-06 07:59:51.980 adding: pvr as a client (events: 0)
2011-04-06 07:59:51.981 MainServer::ANN Monitor
2011-04-06 07:59:51.982 adding: pvr as a client (events: 1)
2011-04-06 08:00:52.213 MainServer::ANN Monitor
2011-04-06 08:00:52.213 adding: pvr as a client (events: 0)
2011-04-06 08:00:52.215 MainServer::ANN Monitor
2011-04-06 08:00:52.215 adding: pvr as a client (events: 1)
2011-04-06 08:01:52.448 MainServer::ANN Monitor
2011-04-06 08:01:52.449 adding: pvr as a client (events: 0)
2011-04-06 08:01:52.450 MainServer::ANN Monitor
2011-04-06 08:01:52.450 adding: pvr as a client (events: 1)
2011-04-06 08:02:52.679 MainServer::ANN Monitor
2011-04-06 08:02:52.680 adding: pvr as a client (events: 0)
2011-04-06 08:02:52.681 MainServer::ANN Monitor
2011-04-06 08:02:52.682 adding: pvr as a client (events: 1)
2011-04-06 08:03:52.912 MainServer::ANN Monitor
2011-04-06 08:03:52.912 adding: pvr as a client (events: 0)
2011-04-06 08:03:52.913 MainServer::ANN Monitor
2011-04-06 08:03:52.914 adding: pvr as a client (events: 1)
2011-04-06 08:04:53.144 MainServer::ANN Monitor
2011-04-06 08:04:53.145 adding: pvr as a client (events: 0)
2011-04-06 082011-04-06 08:05:00.781 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 08:05:53.377 MainServer::ANN Monitor
2011-04-06 08:05:53.377 adding: pvr as a client (events: 0)
2011-04-06 08:05:53.379 MainServer::ANN Monitor
2011-04-06 08:05:53.379 adding: pvr as a client (events: 1)
2011-04-06 08:06:08.094 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 08:04:53.146 MainServer::ANN Monitor
2011-04-06 08:04:53.146 adding: pvr as a client (events: 1)
2011-04-06 08:05:00.732 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 08:06:53.613 MainServer::ANN Monitor
2011-04-06 08:06:53.613 adding: pvr as a client (events: 0)
2011-04-06 08:06:53.614 MainServer::ANN Monitor
2011-04-06 08:06:53.615 adding: pvr as a client (events: 1)

When it goes for hours without idling and without being polled for it's status like it did all night last night, the backend log looks like: 

2011-04-05 23:15:09.046 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-05 23:17:05.006 MainServer::ANN Monitor
2011-04-05 23:17:05.007 adding: pvr as a client (events: 2)
2011-04-05 23:30:09.168 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-05 23:30:53.748 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-05 23:30:53.863 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-05 23:45:09.446 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 00:00:09.723 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 00:00:58.874 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 00:00:58.924 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 00:15:10.000 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 00:17:02.904 MainServer::ANN Monitor
2011-04-06 00:17:02.905 adding: pvr as a client (events: 2)
2011-04-06 00:30:10.286 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 00:30:59.935 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 00:30:59.999 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 00:45:10.575 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 01:00:10.861 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 01:01:05.010 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 01:01:05.059 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 01:15:11.146 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 01:17:01.755 MainServer::ANN Monitor
2011-04-06 01:17:01.756 adding: pvr as a client (events: 2)
2011-04-06 01:30:11.426 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 01:31:07.070 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 01:31:07.119 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 01:45:11.711 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 02:00:11.994 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 02:01:11.130 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 02:01:11.180 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 02:15:12.277 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 02:17:02.299 MainServer::ANN Monitor
2011-04-06 02:17:02.299 adding: pvr as a client (events: 2)
2011-04-06 02:30:12.558 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 02:31:18.192 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 02:31:18.242 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 02:45:12.841 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 03:00:13.119 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 03:01:20.253 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 03:01:20.303 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 03:15:13.402 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 03:17:01.844 MainServer::ANN Monitor
2011-04-06 03:17:01.845 adding: pvr as a client (events: 2)
2011-04-06 03:30:13.685 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 03:31:24.313 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 03:31:24.363 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 03:45:13.969 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 04:00:14.252 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 04:01:26.374 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 04:01:26.423 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 04:15:14.535 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 04:17:02.388 MainServer::ANN Monitor
2011-04-06 04:17:02.389 adding: pvr as a client (events: 2)
2011-04-06 04:26:19.938 mythbackend: Last message repeated 88 times: Running housekeeping thread
2011-04-06 04:26:19.942 mythbackend: Running mythfilldatabase
2011-04-06 04:26:19.942 Running mythfilldatabase
2011-04-06 04:30:14.820 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 04:31:24.027 mythfilldatabase still running, skipping checks.
2011-04-06 04:31:31.434 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 04:31:31.500 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 04:36:30.031 mythfilldatabase still running, skipping checks.
2011-04-06 04:40:56.775 MainServer::ANN Playback
2011-04-06 04:40:56.776 adding: pvr as a client (events: 0)
2011-04-06 04:40:56.777 MainServer::ANN Monitor
2011-04-06 04:40:56.777 adding: pvr as a client (events: 1)
2011-04-06 04:40:56.821 Reschedule requested for id -1.
2011-04-06 04:41:18.684 Scheduled 750 items in 21.7 = 0.89 match + 20.85 place
2011-04-06 04:41:18.756 scheduler: Scheduled items: Scheduled 750 items in 21.7 = 0.89 match + 20.85 place
2011-04-06 04:45:15.153 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 05:00:15.460 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 05:01:31.521 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 05:01:31.572 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 05:15:15.755 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 05:17:02.106 MainServer::ANN Monitor
2011-04-06 05:17:02.107 adding: pvr as a client (events: 2)
2011-04-06 05:30:16.050 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 05:31:35.583 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 05:31:35.632 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 05:45:16.347 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 06:00:16.642 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 06:00:54.681 MainServer::ANN Playback
2011-04-06 06:00:54.682 adding: jenny as a client (events: 0)
2011-04-06 06:00:54.685 MainServer::ANN Monitor
2011-04-06 06:00:54.686 adding: jenny as a client (events: 1)
2011-04-06 06:01:40.642 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 06:01:40.693 UPnpMedia: BuildMediaMap Done. Found 118 objects
2011-04-06 06:15:16.937 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 06:17:01.655 MainServer::ANN Monitor
2011-04-06 06:17:01.656 adding: pvr as a client (events: 2)
2011-04-06 06:30:17.229 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 06:31:45.703 UPnpMedia: BuildMediaMap VIDEO scan starting in :/video/mythvideo:
2011-04-06 06:31:45.752 UPnpMedia: BuildMediaMap Done. Found 118 objects

As you can see, all night it ran and did no appreciable work other than the mythfilldatabase at 4:26.

Change History (12)

comment:1 Changed 14 years ago by brian@…

And finally, it decided to go to sleep: 

...

Wed Apr  6 09:38:15 EDT 2011: 0
Wed Apr  6 09:39:15 EDT 2011: 0
Wed Apr  6 09:40:16 EDT 2011: 0
Wed Apr  6 09:41:16 EDT 2011: 0
Wed Apr  6 09:42:16 EDT 2011: 0
Wed Apr  6 09:43:16 EDT 2011: 0

The backend log: 

2011-04-06 09:38:15.757 MainServer::ANN Monitor
2011-04-06 09:38:15.757 adding: pvr as a client (events: 0)
2011-04-06 09:38:15.758 MainServer::ANN Monitor
2011-04-06 09:38:15.759 adding: pvr as a client (events: 1)
2011-04-06 09:38:26.055 I'm idle now... shutdown will occur in 300 seconds.
2011-04-06 09:38:35.060 290 secs left to system shutdown!
2011-04-06 09:38:45.066 280 secs left to system shutdown!
2011-04-06 09:38:55.071 270 secs left to system shutdown!
2011-04-06 09:39:05.076 260 secs left to system shutdown!
2011-04-06 09:39:15.082 250 secs left to system shutdown!
2011-04-06 09:39:15.988 MainServer::ANN Monitor
2011-04-06 09:39:15.989 adding: pvr as a client (events: 0)
2011-04-06 09:39:15.990 MainServer::ANN Monitor
2011-04-06 09:39:15.991 adding: pvr as a client (events: 1)
2011-04-06 09:39:25.087 240 secs left to system shutdown!
2011-04-06 09:39:35.093 230 secs left to system shutdown!
2011-04-06 09:39:45.098 220 secs left to system shutdown!
2011-04-06 09:39:55.103 210 secs left to system shutdown!
2011-04-06 09:40:05.109 200 secs left to system shutdown!
2011-04-06 09:40:15.114 190 secs left to system shutdown!
2011-04-06 09:40:16.222 MainServer::ANN Monitor
2011-04-06 09:40:16.223 adding: pvr as a client (events: 0)
2011-04-06 09:40:16.224 MainServer::ANN Monitor
2011-04-06 09:40:16.224 adding: pvr as a client (events: 1)
2011-04-06 09:40:25.120 180 secs left to system shutdown!
2011-04-06 09:40:35.125 170 secs left to system shutdown!
2011-04-06 09:40:45.131 160 secs left to system shutdown!
2011-04-06 09:40:55.136 150 secs left to system shutdown!
2011-04-06 09:41:05.141 140 secs left to system shutdown!
2011-04-06 09:41:15.147 130 secs left to system shutdown!
2011-04-06 09:41:16.455 MainServer::ANN Monitor
2011-04-06 09:41:16.456 adding: pvr as a client (events: 0)
2011-04-06 09:41:16.457 MainServer::ANN Monitor
2011-04-06 09:41:16.458 adding: pvr as a client (events: 1)
2011-04-06 09:41:25.152 120 secs left to system shutdown!
2011-04-06 09:41:35.158 110 secs left to system shutdown!
2011-04-06 09:41:45.163 100 secs left to system shutdown!
2011-04-06 09:41:55.169 90 secs left to system shutdown!
2011-04-06 09:42:05.174 80 secs left to system shutdown!
2011-04-06 09:42:15.179 70 secs left to system shutdown!
2011-04-06 09:42:16.688 MainServer::ANN Monitor
2011-04-06 09:42:16.688 adding: pvr as a client (events: 0)
2011-04-06 09:42:16.689 MainServer::ANN Monitor
2011-04-06 09:42:16.690 adding: pvr as a client (events: 1)
2011-04-06 09:42:25.185 60 secs left to system shutdown!
2011-04-06 09:42:35.190 50 secs left to system shutdown!
2011-04-06 09:42:45.196 40 secs left to system shutdown!
2011-04-06 09:42:55.201 30 secs left to system shutdown!
2011-04-06 09:43:05.207 20 secs left to system shutdown!
2011-04-06 09:43:15.212 10 secs left to system shutdown!
2011-04-06 09:43:16.924 MainServer::ANN Monitor
2011-04-06 09:43:16.924 adding: pvr as a client (events: 0)
2011-04-06 09:43:16.925 MainServer::ANN Monitor
2011-04-06 09:43:16.926 adding: pvr as a client (events: 1)
2011-04-06 09:43:25.241 No backup is running, ok to shut down.
2011-04-06 09:43:25.241 No backup will run soon, ok to shut down.
2011-04-06 09:43:25.241 User brian on pts/1 has been idle for 7320 seconds
2011-04-06 09:43:25.241 User brian on pts/0 has been idle for 139260 seconds
2011-04-06 09:43:25.241 Anyone logged in is idle, ok to shut down.
2011-04-06 09:43:30.328 CheckShutdownServer returned - OK to shutdown
2011-04-06 09:43:30.333 Running the command to set the next scheduled wakeup time :-
						sudo sh -c "/home/mythtv/bin/setwakeup.sh 1302134280"
clearing the alarm
i am: uid=0(root) gid=0(root) groups=0(root),105(mythtv)
clearing the alarm
setting the alarm to 1302105540
it's set to: 1302105540
2011-04-06 09:43:31.530 Running the command to shutdown this computer :-
						sudo /usr/sbin/pm-suspend

Nothing at all was done since my last/initial posting on this ticket except wait for the backend to finally decide that it was indeed idle.

comment:2 Changed 14 years ago by brian@…

And once again, after being woken up for the semi-daily backup, it's not going back to sleep in a timely manner: 

2011-04-06 11:59:10.129 QMulticastSocket: setsockopt - IP_ADD_MEMBERSHIP Error
2011-04-06 11:59:13.111 New DB connection, total: 1
2011-04-06 11:59:13.121 Connected to database 'mythconverg' at host: localhost
2011-04-06 11:59:13.163 Waited more than 60 seconds for shutdown to complete - resetting idle time
2011-04-06 11:59:14.151 300 secs left to system shutdown!
2011-04-06 11:59:15.395 I'm idle now... shutdown will occur in 300 seconds.
2011-04-06 11:59:16.703 MainServer::ANN Playback
2011-04-06 11:59:16.712 adding: jenny as a client (events: 0)
2011-04-06 11:59:16.730 MainServer::ANN Monitor
2011-04-06 11:59:16.739 adding: jenny as a client (events: 1)
2011-04-06 11:59:39.000 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 11:59:39.007 New DB connection, total: 2
2011-04-06 11:59:39.008 Connected to database 'mythconverg' at host: localhost
2011-04-06 11:59:42.960 MainServer::ANN Monitor
2011-04-06 11:59:42.960 adding: pvr as a client (events: 0)
2011-04-06 11:59:42.961 MainServer::ANN Monitor
...
2011-04-06 13:10:59.636 MainServer::ANN Monitor
2011-04-06 13:10:59.637 adding: pvr as a client (events: 0)
2011-04-06 13:10:59.638 MainServer::ANN Monitor
2011-04-06 13:10:59.638 adding: pvr as a client (events: 1)
2011-04-06 13:11:59.873 MainServer::ANN Monitor
2011-04-06 13:11:59.873 adding: pvr as a client (events: 0)
2011-04-06 13:11:59.875 MainServer::ANN Monitor
2011-04-06 13:11:59.877 adding: pvr as a client (events: 1)
2011-04-06 13:13:00.110 MainServer::ANN Monitor
2011-04-06 13:13:00.111 adding: pvr as a client (events: 0)
2011-04-06 13:13:00.112 MainServer::ANN Monitor
2011-04-06 13:13:00.113 adding: pvr as a client (events: 1)
2011-04-06 13:14:00.345 MainServer::ANN Monitor
2011-04-06 13:14:00.346 adding: pvr as a client (events: 0)
2011-04-06 13:14:00.347 MainServer::ANN Monitor
2011-04-06 13:14:00.348 adding: pvr as a client (events: 1)
2011-04-06 13:14:39.807 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2011-04-06 13:15:00.578 MainServer::ANN Monitor
2011-04-06 13:15:00.579 adding: pvr as a client (events: 0)
2011-04-06 13:15:00.580 MainServer::ANN Monitor
2011-04-06 13:15:00.581 adding: pvr as a client (events: 1)
2011-04-06 11:59:42.964 adding: pvr as a client (events: 1)
2011-04-06 12:00:43.199 MainServer::ANN Monitor

And still running as I write this. FWIW, "pvr" is the BE machine itself, in case that was not clear and "jenny" is a frontend that also wakes up at slightly before 12:00:00 for backup and is asleep again by 12:30:00.

comment:3 Changed 14 years ago by brian@…

OK. Since I've had the debug turned up for a different bug, more has come to light. If we look at the beginning of the most recent wake up cycle: 

...
2011-04-07 11:59:13.001 300 secs left to system shutdown!
2011-04-07 11:59:13.055 MythEvent: SHUTDOWN_COUNTDOWN 300
2011-04-07 11:59:14.069 300 secs left to system shutdown!
2011-04-07 11:59:14.079 MythEvent: SHUTDOWN_COUNTDOWN 300
2011-04-07 11:59:15.095 I'm idle now... shutdown will occur in 300 seconds.
2011-04-07 11:59:15.749 MythSocket(ffffffffa33f55f0:18): new socket
2011-04-07 11:59:15.758 MythSocket(ffffffffa33f55f0:18): setSocket: 17
2011-04-07 11:59:15.767 MythSocket(ffffffffa33f55f0:17): state change Idle -> Connected
2011-04-07 11:59:15.776 MythSocket(ffffffffa33f55f0:17): UpRef: 1
2011-04-07 11:59:15.785 MythSocket(a3f4338:-1): DownRef: -1
2011-04-07 11:59:15.794 MythSocket(a3f4338:-1): delete socket
2011-04-07 11:59:15.804 MythSocketThread(sock 0xffffffffa33f55f0:17): socket is readable
2011-04-07 11:59:15.813 MythSocketThread(sock 0xffffffffa33f55f0:17): calling m_cb->readyRead()
2011-04-07 11:59:15.822 MythSocket(ffffffffa33f55f0:17): UpRef: 2
2011-04-07 11:59:15.831 MythSocket(ffffffffa33f55f0:17): read  <- 17 30      MYTH_PROTO_VERSION 63 3875641D
2011-04-07 11:59:15.840 MythSocket(ffffffffa33f55f0:17): write -> 17 13      ACCEPT[]:[]63
2011-04-07 11:59:15.849 MythSocket(ffffffffa33f55f0:17): DownRef: 1
2011-04-07 11:59:15.858 MythSocketThread(sock 0xffffffffa33f55f0:17): socket is readable
2011-04-07 11:59:15.867 MythSocketThread(sock 0xffffffffa33f55f0:17): calling m_cb->readyRead()
2011-04-07 11:59:15.877 MythSocket(ffffffffa33f55f0:17): UpRef: 2
2011-04-07 11:59:15.886 MythSocket(ffffffffa33f55f0:17): read  <- 17 20      ANN Playback jenny 0
2011-04-07 11:59:15.895 MainServer::ANN Playback
2011-04-07 11:59:15.904 adding: jenny as a client (events: 0)
2011-04-07 11:59:15.913 MythSocket(ffffffffa33f55f0:17): write -> 17 2       OK
2011-04-07 11:59:15.922 MythSocket(ffffffffa33f55f0:17): DownRef: 1
2011-04-07 11:59:15.931 MythSocket(ffffffffa33001b8:41): new socket
2011-04-07 11:59:15.935 MythSocket(ffffffffa33001b8:41): setSocket: 18
2011-04-07 11:59:15.937 MythSocket(ffffffffa33001b8:18): state change Idle -> Connected
2011-04-07 11:59:15.938 MythSocket(ffffffffa33001b8:18): UpRef: 1
2011-04-07 11:59:15.939 MythSocketThread(sock 0xffffffffa33001b8:18): socket is readable
2011-04-07 11:59:15.948 MythSocketThread(sock 0xffffffffa33001b8:18): calling m_cb->readyRead()
2011-04-07 11:59:15.950 MythSocket(ffffffffa33001b8:18): UpRef: 2
2011-04-07 11:59:15.959 MythSocket(ffffffffa33001b8:18): read  <- 18 19      ANN Monitor jenny 1
2011-04-07 11:59:15.968 MainServer::ANN Monitor
2011-04-07 11:59:16.005 adding: jenny as a client (events: 1)
2011-04-07 11:59:16.014 MythEvent: SYSTEM_EVENT CLIENT_CONNECTED HOSTNAME jenny SENDER pvr
...

So, a frontend called jenny woke up and connected, presumably canceling the shutdown that started to happen, right?

That frontend host, jenny, should have gone to sleep again at 12:30 however the next event for it seems to be: 

2011-04-07 13:05:08.103 MythSocket(ffffffffa5419118:-1): DownRef: -1
2011-04-07 13:05:08.104 MythSocket(ffffffffa5419118:-1): delete socket
2011-04-07 13:05:08.104 MythSocket(ffffffffa5420540:-1): DownRef: -1
2011-04-07 13:05:08.105 MythSocket(ffffffffa5420540:-1): delete socket
2011-04-07 13:05:08.105 MythSocket(ffffffffa54a9498:-1): DownRef: -1
2011-04-07 13:05:08.106 MythSocket(ffffffffa54a9498:-1): delete socket
2011-04-07 13:05:08.106 MythSocketThread(sock 0xffffffffa33001b8:18): socket is readable
2011-04-07 13:05:08.107 MythSocketThread(sock 0xffffffffa33001b8:18): socket closed
2011-04-07 13:05:08.109 MythSocket(ffffffffa33001b8:18): state change Connected -> Idle
2011-04-07 13:05:08.109 MythSocket(ffffffffa33001b8:-1): calling m_cb->connectionClosed()
2011-04-07 13:05:08.110 MythEvent: SYSTEM_EVENT CLIENT_DISCONNECTED HOSTNAME jenny SENDER pvr

So now shutdown should be possible, right? It appear not. The next "i'm idle and going to suspend" cycle doesn't start until 14:40:48 and it looks like this: 

2011-04-07 14:40:48.411 MythSocket(ffffffffa5437cf0:-1): DownRef: -1
2011-04-07 14:40:48.412 MythSocket(ffffffffa5437cf0:-1): delete socket
2011-04-07 14:40:48.412 MythSocketThread(sock 0xffffffffa33f55f0:17): socket is 
readable
2011-04-07 14:40:48.413 MythSocketThread(sock 0xffffffffa33f55f0:17): socket clo
sed
2011-04-07 14:40:48.413 MythSocket(ffffffffa33f55f0:17): state change Connected 
-> Idle
2011-04-07 14:40:48.414 MythSocket(ffffffffa33f55f0:-1): calling m_cb->connectio
nClosed()
2011-04-07 14:40:48.414 MythEvent: SYSTEM_EVENT CLIENT_DISCONNECTED HOSTNAME jenny SENDER pvr
2011-04-07 14:40:49.787 I'm idle now... shutdown will occur in 300 seconds.
2011-04-07 14:40:49.788 MythEvent: SHUTDOWN_COUNTDOWN 300
2011-04-07 14:40:58.791 290 secs left to system shutdown!
2011-04-07 14:40:58.792 MythEvent: SHUTDOWN_COUNTDOWN 290
2011-04-07 14:41:08.795 280 secs left to system shutdown!
2011-04-07 14:41:08.796 MythEvent: SHUTDOWN_COUNTDOWN 280
...
2011-04-07 14:45:28.910 20 secs left to system shutdown!
2011-04-07 14:45:28.911 MythEvent: SHUTDOWN_COUNTDOWN 20
2011-04-07 14:45:38.914 10 secs left to system shutdown!
2011-04-07 14:45:38.915 MythEvent: SHUTDOWN_COUNTDOWN 10
2011-04-07 14:45:48.929 No backup is running, ok to shut down.
2011-04-07 14:45:48.929 No backup will run soon, ok to shut down.
2011-04-07 14:45:48.929 User brian on pts/1 has been idle for 91440 seconds
2011-04-07 14:45:48.929 User brian on pts/0 has been idle for 9960 seconds
2011-04-07 14:45:48.929 Anyone logged in is idle, ok to shut down.
2011-04-07 14:45:53.990 CheckShutdownServer returned - OK to shutdown
2011-04-07 14:45:53.990 Running the command to set the next scheduled wakeup time :-
                                                sudo sh -c "/home/mythtv/bin/setwakeup.sh 1302206280"
clearing the alarm
i am: uid=0(root) gid=0(root) groups=0(root),105(mythtv)
clearing the alarm
setting the alarm to 1302206280
it's set to: 1302206280
2011-04-07 14:45:55.090 MythEvent: SHUTDOWN_NOW
2011-04-07 14:45:55.091 Running the command to shutdown this computer :-
                                                sudo /usr/sbin/pm-suspend

So, it seems that this frontend "jenny" was keeping the backend awake until 14:40:48. But wait, it went to sleep at 12:30:00 and was noticed as "DISCONNECTED" earlier, at 13:05:08, was not noticed as connecting again but noticed as "DISCONNECTED" again at 14:40:48.

So how can a frontend be "DISCONNECTED" twice without an intervening "CLIENT_CONNECTED" and why didn't the first "DISCONNECTED" allow the shutdown to start where the second one clearly did?

comment:4 Changed 9 years ago by Karl Egly

Component: MythTV - General → MythTV - Mythwelcome & Mythshutdown

comment:5 Changed 7 years ago by Peter Bennett

Owner: set to Peter Bennett
Status: new → assigned

This is still happening, very occasionally. It happened last night. My backend never went idle. It was running from midnight to 9 AM, then I restarted it. One thing that may be relevant, I exited from the frontend last night then immediately started the frontend again, deleted a show and a recording rule, then exited the frontend again. It normally seems to be associated with stopping a frontend and starting it up again immediately.

comment:6 Changed 7 years ago by Peter Bennett <pbennett@…>

In 2fa7549706fc6d5807c93d6c2ddbd1bec5a85489/mythtv:

Backend: Add log messages on reasons for failure to shut down

Every 15 minutes (i.e. at 00,15,30,45 past the hour) output a general
log message with reason for blocking shutdown, if the system has
a shutdown timeout.

Refs #9712

comment:7 Changed 7 years ago by Peter Bennett <pbennett@…>

In 9c01fa4e91345d665a1a7aa2a652961b99ce8634/mythtv:

Backend: Add log messages on reasons for failure to shut down

Every 15 minutes (i.e. at 00,15,30,45 past the hour) output a general
log message with reason for blocking shutdown, if the system has
a shutdown timeout.

Refs #9712

(cherry picked from commit 2fa7549706fc6d5807c93d6c2ddbd1bec5a85489)

comment:8 Changed 7 years ago by Peter Bennett

I found that the backend failed to shut down for 1 hour and reporting a connected client. Using netstat -t --program i found that it was mythmetadatalookup that was holding connections. It had been running 1 hour, no log messages in 1 hour, it seems there must be a bug in mythmetadatalookup --refresh-all-artwork 

ps -ef|grep mythmeta
mythtv    1948  1681  0 14:34 ?        00:00:00 sh -c /usr/bin/mythmetadatalookup --refresh-all-artwork  --verbose general --loglevel info --syslog local7
mythtv    1949  1948  0 14:34 ?        00:00:13 /usr/bin/mythmetadatalookup --refresh-all-artwork --verbose general --loglevel info --syslog local7
peter     2632  2540  0 15:36 pts/0    00:00:00 grep --color=auto mythmeta

comment:9 Changed 7 years ago by Peter Bennett

Since disabling the "Daily Updates of Recording Artwork" option, this has not happened. However looking at old logs shows that the failure to shut down also occurred when there was no metadatalookup job running. That metadatalookup hang is addressed in ticket #13111

Last edited 7 years ago by Peter Bennett (previous) (diff)

comment:10 Changed 7 years ago by Peter Bennett

Another situation where the backend fails to shut down for a long time is reported in the mailing list.

​https://lists.gt.net/mythtv/users/612310#612310

comment:11 Changed 7 years ago by Peter Bennett

Owner: changed from Peter Bennett to Peter Bennett

comment:12 Changed 7 years ago by Peter Bennett

Resolution: → Fixed
Status: assigned → closed

Closing this as fixed since it has not happened since the fix in #13111. Also the situation in the mailing list is caused by the user choosing to power off the frontend without exiting MythTV. Any fix to allow that would be an enhancement, as it is not currently supported.

Note: See TracTickets for help on using tickets.