TV-Scheduler loses scheduled entries (again)
Brought to you by:
christianrapp
Menu
▾
▴
#108 TV-Scheduler loses scheduled entries (again)
Basically reopen of Bug 3443362
I still run rev180.
I had 7 recordings (over the next 3 weeks, first later that evening) scheduled.
Then I added one and it recorded it.
After that the scheduler just had 4 recordings left.
So the problem still exists. Sorry.
Yes in rev180 this problem still exists but it was fixed in rev181, please check out again and give it a try
I haven't seen any schedule loss in the last 5 recordings, but the scheduler just terminated itself with 3 recordings to go.
Stupid me. I forgot to mention: this was with the rev181.
I checked with rev181 and today it again deleted a scheduled recording.
The rev181 does mitigate the problem though, but, nevertheless, a recording was killed. (I know for sure, because I use TV-Browser and it does store the recording as well)
randomcore, I need to test this myself intensively so I can debug the problem. Currently my time is very limited so give me another week or two to look inti this issue.
No haste here. But maybe I can give you a bit more information on what happened.
Just to confirm this matter. I just had a loss of two scheduled entries. The interesting thing here is the start of of the recording seemed to have triggered the removal. I had 7 recordings scheduled, one is currently running and I expected to have 6 recordings left, but there are just 4 now even while the recording is running.
Here is the scheduler.log:
---- SNIP ----
########################################################################
# Scheduler logfile. Release version 0.8.2b1 Build 181
# Start new session 29.01.2012 09:47:07
#
# [09:59:11] WARNING: Scheduler has been reinitiated.
# [09:59:23] WARNING: Scheduler has been reinitiated.
# [00:00:05] DEBUG: Job number 116 will be recorded today at 7:58
# [07:58:00] DEBUG: Attempting to record job number 116.
# [07:58:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [07:58:00] DEBUG: Recorder has been executed for Job 116.
# [07:58:03] DEBUG: Recording of job 116 {ARD} {7:58} 2012-02-04 0:32:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-02-04_07-58.mpeg} started successfully.
# [07:58:03] DEBUG: Recorder process PID 17989
# [00:00:09] DEBUG: Job number 117 will be recorded today at 11:28
# [00:00:09] DEBUG: Job number 118 will be recorded today at 20:13
# [11:28:00] DEBUG: Attempting to record job number 117.
# [11:28:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [11:28:00] DEBUG: Recorder has been executed for Job 117.
# [11:28:03] DEBUG: Recording of job 117 {ARD} {11:28} 2012-02-05 0:37:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-02-05_11-28.mpeg} started successfully.
# [11:28:03] DEBUG: Recorder process PID 527
# [18:55:23] WARNING: Scheduler has been reinitiated.
# [18:55:23] DEBUG: Job number 118 will be recorded today at 20:13
# [18:55:34] WARNING: Scheduler has been reinitiated.
# [18:55:34] DEBUG: Job number 118 will be recorded today at 20:13
# [20:13:00] DEBUG: Attempting to record job number 118.
# [20:13:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [20:13:00] DEBUG: Recorder has been executed for Job 118.
# [20:13:03] DEBUG: Recording of job 118 {ARD} {20:13} 2012-02-05 1:37:0 0 1 720/576 {/data/Video/Recording/Tatort_Kein_Entkommen_2012-02-05_20-13.mpeg} started successfully.
# [20:13:03] DEBUG: Recorder process PID 4355
# [00:00:19] DEBUG: Job number 119 will be recorded today at 8:58
# [08:58:00] DEBUG: Attempting to record job number 119.
# [08:58:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [08:58:00] DEBUG: Recorder has been executed for Job 119.
# [08:58:03] DEBUG: Recording of job 119 {ARD} {8:58} 2012-02-12 0:37:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-02-12_08-58.mpeg} started successfully.
# [08:58:03] DEBUG: Recorder process PID 17574
# [07:47:01] WARNING: Scheduler has been reinitiated.
# [07:47:12] WARNING: Scheduler has been reinitiated.
# [07:48:04] WARNING: Scheduler has been reinitiated.
# [07:48:07] WARNING: Scheduler has been reinitiated.
# [00:00:14] DEBUG: Job number 120 will be recorded today at 7:58
# [07:58:00] DEBUG: Attempting to record job number 120.
# [07:58:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [07:58:00] DEBUG: Recorder has been executed for Job 120.
# [07:58:03] DEBUG: Recording of job 120 {ARD} {7:58} 2012-02-18 0:32:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-02-18_07-58.mpeg} started successfully.
# [07:58:03] DEBUG: Recorder process PID 26168
# [00:00:18] DEBUG: Job number 121 will be recorded today at 11:28
# [11:28:00] DEBUG: Attempting to record job number 121.
# [11:28:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [11:28:00] DEBUG: Recorder has been executed for Job 121.
# [11:28:03] DEBUG: Recording of job 121 {ARD} {11:28} 2012-02-19 0:34:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-02-19_11-28.mpeg} started successfully.
# [11:28:03] DEBUG: Recorder process PID 20286
# [00:00:01] DEBUG: Job number 122 will be recorded today at 7:56
# [07:56:00] DEBUG: Attempting to record job number 122.
# [07:56:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [07:56:01] DEBUG: Recorder has been executed for Job 122.
# [07:56:04] DEBUG: Recording of job 122 {ARD} {7:56} 2012-02-25 0:39:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-02-25_07-56.mpeg} started successfully.
# [07:56:04] DEBUG: Recorder process PID 20904
# [19:26:36] WARNING: Scheduler has been reinitiated.
# [19:26:40] WARNING: Scheduler has been reinitiated.
# [19:26:49] WARNING: Scheduler has been reinitiated.
# [00:00:09] DEBUG: Job number 123 will be recorded today at 8:07
# [00:00:09] DEBUG: Job number 124 will be recorded today at 20:12
# [08:07:00] DEBUG: Attempting to record job number 123.
# [08:07:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [08:07:01] DEBUG: Recorder has been executed for Job 123.
# [08:07:04] DEBUG: Recording of job 123 {ARD} {8:07} 2012-02-26 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-02-26_08-07.mpeg} started successfully.
# [08:07:04] DEBUG: Recorder process PID 25489
# [20:12:00] DEBUG: Attempting to record job number 124.
# [20:12:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [20:12:01] DEBUG: Recorder has been executed for Job 124.
# [20:12:04] DEBUG: Recording of job 124 {ARD} {20:12} 2012-02-26 1:39:0 0 1 720/576 {/data/Video/Recording/Tatort_Der_traurige_K_nig_2012-02-26_20-12.mpeg} started successfully.
# [20:12:04] DEBUG: Recorder process PID 12665
# [00:00:13] DEBUG: Job number 125 will be recorded today at 8:02
# [08:02:00] DEBUG: Attempting to record job number 125.
# [08:02:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [08:02:00] DEBUG: Recorder has been executed for Job 125.
# [08:02:03] DEBUG: Recording of job 125 {ARD} {8:02} 2012-03-03 0:34:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-03-03_08-02.mpeg} started successfully.
# [08:02:03] DEBUG: Recorder process PID 25528
# [12:22:38] WARNING: Scheduler has been reinitiated.
# [12:24:31] WARNING: Scheduler has been reinitiated.
# [12:24:48] WARNING: Scheduler has been reinitiated.
# [12:25:14] WARNING: Scheduler has been reinitiated.
# [12:25:34] WARNING: Scheduler has been reinitiated.
# [12:25:52] WARNING: Scheduler has been reinitiated.
# [12:25:58] WARNING: Scheduler has been reinitiated.
# [12:26:05] WARNING: Scheduler has been reinitiated.
# [12:26:53] WARNING: Scheduler has been reinitiated.
# [12:27:04] WARNING: Scheduler has been reinitiated.
# [12:27:28] WARNING: Scheduler has been reinitiated.
# [12:27:38] WARNING: Scheduler has been reinitiated.
# [00:00:19] DEBUG: Job number 127 will be recorded today at 8:02
# [08:02:00] DEBUG: Attempting to record job number 127.
# [08:02:01] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [08:02:01] DEBUG: Recorder has been executed for Job 127.
# [08:02:04] DEBUG: Recording of job 127 {ARD} {8:02} 2012-03-10 0:34:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-03-10_08-02.mpeg} started successfully.
# [08:02:04] DEBUG: Recorder process PID 25267
# [00:00:03] DEBUG: Job number 128 will be recorded today at 8:27
# [00:00:03] DEBUG: Job number 129 will be recorded today at 20:12
# [08:27:00] DEBUG: Attempting to record job number 128.
# [08:27:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [08:27:00] DEBUG: Recorder has been executed for Job 128.
# [08:27:03] DEBUG: Recording of job 128 {ARD} {8:27} 2012-03-11 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-03-11_08-27.mpeg} started successfully.
# [08:27:03] DEBUG: Recorder process PID 27276
# [20:12:00] DEBUG: Attempting to record job number 129.
# [20:12:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [20:12:00] DEBUG: Recorder has been executed for Job 129.
# [20:12:03] DEBUG: Recording of job 129 {ARD} {20:12} 2012-03-11 1:39:0 0 1 720/576 {/data/Video/Recording/Tatort_Hinkebein_2012-03-11_20-12.mpeg} started successfully.
# [20:12:03] DEBUG: Recorder process PID 21550
# [00:00:07] DEBUG: Job number 131 will be recorded today at 5:42
# [05:42:00] DEBUG: Attempting to record job number 131.
# [05:42:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [05:42:00] DEBUG: Recorder has been executed for Job 131.
# [05:42:03] DEBUG: Recording of job 131 {RTL} {5:42} 2012-03-17 2:58:0 0 1 720/576 {/data/Video/Recording/Formel_1_Freies_Training_2012-03-17_05-42.mpeg} started successfully.
# [05:42:03] DEBUG: Recorder process PID 21151
# [23:23:11] WARNING: Scheduler has been reinitiated.
# [23:23:40] WARNING: Scheduler has been reinitiated.
# [23:25:41] WARNING: Scheduler has been reinitiated.
# [23:26:07] WARNING: Scheduler has been reinitiated.
# [23:26:30] WARNING: Scheduler has been reinitiated.
# [23:26:39] WARNING: Scheduler has been reinitiated.
# [00:00:19] DEBUG: Job number 133 will be recorded today at 10:57
# [00:00:19] DEBUG: Job number 139 will be recorded today at 5:40
# [05:40:00] DEBUG: Attempting to record job number 139.
# [05:40:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [05:40:01] DEBUG: Recorder has been executed for Job 139.
# [05:40:04] DEBUG: Recording of job 139 {RTL} {5:40} 2012-03-18 4:14:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-03-18_05-40.mpeg} started successfully.
# [05:40:04] DEBUG: Recorder process PID 3789
# [10:57:00] DEBUG: Attempting to record job number 133.
# [10:57:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [10:57:00] DEBUG: Recorder has been executed for Job 133.
# [10:57:03] DEBUG: Recording of job 133 {ARD} {10:57} 2012-03-18 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-03-18_10-57.mpeg} started successfully.
# [10:57:04] DEBUG: Recorder process PID 26813
# [00:00:04] DEBUG: Job number 137 will be recorded today at 7:42
# [07:42:00] DEBUG: Attempting to record job number 137.
# [07:42:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [07:42:00] DEBUG: Recorder has been executed for Job 137.
# [07:42:03] DEBUG: Recording of job 137 {RTL} {7:42} 2012-03-24 3:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Freies_Training_2012-03-24_07-42.mpeg} started successfully.
# [07:42:03] DEBUG: Recorder process PID 32310
---- SNAP ----
The current scheduler.conf says just: 143
And scheduled_recordings.conf is:
---- SNIP ----
138 {RTL} {8:42} 2012-03-25 4:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-03-25_08-42.mpeg}
140 {ARD} {11:27} 2012-04-01 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-04-01_11-27.mpeg}
142 {ARD} {7:53} 2012-04-07 0:43:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-04-07_07-53.mpeg}
143 {ARD} {9:32} 2012-04-08 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-04-08_09-32.mpeg}
---- SNAP ----
The scheduled_recordings.conf from last weeks backup:
---- SNIP ----
133 {ARD} {10:57} 2012-03-18 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-03-18_10-57.mpeg}
136 {ARD} {20:12} 2012-03-25 1:39:0 0 1 720/576 {/data/Video/Recording/Tatort_Falsch_verpackt_2012-03-25_20-12.mpeg}
137 {RTL} {7:42} 2012-03-24 3:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Freies_Training_2012-03-24_07-42.mpeg}
138 {RTL} {8:42} 2012-03-25 4:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-03-25_08-42.mpeg}
---- SNAP ----
Missing are recordings 136 and a new one for 2012-03-31 7_50 (no number).
I hope that helps.
Can I activate logging as to what I scheduled with the command line scheduler? This might be helpful to determin what is missing in the future.
cu, RandomCore
And again - I watched closely - at the start of a recording another scheduled recording vanished. I started out last week with this:
138 {RTL} {8:42} 2012-03-25 4:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-03-25_08-42.mpeg}
140 {ARD} {11:27} 2012-04-01 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-04-01_11-27.mpeg}
142 {ARD} {7:53} 2012-04-07 0:43:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-04-07_07-53.mpeg}
143 {ARD} {9:32} 2012-04-08 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-04-08_09-32.mpeg}
144 {ARD} {20:12} 2012-03-25 1:39:0 0 1 720/576 {/data/Video/Recording/Tatort_Falsch_verpackt_2012-03-25_20-12.mpeg}
145 {ARD} {7:50} 2012-03-31 0:41:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-03-31_07-50.mpeg}
147 {RTL} {6:42} 2012-04-14 2:58:0 0 1 720/576 {/data/Video/Recording/Formel_1_Freies_Training_2012-04-14_06-42.mpeg}
148 {RTL} {7:42} 2012-04-15 4:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-04-15_07-42.mpeg}
And richt after starting job 140, the resulting list looks like this:
142 {ARD} {7:53} 2012-04-07 0:43:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-04-07_07-53.mpeg}
143 {ARD} {9:32} 2012-04-08 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-04-08_09-32.mpeg}
148 {RTL} {7:42} 2012-04-15 4:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-04-15_07-42.mpeg}
As you sure see, the jobs 138, 144 and 145 are of last week and all got recorded as planed. This should leave us with the jobs 142, 143, 147 and 148, but job 147 mysteriously vanished:
147 {RTL} {6:42} 2012-04-14 2:58:0 0 1 720/576 {/data/Video/Recording/Formel_1_Freies_Training_2012-04-14_06-42.mpeg}
Here's the next chunk of the scheduler.log:
--- SNIP ---
# [10:09:05] WARNING: Scheduler has been reinitiated.
# [10:09:11] WARNING: Scheduler has been reinitiated.
# [10:09:30] WARNING: Scheduler has been reinitiated.
# [10:09:38] WARNING: Scheduler has been reinitiated.
# [10:10:25] WARNING: Scheduler has been reinitiated.
# [10:10:34] WARNING: Scheduler has been reinitiated.
# [10:10:49] WARNING: Scheduler has been reinitiated.
# [10:11:09] WARNING: Scheduler has been reinitiated.
# [00:00:11] DEBUG: Job number 138 will be recorded today at 8:42
# [00:00:11] DEBUG: Job number 144 will be recorded today at 20:12
# [08:42:00] DEBUG: Attempting to record job number 138.
# [08:42:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [08:42:01] DEBUG: Recorder has been executed for Job 138.
# [08:42:04] DEBUG: Recording of job 138 {RTL} {8:42} 2012-03-25 4:3:0 0 1 720/576 {/data/Video/Recording/Formel_1_Countdown_2012-03-25_08-42.mpeg} started successfully.
# [08:42:04] DEBUG: Recorder process PID 22570
# [12:45:29] WARNING: Scheduler has been reinitiated.
# [12:45:29] DEBUG: Job number 144 will be recorded today at 20:12
# [12:45:29] DEBUG: Job number 149 will be recorded today at 12:45
# [12:45:29] DEBUG: Attempting to record job number 149.
# [12:45:29] DEBUG: Scheduler detected TV-Viewer is running, sending commands via socket.
# [12:45:29] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [12:45:29] DEBUG: Recorder has been executed for Job 149.
# [12:45:32] DEBUG: Recording of job 149 {RTL} {12:45} 2012-03-25 1:0:0 0 1 720/576 {/data/Video/Recording/RTL_2012-03-25_12:45.mpeg} started successfully.
# [12:45:32] DEBUG: Recorder process PID 10880
# [20:12:00] DEBUG: Attempting to record job number 144.
# [20:12:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [20:12:00] DEBUG: Recorder has been executed for Job 144.
# [20:12:03] DEBUG: Recording of job 144 {ARD} {20:12} 2012-03-25 1:39:0 0 1 720/576 {/data/Video/Recording/Tatort_Falsch_verpackt_2012-03-25_20-12.mpeg} started successfully.
# [20:12:03] DEBUG: Recorder process PID 16566
# [00:00:10] DEBUG: Job number 145 will be recorded today at 7:50
# [07:50:00] DEBUG: Attempting to record job number 145.
# [07:50:01] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [07:50:01] DEBUG: Recorder has been executed for Job 145.
# [07:50:04] DEBUG: Recording of job 145 {ARD} {7:50} 2012-03-31 0:41:0 0 1 720/576 {/data/Video/Recording/Wissen_macht_Ah__2012-03-31_07-50.mpeg} started successfully.
# [07:50:04] DEBUG: Recorder process PID 21686
# [00:00:14] DEBUG: Job number 140 will be recorded today at 11:27
# [11:27:00] DEBUG: Attempting to record job number 140.
# [11:27:00] DEBUG: Video standard "pal-b/b1/g/h", nothing to change
# [11:27:01] DEBUG: Recorder has been executed for Job 140.
# [11:27:04] DEBUG: Recording of job 140 {ARD} {11:27} 2012-04-01 0:39:0 0 1 720/576 {/data/Video/Recording/Die_Sendung_mit_der_Maus_2012-04-01_11-27.mpeg} started successfully.
# [11:27:04] DEBUG: Recorder process PID 5002
--- SNAP ---
I wonder if this might help at all...
cu, ReandomCore
Yes this helps very much. I decided to do a step that I planned for the version of TV-Viewer. I started implementing code to use a sqlite database. This database will hold things like stations list, recordings and so on. This will make things much easier and more robust. Storing data in a flat file often causes trouble, it would be better to use xml but I love databases :) For TV-Viewer 0.8.2 I'll just implement the recordings to be stored in the database. The best thing about it, I don't have to delete old recordings anymore. I'll keep you posted on the progress here, it doesn't look like to much work so maybe I can do most of it on the easter holidays.
Any progress (fix or reimplementation) that I can test?
The current state is a bit prblematic, because it nearly always kills at least one scheduled recording as soon as one is started from schedule, so I have to check after each and every recording and re-add the lost one.
I just commited rev 182 0.8.2b2. I think thi should fix the problem, but introduces a lot of new code. So there might be other problems. I am now using a sqlite database to store scheduled recordings. this is way more effective. Read the new README because of updated system dependencies (sqlite3, sqlite tcl extension)
Please let me know if it helps or if there are any other bugs!
I installed the rev 182 and since it doesn't import the old scheduled recordings, I added them manually (got used to it because of the issue).
I tested two recordings so far and both were recorded smoothly without any deletion. So rev 182 seems to fix the issue.
That said, it is of course an euphemism since rev 182 doesn't actually delete scheduled recordings anymore and just keeps them in the sqlite3 databasefile forever. But this is actually not a real problem, since you can always manually delete if there is a performance problem after scheduling (hundreds? thousands? millions?) recordings.
I just had to reinvent my surrounding tools (script based XFCE4 Panel widget to show scheduled recordings, current recording and running state of the scheduler) to using sqlite3 instead of parsing some obsucre TCL data file.
Yes I do no longer delete the recordings :) That seems a bit like a hack, but I don't think the code would crash anymore or do strange things even if I did. A database offers much better data integrity and the code is much simpler and efficient now. A performance drop is not very likely. Even if you record 10 shows a day that'll make 3650 shows a year. I think with such a simple data structure you might have hundred of thousand rows in the database with any issues. But the main cause why I don't delete the entries is because in the future the Record wizard should also list already completed recordings with the possibility to playback the recording. If you delete the recording from there it will also be removed from the database.
Regards