[mythtv-commits] Ticket #9712: the backend is not suspending when idle reliably

Thu Apr 7 20:21:33 UTC 2011

#9712: the backend is not suspending when idle reliably
-----------------------------------+----------------------------
 Reporter:  brian@…                |          Owner:
     Type:  Bug Report - General   |         Status:  new
 Priority:  minor                  |      Milestone:  unknown
Component:  MythTV - General       |        Version:  0.24-fixes
 Severity:  medium                 |     Resolution:
 Keywords:                         |  Ticket locked:  0
-----------------------------------+----------------------------

Comment (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?

-- 
Ticket URL: <http://code.mythtv.org/trac/ticket/9712#comment:3>
MythTV <http://code.mythtv.org/trac>
MythTV Media Center