[mythtv-users] Backend is crashing, usually after commflag has finished.

James Dio psunit at gmail.com
Sat Mar 17 18:27:06 UTC 2007 

On 3/16/07, James Dio <psunit at gmail.com> wrote:
> Hi,
>
> First of all, I wanted to say thanks for any help ahead of time, I love mythtv.
>
> I am using svn trunk and recently setup a slave backend. Everything
> had been working fine for a few days, but I woke up one morning and
> saw that mythbackend was no longer running on my MBE (master backend,
> hope abbreviation is alright) but instead there were about 10-12
> mythcommflags running. I had been getting some:
>
>  2007-03-16 19:11:40.844 NVP::OpenFile(): Error, file not found:
> /GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/tvbox/1062_20060419173844.mpg
>
> (not actual error, but it was like this) so I killed all of the
> commercial flagging processes and started the backend up. I just
> recently went through my recordings and tried to find most of the ones
> which have entries but do not exist. I believe this is a separate
> problem, but worth mentioning IMHO. (side note; is there a way to have
> mythtv confirm the existence of recordings and if not let me know so I
> can delete those entries? I'm not sure why they do not exist in the
> first place)
>
> I hadn't had any new problems with this specially since I got rid of
> those entries, but a day or two ago I started having errors like:
>
> [mpeg2video @ 0xb731d610]Warning MVs not available
>
> and I was quickly informed that this is usually the cause of a poor
> signal (no apparent changes which would make cable signal worse) so I
> just changed around configuration so I now have a better signal
> (judged by cable modem plugged into same splitter) and no longer get
> these messages while recording. I also removed recordings from the
> past few days in case those could also cause problems while being
> watched or commercial flagged.
>
> I no longer have these errors (but again, worth mentioning in case it
> is part of the cause of MBE crashing).
>
> I have enabled more logging now, and it always seems that the backend
> crashes after commercial flagging has finished. I have also added the
> --noupnp flag, I knew that could cause some instability (from past
> problems I was instructed to try that, plus I don't use it).
>
> .....
> 2007-03-16 19:00:22.641 Final Commercial Break Map
> 2007-03-16 19:00:30.885 DB Error (SetMarkupMap inserting):
> Query was:
> INSERT INTO recordedmarkup (chanid, starttime, mark, type) VALUES (
> '1038' , '2007-03-16T18:00:00' , 0 , -3 );
> Driver error was [2/1062]:
> QMYSQL3: Unable to execute query
> Database error was:
> Duplicate entry '1038-2007-03-16 18:00:00--3-0' for key 1
>
> 2007-03-16 19:00:30.916 write ->  7 33      MESSAGE[]:[]RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.918 read  <- 18 33      MESSAGE[]:[]RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.920 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.922 write -> 18 2       OK
> 2007-03-16 19:00:30.922 write -> 14 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.925 write -> 19 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.927 write -> 23 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.928 write -> 27 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.936 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.944 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.941 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.949 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.941 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.954 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.956 write ->  7 33      MESSAGE[]:[]RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.959 read  <- 26 33      MESSAGE[]:[]RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.961 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.964 write -> 14 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.964 write -> 26 2       OK
> 2007-03-16 19:00:30.966 write -> 19 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.969 write -> 23 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.971 write -> 27 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.941 read  <-  7 2       OK
> 2007-03-16 19:00:30.968 read  <-  7 2       OK
> 2007-03-16 19:00:30.970 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.991 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.978 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.026 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:30.996 write ->  7 33      MESSAGE[]:[]RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.268 read  <- 22 33      MESSAGE[]:[]RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.301 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.302 write -> 22 2       OK
> 2007-03-16 19:00:32.302 write -> 14 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.305 write -> 23 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.307 write -> 27 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:30.972 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.443 Scheduled 454 items in 12.8 = 0.00 match + 12.82 place
> 2007-03-16 19:00:32.480 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.626 scheduler: Scheduled items: Scheduled 454
> items in 12.8 = 0.00 match + 12.82 place
> 2007-03-16 19:00:32.856 MythEvent: SCHEDULE_CHANGE
> 2007-03-16 19:00:32.958 write -> 14 45
> BACKEND_MESSAGE[]:[]SCHEDULE_CHANGE[]:[]empty
> 2007-03-16 19:00:32.961 write -> 23 45
> BACKEND_MESSAGE[]:[]SCHEDULE_CHANGE[]:[]empty
> 2007-03-16 19:00:32.959 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.965 write -> 14 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.967 write -> 23 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.698 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:32.973 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.979 read  <-  6 45
> BACKEND_MESSAGE[]:[]SCHEDULE_CHANGE[]:[]empty
> 0: start_time: 0.036 duration: 8589.932
> 1: start_time: 0.026 duration: 0.004
> stream: start_time: 0.289 duration: 95443.795 bitrate=0 kb/s
> 2007-03-16 19:00:32.989 AFD: Opened codec 0x8ce20b0, id(MPEG2VIDEO) type(Video)
> 2007-03-16 19:00:32.991 AFD: Opened codec 0x859a1c0, id(MP2) type(Audio)
> 2007-03-16 19:00:32.993 AFD: Audio Track #1 is A/V stream #1 and has 2
> channels in the Unknown language(0).
> 2007-03-16 19:00:32.996 AFD: Selected track 1: Unknown MP2 2ch (A/V Stream #1)
> 2007-03-16 19:00:32.998 AFD: Initializing audio parms from audio track #1
> 2007-03-16 19:00:32.999 AFD: Audio format changed
>                         from id(NONE)    -1Hz -1ch   0bps    ;
> id(NONE)    -1Hz -1ch   0bps
>                         to   id( MP2) 48000Hz  2ch  16bps    ; id(
> MP2) 48000Hz  2ch  16bps
> 2007-03-16 19:00:32.989 MythEvent: SCHEDULE_CHANGE
> 2007-03-16 19:00:33.004 read  <-  6 51
> BACKEND_MESSAGE[]:[]RECORDING_LIST_CHANGE[]:[]empty
> 2007-03-16 19:00:33.009 MythEvent: RECORDING_LIST_CHANGE
> 2007-03-16 19:00:32.328 read  <-  7 2       OK
> Input #0, mpeg, from '/store/myth2/1038_20070316180000.mpg':
>   Duration: 26:30:43.7, start: 0.289389, bitrate: 0 kb/s
>   Stream #0.0[0x1e0], 1/90000: Video: mpeg2video, yuv420p, 480x480,
> 1001/30000, 5000 kb/s, 29.97 fps(r)
>   Stream #0.1[0x1c0], 1/90000: Audio: mp2, 48000 Hz, stereo, 384 kb/s
> 2007-03-16 19:00:33.251 commflag: Last message repeated 2 times:
> Commercial Flagging Starting: 7th Heaven "Work" recorded from channel
> 1038 at Fri Mar 16 18:00:00 2007
> 2007-03-16 19:00:33.259 commflag: Commercial Flagging Finished: 7th
> Heaven "Work" recorded from channel 1038 at Fri Mar 16 18:00:00 2007
> (6 commercial break(s))
>
>
> I have plenty more output before this, but this previous line is the
> last outputted to log when the backend crashes.
>
> I just ran mythcommflag alone, maybe thinking that it would tell me
> something when manually running, the only odd thing (while still
> finishing successfully) that I see is:
>
> Compiler did not align stack variables. Libavcodec has been miscompiled
> and may be very slow or crash. This is not a bug in libavcodec,
> but in the compiler. Do not report crashes to FFmpeg developers.
>
> Is this a real problem?
>
> I run gentoo linux, I have run revdep-rebuild, and did not do any
> updates prior to these problems. I had this problem with older svn
> version (that had been successfully running for a few days) but now
> have updated to Revision: 13054.
>
> I really don't know where to go from here, but any help is greatly appreciated.
>
> Thanks,
> Jim
>


I have recompile the backend to enable debugging, and have run gdb (as
advised in the mythtv documentation) and this is where things start to
go bad:

Thread 1 (Thread -1243817760 (LWP 7930)):
#0  0xb7f24410 in ?? ()
No symbol table info available.
#1  0xbfcd0ac8 in ?? ()
No symbol table info available.
#2  0x082230bc in ?? ()
No symbol table info available.
#3  0x08222f38 in ?? ()
No symbol table info available.
#4  0xb60390d1 in select () from /lib/libc.so.6
No symbol table info available.
#5  0xb6562305 in QEventLoop::processEvents () from /usr/qt/3/lib/libqt-mt.so.3
No symbol table info available.
#6  0xb65c9551 in QEventLoop::enterLoop () from /usr/qt/3/lib/libqt-mt.so.3
No symbol table info available.
#7  0xb65c93d6 in QEventLoop::exec () from /usr/qt/3/lib/libqt-mt.so.3
No symbol table info available.
#8  0xb65b238f in QApplication::exec () from /usr/qt/3/lib/libqt-mt.so.3
No symbol table info available.
#9  0x0808eb6f in main (argc=5, argv=0xbfcd11e4) at main.cpp:669
        a = <incomplete type>
        settingsOverride = {sh = 0x81c87b8}
        binname = {static null = {static null = <same as static member
of an already seen type>, d = 0x813f070, static shared_null =
0x813f070}, d = 0x81c8808, static shared_null = 0x813f070}
        daemonize = false
        printsched = false
        testsched = false
        resched = false
        nosched = false
        noupnp = false
        nojobqueue = false
        nohousekeeper = false
        noexpirer = false
        printexpire = false
        clearsettingscache = false
        pidfs = <incomplete type>
        port = 6543
        myip = {static null = {static null = <same as static member of
an already seen type>, d = 0x813f070, static shared_null = 0x813f070},
d = 0x81e4f28, static shared_null = 0x813f070}
        masterip = {static null = {static null = <same as static
member of an already seen type>, d = 0x813f070, static shared_null =
0x813f070}, d = 0x81ce108, static shared_null = 0x813f070}
        ismaster = true
        fatal_error = false
        runsched = true
0xb78a364c      2041        else if ((*(jobControlFlags[key]) == JOB_STOP))
tvbox ~ #


Again... any help is appreciated.

More information about the mythtv-users mailing list