Opened 13 years ago
Closed 13 years ago
#10911 closed Bug Report - Hang/Deadlock (Duplicate)
another backend deadlock
| Reported by: | Owned by: | ||
|---|---|---|---|
| Priority: | minor | Milestone: | 0.25.2 |
| Component: | MythTV - General | Version: | 0.25-fixes |
| Severity: | medium | Keywords: | |
| Cc: | Ticket locked: | no |
Description
So, I went away for a week's vacation only to return and find out that my Mythbackend deadlocked the day after I left. 1 week's worth of recordings never happened. WAF is extremely low here. She wants to know what is the point of having a PVR that needs to be babysat daily. :-(
Anyway, threaded stack trace will be attached.
Log messages for the last day of recordings (and the day following where nothing recorded):
# grep Jul\ \ [89] /var/log/mythtv/mythbackend.log | grep -v -e HouseKeeping -e Expire -e HandleAnnounce Jul 8 00:00:00 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(6): Changing from RecordingOnly to None Jul 8 00:00:00 pvr mythbackend[2426]: E DVBRead dvbstreamhandler.cpp:214 (RunTS) DVBSH(/dev/dvb/adapter0/frontend0): Device EOF detected Jul 8 00:00:00 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(11): Changing from RecordingOnly to None Jul 8 00:00:00 pvr mythbackend[2426]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/pvr_mpeg0): poll error Jul 8 00:00:00 pvr mythbackend[2426]: E RecThread mpegrecorder.cpp:1010 (run) MPEGRec(/dev/pvr_mpeg0): Device error detected Jul 8 00:00:00 pvr mythbackend[2426]: I PreviewGeneratorQueue mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 16 Jul 8 00:00:00 pvr mythbackend[2426]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording Marketplace: channel 2878 Jul 8 00:00:01 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(6): Changing from None to RecordingOnly Jul 8 00:00:01 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:3459 (TuningCheckForHWChange) TVRec(6): HW Tuner: 6->6 Jul 8 00:00:02 pvr mythbackend[2426]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/pvr_mpeg0): poll error Jul 8 00:00:03 pvr mythbackend[2426]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording The Finder "The Inheritance": channel 3024 Jul 8 00:00:03 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording: "A Good Show":"Episode 1": channel 4188 on cardid 6, sourceid 2 Jul 8 00:00:03 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for Marketplace on cardid 6 (Recording => Recorded) Jul 8 00:00:04 pvr mythbackend[2426]: N DVBRead dtvsignalmonitor.cpp:354 (HandlePMT) DTVSM(/dev/dvb/adapter0/frontend0): PMT says program 360 is encrypted Jul 8 00:00:04 pvr mythbackend[2426]: E CoreContext programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(4188_20120708000000.mpg): GetPlaybackURL: '4188_20120708000000.mpg' should be local, but it can not be found. Jul 8 00:00:04 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for "The Finder":"The Inheritance" on cardid 11 (Recording => Recorded) Jul 8 00:00:04 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for "A Good Show":"Episode 1" on cardid 6 (Tuning => Recording) Jul 8 00:00:05 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:3953 (TuningNewRecorder) TVRec(6): rec->GetPathname(): '/storage1/4188_20120708000000.mpg' Jul 8 00:00:05 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0. Jul 8 00:00:05 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0. Jul 8 00:00:30 pvr mythbackend[2426]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/storage1/4188_20120708000000.mpg:70): write(57528) cnt 8 total 475076 -- took a long time, 1634 ms Jul 8 00:00:43 pvr mythbackend[2426]: E Commflag_8569 previewgenerator.cpp:254 (Run) Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 3024 --starttime 20120707230000 --verbose general --loglevel info --syslog local7 --quiet' (128) Jul 8 00:00:56 pvr mythbackend[2426]: I Metadata_8574 jobqueue.cpp:2150 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for "A Good Show":"Episode 1" recorded from channel 4188 at 2012-07-08T00:00:00 Jul 8 00:01:36 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2068 (HandleReschedule) Scheduled 1309 items in 91.1 = 0.00 match + 91.14 place Jul 8 00:02:01 pvr mythbackend[2426]: I Commflag_8575 jobqueue.cpp:2275 (DoFlagCommercialsThread) JobQueue: Commercial Detection Starting for "A Good Show":"Episode 1" recorded from channel 4188 at 2012-07-08T00:00:00 Jul 8 00:02:05 pvr mythbackend[2426]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(6:/dev/dvb/adapter0/frontend0): GetKeyframePositions(3013,9223372036854775807,#9) out of 215 Jul 8 00:30:00 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(6): Changing from RecordingOnly to None Jul 8 00:30:01 pvr mythbackend[2426]: E DVBRead dvbstreamhandler.cpp:214 (RunTS) DVBSH(/dev/dvb/adapter0/frontend0): Device EOF detected Jul 8 00:30:01 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for "A Good Show":"Episode 1" on cardid 6 (Recording => Recorded) Jul 8 00:30:01 pvr mythbackend[2426]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording A Good Show "Episode 1": channel 4188 Jul 8 00:30:02 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0. Jul 8 00:30:24 pvr mythbackend[2426]: E Commflag_8575 previewgenerator.cpp:254 (Run) Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 4188 --starttime 20120708000000 --verbose general --loglevel info --syslog local7 --quiet' (128) Jul 8 00:32:59 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2068 (HandleReschedule) Scheduled 1308 items in 176.7 = 0.00 match + 176.72 place Jul 8 01:01:00 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(1): Changing from RecordingOnly to None Jul 8 01:01:01 pvr mythbackend[2426]: E DVBRead dvbstreamhandler.cpp:214 (RunTS) DVBSH(/dev/dvb/adapter1/frontend0): Device EOF detected Jul 8 01:01:02 pvr mythbackend[2426]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording Saturday Night Live: channel 3093 Jul 8 01:01:02 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for "Saturday Night Live" on cardid 1 (Recording => Recorded) Jul 8 01:01:02 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0. Jul 8 01:02:36 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2068 (HandleReschedule) Scheduled 1307 items in 93.5 = 0.00 match + 93.48 place Jul 8 02:29:29 pvr mythbackend[2426]: I Scheduler mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 8 02:29:29 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(3): ASK_RECORDING 3 29 0 0 Jul 8 02:29:29 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(2): ASK_RECORDING 2 29 0 0 Jul 8 02:29:29 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(4): ASK_RECORDING 4 29 0 0 Jul 8 02:29:29 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(5): ASK_RECORDING 5 29 0 0 Jul 8 02:29:30 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(1): ASK_RECORDING 1 29 0 0 Jul 8 02:30:00 pvr mythbackend[2426]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 8 02:30:01 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(1): Changing from None to RecordingOnly Jul 8 02:30:01 pvr mythbackend[2426]: I TVRecEvent mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 8 02:30:01 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:3459 (TuningCheckForHWChange) TVRec(1): HW Tuner: 1->1 Jul 8 02:30:01 pvr mythbackend[2426]: E CoreContext programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(2878_20120708023000.mpg): GetPlaybackURL: '2878_20120708023000.mpg' should be local, but it can not be found. Jul 8 02:30:03 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording: Marketplace: channel 2878 on cardid 1, sourceid 2 Jul 8 02:30:04 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for Marketplace on cardid 1 (Tuning => Recording) Jul 8 02:30:04 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:3953 (TuningNewRecorder) TVRec(1): rec->GetPathname(): '/storage1/2878_20120708023000.mpg' Jul 8 02:31:04 pvr mythbackend[2426]: I Metadata_8576 jobqueue.cpp:2150 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for Marketplace recorded from channel 2878 at 2012-07-08T02:30:00 Jul 8 02:32:09 pvr mythbackend[2426]: I Commflag_8577 jobqueue.cpp:2275 (DoFlagCommercialsThread) JobQueue: Commercial Detection Starting for Marketplace recorded from channel 2878 at 2012-07-08T02:30:00 Jul 8 02:32:10 pvr mythbackend[2426]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(1:/dev/dvb/adapter1/frontend0): GetKeyframePositions(3679,9223372036854775807,#4) out of 260 Jul 8 02:59:29 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1521 (HandlePendingRecordings) TVRec(11): ASK_RECORDING 11 29 0 0 Jul 8 02:59:59 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(11): Changing from None to RecordingOnly Jul 8 02:59:59 pvr mythbackend[2426]: I TVRecEvent mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 14 Jul 8 02:59:59 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:3459 (TuningCheckForHWChange) TVRec(11): HW Tuner: 11->11 Jul 8 03:00:00 pvr mythbackend[2426]: I TVRecEvent v4lchannel.cpp:661 (SetInputAndFormat) V4LChannel(/dev/pvr_mpeg0): SetInputAndFormat(11, NTSC) (v4l v2) input_switch: 0 mode_switch: 0 Jul 8 03:00:00 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2459 (HandleRecordingStatusChange) Tuning recording: Grimm: channel 3050 on cardid 11, sourceid 3 Jul 8 03:00:00 pvr mythbackend[2426]: E CoreContext programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(3050_20120708030000.mpg): GetPlaybackURL: '3050_20120708030000.mpg' should be local, but it can not be found. Jul 8 03:00:00 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(1): Changing from RecordingOnly to None Jul 8 03:00:01 pvr mythbackend[2426]: E DVBRead dvbstreamhandler.cpp:214 (RunTS) DVBSH(/dev/dvb/adapter1/frontend0): Device EOF detected Jul 8 03:00:01 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for Marketplace on cardid 1 (Recording => Recorded) Jul 8 03:00:01 pvr mythbackend[2426]: I PreviewGeneratorQueue mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 8 03:00:02 pvr mythbackend[2426]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording Marketplace: channel 2878 Jul 8 03:00:02 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for Grimm on cardid 11 (Tuning => Recording) Jul 8 03:00:03 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:3953 (TuningNewRecorder) TVRec(11): rec->GetPathname(): '/storage1/3050_20120708030000.mpg' Jul 8 03:00:03 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0. Jul 8 03:00:04 pvr mythbackend[2426]: W RecThread mpegrecorder.cpp:1315 (StartEncoding) MPEGRec(/dev/pvr_mpeg0): StartEncoding failed#012#011#011#011eno: Input/output error (5) Jul 8 03:00:16 pvr mythbackend[2426]: I Metadata_8578 jobqueue.cpp:2150 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for Grimm recorded from channel 3050 at 2012-07-08T03:00:00 Jul 8 03:00:57 pvr mythbackend[2426]: E DeviceReadBuffer DeviceReadBuffer.cpp:513 (Poll) DevRdB(/dev/pvr_mpeg0): Poll giving up 2 Jul 8 03:00:57 pvr mythbackend[2426]: E RecThread mpegrecorder.cpp:1010 (run) MPEGRec(/dev/pvr_mpeg0): Device error detected Jul 8 03:01:02 pvr mythbackend[2426]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/storage1/3050_20120708030000.mpg:69): write(63362) cnt 3 total 157704 -- took a long time, 1625 ms Jul 8 03:01:04 pvr mythbackend[2426]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/storage1/3050_20120708030000.mpg:69): write(57470) cnt 10 total 604034 -- took a long time, 2231 ms Jul 8 03:01:33 pvr mythbackend[2426]: I Commflag_8579 jobqueue.cpp:2275 (DoFlagCommercialsThread) JobQueue: Commercial Detection Starting for Grimm recorded from channel 3050 at 2012-07-08T03:00:00 Jul 8 03:01:53 pvr mythbackend[2426]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/storage1/3050_20120708030000.mpg:69): write(65440) cnt 1 total 28894 -- took a long time, 1129 ms Jul 8 03:02:48 pvr mythbackend[2426]: W TFWWrite ThreadedFileWriter.cpp:499 (DiskLoop) TFW(/storage1/3050_20120708030000.mpg:69): write(61432) cnt 1 total 10366 -- took a long time, 2357 ms Jul 8 03:02:57 pvr mythbackend[2426]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(11:/dev/pvr_mpeg0): GetKeyframePositions(3287,9223372036854775807,#17) out of 236 Jul 8 03:03:07 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2068 (HandleReschedule) Scheduled 1305 items in 184.4 = 0.00 match + 184.44 place Jul 8 04:00:00 pvr mythbackend[2426]: I TVRecEvent tv_rec.cpp:1014 (HandleStateChange) TVRec(11): Changing from RecordingOnly to None Jul 8 04:00:01 pvr mythbackend[2426]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/pvr_mpeg0): poll error Jul 8 04:00:01 pvr mythbackend[2426]: E RecThread mpegrecorder.cpp:1010 (run) MPEGRec(/dev/pvr_mpeg0): Device error detected Jul 8 04:00:03 pvr mythbackend[2426]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/pvr_mpeg0): poll error Jul 8 04:00:06 pvr mythbackend[2426]: I PreviewGeneratorQueue mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 14 Jul 8 04:00:07 pvr mythbackend[2426]: I TVRecEvent recordinginfo.cpp:1113 (FinishedRecording) Finished recording Grimm: channel 3050 Jul 8 04:00:07 pvr mythbackend[2426]: I CoreContext scheduler.cpp:634 (UpdateRecStatus) Updating status for Grimm on cardid 11 (Recording => Recorded) Jul 8 04:00:09 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2010 (HandleReschedule) Reschedule requested for id 0. Jul 8 04:00:32 pvr mythbackend[2426]: E Commflag_8579 previewgenerator.cpp:254 (Run) Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 3050 --starttime 20120708030000 --verbose general --loglevel info --syslog local7 --quiet' (128) Jul 8 04:00:32 pvr mythbackend[2426]: E PreviewGenerator previewgenerator.cpp:254 (Run) Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 3050 --starttime 20120708030000 --verbose general --loglevel info --syslog local7 --quiet' (128) Jul 8 05:07:05 pvr mythbackend[2426]: E Scheduler mythdb.cpp:192 (DBError) DB Error (AddNewRecords):#012Query was:#012SELECT c.chanid, c.sourceid, p.starttime, p.endtime, p.title, p.subtitle, p.description, c.channum, c.callsign, c.name, oldrecduplicate, p.category, sched_temp_record.recpriority, sched_temp_record.dupin, recduplicate, findduplicate, sched_temp_record.type, sched_temp_record.recordid, p.starttime - INTERVAL sched_temp_record.startoffset minute AS recstartts, p.endtime + INTERVAL sched_temp_record.endoffset minute AS recendts, p.previouslyshown, sched_temp_record.recgroup, sched_temp_record.dupmethod, c.commmethod, capturecard.cardid, cardinput.cardinputid,p.seriesid, p.programid, sched_temp_record.inetref, p.category_type, p.airdate, p.stars, p.originalairdate, sched_temp_record.inactive, sched_temp_record.parentid,(CASE sched_temp_record.type WHEN 6 THEN sched_temp_record.findid WHEN 9 THEN to_days(date_sub(p.starttime, interval time_format(sched_temp_record.findtime, '%H:%i') hour_minute)) WHEN 10 THEN floor((to_days(date_sub(p.starttime, interval time_format(sched_temp_record.findtime, '%H:%i') hour_minute)) - sched_temp_record.findday)/7) * 7 + sched_temp_record.findday WHEN 7 THEN sched_temp_record.findid ELSE 0 END) , sched_temp_record.playgroup, oldrecstatus.recstatus, oldrecstatus.reactivate, p.videoprop+0, p.subtitletypes+0, p.audioprop+0, sched_temp_record.storagegroup, capturecard.hostname, recordmatch.oldrecstatus, sched_temp_record.avg_delay, oldrecstatus.future, cardinput.schedorder, c.recpriority + cardinput.recpriority + (cardinput.cardinputid = sched_te Jul 8 05:07:19 pvr mythbackend[2426]: I Scheduler scheduler.cpp:2068 (HandleReschedule) Scheduled 0 items in -266.1 = 0.77 match + -266.86 place Jul 8 06:17:45 pvr mythbackend[2426]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 14 Jul 8 06:23:44 pvr mythbackend[2426]: I Scheduler mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 8 19:07:27 pvr mythbackend[2426]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 8 19:13:27 pvr mythbackend[2426]: I Scheduler mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 9 00:00:02 pvr mythbackend[2426]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 9 17:52:47 pvr mythbackend[2426]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 14 Jul 9 17:58:47 pvr mythbackend[2426]: I Scheduler mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 9 19:01:17 pvr mythbackend[2426]: I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13 Jul 9 19:07:17 pvr mythbackend[2426]: I Scheduler mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 13
The kernel log for Jul 8 reported:
Jul 8 03:00:57 pvr kernel: [288308.196329] ivtv0: Encoder has died : ivtv_serialized_open Jul 8 03:00:57 pvr kernel: [288308.202011] ivtv0: Detected in ivtv_serialized_open that firmware had failed - Reloading Jul 8 03:00:58 pvr kernel: [288309.360730] ivtv0: Loaded v4l-cx2341x-enc.fw firmware (376836 bytes) Jul 8 03:00:58 pvr kernel: [288309.569261] ivtv0: Firmware restart okay
Attachments (2)
Change History (11)
Changed 13 years ago by
| Attachment: | ThreadStacktrace.txt added |
|---|
comment:1 Changed 13 years ago by
There are no deadlocks evident in that backtrace at all ...
The database error in the logs does however look like the culprit, the scheduler was unable to run because queries were failing - table corruption or a mysql server failure maybe? Both are outside our control.
comment:2 Changed 13 years ago by
Hrm. I restarted the BE and it deadlocked again (I will attach another stacktrace at the time of this most recent deadlock. The backend status on mythweb for example just spins and eventually times out with:
Warning at /usr/share/mythtv/mythweb/modules/status/handler.php, line 32: !!NoTrans: file_get_contents(http://10.75.22.2:6544/Status/GetStatusHTML): failed to open stream: HTTP request failed! !!
Frontends fail to fetch the list of recordings. This is exactly the symptoms I have seen with previous deadlocks.
I am happy to entertain database problems though. How would I verify, one way or the other the state of the database to your satisfaction to either confirm it's a database problem or rule it out?
comment:3 Changed 13 years ago by
Hrm. My attempt last night to attach seems to have noop'd. My apologies for that. The stacktrace is attached now. My BE seems to have survived the night, doing 4 recordings, without another deadlock.
Still happy to entertain database problems though.
comment:4 Changed 13 years ago by
Could you please update to the latest version of 0.25-fixes, I'm fairly certain the deadlock in the second trace hash already been fixed.
comment:5 Changed 13 years ago by
Commenting from work. I am also getting the dreaded MYTH_PROTO_VERSION is empty message from mythfrontend.
Repeatable, and instant. Backend cannot record. This is MORE than a minor fault. Evidenced in a trunk build from about a week ago, Rebuilt from master trunk from about 11:00 pm EDT last night, and compiled early this morning. Single box BE/FE, Fedora 17. Updated to schema 1307 on first launch this morning.
What is happening may provide a clue for the spelunking. I launch mythfrontend and it comes up cleanly. I can then: Open Watch Recordings, and see the list of programs in mythconverg.recorded. I can play any of them. I can exit to Schedule Recordings, and enter the Program Guide, or the Program Finder, or do any keyword search.
But in Upcoming Recordings, I get "You have not scheduled..." And in the console I see the dreaded error. Meanwhile I can open a mysql console as user mythtv etc, and see that table mythconverg.record has 111 records.
If I try a Manual Schedule, it *appears* to run, but produces no file (not even a zero byte file). I get a 'file cannot be found' error when I select the recording in Watch Recordings. That is, it creates the 'recorded' record but the tuner side is 'missing in in-action'.
I also cannot get anything in Watch TV.. It hangs on 'Please Wait' whereas it should give me the EPG.
Restart of the backend makes no difference. Same 'empty' error in the console every time. More than 'repeatable'. I googled the error and checked the possible error conditions. One post on how to fix the the usual causes of this error was one of my own from 2010! And none of those usual conditions applies. I optimize'd on every relaunch cycle in case a file/table was being corrupted. No joy.
So this is either two distinct deadlock conditions or one deadlock found in the common code for the 'Upcoming Recordings' retrieval code and in the scheduling code. How those two threads would cross paths is a little unclear to me, but I am assuming there is a common base, deep in the code in a section which deals with 'and now talk to the database'. It is must be tied to the scheduling code as the EPG and Finder and Watch Recordings sections work properly.
So I cannot record ATM. The WAF will PLUNGE.. This is more than 'babysat daily'. What would you like to see in the way of logs, etc?
I am going to have to rebuild. Would it help to dissect if I created a new branch from git, say 2/3/4 weeks ago, and built from that?
Geoff Newbury not logged in... TRAC doesn't seem to like my password any more...
comment:6 Changed 13 years ago by
Geoff, I can't make out from that which version you are running? We believe these issues to all be fixed in current 0.25-fixes.
Could people please ensure they are running the LATEST code before reporting bugs?
comment:7 Changed 13 years ago by
Sorry, I don't have the actual hash here. Looking at the git log it would likely be, master trunk at:
commit 2af21560c7ba4f219b79403e11e79c14ebbf90ca Author: Stuart Morgan <smorgan@…> Date: Mon Jul 16 12:01:53 2012 +0100
as it was late last night. I think those times are UTC and it would have been 11:30-midnight EDT, or 03:00+ UTC or so when I started the git clone and went to bed.
Further information: some code dissection.
Using the setup here at the office from a July 3 download. mythfrontend version: master [v0.26-pre-757-ge2a0efd-dirty
This setup does not exhibit the problem. Oddly I cannot use 'skip-networking' in the my.cnf file, or the backend cannot 'see' the mysql server. The setup is localhost in config,xml etc. and no bind-address. This is part of mythfrontend startup: The 'identifier' hostname maps to 192.168.1.99
2012-07-16 12:04:53.922440 I Listening on TCP 127.0.0.1:6546 2012-07-16 12:04:53.922532 I Listening on TCP 192.168.1.99:6546 2012-07-16 12:04:53.927915 I Listening on TCP [::1]:6546
2012-07-16 12:05:09.098875 I MythCoreContext?: Connecting to backend server: 192.168.1.99:6543 (try 1 of 3) 2012-07-16 12:05:09.103711 I Using protocol version 75
I can schedule recordings and they are inserted into the 'record' table. I can even play 'Live TV' from a file set up with the dummy demo tuner. It looks like something got boken after that, which did not need to be frixed.
Geoff
comment:8 Changed 13 years ago by
Geoff, it sound like you are experiencing a new problem. Please get the exact version and a backtrace and then open a new ticket. We're pretty sure the problem as originally reported for this ticket is fixed.
comment:9 Changed 13 years ago by
| Milestone: | unknown → 0.25.2 |
|---|---|
| Resolution: | → Duplicate |
| Status: | new → closed |
Brian, if this turns out to not be the problem we already fixed, then reopen this ticket with the new information.
stack trace of deadlocked threads