This is the second time I've encountered this and I ended up going through a long charade before finding the solution again. The main problem is that my MythTV backend didn't record the episode of Heroes that aired earlier tonight. I figured I'd watch the episode using MythTV's Live TV viewing feature but that didn't work either. I had other work to take care of so I figured I'd get to it later in the night which happens to be 30 minutes ago.
The symptoms of the problem are that checking the schedule of upcoming recordings from the commandline returns nothing.
root@backend0:~# mythbackend --printsched
2009-04-20 23:23:55.207 Using runtime prefix = /usr
2009-04-20 23:23:55.208 Empty LocalHostName.
2009-04-20 23:23:55.208 Using localhost value of backend0
2009-04-20 23:23:55.806 Cannot find default UPnP backend
2009-04-20 23:23:55.811 New DB connection, total: 1
2009-04-20 23:23:55.814 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:23:55.815 Closing DB connection named 'DBManager0'
2009-04-20 23:23:55.815 Deleting UPnP client...
2009-04-20 23:23:56.490 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:23:56.491 New DB connection, total: 2
2009-04-20 23:23:56.491 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:23:56.492 Current Schema Version: 1214
2009-04-20 23:23:56.493 New DB DataDirect connection
2009-04-20 23:23:56.494 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:23:56.496 Connecting to backend server: 192.168.2.12:6543 (try 1 of 5)
2009-04-20 23:23:56.499 Using protocol version 40
Retrieving Schedule from Master backend.
--- print list start ---
Title - Subtitle Ch Station Day Start End S C I T N Pri
--- print list end ---
However, testing the scheduling functionality returns a list of all shows that would have been recorded.
root@backend0:~# mythbackend --testsched | more
2009-04-20 23:25:54.768 Using runtime prefix = /usr
2009-04-20 23:25:54.768 Empty LocalHostName.
2009-04-20 23:25:54.769 Using localhost value of backend0
2009-04-20 23:25:55.185 Cannot find default UPnP backend
2009-04-20 23:25:55.190 New DB connection, total: 1
2009-04-20 23:25:55.194 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:25:55.195 Closing DB connection named 'DBManager0'
2009-04-20 23:25:55.195 Deleting UPnP client...
2009-04-20 23:25:56.247 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:25:56.248 New DB connection, total: 2
2009-04-20 23:25:56.248 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:25:56.249 Current Schema Version: 1214
2009-04-20 23:25:56.250 New DB DataDirect connection
2009-04-20 23:25:56.251 Connected to database 'mythconverg' at host: localhost
Calculating Schedule from database.
Inputs, Card IDs, and Conflict info may be invalid if you have multiple tuners.
2009-04-20 23:25:56.317 Speculative scheduled 45 items in 0.1 = 0.01 match + 0.06 place
--- print list start ---
Title - Subtitle Ch Station Day Start End S C I T N Pri
Sesame Street - "The Cookie To 67.1 MPTHD 21 09:30-10:30 1 5 5 w 5 -2/0
Charlie Rose 67.1 MPTHD 21 12:35-13:32 1 5 5 C 5 0/0
Two and a Half Men - "Best H.O 13.1 PN-2 21 20:30-21:00 1 5 5 C 5 0/0
Fringe - "Bad Dreams" 45.1 FOX45 H 21 21:01-22:00 1 5 5 C 5 0/0
The Mentalist - "Paint It Red" 13.1 PN-2 21 22:00-23:00 1 5 5 C 5 0/0
.
.
.
Dollhouse - "Briar Rose" 45.1 FOX45 H 01 21:01-22:00 1 5 5 C 5 0/0
Boston Legal - "Smile" 2.1 PN-7 02 23:35-00:35 1 5 5 C 5 0/0
Jericho - "Reconstruction" 54.1 WNUV HD 03 18:30-19:30 1 5 5 C 5 0/0
Desperate Housewives - "Bargai 2.1 PN-7 03 21:00-22:01 1 5 5 C 5 0/0
--- print list end ---
This puzzled me to no end. Lots of posts online talk about ensuring your mythbackend IP isn't set to 127.0.0.1 and to redo the entire setup of tuners and lineups for the backend. I checked the former and wasn't interested in the latter. I even ran mysqlrepair on the mythconverg database just in case - I found nothing.
It turns out there's a way to increase logging for specific aspects of the MythTV backend. I modified the /etc/default/mythtv-backend file by uncommenting the EXTRA_ARGS variable and setting it to:
EXTRA_ARGS="--verbose schedule"
I restarted the MythTV backend while tailing /var/log/mythtv/mythbackend.log and found this little nugget:
2009-04-20 23:41:39.464 Using runtime prefix = /usr
2009-04-20 23:41:39.465 Empty LocalHostName.
2009-04-20 23:41:39.465 Using localhost value of backend0
2009-04-20 23:41:39.472 New DB connection, total: 1
2009-04-20 23:41:39.476 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:41:39.477 Closing DB connection named 'DBManager0'
2009-04-20 23:41:39.478 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:41:39.479 New DB connection, total: 2
2009-04-20 23:41:39.480 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:41:39.481 Current Schema Version: 1214
Starting up as the master server.
2009-04-20 23:41:40.494 HDHRChan(10114243/0), Error: device not found
2009-04-20 23:41:41.506 HDHRChan(10114243/1), Error: device not found
ERROR: no valid capture cards are defined in the database.
Perhaps you should read the installation instructions?
2009-04-20 23:41:41.513 New DB connection, total: 3
2009-04-20 23:41:41.514 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:41:42.725 Main::Registering HttpStatus Extension
2009-04-20 23:41:42.725 mythbackend version: 0.21.20080304-1 www.mythtv.org
2009-04-20 23:41:42.727 Enabled verbose msgs: important general schedule
2009-04-20 23:41:42.728 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-04-20 23:41:51.927 UPnpMedia: BuildMediaMap VIDEO scan starting in :/var/lib/mythtv/videos:
2009-04-20 23:41:54.489 UPnpMedia: BuildMediaMap Done. Found 8257 objects
2009-04-20 23:43:01.513 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
It turns out my HDHomerun wasn't being properly recognized. The lights seemed to indicate it was on the network but I power cycled it just in case. A restart of the MythTV backend revealed:
2009-04-20 23:43:18.272 Using runtime prefix = /usr
2009-04-20 23:43:18.273 Empty LocalHostName.
2009-04-20 23:43:18.273 Using localhost value of backend0
2009-04-20 23:43:18.279 New DB connection, total: 1
2009-04-20 23:43:18.283 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:43:18.284 Closing DB connection named 'DBManager0'
2009-04-20 23:43:18.285 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:43:18.286 New DB connection, total: 2
2009-04-20 23:43:18.286 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:43:18.287 Current Schema Version: 1214
Starting up as the master server.
2009-04-20 23:43:18.293 HDHRChan(10114243/0): device found at address 192.168.2.13
2009-04-20 23:43:18.295 New DB connection, total: 3
2009-04-20 23:43:18.295 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:43:18.366 HDHRChan(10114243/1): device found at address 192.168.2.13
2009-04-20 23:43:18.428 New DB scheduler connection
2009-04-20 23:43:18.428 Connected to database 'mythconverg' at host: localhost
2009-04-20 23:43:19.637 Main::Registering HttpStatus Extension
2009-04-20 23:43:19.637 mythbackend version: 0.21.20080304-1 www.mythtv.org
2009-04-20 23:43:19.637 Enabled verbose msgs: important general schedule
2009-04-20 23:43:19.638 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2009-04-20 23:43:21.431 Reschedule requested for id -1.
Query 0: /record.search = :NRST AND program.manualid = 0 AND program.title = record.title
2009-04-20 23:43:21.433 |-- Start DB Query 0...
2009-04-20 23:43:21.438 |-- -1 results in 0.004817 sec.
2009-04-20 23:43:21.438 +-- Done.
2009-04-20 23:43:21.440 BuildWorkList...
2009-04-20 23:43:21.440 AddNewRecords...
2009-04-20 23:43:21.451 |-- Start DB Query...
2009-04-20 23:43:21.478 |-- 160 results in 0.02642 sec. Processing...
2009-04-20 23:43:21.500 +-- Cleanup...
2009-04-20 23:43:21.501 AddNotListed...
2009-04-20 23:43:21.502 |-- Start DB Query...
2009-04-20 23:43:21.503 |-- 0 results in 0.000614 sec. Processing...
2009-04-20 23:43:21.503 Sort by time...
2009-04-20 23:43:21.503 PruneOverlaps...
2009-04-20 23:43:21.504 Sort by priority...
2009-04-20 23:43:21.504 BuildListMaps...
2009-04-20 23:43:21.505 SchedNewRecords...
2009-04-20 23:43:21.505 Scheduling:
+Charlie Rose 67.1 MPTHD 21 12:35-13:32 1 5 5 C 5 0/0
+Two and a Half Men - "Best H.O 13.1 PN-2 21 20:30-21:00 1 5 5 C 5 0/0
+Fringe - "Bad Dreams" 45.1 FOX45 H 21 21:01-22:00 1 5 5 C 5 0/0
+The Mentalist - "Paint It Red" 13.1 PN-2 21 22:00-23:00 1 5 5 C 5 0/0
+Charlie Rose 67.1 MPTHD 22 12:35-13:32 1 5 5 C 5 0/0
+Lie to Me - "Undercover" 45.1 FOX45 H 22 20:00-21:00 1 5 5 C 5 0/0
.
.
.
+Dollhouse - "Briar Rose" 45.1 FOX45 H 01 21:01-22:00 1 5 5 C 5 0/0
+Boston Legal - "Smile" 2.1 PN-7 02 23:35-00:35 1 5 5 C 5 0/0
+Jericho - "Reconstruction" 54.1 WNUV HD 03 18:30-19:30 1 5 5 C 5 0/0
+Desperate Housewives - "Bargai 2.1 PN-7 03 21:00-22:01 1 5 5 C 5 0/0
+The Big Comfy Couch - "Gimme G 67.1 MPTHD 27 05:00-05:30 1 5 5 C 5 -1/0
+Sesame Street - "The Cookie To 67.1 MPTHD 21 09:30-10:30 1 5 5 w 5 -2/0
+Sesame Street - "Firefly Show" 67.1 MPTHD 27 09:30-10:30 1 5 5 w 5 -2/0
2009-04-20 23:43:21.549 SchedPreserveLiveTV...
2009-04-20 23:43:21.549 ClearListMaps...
2009-04-20 23:43:21.550 Sort by time...
2009-04-20 23:43:21.550 PruneRedundants...
2009-04-20 23:43:21.551 Sort by time...
2009-04-20 23:43:21.552 ClearWorkList...
2009-04-20 23:43:21.554 Scheduler: Update next_record for 28
2009-04-20 23:43:21.554 Scheduler: Update next_record for 36
--- print list start ---
Title - Subtitle Ch Station Day Start End S C I T N Pri
Sesame Street - "The Cookie To 67.1 MPTHD 21 09:30-10:30 1 5 5 w 5 -2/0
Charlie Rose 67.1 MPTHD 21 12:35-13:32 1 5 5 C 5 0/0
Two and a Half Men - "Best H.O 13.1 PN-2 21 20:30-21:00 1 5 5 C 5 0/0
Fringe - "Bad Dreams" 45.1 FOX45 H 21 21:01-22:00 1 5 5 C 5 0/0
The Mentalist - "Paint It Red" 13.1 PN-2 21 22:00-23:00 1 5 5 C 5 0/0
.
.
.
Dollhouse - "Briar Rose" 45.1 FOX45 H 01 21:01-22:00 1 5 5 C 5 0/0
Boston Legal - "Smile" 2.1 PN-7 02 23:35-00:35 1 5 5 C 5 0/0
Jericho - "Reconstruction" 54.1 WNUV HD 03 18:30-19:30 1 5 5 C 5 0/0
Desperate Housewives - "Bargai 2.1 PN-7 03 21:00-22:01 1 5 5 C 5 0/0
--- print list end ---
2009-04-20 23:43:21.631 Scheduled 45 items in 0.1 = 0.01 match + 0.11 place
2009-04-20 23:43:21.634 Seem to be woken up by USER
2009-04-20 23:43:28.830 UPnpMedia: BuildMediaMap VIDEO scan starting in :/var/lib/mythtv/videos:
2009-04-20 23:43:31.404 UPnpMedia: BuildMediaMap Done. Found 8257 objects
2009-04-20 23:44:38.430 AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
In other words, sweet, sweet victory :) While the whole teardown/setup of the backend would probably have caught the tuner issue as well I find checking the tuners to be an easier solution with fewer hair pulls required :)
No comments:
Post a Comment