[mythtv-users] Scheduler strange behavior

Ismo Tanskanen ismot at telemail.fi
Wed Mar 26 18:00:40 UTC 2008


Hi,

I'm running trunk 16588, but i have seen this behavior with earlier 
versions too.

I'm recording short episodes of "milo", they are only 5 minutes long and 
two episodes sent back to back in same channel. I have only one tuner 
what is capable to show this channel, and no multirec enabled because 
channel is encrypted and my card can only decrypt one channel at a time.

I have set recording rule to record "milo" any time at this channel. I 
have not set scheduler to record overtime, only set "Time to record past 
end of show" 420sec in general settings. This should not affect back to 
back records.

In upcoming recordings they seem ok, no conflicts. But sometimes, 
actually very often, myth only records first episode and adds 420sec 
overtime to it. I don't understand why it is doing it.

Backend log seems very strange, I'm sure that there was nobody canceling 
record, as nobody was home;

2008-03-25 17:59:29.875 TVRec(1): ASK_RECORDING 1 29 0 0
2008-03-25 18:00:02.395 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:00:02.402 Started recording: Milo: channel 1508 on cardid 
1, sourceid 1
2008-03-25 18:00:02.406 scheduler: Started recording: Milo: channel 1508 
on cardid 1, sourceid 1
2008-03-25 18:00:02.423 TVRec(1): HW Tuner: 1->1
2008-03-25 18:00:03.511 Finished recording Mitä tänään syötäisiin?: 
channel 1503
2008-03-25 18:00:03.519 scheduler: Finished recording: Mit?t??n 
sy??siin?: channel 1503
2008-03-25 18:00:03.540 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:00:03.624 DTVSM(0) Error: Wrong PMT; pmt->pn(3346) 
desired(257)
2008-03-25 18:00:03.629 DTVSM(0) Error: Wrong PMT; pmt->pn(97) desired(257)
2008-03-25 18:00:03.732 DTVSM(0) Error: Wrong PMT; pmt->pn(241) desired(257)
2008-03-25 18:00:03.735 DTVSM(0) Error: Wrong PMT; pmt->pn(177) desired(257)
2008-03-25 18:00:03.736 DTVSM(0) Error: Wrong PMT; pmt->pn(65) desired(257)
2008-03-25 18:00:03.736 DTVSM(0) Error: Wrong PMT; pmt->pn(209) desired(257)
2008-03-25 18:00:03.737 DTVSM(0) Error: Wrong PMT; pmt->pn(49) desired(257)
2008-03-25 18:00:03.735 Using runtime prefix = /usr/local, libdir = 
/usr/local/lib
2008-03-25 18:00:03.740 Empty LocalHostName.
2008-03-25 18:00:03.740 Using localhost value of mediaserver
2008-03-25 18:00:03.842 Finished recording Milo: channel 1508
2008-03-25 18:00:03.847 scheduler: Finished recording: Milo: channel 1508
2008-03-25 18:00:04.896 Finished recording Milo: channel 1508
2008-03-25 18:00:04.936 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:00:04.975 MainServer::HandleAnnounce Playback
2008-03-25 18:00:04.977 adding: mediaclient2 as a client (events: 0)
2008-03-25 18:00:04.978 MainServer::HandleAnnounce FileTransfer
2008-03-25 18:00:04.979 adding: mediaclient2 as a remote file transfer
2008-03-25 18:00:04.994 New DB connection, total: 1
2008-03-25 18:00:05.018 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:00:05.019 Closing DB connection named 'DBManager0'
2008-03-25 18:00:05.020 Deleting UPnP client...
2008-03-25 18:00:05.102 Using runtime prefix = /usr/local, libdir = 
/usr/local/lib
2008-03-25 18:00:05.105 Empty LocalHostName.
2008-03-25 18:00:05.106 Using localhost value of mediaserver
QServerSocket: failed to bind or listen to the socket
2008-03-25 18:00:05.109 MCP::InitUPnP() - HttpServer Create Error
2008-03-25 18:00:05.109 Deleting UPnP client...
2008-03-25 18:00:05.110 UPnP is broken?
2008-03-25 18:00:05.128 New DB connection, total: 1
2008-03-25 18:00:05.135 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:00:05.136 Closing DB connection named 'DBManager0'
2008-03-25 18:00:05.137 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:00:05.139 New DB connection, total: 2
2008-03-25 18:00:05.140 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:00:05.141 Current Schema Version: 1214
2008-03-25 18:00:05.148 Preview Error: Previewer file 
'/recordings/1508_20080325180002.mpg' is not valid.
2008-03-25 18:00:05.149 Preview Error: Run() file not local: 
'/recordings/1508_20080325180002.mpg'
2008-03-25 18:00:05.155 Preview Error: Preview process not ok.
fileinfo(/recordings/1508_20080325180002.mpg.png) exists: 0 readable: 0 
size: 0
2008-03-25 18:00:05.676 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:00:05.679 New DB connection, total: 2
2008-03-25 18:00:05.680 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:00:05.681 Current Schema Version: 1214
2008-03-25 18:00:08.253 AFD: Opened codec 0x86e04e0, id(MPEG2VIDEO) 
type(Video)
2008-03-25 18:00:08.254 AFD: codec MP3 has 2 channels
2008-03-25 18:00:08.255 AFD: Opened codec 0x86e0ad0, id(MP3) type(Audio)
2008-03-25 18:00:08.255 AFD: Opened codec 0x86e16b0, id(DVB_SUBTITLE) 
type(Subtitle)
2008-03-25 18:00:08.340 Preview: Grabbed preview 
'/recordings/1503_20080325175500.mpg' 720x576 at 84s
2008-03-25 18:00:26.442 Reschedule requested for id -1.
2008-03-25 18:00:26.554 Scheduled 14 items in 0.1 = 0.02 match + 0.09 place
2008-03-25 18:00:26.560 scheduler: Last message repeated 1 times: 
Finished recording: Milo: channel 1508
2008-03-25 18:00:26.564 scheduler: Scheduled items: Scheduled 14 items 
in 0.1 = 0.02 match + 0.09 place
2008-03-25 18:02:56.388 Expiring 0 MBytes for 1508 @ Tue Mar 25 18:00:00 
2008 => Milo
2008-03-25 18:02:56.392 autoexpire: Expiring Program: Expiring 0 MBytes 
for 1508 @ Tue Mar 25 18:00:00 2008 => Milo
2008-03-25 18:03:40.916 Reschedule requested for id 0.
2008-03-25 18:03:41.014 Scheduled 14 items in 0.1 = 0.00 match + 0.09 place
2008-03-25 18:03:41.027 scheduler: Scheduled items: Scheduled 14 items 
in 0.1 = 0.00 match + 0.09 place
2008-03-25 18:04:29.668 TVRec(1): ASK_RECORDING 1 29 1 0
2008-03-25 18:04:56.442 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:04:56.446 Expiring 535 MBytes for 1503 @ Mon Mar 24 
17:30:00 2008 => Kauniit ja rohkeat
2008-03-25 18:04:56.450 autoexpire: Expiring Program: Expiring 535 
MBytes for 1503 @ Mon Mar 24 17:30:00 2008 => Kauniit ja rohkeat
2008-03-25 18:04:56.451 Expiring 147 MBytes for 1503 @ Mon Mar 24 
17:55:00 2008 => Mit?t??n sy??siin?
2008-03-25 18:04:56.454 autoexpire: Expiring Program: Expiring 147 
MBytes for 1503 @ Mon Mar 24 17:55:00 2008 => Mit?t??n sy??siin?
2008-03-25 18:05:02.183 TVRec(1): Wanted to record: Milo 1508 Tue Mar 25 
18:05:00 2008 Tue Mar 25 18:15:00 2008
But a user has canceled this recording
2008-03-25 18:05:02.199 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:05:02.210 Canceled recording (Manual Cancel): Milo: 
channel 1508 on cardid 1, sourceid 1
2008-03-25 18:05:02.213 scheduler: Canceled recording (Manual Cancel): 
Milo: channel 1508 on cardid 1, sourceid 1
2008-03-25 18:05:03.217 Reschedule requested for id 0.
2008-03-25 18:05:03.308 Scheduled 14 items in 0.1 = 0.00 match + 0.09 place
2008-03-25 18:05:03.312 scheduler: Scheduled items: Scheduled 14 items 
in 0.1 = 0.00 match + 0.09 place
2008-03-25 18:06:57.028 Reschedule requested for id -1.
2008-03-25 18:06:57.127 Scheduled 14 items in 0.1 = 0.01 match + 0.09 place
2008-03-25 18:06:57.132 scheduler: Scheduled items: Scheduled 14 items 
in 0.1 = 0.01 match + 0.09 place
QDateTime::fromString: Parameter out of range
2008-03-25 18:12:02.261 Finished recording Milo: channel 1508
2008-03-25 18:12:02.269 scheduler: Finished recording: Milo: channel 1508
2008-03-25 18:12:02.333 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:12:02.448 Using runtime prefix = /usr/local, libdir = 
/usr/local/lib
2008-03-25 18:12:02.451 Empty LocalHostName.
2008-03-25 18:12:02.452 Using localhost value of mediaserver
2008-03-25 18:12:02.495 TVRec(1): RingBufferChanged()
2008-03-25 18:12:02.502 Finished recording Milo: channel 1508
2008-03-25 18:12:02.502 Reschedule requested for id 0.
2008-03-25 18:12:02.596 Scheduled 13 items in 0.1 = 0.00 match + 0.09 place
2008-03-25 18:12:02.600 scheduler: Last message repeated 1 times: 
Finished recording: Milo: channel 1508
2008-03-25 18:12:02.604 scheduler: Scheduled items: Scheduled 13 items 
in 0.1 = 0.00 match + 0.09 place
2008-03-25 18:12:02.769 New DB connection, total: 1
2008-03-25 18:12:02.777 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:12:02.778 Closing DB connection named 'DBManager0'
2008-03-25 18:12:02.779 Deleting UPnP client...
2008-03-25 18:12:02.990 MainServer::HandleAnnounce Playback
2008-03-25 18:12:02.992 adding: mediaclient2 as a client (events: 0)
2008-03-25 18:12:02.992 MainServer::HandleAnnounce FileTransfer
2008-03-25 18:12:02.993 adding: mediaclient2 as a remote file transfer
2008-03-25 18:12:03.419 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:12:03.421 New DB connection, total: 2
2008-03-25 18:12:03.422 Connected to database 'mythconverg' at host: 
localhost
2008-03-25 18:12:03.424 Current Schema Version: 1214
2008-03-25 18:12:05.977 AFD: Opened codec 0xb7b82500, id(MPEG2VIDEO) 
type(Video)
2008-03-25 18:12:05.979 AFD: codec MP3 has 2 channels
2008-03-25 18:12:05.980 AFD: Opened codec 0xb7b82af0, id(MP3) type(Audio)
2008-03-25 18:12:05.980 AFD: Opened codec 0xb7b830e0, id(DVB_SUBTITLE) 
type(Subtitle)
2008-03-25 18:12:06.072 Preview: Grabbed preview 
'/recordings/1508_20080325180000.mpg' 704x576 at 84s
2008-03-25 18:15:01.806 Finished recording Milo: channel 1508
2008-03-25 18:15:01.822 scheduler: Finished recording: Milo: channel 1508
2008-03-25 18:15:01.868 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-03-25 18:15:01.988 Using runtime prefix = /usr/local, libdir = 
/usr/local/lib
2008-03-25 18:15:01.991 Empty LocalHostName.
2008-03-25 18:15:01.991 Using localhost value of mediaserver
2008-03-25 18:15:02.167 TVRec(1): RingBufferChanged()
2008-03-25 18:15:02.188 Finished recording Milo: channel 1508

-Kane




More information about the mythtv-users mailing list