Opened 9 years ago

Closed 9 years ago

#7752 closed defect (fixed)

mythshutdown sometimes doesn't shut down

Reported by: Petr Stehlik <pstehlik@…> Owned by: Isaac Richards
Priority: minor Milestone: unknown
Component: MythTV - General Version: unknown
Severity: medium Keywords:
Cc: Ticket locked: no

Description

Using up-to-date mythtv 0.22-fixes. Sometimes mythshutdown (started from mythbackend) doesn't shut the machine down. Not sure when and why. I have disabled active EIT recently but it didn't help, see the following mythbackend log from yesterday night:

2009-12-13 22:53:03.313 I'm idle now... shutdown will occur in 60 seconds.
2009-12-13 22:53:05.988 AFD: Opened codec 0x9b8bcf0, id(MPEG2VIDEO) type(Video)
2009-12-13 22:53:05.992 AFD: codec MP2 has 2 channels
2009-12-13 22:53:06.001 AFD: Opened codec 0x9b8c460, id(MP2) type(Audio)
2009-12-13 22:53:07.032 Preview: Grabbed preview '/myth/tv/14138_20091213200000.mpg' 720x576@600s
2009-12-13 22:54:04.170 MainServer::ANN Monitor
2009-12-13 22:54:04.176 adding: htpc as a client (events: 0)
2009-12-13 22:54:04.178 MainServer::ANN Monitor
2009-12-13 22:54:04.196 adding: htpc as a client (events: 1)
2009-12-13 22:54:04.272 CheckShutdownServer returned - OK to shutdown
2009-12-13 22:54:04.280 Running the command to set the next scheduled wakeup time :-
                                                mythshutdown --setwakeup 2009-12-14T09:13:00
2009-12-13 22:54:04.487 Running the command to shutdown this computer :-
                                                mythshutdown --shutdown
2009-12-13 22:56:01.088 UPnpMedia: BuildMediaMap VIDEO scan starting in :/myth/video:
2009-12-13 22:56:01.804 UPnpMedia: BuildMediaMap Done. Found 580 objects
...

Yesterday at 22:54:04 it should have shut down. 24 hours later the running processes are (ps ax | grep myth):

 2912 ?        Ssl    6:59 /usr/local/myth/bin/mythbackend -d -l /var/log/mythtv/mythbackend.log
 4783 ?        SNl    0:00 mythshutdown --shutdown
21734 ?        Sl     0:07 mythwelcome

If, in this state, I run the mythshutdown -q manually it does shut down properly. What's bad is that when it's in this zombie state it doesn't record anything like if scheduling was disabled. The MythWelcome? even shows that next recording will start this morning which was 10 hours ago. So the backend is sort of unusable and needs to be restarted to get things recording again.

Change History (7)

comment:1 Changed 9 years ago by Petr Stehlik <pstehlik@…>

Related frontend log:

2009-12-13 22:53:00.803 MythWelcome received a RECORDING_LIST_CHANGE event
2009-12-13 22:53:02.317 MythWelcome received a SCHEDULE_CHANGE event
2009-12-13 22:54:06.080 MythWelcome received a SHUTDOWN_NOW event

and there the frontend log ends.

comment:2 Changed 9 years ago by Petr Stehlik <pstehlik@…>

Yesterday night it happened again. I am wondering what is the ANN Monitor and why it is being added and removed constantly. Maybe that's what prevents MythTV from shutting down?

2009-12-20 00:06:33.785 AutoExpire: CalcParams(): Max required Free Space: 30.0 GB w/freq: 15 min
2009-12-20 00:21:33.867 AutoExpire: CalcParams(): Max required Free Space: 30.0 GB w/freq: 15 min
2009-12-20 00:27:38.168 UPnpMedia: BuildMediaMap VIDEO scan starting in :/myth/video:
2009-12-20 00:27:41.746 UPnpMedia: BuildMediaMap Done. Found 583 objects
2009-12-20 00:30:18.035 I'm idle now... shutdown will occur in 60 seconds.
2009-12-20 00:30:34.101 MainServer::ANN Playback
2009-12-20 00:30:34.103 adding: htpc as a client (events: 0)
2009-12-20 00:30:34.104 MainServer::ANN Monitor
2009-12-20 00:30:34.107 adding: htpc as a client (events: 1)
2009-12-20 00:30:38.339 I'm idle now... shutdown will occur in 60 seconds.
2009-12-20 00:31:37.620 MainServer::ANN Monitor
2009-12-20 00:31:37.621 adding: htpc as a client (events: 0)
2009-12-20 00:31:37.622 MainServer::ANN Monitor
2009-12-20 00:31:37.633 adding: htpc as a client (events: 1)
2009-12-20 00:31:39.658 I'm idle now... shutdown will occur in 60 seconds.
2009-12-20 00:32:40.445 MainServer::ANN Monitor
2009-12-20 00:32:40.446 adding: htpc as a client (events: 0)
2009-12-20 00:32:40.448 MainServer::ANN Monitor
2009-12-20 00:32:40.450 adding: htpc as a client (events: 1)
2009-12-20 00:32:42.516 I'm idle now... shutdown will occur in 60 seconds.
2009-12-20 00:33:43.297 MainServer::ANN Monitor
2009-12-20 00:33:43.298 adding: htpc as a client (events: 0)
2009-12-20 00:33:43.300 MainServer::ANN Monitor
2009-12-20 00:33:43.301 adding: htpc as a client (events: 1)
2009-12-20 00:33:45.377 I'm idle now... shutdown will occur in 60 seconds.
2009-12-20 00:34:46.196 MainServer::ANN Monitor
2009-12-20 00:34:46.198 adding: htpc as a client (events: 0)
2009-12-20 00:34:46.199 MainServer::ANN Monitor
2009-12-20 00:34:46.201 adding: htpc as a client (events: 1)

... this continued for another hour until I came in and ran mythshutdown -q manually. That turned it off immediately.

comment:3 Changed 9 years ago by Petr Stehlik <pstehlik@…>

Something new observed today: mythbackend started mythshutdown and that one got stuck waiting for some UPnP stuff?? It seems like it's trying to use UPnP to find the local database and gets stuck there...

pstree shows:

mythbackend(2990)-->mythshutdown(4796)-->{mythshutdown}(4800)

ps ax shows:

4796 ? SNl 0:00 mythshutdown --setwakeup 2010-02-10T17:43:00

there is no process with pid 4800 so I attached the gdb to pid 4796 and ran backtrace:

(gdb) thread apply all bt full

Thread 2 (Thread 0xb3462b90 (LWP 4800)):
#0  0xb7f6e424 in __kernel_vsyscall ()
No symbol table info available.
#1  0xb5362e67 in poll () from /lib/i686/cmov/libc.so.6
No symbol table info available.
#2  0xb3656702 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#3  0x08684158 in ?? ()
No symbol table info available.
#4  0x00000001 in ?? ()
No symbol table info available.
#5  0xffffffff in ?? ()
No symbol table info available.
#6  0x08684158 in ?? ()
No symbol table info available.
#7  0x00000001 in ?? ()
No symbol table info available.
#8  0xb36ce9a8 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#9  0xb36ce5f8 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#10 0xb36ce620 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#11 0xb34620e4 in ?? ()
No symbol table info available.
#12 0xb36ce5f8 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#13 0xb36ce620 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#14 0x0868274c in ?? ()
No symbol table info available.
#15 0x00000001 in ?? ()
No symbol table info available.
#16 0x08682748 in ?? ()
No symbol table info available.
#17 0x08684158 in ?? ()
No symbol table info available.
#18 0xb5362df0 in ?? () from /lib/i686/cmov/libc.so.6
No symbol table info available.
#19 0xb61a23f0 in ?? () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#20 0xb61a0980 in ?? () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#21 0x0868274c in ?? ()
No symbol table info available.
#22 0xb553a81d in ?? () from /usr/lib/libQtCore.so.4
No symbol table info available.
#23 0x0000005e in ?? ()
No symbol table info available.
#24 0xffffffff in ?? ()
No symbol table info available.
#25 0x7fffffff in ?? ()
No symbol table info available.
#26 0xb36ce240 in ?? () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
#27 0x08682748 in ?? ()
No symbol table info available.
#28 0xb61a0980 in ?? () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#29 0xb3462118 in ?? ()
No symbol table info available.
#30 0xb3656a31 in g_main_context_iteration () from /usr/lib/libglib-2.0.so.0
No symbol table info available.
Backtrace stopped: frame did not save the PC

Thread 1 (Thread 0xb349c6e0 (LWP 4796)):
#0  0xb7f6e424 in __kernel_vsyscall ()
No symbol table info available.
#1  0xb61a3025 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i686/cmov/libpthread.so.0
No symbol table info available.
#2  0xb5561542 in QWaitCondition::wait () from /usr/lib/libQtCore.so.4
No symbol table info available.
#3  0xb55606d3 in QThread::wait () from /usr/lib/libQtCore.so.4
No symbol table info available.
#4  0xb6a2a7e6 in WorkerThread::~WorkerThread () from /usr/local/myth/lib/libmythupnp-0.22.so.0
No symbol table info available.
#5  0xb6a2d640 in HttpWorkerThread::~HttpWorkerThread () from /usr/local/myth/lib/libmythupnp-0.22.so.0
No symbol table info available.
#6  0xb6a2abce in ThreadPool::~ThreadPool () from /usr/local/myth/lib/libmythupnp-0.22.so.0
No symbol table info available.
#7  0xb6a2dfdc in HttpServer::~HttpServer () from /usr/local/myth/lib/libmythupnp-0.22.so.0
No symbol table info available.
#8  0xb6786329 in MythContextPrivate::DeleteUPnP () from /usr/local/myth/lib/libmyth-0.22.so.0
No symbol table info available.
#9  0xb678685d in MythContextPrivate::InitUPnP () from /usr/local/myth/lib/libmyth-0.22.so.0
No symbol table info available.
#10 0xb679c9ea in MythContextPrivate::DefaultUPnP () from /usr/local/myth/lib/libmyth-0.22.so.0
No symbol table info available.
#11 0xb67a0322 in MythContextPrivate::FindDatabase () from /usr/local/myth/lib/libmyth-0.22.so.0
No symbol table info available.
#12 0xb67a0954 in MythContextPrivate::Init () from /usr/local/myth/lib/libmyth-0.22.so.0
No symbol table info available.
#13 0xb67a112a in MythContext::Init () from /usr/local/myth/lib/libmyth-0.22.so.0
No symbol table info available.
#14 0x08058e69 in ?? ()
No symbol table info available.
#15 0xb52a3455 in __libc_start_main () from /lib/i686/cmov/libc.so.6
No symbol table info available.
#16 0x0804a5d1 in ?? ()
No symbol table info available.
#0  0xb7f6e424 in __kernel_vsyscall ()
(gdb) quit

comment:4 Changed 9 years ago by martin_ginkel@…

I have similar observations. My script for setting the wakeup time into NvRam? is writing it's own log. It often has no entry, when the machine is shut down by mythshutdown.

Further mythshutdown is crashing quite often with different random segfaults:

/var/log/syslog:Feb 17 02:52:51 karamea kernel: [  886.127873]
mythshutdown[3326]: segfault at 8fbb478 ip 05305858 sp bfab49e0 error 7 in
libGL.so.185.18.36[52aa000+81000]
/var/log/syslog.1:Feb 14 19:05:33 karamea kernel: [20921.780411]
mythshutdown[7762]: segfault at 8cab0f4 ip 00526ab3 sp bfdfb380 error 7 in
libGL.so.185.18.36[4fb000+81000]
/var/log/syslog.1:Feb 14 19:49:03 karamea kernel: [23532.265238]
mythshutdown[10856]: segfault at 87c5018 ip 087882d2 sp bff8dc50 error 7 in
libfaad.so.0.0.0[8786000+3b000]
/var/log/syslog.1:Feb 14 19:55:15 karamea kernel: [23903.629344]
mythshutdown[11910]: segfault at 8c75034 ip 076abc22 sp bfdc987c error 6 in
libc-2.10.1.so[763e000+13e000]
/var/log/syslog.1:Feb 14 23:59:03 karamea kernel: [38532.454269]
mythshutdown[18942]: segfault at 8cf53ec ip 0215b30c sp bfff2528 error 7 in
libc-2.10.1.so[20ef000+13e000]
/var/log/syslog.1:Feb 16 02:25:45 karamea kernel: [   30.765420]
mythshutdown[2676]: segfault at 8d5ee40 ip 08c44632 sp bf811bd0 error 7 in
libX11.so.6.2.0[8c31000+12a000]

In this case mythbackend apparently restarts the countdown and retries mythshutdown after a while.

comment:5 Changed 9 years ago by robertm

Status: newinfoneeded_new

Petr,

It seems fairly clear that the mythshutdown segfaults are preventing it from working, but I have two requests-- first, if at all possible can you run tests on a *completely clean* .23-fixes build (installed on a fresh system or making sure to clear out ALL the myth libraries first to ensure a clean build/install environment) and if mythshutdown still fails, then can we get a backtrace of the failure with debug symbols?

comment:6 Changed 9 years ago by pstehlik@…

I couldn't see the segfaults but I believe you that they were there. Anyway, since I upgraded to 0.23-fixes (couple of weeks ago) I haven't seen the failed shutdown yet. So hopefully it's fixed. Please close as is, I'd reopen with a backtrace had it happen again. Thanks!

comment:7 Changed 9 years ago by robertm

Resolution: fixed
Status: infoneeded_newclosed

Thanks for reporting back, Petr.

Note: See TracTickets for help on using tickets.