Bug #3296
Auto recording failed
100%
Description
Some auto recordings faild. Is there made a change that I have to reconfigure all of the auto recordings?
The failed recordings have in common that it seems there is a file stream, but looking on the disk the file size is small and not changed.
Part of syslog:
Nov 13 19:24:30 core2 tvheadend1291: dvr: "RTL Nieuws" on "RTL 4 HD" recorder starting
Nov 13 19:24:30 core2 tvheadend1291: mpegts: 11856V in Astra 3 NL HD - tuning on Conexant CX24117/CX24132 : DVB-S #1
Nov 13 19:24:31 core2 tvheadend1291: capmt: tvheadend: Starting CAPMT server for service "RTL4 HD" on adapter 1 seq 0x0002
Nov 13 19:24:31 core2 tvheadend1291: subscription: 00A9: "DVR: RTL Nieuws" subscribing on channel "RTL 4 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL4 HD", profile="matroska"
Nov 13 19:24:32 core2 tvheadend1291: parser: The timediff for TELETEXT is big (2934739302), using current dts
Nov 13 19:24:32 core2 tvheadend1291: parser: transport stream TELETEXT, DTS discontinuity. DTS = 0, last = 5655191690
Nov 13 19:24:32 core2 tvheadend1291: dvr: /data3/tvheadend/RTL Nieuws2015-11-1319-30.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL4 HD"
Nov 13 19:24:32 core2 tvheadend1291: dvr: # type lang resolution aspect ratio sample rate channels
Nov 13 19:24:32 core2 tvheadend1291: dvr: 1 H264 1920x1080 16:9
Nov 13 19:24:32 core2 tvheadend1291: dvr: 2 AC3 dut 48000 5.1
Nov 13 19:24:52 core2 systemd1: Time has been changed
Nov 13 19:24:52 core2 systemd1554: Time has been changed
Nov 13 19:24:53 core2 systemd1554: Time has been changed
Nov 13 19:24:53 core2 systemd1: Time has been changed
Nov 13 19:26:53 core2 tvheadend1291: epggrab: EIT: DVB Grabber - data completion timeout for 10847V in Astra 2 GB
Nov 13 19:26:53 core2 tvheadend1291: epggrab: UK: Freesat - data completion timeout for 10847V in Astra 2 GB
Nov 13 19:26:53 core2 tvheadend1291: subscription: 00A6: "epggrab" unsubscribing
Nov 13 19:26:54 core2 tvheadend1291: mpegts: 11023.25H in Astra 2 GB - tuning on Conexant CX24117/CX24132 : DVB-S #2
Nov 13 19:26:54 core2 tvheadend1291: subscription: 00AC: "epggrab" subscribing to mux "11023.25H", weight: 4, adapter: "Conexant CX24117/CX24132 : DVB-S #2", network: "Astra 2 GB", service: "Raw PID Subscription"
Nov 13 19:28:31 core2 systemd1: Time has been changed
Nov 13 19:28:31 core2 systemd1554: Time has been changed
Nov 13 19:30:03 core2 systemd1554: Time has been changed
Nov 13 19:30:03 core2 ntpd891: receive: Unexpected origin timestamp from 213.109.127.195
Nov 13 19:30:03 core2 systemd1: Time has been changed
Nov 13 19:30:04 core2 systemd1554: Time has been changed
Nov 13 19:30:04 core2 systemd1: Time has been changed
Nov 13 19:35:13 core2 systemd1: Time has been changed
Nov 13 19:35:13 core2 ntpd891: receive: Unexpected origin timestamp from 94.228.220.14
Nov 13 19:35:13 core2 systemd1554: Time has been changed
Nov 13 19:35:13 core2 ntpd891: receive: Unexpected origin timestamp from 213.109.127.195
Nov 13 19:35:14 core2 systemd1554: Time has been changed
Nov 13 19:35:14 core2 systemd1: Time has been changed
Nov 13 19:37:04 core2 tvheadend1291: epggrab: UK: Freesat - data completion timeout for 11023.25H in Astra 2 GB
Files
History
Updated by Jaroslav Kysela about 9 years ago
Updated by Could enable '--trace dvr' and log to a file ? https://tvheadend.org/projects/tvheadend/wiki/Traces
Updated by Meindert Oldenburger about 9 years ago
Updated by Could not reproduce on the fly, but will see if the recordings this evening fail again.
The following error message appears with testing, about file that does not exists, but it is there so I don't understand this.
2015-11-14 10:24:30.711 [ DEBUG]:dvr: File "/data3/tvheadend/K3 kan het2015-11-1410-30.mkv" -- Bestand of map bestaat niet -- Using for recording
Updated by Meindert Oldenburger about 9 years ago
After deleting all the auto recordings, I made for the test, and stoped the current running recordings, still one "ghost" recording is there streaming, but I can't see anything on the disk, except a recording file that is not growing. I can't anything in the log file.
Updated by Meindert Oldenburger about 9 years ago
Meindert Oldenburger wrote:
After deleting all the auto recordings, I made for the test, and stoped the current running recordings, still one "ghost" recording is there streaming, but I can't see anything on the disk, except a recording file that is not growing. I can't anything in the log file.
Sorry it must be something else, because its on Hotbird and that is not what I recorded on.
Updated by Jaroslav Kysela about 9 years ago
Meindert Oldenburger wrote:
The following error message appears with testing, about file that does not exists, but it is there so I don't understand this.
2015-11-14 10:24:30.711 [ DEBUG]:dvr: File "/data3/tvheadend/K3 kan het2015-11-1410-30.mkv" -- Bestand of map bestaat niet -- Using for recording
It's ok. It's just message that the file is not on disk yet so the filename is used for the output. No error, just an informational messsage.
Updated by Meindert Oldenburger about 9 years ago
Recording failed again but I have no logging, forgot to initialize debugging.
I'm going back to a previous version that seems to work: 4.1-955~ge9a7b3c I will let you know if the problems disappear with older release.
Updated by Kay R. about 9 years ago
Updated by 
I did a clean install of my server this week and I seem to be having same issues. I though I choose stable repo for ubuntu, but got build 900, and I'm on 980 now. At first I notice there are some recordings listed as failed. But then I notice missing recordings that are not listed anywhere. So I did some testing tonight and notice that recordings start but a file is newer written, if I look at status->Subscribtions I see there is input data but no output data. I can watch the same channel just fine, subscribtion then lists kodi with both input and output data. I restarted tvheadend while a "failed" recording was in progress and it then resumed to create output data and a file. I've tried using both PASS and Matroska profile, but makes no difference.
Updated by Kay R. about 9 years ago
Inside Amy Schumer worked, What makes a hero failed. I open that show in Kodi and it plays fine.
2015-11-15 01:20:23.907 [ TRACE]:dvr: entry timer scheduled for 1447547070 2015-11-15 01:20:23.907 [ INFO]:dvr: entry 66050907cca95bfac6bfc372cd23dd7a "Inside Amy Schumer (R)" on "Comedy Central Norway" starting at 2015-11-15 01:24:30, scheduled for recording by "192 .168.10.115" 2015-11-15 01:24:30.000 [ INFO]:dvr: "Inside Amy Schumer (R)" on "Comedy Central Norway" recorder starting 2015-11-15 01:24:30.000 [ INFO]:mpegts: 298MHz in CD-Kabel - tuning on DRXK DVB-C DVB-T : DVB-C #0 2015-11-15 01:24:30.004 [ INFO]:subscription: 0033: "epggrab" unsubscribing 2015-11-15 01:24:30.004 [ INFO]:capmt: oscam: Starting CAPMT server for service "Comedy Central (N)" on adapter 0 seq 0x0002 2015-11-15 01:24:30.005 [ INFO]:subscription: 0035: "DVR: Inside Amy Schumer (R)" subscribing on channel "Comedy Central Norway", weight: 300, adapter: "DRXK DVB-C DVB-T : DVB-C #0", network: "CD-Kabel", mux: "298MHz", provider: "Canal Digital KTV", service: "Comedy Central (N)", profile="matroska" 2015-11-15 01:24:30.848 [ DEBUG]:dvr: dvr entry 66050907cca95bfac6bfc372cd23dd7a event Inside Amy Schumer (R) on Comedy Central Norway - EPG marking stop 2015-11-15 01:24:31.256 [ DEBUG]:dvr: dvr entry e2b60cfcb7dceb34583e9f79be338beb other running event Tosh.0 (R) on Comedy Central Norway - EPG marking stop 2015-11-15 01:25:03.647 [ DEBUG]:dvr: dvr entry 66050907cca95bfac6bfc372cd23dd7a event Inside Amy Schumer (R) on Comedy Central Norway - EPG marking start 2015-11-15 01:25:03.781 [ DEBUG]:dvr: File "/mnt/raid/opptak/opptak/Inside Amy Schumer (R)/Inside Amy Schumer (R)2015-11-1501-25.mkv" -- Fila eller mappa finnes ikke -- Using for recording 2015-11-15 01:25:03.781 [ INFO]:dvr: /mnt/raid/opptak/opptak/Inside Amy Schumer (R)/Inside Amy Schumer (R)2015-11-1501-25.mkv from adapter: "DRXK DVB-C DVB-T : DVB-C #0", network: "CD-Kabel", mux: "298MHz", provider: "Canal Digital KTV", service: "Comedy Central (N)" 2015-11-15 01:25:03.781 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels 2015-11-15 01:25:03.781 [ INFO]:dvr: 1 H264 720x576 20:11 2015-11-15 01:25:03.781 [ INFO]:dvr: 2 MPEG2AUDIO nor 48000 2 2015-11-15 01:27:09.061 [ INFO]:subscription: 0035: "DVR: Inside Amy Schumer (R)" unsubscribing from "Comedy Central Norway" 2015-11-15 01:27:09.064 [ INFO]:capmt: oscam: Removing CAPMT Server from service "Comedy Central (N)" on adapter 0 2015-11-15 01:27:09.065 [ INFO]:dvr: "Inside Amy Schumer (R)" on "Comedy Central Norway": End of program: Aborted by user 2015-11-15 01:27:10.000 [ INFO]:mpegts: 298MHz in CD-Kabel - tuning on DRXK DVB-C DVB-T : DVB-C #0 2015-11-15 01:27:10.000 [ INFO]:subscription: 003C: "epggrab" subscribing to mux "298MHz", weight: 4, adapter: "DRXK DVB-C DVB-T : DVB-C #0", network: "CD-Kabel", service: "Raw PID Subscriptio n" 2015-11-15 01:27:26.639 [ TRACE]:dvr: entry timer scheduled for 1447547370 2015-11-15 01:27:26.639 [ INFO]:dvr: entry 734d8428721ed18bb650e4545d134860 "What Makes a Hero?" on "BBC World News" starting at 2015-11-15 01:29:30, scheduled for recording by "192.168.10.115 " 2015-11-15 01:29:30.000 [ INFO]:dvr: "What Makes a Hero?" on "BBC World News" recorder starting 2015-11-15 01:29:30.000 [ INFO]:mpegts: 290MHz in CD-Kabel - tuning on DRXK DVB-C DVB-T : DVB-C #0 2015-11-15 01:29:30.004 [ INFO]:subscription: 003C: "epggrab" unsubscribing 2015-11-15 01:29:30.004 [ INFO]:capmt: oscam: Starting CAPMT server for service "BBC World News" on adapter 0 seq 0x0003 2015-11-15 01:29:30.004 [ INFO]:subscription: 003F: "DVR: What Makes a Hero?" subscribing on channel "BBC World News", weight: 300, adapter: "DRXK DVB-C DVB-T : DVB-C #0", network: "CD-Kabel", mux: "290MHz", provider: "Canal Digital KTV", service: "BBC World News", profile="matroska" 2015-11-15 01:29:30.793 [ DEBUG]:dvr: dvr entry 734d8428721ed18bb650e4545d134860 other running event BBC World News on BBC World News - EPG marking stop 2015-11-15 01:30:04.451 [ DEBUG]:dvr: dvr entry 734d8428721ed18bb650e4545d134860 event What Makes a Hero? on BBC World News - EPG marking start 2015-11-15 01:32:41.538 [ INFO]:subscription: 000C: "192.168.10.16 [ kayrune | Kodi Media Center ]" unsubscribing from "C More Series HD Norway", hostname="192.168.10.16", username="192.168.10 .16", client="Kodi Media Center" 2015-11-15 01:32:41.586 [ INFO]:subscription: 0046: "192.168.10.16 [ kayrune | Kodi Media Center ]" subscribing on channel "BBC World News", weight: 150, adapter: "DRXK DVB-C DVB-T : DVB-C #0" , network: "CD-Kabel", mux: "290MHz", provider: "Canal Digital KTV", service: "BBC World News", profile="htsp", hostname="192.168.10.16", username="192.168.10.16", client="Kodi Media Center"
Updated by Kay R. about 9 years ago
Kay R. wrote:
At first I notice there are some recordings listed as failed. But then I notice missing recordings that are not listed anywhere.
Actually all the test recordings I did last night that failed are listed in the failed recordings list with status "time missed"
Updated by Jaroslav Kysela about 9 years ago
Follow my comment number one.. Provide full debug log including traces..
Updated by Jaroslav Kysela about 9 years ago
@Key R.: I believe that I fixed your issue in v4.1-989-gccc557e .
Updated by Kay R. about 9 years ago
Jaroslav Kysela wrote:
Follow my comment number one.. Provide full debug log including traces..
I though that's what I did :/ except I enable dvr debug log from webui.
Anyways, I think I might have found the issue and solution here http://tvheadend.org/issues/3302
I made the change as suggested and initial testing seems to work 5/5 so far, but maybe to early to confirm.
Updated by Jaroslav Kysela about 9 years ago
It should work even if the EPG running state checking is enabled. Again, I hope it's fixed in v4.1-989-gccc557e .
Updated by Kay R. about 9 years ago
Jaroslav Kysela wrote:
It should work even if the EPG running state checking is enabled. Again, I hope it's fixed in v4.1-989-gccc557e .
Yeah, I just had one fail again 
build 988 is the one available in Ubuntu repository so I guess I have to wait a few days to test. Thanks for update.
Updated by Meindert Oldenburger about 9 years ago
Jaroslav Kysela wrote:
There are no DVR changes from 955 to 986..
I have no problems with 955 this day, so what could be the problem then if nothing is changed after 955?
Updated by Meindert Oldenburger about 9 years ago
Today with version 4.1-992 it seems good, so something is changed after 971 that solves the problem.
I give more feedback end of the week to be sure if it is ok.
Updated by Meindert Oldenburger about 9 years ago
Three recordings at the same time, no auto recording, and two failed. The failed recordings have a small file size and the timestamp is when the recording is finished.
All three started at 20:24:30rw-rw-r- 1 hts video 7808550115 nov 20 22:40 The Voice of Holland2015-11-2020-30.mkvrw-rw-r- 1 hts video 1584 nov 20 22:50 The Frozen Ground2015-11-2020-30.mkvrw-rw-r- 1 hts video 1567 nov 20 22:54 Me, Myself & Irene2015-11-2020-30.mkv
Log with dvr trace:
Start:
2015-11-20 20:24:30.000 [ INFO]:dvr: "Me, Myself & Irene" on "RTL 8 HD" recorder starting
2015-11-20 20:24:30.000 [ INFO]:mpegts: 11856V in Astra 3 NL HD - tuning on Conexant CX24117/CX24132 : DVB-S #1
2015-11-20 20:24:31.482 [ INFO]:capmt: tvheadend: Starting CAPMT server for service "RTL8 HD" on adapter 1 seq 0x0007
2015-11-20 20:24:31.482 [ INFO]:subscription: 00D9: "DVR: Me, Myself & Irene" subscribing on channel "RTL 8 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL8 HD", profile="matroska"
2015-11-20 20:24:31.483 [ INFO]:dvr: "The Frozen Ground" on "RTL 5 HD" recorder starting
2015-11-20 20:24:31.483 [ INFO]:capmt: tvheadend: Starting CAPMT server for service "RTL5 HD" on adapter 1 seq 0x0008
2015-11-20 20:24:31.483 [ INFO]:subscription: 00DA: "DVR: The Frozen Ground" subscribing on channel "RTL 5 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL5 HD", profile="matroska"
2015-11-20 20:24:31.483 [ INFO]:dvr: "The Voice of Holland" on "RTL 4 HD" recorder starting
2015-11-20 20:24:31.483 [ INFO]:capmt: tvheadend: Starting CAPMT server for service "RTL4 HD" on adapter 1 seq 0x0009
2015-11-20 20:24:31.483 [ INFO]:subscription: 00DB: "DVR: The Voice of Holland" subscribing on channel "RTL 4 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL4 HD", profile="matroska"
2015-11-20 20:24:32.390 [WARNING]:parser: The timediff for TELETEXT is big (2934746502), using current dts
2015-11-20 20:24:32.391 [ DEBUG]:dvr: File "/data3/tvheadend/The Voice of Holland2015-11-2020-30.mkv" -- Bestand of map bestaat niet -- Using for recording
2015-11-20 20:24:32.391 [ INFO]:dvr: /data3/tvheadend/The Voice of Holland2015-11-2020-30.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL4 HD"
2015-11-20 20:24:32.391 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2015-11-20 20:24:32.391 [ INFO]:dvr: 1 H264 1920x1080 16:9
2015-11-20 20:24:32.391 [ INFO]:dvr: 2 AC3 dut 48000 5.1
2015-11-20 20:24:32.588 [WARNING]:TS: Astra 3 NL HD/11856V/RTL5 HD: TELETEXT @ #33 Continuity counter error (total 1)
2015-11-20 20:24:32.860 [WARNING]:parser: The timediff for TELETEXT is big (3487211655), using current dts
2015-11-20 20:24:32.860 [ ERROR]:parser: transport stream TELETEXT, DTS discontinuity. DTS = 0, last = 3487208055
2015-11-20 20:24:32.861 [ DEBUG]:dvr: File "/data3/tvheadend/The Frozen Ground2015-11-2020-30.mkv" -- Bestand of map bestaat niet -- Using for recording
2015-11-20 20:24:32.861 [ INFO]:dvr: /data3/tvheadend/The Frozen Ground2015-11-2020-30.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL5 HD"
2015-11-20 20:24:32.861 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2015-11-20 20:24:32.861 [ INFO]:dvr: 1 H264 1920x1080 16:9
2015-11-20 20:24:32.861 [ INFO]:dvr: 2 AC3 dut 48000 5.1
2015-11-20 20:24:33.331 [WARNING]:parser: The timediff for TELETEXT is big (2687230505), using current dts
2015-11-20 20:24:33.331 [ ERROR]:parser: transport stream TELETEXT, DTS discontinuity. DTS = 0, last = 5902700487
2015-11-20 20:24:33.331 [ DEBUG]:dvr: File "/data3/tvheadend/Me, Myself & Irene2015-11-2020-30.mkv" -- Bestand of map bestaat niet -- Using for recording
2015-11-20 20:24:33.331 [ INFO]:dvr: /data3/tvheadend/Me, Myself & Irene2015-11-2020-30.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL8 HD"
2015-11-20 20:24:33.331 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2015-11-20 20:24:33.331 [ INFO]:dvr: 1 H264 1920x1080 16:9
2015-11-20 20:24:33.331 [ INFO]:dvr: 2 AC3 dut 48000 5.1
2
End:
2015-11-20 22:40:00.060 [ INFO]:spawn: Executing "/home/hts/bin/remove_recodings_5w.sh"
2015-11-20 22:40:00.061 [ INFO]:subscription: 00DB: "DVR: The Voice of Holland" unsubscribing from "RTL 4 HD"
2015-11-20 22:40:00.061 [ INFO]:capmt: tvheadend: Removing CAPMT Server from service "RTL4 HD" on adapter 1
2015-11-20 22:40:00.062 [ INFO]:dvr: "The Voice of Holland" on "RTL 4 HD": End of program: Completed OK
2015-11-20 22:45:30.000 [WARNING]:epggrab: UK: Freesat - data completion timeout for 11023.25H in Astra 2 GB
2015-11-20 22:45:30.000 [WARNING]:epggrab: EIT: DVB Grabber - data completion timeout for 11023.25H in Astra 2 GB
2015-11-20 22:45:30.000 [ INFO]:subscription: 014D: "epggrab" unsubscribing
2015-11-20 22:45:31.000 [ INFO]:mpegts: 11804V in Hotbird - tuning on Conexant CX24117/CX24132 : DVB-S #2
2015-11-20 22:45:31.686 [ INFO]:subscription: 0150: "epggrab" subscribing to mux "11804V", weight: 4, adapter: "Conexant CX24117/CX24132 : DVB-S #2", network: "Hotbird", service: "Raw PID Subscription"
2015-11-20 22:46:04.003 [ INFO]:subscription: 0150: "epggrab" unsubscribing
2015-11-20 22:46:05.000 [ INFO]:mpegts: 10832H in Astra 2 GB - tuning on Conexant CX24117/CX24132 : DVB-S #2
2015-11-20 22:46:05.618 [ INFO]:subscription: 0153: "epggrab" subscribing to mux "10832H", weight: 4, adapter: "Conexant CX24117/CX24132 : DVB-S #2", network: "Astra 2 GB", service: "Raw PID Subscription"
2015-11-20 22:46:45.000 [ INFO]:subscription: 0153: "epggrab" unsubscribing
2015-11-20 22:46:46.000 [ INFO]:mpegts: 11765V in Hotbird - tuning on Conexant CX24117/CX24132 : DVB-S #2
2015-11-20 22:46:47.910 [ INFO]:subscription: 0156: "epggrab" subscribing to mux "11765V", weight: 4, adapter: "Conexant CX24117/CX24132 : DVB-S #2", network: "Hotbird", service: "Raw PID Subscription"
2015-11-20 22:47:20.004 [ INFO]:subscription: 0156: "epggrab" unsubscribing
2015-11-20 22:47:21.000 [ INFO]:mpegts: 11778V in Astra 2 GB - tuning on Conexant CX24117/CX24132 : DVB-S #2
2015-11-20 22:47:21.542 [ INFO]:subscription: 0158: "epggrab" subscribing to mux "11778V", weight: 4, adapter: "Conexant CX24117/CX24132 : DVB-S #2", network: "Astra 2 GB", service: "Raw PID Subscription"
2015-11-20 22:47:32.724 [ INFO]:opentv-skyuk: channels complete
2015-11-20 22:47:39.763 [ INFO]:opentv-skyuk: titles complete
2015-11-20 22:47:50.918 [ INFO]:opentv-skyuk: summaries complete
2015-11-20 22:47:50.918 [ INFO]:subscription: 0158: "epggrab" unsubscribing
2015-11-20 22:47:51.000 [ INFO]:mpegts: 11097V in Astra 2 GB - tuning on Conexant CX24117/CX24132 : DVB-S #2
2015-11-20 22:47:51.474 [ INFO]:subscription: 015A: "epggrab" subscribing to mux "11097V", weight: 4, adapter: "Conexant CX24117/CX24132 : DVB-S #2", network: "Astra 2 GB", service: "Raw PID Subscription"
2015-11-20 22:50:00.019 [ INFO]:subscription: 00DA: "DVR: The Frozen Ground" unsubscribing from "RTL 5 HD"
2015-11-20 22:50:00.019 [ INFO]:capmt: tvheadend: Removing CAPMT Server from service "RTL5 HD" on adapter 1
2015-11-20 22:50:00.019 [ INFO]:dvr: "The Frozen Ground" on "RTL 5 HD": End of program: Completed OK
2015-11-20 22:55:00.000 [ INFO]:subscription: 00D9: "DVR: Me, Myself & Irene" unsubscribing from "RTL 8 HD"
2015-11-20 22:55:00.003 [ INFO]:capmt: tvheadend: Removing CAPMT Server from service "RTL8 HD" on adapter 1
2015-11-20 22:55:00.003 [ INFO]:dvr: "Me, Myself & Irene" on "RTL 8 HD": End of program: Completed OK
2015-11-20 22:58:01.000 [WARNING]:epggrab: UK: Freesat - data completion timeout for 11097V in Astra 2 GB
2015-11-20 22:58:01.000 [WARNING]:epggrab: EIT: DVB Grabber - data completion timeout for 11097V in Astra 2 GB
2015-11-20 22:58:01.000 [ INFO]:subscription: 015A: "epggrab" unsubscribing
Updated by Meindert Oldenburger about 9 years ago
Above error is with HTS Tvheadend 4.1-1024~g752b62b
Updated by Meindert Oldenburger about 9 years ago
In oscam log some dvbapi messages, not seen those between 20:25 and 22:50 .
2015/11/20 22:49:31 777DE0 c (ecm) meindert (0100&00006A/5C00/1B6F/64:CCAE667532694CAAA609F41EAEA44EA0): found (662 ms) by CanalDigitaal - RTL 5 HD
2015/11/20 22:49:41 777DE0 c (ecm) meindert (0100&00006A/5C00/1B6F/64:B17181703CCFCBFA7585B0B1B93866EC): found (335 ms) by CanalDigitaal - RTL 5 HD
2015/11/20 22:49:41 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:90936409AE7A03F5777BEC4B1B83B522): found (666 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:49:51 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:22ABACA5FFB0A431216F1C689BA4426F): found (329 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:49:51 777DE0 c (ecm) meindert (0100&00006A/5C00/1B6F/64:4E91F500B979D396879CC7172C8D8006): found (641 ms) by CanalDigitaal - RTL 5 HD
2015/11/20 22:50:00 777DE0 c (dvbapi) Demuxer 0 continue decoding of SRVID 1B7C
2015/11/20 22:50:00 777DE0 c (dvbapi) Demuxer 0 ecmpid 0 CAID: 0500 ECM_PID: 0C21 PROVID: 051900
2015/11/20 22:50:00 777DE0 c (dvbapi) Demuxer 0 ecmpid 1 CAID: 1817 ECM_PID: 070D PROVID: 000000
2015/11/20 22:50:00 777DE0 c (dvbapi) Demuxer 0 ecmpid 2 CAID: 0100 ECM_PID: 070D PROVID: 00006A
2015/11/20 22:50:00 777DE0 c (dvbapi) Demuxer 0 found 3 ECMpids and 1 STREAMpids in PMT
2015/11/20 22:50:00 777DE0 c (dvbapi) Demuxer 0 serving srvid 1B7C (0500:1B7C unknown) on adapter 0001 camask 0002 index 0000 pmtpid 0000
2015/11/20 22:50:01 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:1E04919B353575E4449911133D877F0D): found (330 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:50:11 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:743C9E5BD4E20A691ED32EC4E0DB7F1E): found (331 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:50:21 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:7D477D8C126C39FE155DEAC75484CA31): found (335 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:50:31 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:F82234B64C89D774618EF265BF05D464): found (330 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:50:41 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:04E847AF8CCFB4B9136B8B360823897F): found (332 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:50:51 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:0D30FF370B6D8008242A353C3CC10289): found (331 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:51:01 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:80B65972F004B50A30D255582DDC5A01): found (334 ms) by CanalDigitaal - RTL 8 HD
2015/11/20 22:51:11 777DE0 c (ecm) meindert (0100&00006A/5C00/1B7C/64:AAE7E5C6482627C4C399A59185E9232F): found (330 ms) by CanalDigitaal - RTL 8 HD
Updated by Meindert Oldenburger about 9 years ago
All of my recording profiles have 'EPG runnig state' OFF, so no 'EPG runnig state' in this situation.
Please provide me with more information how I can help. As I stated before with version 955 no problems occur like this.
Updated by Meindert Oldenburger about 9 years ago
Both failed recordings are recorded based on the default profile, the successful recording is based on custom profile. The differences between the profiles is that the default has "Tag files with metadata: ON", "Skip commercials: ON" no post-processing and filename charset is ASCII instead of UTF-8.
Could "Tag files with metadata: ON" be the problem?
Updated by Jaroslav Kysela about 9 years ago
Also, do you have 'EPG running state' off or default in the relevant channel settings ?
See comment 1 . It's the full DVR log/trace which may uncover something.
Updated by Meindert Oldenburger about 9 years ago
"Use EPG running state: Not Set" in all channels
Please provide me with other trace option(s) then "all", because the resulting file stream is to much.
Updated by Meindert Oldenburger about 9 years ago
I don't understand your comment #25, what I deliver at #19 is with --trace dvr
Updated by Jaroslav Kysela about 9 years ago
You have probably tvheadend binary compiled without the trace support. Don't pass --disable-trace as the configure options. You should see '[TRACE]' lines.
Updated by Meindert Oldenburger almost 9 years ago
I always compile like this, so have traces on:
cd /usr/local/src/tvheadend/
git pull
make distclean; ./configure; make -j4
sudo systemctl stop tvheadend
sudo make uninstall
sudo make install
sudo systemctl start tvheadend
Updated by Meindert Oldenburger almost 9 years ago
Started 4 recordings and one fails "LifestyleXperience"
tvheadend is started as following:
/usr/local/bin/tvheadend -f -u hts -g video --trace dvr -l /data3/tvheadend/tvheadend.log
disk:
-rw-rw-r-- 1 hts video 825 nov 22 14:19 LifestyleXperience2015-11-2214-25.mkv -rw-rw-rw- 1 hts video 162303 nov 22 14:25 tvheadend.log -rw-rw-r-- 1 hts video 922372618 nov 22 14:37 Jill2015-11-2214-20.mkv -rw-rw-r-- 1 hts video 842274109 nov 22 14:37 LEGO Friends2015-11-2214-06.mkv -rw-rw-r-- 1 hts video 555865693 nov 22 14:37 Theaterkids2015-11-2214-31.mkv
logging:
2015-11-22 14:16:30.008 [ TRACE]:dvr: entry timer scheduled for 1448197230 2015-11-22 14:16:30.008 [ INFO]:dvr: entry cfd55c18f5dc55cb5e8942ec092416a1 "LEGO Friends" on "RTL 8 HD" starting at 2015-11-22 14:00:30, scheduled for recording by "192.168.2.101" 2015-11-22 14:16:30.064 [ INFO]:dvr: "LEGO Friends" on "RTL 8 HD" recorder starting 2015-11-22 14:16:30.064 [ INFO]:mpegts: 11856V in Astra 3 NL HD - tuning on Conexant CX24117/CX24132 : DVB-S #1 2015-11-22 14:16:31.549 [ INFO]:capmt: tvheadend: Starting CAPMT server for service "RTL8 HD" on adapter 1 seq 0x0003 2015-11-22 14:16:31.549 [ INFO]:subscription: 00A5: "DVR: LEGO Friends" subscribing on channel "RTL 8 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL8 HD", profile="matroska" 2015-11-22 14:16:32.147 [WARNING]:TS: Astra 3 NL HD/11856V/RTL8 HD: TELETEXT @ #38 Continuity counter error (total 1) 2015-11-22 14:16:32.685 [ DEBUG]:dvr: File "/data3/tvheadend/LEGO Friends2015-11-2214-06.mkv" -- Bestand of map bestaat niet -- Using for recording 2015-11-22 14:16:32.685 [ INFO]:dvr: /data3/tvheadend/LEGO Friends2015-11-2214-06.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL8 HD" 2015-11-22 14:16:32.685 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels 2015-11-22 14:16:32.685 [ INFO]:dvr: 1 H264 1920x1080 16:9 2015-11-22 14:16:32.685 [ INFO]:dvr: 2 AC3 dut 48000 5.1 2015-11-22 14:16:32.698 [WARNING]:parser: The timediff for TELETEXT is big (2687272869), using current dts 2015-11-22 14:16:35.849 [ TRACE]:dvr: entry timer scheduled for 1448198070 2015-11-22 14:16:35.849 [ INFO]:dvr: entry 7d5af3e0616333e0c4822107e95ed2eb "Jill" on "NPO 3 HD" starting at 2015-11-22 14:14:30, scheduled for recording by "192.168.2.101" 2015-11-22 14:16:35.850 [ INFO]:dvr: "Jill" on "NPO 3 HD" recorder starting 2015-11-22 14:16:35.850 [ INFO]:mpegts: 12187.5H in Astra 3 NL HD - tuning on Conexant CX24117/CX24132 : DVB-S #0 2015-11-22 14:16:37.409 [ INFO]:capmt: tvheadend: Starting CAPMT server for service "NPO3 HD" on adapter 0 seq 0x0004 2015-11-22 14:16:37.409 [ INFO]:subscription: 00A6: "DVR: Jill" subscribing on channel "NPO 3 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #0", network: "Astra 3 NL HD", mux: "12187.5H", provider: "M7 Group", service: "NPO3 HD", profile="matroska" 2015-11-22 14:16:37.998 [WARNING]:TS: Astra 3 NL HD/12187.5H/NPO3 HD: TELETEXT @ #38 Continuity counter error (total 1) 2015-11-22 14:16:38.420 [ DEBUG]:dvr: File "/data3/tvheadend/Jill2015-11-2214-20.mkv" -- Bestand of map bestaat niet -- Using for recording 2015-11-22 14:16:38.421 [ INFO]:dvr: /data3/tvheadend/Jill2015-11-2214-20.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #0", network: "Astra 3 NL HD", mux: "12187.5H", provider: "M7 Group", service: "NPO3 HD" 2015-11-22 14:16:38.421 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels 2015-11-22 14:16:38.421 [ INFO]:dvr: 1 H264 1920x1080 16:9 2015-11-22 14:16:38.421 [ INFO]:dvr: 2 AC3 dut 48000 5.1 2015-11-22 14:16:42.176 [ TRACE]:dvr: entry timer scheduled for 1448198370 2015-11-22 14:16:42.176 [ INFO]:dvr: entry 7a1446ca26fd3c9573b3c5004f1ed83e "LifestyleXperience" on "RTL 4 HD" starting at 2015-11-22 14:19:30, scheduled for recording by "192.168.2.101" 2015-11-22 14:16:50.911 [ TRACE]:dvr: entry timer scheduled for 1448198730 2015-11-22 14:16:50.911 [ INFO]:dvr: entry ce4e8ef582d126d16c77e53094a81cf4 "Theaterkids" on "RTL 8 HD" starting at 2015-11-22 14:25:30, scheduled for recording by "192.168.2.101" 2015-11-22 14:18:00.000 [ TRACE]:dvr: timerec update 2015-11-22 14:19:30.000 [ INFO]:dvr: "LifestyleXperience" on "RTL 4 HD" recorder starting 2015-11-22 14:19:30.001 [ INFO]:capmt: tvheadend: Starting CAPMT server for service "RTL4 HD" on adapter 1 seq 0x0005 2015-11-22 14:19:30.001 [ INFO]:subscription: 00A7: "DVR: LifestyleXperience" subscribing on channel "RTL 4 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL4 HD", profile="matroska" 2015-11-22 14:19:30.860 [ DEBUG]:dvr: File "/data3/tvheadend/LifestyleXperience2015-11-2214-25.mkv" -- Bestand of map bestaat niet -- Using for recording 2015-11-22 14:19:30.860 [ INFO]:dvr: /data3/tvheadend/LifestyleXperience2015-11-2214-25.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL4 HD" 2015-11-22 14:19:30.860 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels 2015-11-22 14:19:30.860 [ INFO]:dvr: 1 H264 1920x1080 16:9 2015-11-22 14:19:30.860 [ INFO]:dvr: 2 AC3 dut 48000 5.1 2015-11-22 14:19:30.884 [WARNING]:parser: The timediff for TELETEXT is big (2934753702), using current dts 2015-11-22 14:19:30.884 [ ERROR]:parser: transport stream TELETEXT, DTS discontinuity. DTS = 0, last = 5655177290 2015-11-22 14:25:30.000 [ INFO]:dvr: "Theaterkids" on "RTL 8 HD" recorder starting 2015-11-22 14:25:30.000 [ INFO]:subscription: 00A8: "DVR: Theaterkids" subscribing on channel "RTL 8 HD", weight: 300, adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL8 HD", profile="matroska" 2015-11-22 14:25:30.583 [WARNING]:parser: The timediff for TELETEXT is big (2687290869), using current dts 2015-11-22 14:25:30.587 [ DEBUG]:dvr: File "/data3/tvheadend/Theaterkids2015-11-2214-31.mkv" -- Bestand of map bestaat niet -- Using for recording 2015-11-22 14:25:30.587 [ INFO]:dvr: /data3/tvheadend/Theaterkids2015-11-2214-31.mkv from adapter: "Conexant CX24117/CX24132 : DVB-S #1", network: "Astra 3 NL HD", mux: "11856V", provider: "M7 Group", service: "RTL8 HD" 2015-11-22 14:25:30.587 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels 2015-11-22 14:25:30.587 [ INFO]:dvr: 1 H264 1920x1080 16:9 2015-11-22 14:25:30.587 [ INFO]:dvr: 2 AC3 dut 48000 5.1
Updated by Jaroslav Kysela almost 9 years ago
Thanks. I cannot determine anything from this. Could you add this code?
diff --git a/src/dvr/dvr_rec.c b/src/dvr/dvr_rec.c
index 2ffd929..afd238c 100644
--- a/src/dvr/dvr_rec.c
+++ b/src/dvr/dvr_rec.c
@@ -1298,6 +1298,7 @@ dvr_thread(void *aux)
}
if (dts_offset == PTS_UNSET && pkt->pkt_dts != PTS_UNSET)
dts_offset = pkt->pkt_dts;
+ tvhtrace("dvr", "packet for '%s': dts %ld/%ld", lang_str_get(de->de_title, NULL), (long)dts_offset, (long)pkt->pkt_dts);
if (dts_pts_valid(pkt, dts_offset)) {
pkt3 = pkt_copy_shallow(pkt);
pkt3->pkt_dts -= dts_offset;
Updated by Meindert Oldenburger almost 9 years ago
- File tvheadend.log.zip tvheadend.log.zip added
Some recodings failed again. Code added as stated in #32 and that resulted in a log file of 216 Mb, see file tvheadend.log.zip
rw-rw-r- 1 hts video 1655959004 nov 23 18:55 Het Klokhuis2015-11-2318-25.mkvrw-rw-r- 1 hts video 1643184772 nov 23 18:55 EénVandaag2015-11-2318-15.mkvrw-rw-r- 1 hts video 1429566198 nov 23 19:10 The Bold and the Beautiful2015-11-2318-30.mkvrw-rw-r- 1 hts video 1555388349 nov 23 19:10 Blokken2015-11-2318-30.mkvrw-rw-r- 1 hts video 831 nov 23 19:20 Still Standing2015-11-2318-40.mkvrw-rw-r- 1 hts video 840 nov 23 19:24 Ramsay's Kitchen Nightmares2015-11-2319-30.mkvrw-rw-r- 1 hts video 823 nov 23 20:04 RTL Nieuws2015-11-2319-30.mkvrw-rw-r- 1 hts video 831035321 nov 23 20:09 RTL Weer2015-11-2319-55.mkvrw-rw-r- 1 hts video 807329062 nov 23 20:14 NOS Journaal2015-11-2320-00.mkv
Updated by Jaroslav Kysela almost 9 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset commit:tvheadend|b9882fe5dc652aa98248a5fe5d59ab3995710cf5.
Updated by Jaroslav Kysela almost 9 years ago
Fixed in v4.1-1054-gb9882fe . Thank you for your patience and tests!