Bug #3899
Timeshift problems
0%
Description
I'm not sure if this can be fixed but here is my problem. If I get continuity error on my HDHomeRun ATSC-T Tuner timeshift stops working. Here is an example of one such problem encountered today running under KODI 16.1:
The log file is:
2016-07-16 08:09:17.593 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 3)
2016-07-16 08:09:17.593 [WARNING]:TS: hdhr/189.028MHz/CFTO: MPEG2VIDEO #49 Corrupted PES header (errors 1) #49: Invalid start code 43:42:ba
2016-07-16 08:10:43.604 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 6)
2016-07-16 08:10:43.604 [WARNING]:TS: hdhr/189.028MHz/CFTO: MPEG2VIDEO
2016-07-16 08:10:43.615 [WARNING]:TS: hdhr/189.028MHz/CFTO: MPEG2VIDEO #49 Continuity counter error (total 1) #52 Continuity counter error (total 1)
2016-07-16 08:10:43.615 [WARNING]:TS: hdhr/189.028MHz/CFTO: AC3
2016-07-16 08:13:07.185 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 28)
2016-07-16 08:13:07.185 [WARNING]:TS: hdhr/189.028MHz/CFTO: MPEG2VIDEO #49 Continuity counter error (total 4) #51 Continuity counter error (total 1)
2016-07-16 08:13:07.185 [WARNING]:TS: hdhr/189.028MHz/CFTO: AC3
2016-07-16 08:13:07.185 [WARNING]:TS: hdhr/189.028MHz/CFTO: AC3 #52 Continuity counter error (total 2) #49 Corrupted PES header (errors 4)
2016-07-16 08:15:52.315 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 42)
2016-07-16 08:16:07.135 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 47)
2016-07-16 08:16:14.533 [WARNING]:TS: hdhr/189.028MHz/CFTO: MPEG2VIDEO
2016-07-16 08:20:53.111 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 63)
2016-07-16 08:24:45.991 [WARNING]:TS: hdhr/189.028MHz/CFTO Transport error indicator (total 74)
2016-07-16 08:27:10.475 [ INFO]:subscription: 0001: "10.1.1.51 [ | Kodi Media Center ]" unsubscribing from "CTV", hostname="10.1.1.51", username="10.1.1.51", client="Kodi Media Center"
2016-07-16 08:28:45.113 [ INFO]:htsp: 10.1.1.51 [ | Kodi Media Center ]: Disconnected
The time shift buffers are as follows:
drwx------ 3 tvh tvh 4096 Jul 16 07:16 ..rw------ 1 tvh tvh 131941916 Jul 16 07:17 tvh-0rw------ 1 tvh tvh 133939476 Jul 16 07:18 tvh-60006733rw------ 1 tvh tvh 133706587 Jul 16 07:19 tvh-120066733rw------ 1 tvh tvh 133935520 Jul 16 07:20 tvh-180026633rw------ 1 tvh tvh 133706412 Jul 16 07:21 tvh-240086633rw------ 1 tvh tvh 133702457 Jul 16 07:22 tvh-300046533rw------ 1 tvh tvh 133939473 Jul 16 07:23 tvh-360006433rw------ 1 tvh tvh 133702459 Jul 16 07:24 tvh-420066433rw------ 1 tvh tvh 133926450 Jul 16 07:25 tvh-480026333rw------ 1 tvh tvh 133719780 Jul 16 07:26 tvh-540086333rw------ 1 tvh tvh 133706589 Jul 16 07:27 tvh-600046233rw------ 1 tvh tvh 133922063 Jul 16 07:28 tvh-660006133rw------ 1 tvh tvh 133715481 Jul 16 07:29 tvh-720066133rw------ 1 tvh tvh 133926452 Jul 16 07:30 tvh-780026033rw------ 1 tvh tvh 133706756 Jul 16 07:31 tvh-840086033rw------ 1 tvh tvh 133755599 Jul 16 07:32 tvh-900045933rw------ 1 tvh tvh 133894838 Jul 16 07:33 tvh-960005833rw------ 1 tvh tvh 133817727 Jul 16 07:34 tvh-1020065833rw------ 1 tvh tvh 133904427 Jul 16 07:35 tvh-1080025733rw------ 1 tvh tvh 133617861 Jul 16 07:36 tvh-1140085733rw------ 1 tvh tvh 133758190 Jul 16 07:37 tvh-1200045633rw------ 1 tvh tvh 133883743 Jul 16 07:38 tvh-1260005533rw------ 1 tvh tvh 133702456 Jul 16 07:39 tvh-1320065533rw------ 1 tvh tvh 133939477 Jul 16 07:40 tvh-1380025433rw------ 1 tvh tvh 133706756 Jul 16 07:41 tvh-1440085433rw------ 1 tvh tvh 133875403 Jul 16 07:42 tvh-1500045333rw------ 1 tvh tvh 133806289 Jul 16 07:43 tvh-1560005233rw------ 1 tvh tvh 133679851 Jul 16 07:44 tvh-1620065233rw------ 1 tvh tvh 133922063 Jul 16 07:45 tvh-1680025133rw------ 1 tvh tvh 133706756 Jul 16 07:46 tvh-1740085133rw------ 1 tvh tvh 133702456 Jul 16 07:47 tvh-1800045033rw------ 1 tvh tvh 133961838 Jul 16 07:48 tvh-1860004933rw------ 1 tvh tvh 133680095 Jul 16 07:49 tvh-1920064933rw------ 1 tvh tvh 133939477 Jul 16 07:50 tvh-1980024833rw------ 1 tvh tvh 133734919 Jul 16 07:51 tvh-2040084833rw------ 1 tvh tvh 133691447 Jul 16 07:52 tvh-2100044733rw------ 1 tvh tvh 133922153 Jul 16 07:53 tvh-2160004633rw------ 1 tvh tvh 133702456 Jul 16 07:54 tvh-2220064633rw------ 1 tvh tvh 133939476 Jul 16 07:55 tvh-2280024533rw------ 1 tvh tvh 133716513 Jul 16 07:56 tvh-2340084533rw------ 1 tvh tvh 133735641 Jul 16 07:57 tvh-2400044433rw------ 1 tvh tvh 133934310 Jul 16 07:58 tvh-2460004333rw------ 1 tvh tvh 133664682 Jul 16 07:59 tvh-2520064333rw------ 1 tvh tvh 133999346 Jul 16 08:00 tvh-2580024233rw------ 1 tvh tvh 133646630 Jul 16 08:01 tvh-2640084233rw------ 1 tvh tvh 133752361 Jul 16 08:02 tvh-2700044133rw------ 1 tvh tvh 133889572 Jul 16 08:03 tvh-2760004033rw------ 1 tvh tvh 133702456 Jul 16 08:04 tvh-2820064033rw------ 1 tvh tvh 133926453 Jul 16 08:05 tvh-2880023933rw------ 1 tvh tvh 133715480 Jul 16 08:06 tvh-2940083933rw------ 1 tvh tvh 133706756 Jul 16 08:07 tvh-3000043833rw------ 1 tvh tvh 133926453 Jul 16 08:08 tvh-3060003733rw------ 1 tvh tvh 93438805 Jul 16 08:09 tvh-3120063733
drwx------ 2 tvh tvh 4096 Jul 16 08:09 .rw------ 1 tvh tvh 2342335193 Jul 16 08:26 tvh-7333994533
One can see that when the first error occurs at 08:09 new buffers stop being created and only one is being appended to. I'm not sure what the number at the end of the buffer is (maybe frame) but it seems to be incorrect when looking at the pattern. Once this happens one cannot shift in time if watching in real time. If I had been watching in past time (did a pause) then the stream will stop and I have to stop the channel and start it again.
My build is as follows:
Configure arguments:
--enable-hdhomerun_static --enable-hdhomerun_client --enable-libffmpeg_static --enable-libmfx --enable-libx265
Compiler:
Using C compiler: ccache cc
Build for arch: x86_64
Binaries:
Using PYTHON: python
Using GZIP: gzip
Using BZIP2: bzip2
Options:
pie yes
ccdebug no
cwc yes
capmt yes
constcw yes
linuxdvb yes
satip_server yes
satip_client yes
hdhomerun_client yes
hdhomerun_static yes
iptv yes
tsfile yes
dvbscan yes
timeshift yes
trace yes
imagecache yes
avahi yes
zlib yes
libav yes
ffmpeg_static yes
libx264 yes
libx264_static yes
libx265 yes
libx265_static yes
libvpx yes
libvpx_static yes
libtheora yes
libtheora_static yes
libvorbis yes
libvorbis_static yes
libfdkaac yes
libfdkaac_static yes
nvenc no
qsv no
libmfx_static no
inotify yes
epoll yes
uriparser no
ccache yes
tvhcsa yes
bundle no
dvbcsa no
dvben50221 no
kqueue no
dbus_1 yes
android no
tsdebug no
gtimer_check no
slow_memoryinfo no
libsystemd_daemon no
bintray_cache yes
execinfo yes
mmx yes
sse2 yes
W_unused_result yes
getloadavg yes
atomic64 yes
atomic_time_t yes
lockowner yes
qsort_r yes
stime yes
gmtoff yes
recvmmsg yes
sendmmsg yes
ifnames yes
py_gzip yes
bin_pkg_config yes
bin_xgettext yes
bin_msgmerge yes
bin_gzip yes
bin_bzip2 yes
ssl yes
linuxdvbapi yes
upnp yes
bin_cmake yes
stdcpp yes
libogg_static yes
inotify_h yes
mpegts yes
mpegts_dvb yes
Packages:
openssl 1.0.2g
zlib 1.2.8
avahi-client 0.6.32-rc
dbus-1 1.10.6
Installation paths:
Prefix: /usr/local
Binaries: ${prefix}/bin
Libraries: ${prefix}/lib
Data files: ${prefix}/share
Man pages: ${datadir}/man
Thank you in advance.
Files
History
Updated by Richard Pavlik over 8 years ago
Updated by - File tsdemux.patch tsdemux.patch added
I have looked a bit more into this, and the number appended to the end of the timeshift buffer files is simply the number of micro seconds elapsed since the channel has been tuned to. I have attached a patch file that modifies src/input/mpegts/tsdemux.c . I am a noob when it comes to decoding an mpeg stream so it was miss and hit. This patch simply skips a packet if it finds a transport or continuity error. This has resolved 90% of my problems. There is still a problem if the first timeshift buffer creation starts while getting an error of this type:
2016-07-24 13:30:01.316 [ ERROR]:parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 197378689, last = 197054365
2016-07-24 13:30:01.391 [ ERROR]:parser: transport stream AC3, DTS discontinuity. DTS = 197343360, last = 197029440
I am not skipping any packets for those errors. I am not sure how one would do that since this is not in tsdemux.c
Can someone please have a look at my patch to see if it reasonable?
Thanks
Richard
Updated by Jaroslav Kysela over 8 years ago
Updated by Provide '--trace timeshift' . https://tvheadend.org/projects/tvheadend/wiki/Traces
Updated by Richard Pavlik over 8 years ago
I have now tried over and over again with channels that are very weak in my area ( I get many errors, continuity, transport, AC3 ) and I cannot reproduce the problem if may patch is applied. The timeshift function works without problems. I must have got those errors when I was testing with a different fix that I was experimenting with. The supplied patch seems to have fixed my problems 100%. Is it a valid fix or is there some better way to go about fixing this ?
Thank you for all your efforts.
Updated by Richard Pavlik over 8 years ago
I have placed a pull request to get this reviewed
Updated by Jaroslav Kysela over 8 years ago
Based on your comment in the pull request, provide '--trace parser' info when the one-line (return) patch is applied. Or maybe, provide a dump of the input MPEG-TS stream when the bug is visible. Use 'wget -O file.ts http://tvh:9981/stream/channelname/<CHNAME>?profile=pass' .
Updated by Richard Pavlik over 8 years ago
- File parser.log parser.log added
Attached are the '--trace parser' results.
The buffers look like this:
root@r:~# ls altr /big/time-shift/buffer/0 3 tvh tvh 4096 Aug 8 09:03 ..
total 69836
drwx-----rw------ 1 tvh tvh 37756202 Aug 8 09:04 tvh-0rw------ 1 tvh tvh 22083789 Aug 8 09:05 tvh-60047866
drwx------ 2 tvh tvh 4096 Aug 8 09:05 .rw------ 1 tvh tvh 11658335 Aug 8 09:05 tvh-37072659611
And the console log is:
2016-08-08 09:03:31.863 [ INFO] tvhdhomerun: tuning to auto:647028615
2016-08-08 09:03:31.877 [ INFO] subscription: 0001: "10.1.1.55 [ | Kodi Media Center ]" subscribing on channel "Think", weight: 150, adapter: "HDHomeRun ATSC-T Tuner #0 (10.1.1.30)", network: "hdhr", mux: "647.028MHz", service: "Think", profile="htsp", hostname="10.1.1.55", username="10.1.1.55", client="Kodi Media Center"
2016-08-08 09:05:06.008 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 1)
2016-08-08 09:05:06.008 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65 Continuity counter error (total 1) #70 Continuity counter error (total 1)
2016-08-08 09:05:06.039 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-08 09:05:06.510 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 1) #69 Continuity counter error (total 1)
2016-08-08 09:05:06.544 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-08 09:05:09.178 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 8758659, last = 8653554
2016-08-08 09:05:09.493 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 8755200, last = 8622720
2016-08-08 09:05:09.493 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 8755200, last = 8622720
2016-08-08 09:05:09.522 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 8755200, last = 8622720
2016-08-08 09:05:11.823 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 8992893, last = 8842743
2016-08-08 09:05:13.358 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 9100800, last = 8809920
2016-08-08 09:05:13.358 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 9100800, last = 8809920
2016-08-08 09:05:13.358 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 9100800, last = 8809920
2016-08-08 09:05:16.170 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 1347)
2016-08-08 09:05:16.170 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65 Continuity counter error (total 752) #68 Continuity counter error (total 64)
2016-08-08 09:05:16.621 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-08 09:05:16.658 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 35) #69 Continuity counter error (total 89)
2016-08-08 09:05:16.658 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-08 09:05:17.532 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 9475200, last = 9357120
2016-08-08 09:05:18.814 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 9590400, last = 9227520
2016-08-08 09:05:54.282 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 1498)
2016-08-08 09:05:54.369 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65 Continuity counter error (total 801) #69 Continuity counter error (total 91)
2016-08-08 09:05:54.397 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-08 09:05:54.630 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 39) #68 Continuity counter error (total 72)
2016-08-08 09:05:54.688 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-08 09:05:55.511 [ INFO] subscription: 0001: "10.1.1.55 [ | Kodi Media Center ]" unsubscribing from "Think", hostname="10.1.1.55", username="10.1.1.55", client="Kodi Media Center"
2016-08-08 09:06:23.153 [ INFO] htsp: 10.1.1.55 [ | Kodi Media Center ]: Disconnected
Updated by Jaroslav Kysela over 8 years ago
Thanks, I believe that this patch (applied to tvh git repo) should fix this issue: http://tvheadend.org/projects/tvheadend/repository/revisions/384ca69fefdb14213cd4e5daac9597d5a4905cda/diff/ . Could you test v4.1-2147-g384ca69 ?
Updated by Richard Pavlik over 8 years ago
- File parser.zip parser.zip added
The problem still persists on HTS Tvheadend 4.1-2147~g384ca69
Attached is the zipped parser log file. It starts on the last channel tuned into (Search for "FOX").
The timeshift buffers are:
root@r:~# ls altr /big/time-shift/buffer/2/ 3 tvh tvh 4096 Aug 9 06:42 ..
total 76240
drwx-----rw------ 1 tvh tvh 21168497 Aug 9 06:43 tvh-0
drwx------ 2 tvh tvh 4096 Aug 9 06:43 .rw------ 1 tvh tvh 56886238 Aug 9 06:44 tvh-93965552755
There were many erros and here is the console log after tuning into FOX.
2016-08-09 06:42:55.411 [ INFO] tvhdhomerun: tuning to auto:473028615
2016-08-09 06:42:55.414 [ INFO] subscription: 0003: "10.1.1.55 [ | Kodi Media Center ]" subscribing on channel "FOX", weight: 150, adapter: "HDHomeRun ATSC-T Tuner #0 (10.1.1.30)", network: "hdhr", mux: "473.028MHz", service: "WUTV-HD", profile="htsp", hostname="10.1.1.55", username="10.1.1.55", client="Kodi Media Center"
2016-08-09 06:43:03.694 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 1)
2016-08-09 06:43:04.759 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49 Continuity counter error (total 1) #53 Continuity counter error (total 1)
2016-08-09 06:43:06.669 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:10.003 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52 Continuity counter error (total 1) #52: Invalid start code e5:01:88
2016-08-09 06:43:12.854 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:13.028 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49 Corrupted PES header (errors 1) #49 Continuity counter error (total 288)
2016-08-09 06:43:13.688 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 1216)
2016-08-09 06:43:14.832 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
2016-08-09 06:43:19.675 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 28) #52 Continuity counter error (total 19)
2016-08-09 06:43:20.904 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:22.779 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53: Invalid start code 30:53:b1 #49: Invalid start code c9:7c:1f
2016-08-09 06:43:22.975 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
2016-08-09 06:43:23.010 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52: Invalid start code fe:bf:94 #49 Continuity counter error (total 3435)
2016-08-09 06:43:23.680 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 6721)
2016-08-09 06:43:24.783 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
2016-08-09 06:43:29.807 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 581) #52 Continuity counter error (total 420)
2016-08-09 06:43:31.659 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:33.058 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code f3:15:24 #52 Corrupted PES header (errors 12)
2016-08-09 06:43:33.411 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:33.689 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 24192)
2016-08-09 06:43:34.788 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49 Continuity counter error (total 9026) #53: Invalid start code 74:92:e3
2016-08-09 06:43:36.019 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:36.592 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 457224, last = 270024
2016-08-09 06:43:37.702 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 554956, last = 321676
2016-08-09 06:43:39.852 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 884) #52 Continuity counter error (total 685)
2016-08-09 06:43:41.674 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:43.066 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 8f:2e:be #52: Invalid start code b0:c9:53
2016-08-09 06:43:43.249 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 1056264, last = 650184
2016-08-09 06:43:43.705 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 44370)
2016-08-09 06:43:44.174 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:44.811 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49 Continuity counter error (total 15649) #53: Invalid start code f9:a6:00
2016-08-09 06:43:46.345 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:48.073 [ ERROR] parser: transport stream AC3, DTS discontinuity. DTS = 1488076, last = 655756
2016-08-09 06:43:49.809 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 1420) #52 Continuity counter error (total 1140)
2016-08-09 06:43:51.623 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:53.017 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 74:07:c3 #49 Continuity counter error (total 24282)
2016-08-09 06:43:53.706 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 67219)
2016-08-09 06:43:54.808 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
2016-08-09 06:43:55.186 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52: Invalid start code c8:3c:8c #53: Invalid start code b6:6c:83
2016-08-09 06:43:57.109 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:43:59.845 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 2178) #52 Continuity counter error (total 1737)
2016-08-09 06:44:00.215 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 2637475, last = 2524810
2016-08-09 06:44:01.640 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:44:03.025 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 24:c9:c9 #49 Continuity counter error (total 36838)
2016-08-09 06:44:03.715 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 89749)
2016-08-09 06:44:04.825 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
2016-08-09 06:44:05.019 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 3066904, last = 2951256
2016-08-09 06:44:05.993 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52: Invalid start code 8f:80:71 #53 Corrupted PES header (errors 52)
2016-08-09 06:44:07.220 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 3277114, last = 3177978
2016-08-09 06:44:09.067 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:44:09.822 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 3102) #52 Continuity counter error (total 2544)
2016-08-09 06:44:11.661 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:44:12.303 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = -468241, last = 3715550
2016-08-09 06:44:12.795 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 3774111, last = -454732
2016-08-09 06:44:13.036 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 77:ac:2b #49 Continuity counter error (total 53443)
2016-08-09 06:44:13.735 [WARNING] TS: hdhr/473.028MHz/WUTV-HD Transport error indicator (total 109873)
2016-08-09 06:44:14.830 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
2016-08-09 06:44:14.962 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 3967804, last = 3862670
2016-08-09 06:44:16.010 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52: Invalid start code 8c:a5:55 #53: Invalid start code 35:a4:f4
2016-08-09 06:44:18.601 [ ERROR] parser: transport stream MPEG2VIDEO, DTS discontinuity. DTS = 4293630, last = 4161481
2016-08-09 06:44:19.158 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
2016-08-09 06:44:19.444 [ INFO] subscription: 0003: "10.1.1.55 [ | Kodi Media Center ]" unsubscribing from "FOX", hostname="10.1.1.55", username="10.1.1.55", client="Kodi Media Center"
2016-08-09 06:45:08.174 [ INFO] htsp: 10.1.1.55 [ | Kodi Media Center ]: Disconnected
Updated by Richard Pavlik over 8 years ago
Attached the is the zipped trace (search for second occurrence of '/1/tvh' for the bad timeshift file)
Time shift buffers:
total 2892
drwx------ 3 tvh tvh 4096 Aug 10 02:40 ..
-rw------- 1 tvh tvh 1910753 Aug 10 02:40 tvh-0
drwx------ 2 tvh tvh 4096 Aug 10 02:40 .
-rw------- 1 tvh tvh 1039493 Aug 10 02:41 tvh-78126332366
Console log for channel:2016-08-10 02:40:42.528 [ INFO] tvhdhomerun: tuning to auto:647028615 #69: Invalid start code 7a:a2:56
2016-08-10 02:40:42.531 [ INFO] subscription: 0002: "10.1.1.55 [ | Kodi Media Center ]" subscribing on channel "Think", weight: 150, adapter: "HDHomeRun ATSC-T Tuner #0 (10.1.1.30)", network: "hdhr", mux: "647.028MHz", service: "Think", profile="htsp", hostname="10.1.1.55", username="10.1.1.55", client="Kodi Media Center"
2016-08-10 02:40:42.985 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 1)
2016-08-10 02:40:42.985 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:40:43.027 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65: Invalid start code e0:9b:94 #65 Continuity counter error (total 1)
2016-08-10 02:40:43.534 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
2016-08-10 02:40:43.565 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 1) #69 Continuity counter error (total 1)
2016-08-10 02:40:43.732 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:40:43.954 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 1) #70: Invalid start code 9c:b3:6e
2016-08-10 02:40:45.771 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:40:50.159 [WARNING] parser: The timediff for AC3 is big (374164), using current dts
2016-08-10 02:40:51.362 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68: Invalid start code 83:7c:2a #65: Invalid start code 28:07:65
2016-08-10 02:40:53.033 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 4974)
2016-08-10 02:40:53.033 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
2016-08-10 02:40:53.033 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #69: Invalid start code 08:14:a7 #65 Continuity counter error (total 1942)
2016-08-10 02:40:53.555 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
2016-08-10 02:40:53.555 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 82) #69 Continuity counter error (total 168)
2016-08-10 02:40:53.692 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:40:53.932 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 156) #68: Invalid start code 26:af:df
2016-08-10 02:41:02.118 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:41:02.382 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70: Invalid start code f5:d5:52 #65: Invalid start code 3d:5b:00
2016-08-10 02:41:03.001 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 7514)
2016-08-10 02:41:03.001 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
2016-08-10 02:41:03.001 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #69: Invalid start code 65:c6:d9 #65 Continuity counter error (total 3586)
2016-08-10 02:41:03.566 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
2016-08-10 02:41:03.566 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 152) #69 Continuity counter error (total 358)
2016-08-10 02:41:03.728 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:41:04.022 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 292) #65 Continuity counter error (total 4791)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think Transport error indicator (total 9704)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #69 Continuity counter error (total 461) #68 Continuity counter error (total 354)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65: Invalid start code 7b:cf:d1 #70 Continuity counter error (total 207)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:41:16.420 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68: Invalid start code 84:95:0c #69: Invalid start code 11:68:68
2016-08-10 02:41:16.487 [WARNING] TS: hdhr/647.028MHz/Think: AC3
2016-08-10 02:41:17.318 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70: Invalid start code 35:11:df
2016-08-10 02:41:26.207 [ INFO] subscription: 0002: "10.1.1.55 [ | Kodi Media Center ]" unsubscribing from "Think", hostname="10.1.1.55", username="10.1.1.55", client="Kodi Media Center"
2016-08-10 02:41:46.005 [ INFO] htsp: 10.1.1.55 [ | Kodi Media Center ]: Disconnected
Updated by Jaroslav Kysela over 8 years ago
2016-08-10 02:40:50.838 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type B dts 17322499766 (1559024979) pts 17322499766 (1559024979) dur 3003 len 7904 err 1 2016-08-10 02:40:50.838 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type B dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 3003 len 5592 err 1 2016-08-10 02:40:50.915 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type P dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 3003 len 25080 err 1 2016-08-10 02:40:50.915 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type B dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 3003 len 5264 err 1 2016-08-10 02:40:50.954 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type B dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 3003 len 7456 err 1 2016-08-10 02:40:50.994 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type P dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 3003 len 24784 err 1 2016-08-10 02:40:50.994 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type B dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 3003 len 6472 err 1 2016-08-10 02:40:51.034 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type dts 0 (-9223372036854775808) pts 0 (-9223372036854775808) dur 0 len 0 err 1 2016-08-10 02:40:51.034 [ TRACE]:timeshift: ts 1 pkt wr - stream 1 type P pts 5314644 dts 5281277 dur 3003 len 24784 time 5314644 2016-08-10 02:40:51.034 [ TRACE]:timeshift: ts 1 pkt wr - stream 1 type B pts 5314644 dts 5314644 dur 3003 len 6472 time 5314644 2016-08-10 02:40:51.034 [ TRACE]:timeshift: ts 1 pkt wr - stream 1 type pts 78126332366 dts 5314644 dur 0 len 0 time 78126332366
Notes for me: the last line is the issue, but where's the source for this pts? -9223372036854775808 means PTS_UNSET (last parser line, but something in the timeshift / plumbing code mangles this value).
Updated by Jaroslav Kysela over 8 years ago
Could you retry with v4.1-2150-gfd72688 ? If things does not work, provide '--trace parser,timeshift,tsfix'.
Updated by Richard Pavlik over 8 years ago
- File TraceAndLogs.zip TraceAndLogs.zip added
It seems more resilient, but I still have a problems. In the attached zipped file are 3 files:
trace.log - log with --trace parser,timeshift,tsfix
tvh.log - standard tvh log
tsbuf.log - just directory with timeshift buffers as also seen here:
total 408896 drwx------ 3 tvh tvh 4096 Aug 11 07:01 .. -rw------- 1 tvh tvh 97852901 Aug 11 07:02 tvh-0 -rw------- 1 tvh tvh 99435092 Aug 11 07:03 tvh-60010477 -rw------- 1 tvh tvh 98444499 Aug 11 07:04 tvh-120003744 -rw------- 1 tvh tvh 85573482 Aug 11 07:05 tvh-180013688 -rw------- 1 tvh tvh 2393808 Aug 11 07:06 tvh-240006955 -rw------- 1 tvh tvh 2652421 Aug 11 07:06 tvh-95453019666 drwx------ 2 tvh tvh 4096 Aug 11 07:06 . -rw------- 1 tvh tvh 32337887 Aug 11 07:07 tvh-95473206500
Updated by Jaroslav Kysela over 8 years ago
2016-08-11 07:06:21.386 [ TRACE]:parser: pkt stream 1 MPEG2VIDEO type P dts 80240422933 (7221638064) pts 0 (-9223372036854775808) dur 3753 len 22693 err 1 2016-08-11 07:06:21.408 [ TRACE]:tsfix: MPEG2VIDEO PTS *-frame set to 7221637314 2016-08-11 07:06:21.408 [ TRACE]:tsfix: MPEG2VIDEO 2 837928 8590771770 3753 22693 2016-08-11 07:06:21.408 [ TRACE]:timeshift: ts 0 pkt wr - stream 1 type P pts 95453019666 dts 9310311 dur 3753 len 22693 time 95453019666 2016-08-11 07:06:21.408 [ TRACE]:timeshift: ts 0 pkt liv - stream 1 type P pts 95453019666 dts 9310311 dur 3753 len 22693 time 95453019666 2016-08-11 07:06:21.408 [ TRACE]:timeshift: ts 0 create file /big/time-shift/buffer/0/tvh-95453019666
Updated by Jaroslav Kysela over 8 years ago
Could you retry with v4.1-2154-ge3e8a79 ? Post trace log, if something is wrong.
Updated by Richard Pavlik over 8 years ago
Some different symptoms this time. First time I ran it without trace logs it went for a while but hung (no updates to buffers etc.). I could not Ctrl^C it from the console. kill -TERM did nothing, I had to do a kill -9.
Second time (the logs are from this) it also hung after a few minutes (more errors this time). Again had to do kill -9.
dir was:
root@r:~# ls -altr /big/time-shift/buffer/0/ total 11052 drwx------ 3 tvh tvh 4096 Aug 11 11:59 .. -rw------- 1 tvh tvh 10712309 Aug 11 11:59 tvh-0 drwx------ 2 tvh tvh 4096 Aug 11 11:59 . -rw------- 1 tvh tvh 591019 Aug 11 11:59 tvh-2245613444
Updated by Jaroslav Kysela over 8 years ago
I see the issue, but the current code should not hang. Could you try to gather full backtrace? Run tvh, wait for hang and 'gdb -p <tvh_pid>' then:
(gdb) set logging on (gdb) set pagination off (gdb) bt full
And you should post the gdb.txt file created in the directory where gdb is run.
Updated by Richard Pavlik over 8 years ago
- File logs-and-core.tar.gz logs-and-core.tar.gz added
This time I got a core dump. The attached file has the core dump and the trace log
Updated by Jaroslav Kysela over 8 years ago
Pls, do steps described in 'Processing core file'. https://tvheadend.org/projects/tvheadend/wiki/Debugging
Updated by Richard Pavlik over 8 years ago
Attached is the output from gdb
Updated by Jaroslav Kysela over 8 years ago
Pls, use gdb command 'thread apply all bt full' instead 'bt full'. Thanks.
Updated by Jaroslav Kysela over 8 years ago
OK, this crash / hangup should be fixed v4.1-2155-g9a0c876 . The other problem is remaining - the parser decodes a wrong timestamp, because the data are corrupted. More validation checks should be added to the code.
Updated by Richard Pavlik over 8 years ago
- File logs-and-trace.tar.gz logs-and-trace.tar.gz added
It is much better now. I am still able to reproduce the problem if I watch a channel with many errors. This would not be a standard use case. Normally I would not watch a channel this weak. I will keep testing with channels that are suitable for watching. The included file has the trace and standard log.
total 632M drwx------ 3 tvh tvh 4.0K Aug 13 08:22 .. -rw------- 1 tvh tvh 56M Aug 13 08:23 tvh-0 -rw------- 1 tvh tvh 56M Aug 13 08:24 tvh-60242033 -rw------- 1 tvh tvh 83M Aug 13 08:25 tvh-153099377 -rw------- 1 tvh tvh 54M Aug 13 08:26 tvh-180028366 -rw------- 1 tvh tvh 29M Aug 13 08:27 tvh-241890088 -rw------- 1 tvh tvh 60M Aug 13 08:28 tvh-300002088 -rw------- 1 tvh tvh 67M Aug 13 08:29 tvh-360425244 -rw------- 1 tvh tvh 17M Aug 13 08:29 tvh-420001433 drwx------ 2 tvh tvh 4.0K Aug 13 08:29 . -rw------- 1 tvh tvh 214M Aug 13 08:33 tvh-4163406222
Updated by Jaroslav Kysela over 8 years ago
Thanks. Could you trigger this bug with v4.1-2160-g4a9268e and provide new logs? I improved the logging to identify this remaining problem.
Updated by Richard Pavlik over 8 years ago
- File logs-and-trace.tar.gz logs-and-trace.tar.gz added
Attached data is for:
root@r:~# ls -altrh /big/time-shift/buffer/5/ total 65M drwx------ 3 tvh tvh 4.0K Aug 14 07:21 .. -rw------- 1 tvh tvh 1.7M Aug 14 07:21 tvh-0 drwx------ 2 tvh tvh 4.0K Aug 14 07:21 . -rw------- 1 tvh tvh 64M Aug 14 07:24 tvh-284764277 root@r:~#
Updated by Jaroslav Kysela over 8 years ago
... previous valid packet ... 2016-08-14 07:21:16.793 [ TRACE]:parser: deliver (pkt stream 1 MPEG2VIDEO type P dts 8407554951 pts 8407563960 dur 3003 len 25808 err 0) ... lots errors ... 2016-08-14 07:21:19.541 [ TRACE]:parser: deliver (pkt stream 1 MPEG2VIDEO type P dts 8432909452 pts 8432909452 dur 3003 len 70 err 0) ... next valid packet ... 2016-08-14 07:21:22.287 [ TRACE]:parser: deliver (pkt stream 1 MPEG2VIDEO type B dts 8408050446 pts 8408050446 dur 3003 len 20168 err 0)
The middle packet has invalid timestamps (although that parser does not marked it - err 0).