Project

General

Profile

Bug #3899

Timeshift problems

Added by Richard Pavlik almost 5 years ago. Updated over 4 years ago.

Status:
New
Priority:
Normal
Assignee:
Category:
Timeshift
Target version:
-
Start date:
2016-07-16
Due date:
% Done:

0%

Estimated time:
Found in version:
4.1-2141~g01c26fc
Affected Versions:

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)
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
#49: Invalid start code 43:42:ba
2016-07-16 08:10:43.615 [WARNING]:TS: hdhr/189.028MHz/CFTO: MPEG2VIDEO #49 Continuity counter error (total 1)
2016-07-16 08:10:43.615 [WARNING]:TS: hdhr/189.028MHz/CFTO: AC3
#52 Continuity counter error (total 1)
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)
2016-07-16 08:13:07.185 [WARNING]:TS: hdhr/189.028MHz/CFTO: AC3
#51 Continuity counter error (total 1)
2016-07-16 08:13:07.185 [WARNING]:TS: hdhr/189.028MHz/CFTO: AC3 #52 Continuity counter error (total 2)
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
#49 Corrupted PES header (errors 4)
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-0
rw------ 1 tvh tvh 133939476 Jul 16 07:18 tvh-60006733
rw------ 1 tvh tvh 133706587 Jul 16 07:19 tvh-120066733
rw------ 1 tvh tvh 133935520 Jul 16 07:20 tvh-180026633
rw------ 1 tvh tvh 133706412 Jul 16 07:21 tvh-240086633
rw------ 1 tvh tvh 133702457 Jul 16 07:22 tvh-300046533
rw------ 1 tvh tvh 133939473 Jul 16 07:23 tvh-360006433
rw------ 1 tvh tvh 133702459 Jul 16 07:24 tvh-420066433
rw------ 1 tvh tvh 133926450 Jul 16 07:25 tvh-480026333
rw------ 1 tvh tvh 133719780 Jul 16 07:26 tvh-540086333
rw------ 1 tvh tvh 133706589 Jul 16 07:27 tvh-600046233
rw------ 1 tvh tvh 133922063 Jul 16 07:28 tvh-660006133
rw------ 1 tvh tvh 133715481 Jul 16 07:29 tvh-720066133
rw------ 1 tvh tvh 133926452 Jul 16 07:30 tvh-780026033
rw------ 1 tvh tvh 133706756 Jul 16 07:31 tvh-840086033
rw------ 1 tvh tvh 133755599 Jul 16 07:32 tvh-900045933
rw------ 1 tvh tvh 133894838 Jul 16 07:33 tvh-960005833
rw------ 1 tvh tvh 133817727 Jul 16 07:34 tvh-1020065833
rw------ 1 tvh tvh 133904427 Jul 16 07:35 tvh-1080025733
rw------ 1 tvh tvh 133617861 Jul 16 07:36 tvh-1140085733
rw------ 1 tvh tvh 133758190 Jul 16 07:37 tvh-1200045633
rw------ 1 tvh tvh 133883743 Jul 16 07:38 tvh-1260005533
rw------ 1 tvh tvh 133702456 Jul 16 07:39 tvh-1320065533
rw------ 1 tvh tvh 133939477 Jul 16 07:40 tvh-1380025433
rw------ 1 tvh tvh 133706756 Jul 16 07:41 tvh-1440085433
rw------ 1 tvh tvh 133875403 Jul 16 07:42 tvh-1500045333
rw------ 1 tvh tvh 133806289 Jul 16 07:43 tvh-1560005233
rw------ 1 tvh tvh 133679851 Jul 16 07:44 tvh-1620065233
rw------ 1 tvh tvh 133922063 Jul 16 07:45 tvh-1680025133
rw------ 1 tvh tvh 133706756 Jul 16 07:46 tvh-1740085133
rw------ 1 tvh tvh 133702456 Jul 16 07:47 tvh-1800045033
rw------ 1 tvh tvh 133961838 Jul 16 07:48 tvh-1860004933
rw------ 1 tvh tvh 133680095 Jul 16 07:49 tvh-1920064933
rw------ 1 tvh tvh 133939477 Jul 16 07:50 tvh-1980024833
rw------ 1 tvh tvh 133734919 Jul 16 07:51 tvh-2040084833
rw------ 1 tvh tvh 133691447 Jul 16 07:52 tvh-2100044733
rw------ 1 tvh tvh 133922153 Jul 16 07:53 tvh-2160004633
rw------ 1 tvh tvh 133702456 Jul 16 07:54 tvh-2220064633
rw------ 1 tvh tvh 133939476 Jul 16 07:55 tvh-2280024533
rw------ 1 tvh tvh 133716513 Jul 16 07:56 tvh-2340084533
rw------ 1 tvh tvh 133735641 Jul 16 07:57 tvh-2400044433
rw------ 1 tvh tvh 133934310 Jul 16 07:58 tvh-2460004333
rw------ 1 tvh tvh 133664682 Jul 16 07:59 tvh-2520064333
rw------ 1 tvh tvh 133999346 Jul 16 08:00 tvh-2580024233
rw------ 1 tvh tvh 133646630 Jul 16 08:01 tvh-2640084233
rw------ 1 tvh tvh 133752361 Jul 16 08:02 tvh-2700044133
rw------ 1 tvh tvh 133889572 Jul 16 08:03 tvh-2760004033
rw------ 1 tvh tvh 133702456 Jul 16 08:04 tvh-2820064033
rw------ 1 tvh tvh 133926453 Jul 16 08:05 tvh-2880023933
rw------ 1 tvh tvh 133715480 Jul 16 08:06 tvh-2940083933
rw------ 1 tvh tvh 133706756 Jul 16 08:07 tvh-3000043833
rw------ 1 tvh tvh 133926453 Jul 16 08:08 tvh-3060003733
rw------ 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

tsdemux.patch (910 Bytes) tsdemux.patch Richard Pavlik, 2016-07-26 16:32
parser.log (2.75 MB) parser.log Richard Pavlik, 2016-08-08 15:17
parser.zip (463 KB) parser.zip Richard Pavlik, 2016-08-09 12:54
pt.zip (65.4 KB) pt.zip Zipped --trace parser,timeshift Richard Pavlik, 2016-08-10 09:09
TraceAndLogs.zip (2.89 MB) TraceAndLogs.zip Richard Pavlik, 2016-08-11 13:21
trace.log (881 KB) trace.log Richard Pavlik, 2016-08-11 18:09
tvh.log (8.93 KB) tvh.log Richard Pavlik, 2016-08-11 18:09
logs-and-core.tar.gz (6 MB) logs-and-core.tar.gz Richard Pavlik, 2016-08-12 03:43
gdb.txt (13.5 KB) gdb.txt Richard Pavlik, 2016-08-12 10:34
gdb.txt (98.7 KB) gdb.txt Richard Pavlik, 2016-08-12 21:46
logs-and-trace.tar.gz (4.93 MB) logs-and-trace.tar.gz Richard Pavlik, 2016-08-13 14:39
logs-and-trace.tar.gz (708 KB) logs-and-trace.tar.gz Richard Pavlik, 2016-08-14 13:29

History

#1

Updated by Richard Pavlik over 4 years ago

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

#3

Updated by Richard Pavlik over 4 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.

#4

Updated by Richard Pavlik over 4 years ago

I have placed a pull request to get this reviewed

see https://github.com/tvheadend/tvheadend/pull/881

#5

Updated by Jaroslav Kysela over 4 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' .

#6

Updated by Richard Pavlik over 4 years ago

Attached are the '--trace parser' results.

The buffers look like this:

[email protected]:~# ls altr /big/time-shift/buffer/0
total 69836
drwx-----
3 tvh tvh 4096 Aug 8 09:03 ..
rw------ 1 tvh tvh 37756202 Aug 8 09:04 tvh-0
rw------ 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)
2016-08-08 09:05:06.039 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#70 Continuity counter error (total 1)
2016-08-08 09:05:06.510 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 1)
2016-08-08 09:05:06.544 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69 Continuity counter error (total 1)
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)
2016-08-08 09:05:16.621 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#68 Continuity counter error (total 64)
2016-08-08 09:05:16.658 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 35)
2016-08-08 09:05:16.658 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69 Continuity counter error (total 89)
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)
2016-08-08 09:05:54.397 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69 Continuity counter error (total 91)
2016-08-08 09:05:54.630 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 39)
2016-08-08 09:05:54.688 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#68 Continuity counter error (total 72)
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

#7

Updated by Jaroslav Kysela over 4 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 ?

#8

Updated by Richard Pavlik over 4 years ago

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:

[email protected]:~# ls altr /big/time-shift/buffer/2/
total 76240
drwx-----
3 tvh tvh 4096 Aug 9 06:42 ..
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)
2016-08-09 06:43:06.669 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#53 Continuity counter error (total 1)
2016-08-09 06:43:10.003 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52 Continuity counter error (total 1)
2016-08-09 06:43:12.854 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52: Invalid start code e5:01:88
2016-08-09 06:43:13.028 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49 Corrupted PES header (errors 1)
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
#49 Continuity counter error (total 288)
2016-08-09 06:43:19.675 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 28)
2016-08-09 06:43:20.904 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52 Continuity counter error (total 19)
2016-08-09 06:43:22.779 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53: Invalid start code 30:53:b1
2016-08-09 06:43:22.975 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO
#49: Invalid start code c9:7c:1f
2016-08-09 06:43:23.010 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52: Invalid start code fe:bf:94
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
#49 Continuity counter error (total 3435)
2016-08-09 06:43:29.807 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 581)
2016-08-09 06:43:31.659 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52 Continuity counter error (total 420)
2016-08-09 06:43:33.058 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code f3:15:24
2016-08-09 06:43:33.411 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52 Corrupted PES header (errors 12)
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)
2016-08-09 06:43:36.019 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#53: Invalid start code 74:92:e3
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)
2016-08-09 06:43:41.674 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52 Continuity counter error (total 685)
2016-08-09 06:43:43.066 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 8f:2e:be
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
#52: Invalid start code b0:c9:53
2016-08-09 06:43:44.811 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49 Continuity counter error (total 15649)
2016-08-09 06:43:46.345 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#53: Invalid start code f9:a6:00
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)
2016-08-09 06:43:51.623 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52 Continuity counter error (total 1140)
2016-08-09 06:43:53.017 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 74:07:c3
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
#49 Continuity counter error (total 24282)
2016-08-09 06:43:55.186 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #52: Invalid start code c8:3c:8c
2016-08-09 06:43:57.109 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#53: Invalid start code b6:6c:83
2016-08-09 06:43:59.845 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 2178)
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
#52 Continuity counter error (total 1737)
2016-08-09 06:44:03.025 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: MPEG2VIDEO #49: Invalid start code 24:c9:c9
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
#49 Continuity counter error (total 36838)
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
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
#53 Corrupted PES header (errors 52)
2016-08-09 06:44:09.822 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3 #53 Continuity counter error (total 3102)
2016-08-09 06:44:11.661 [WARNING] TS: hdhr/473.028MHz/WUTV-HD: AC3
#52 Continuity counter error (total 2544)
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
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
#49 Continuity counter error (total 53443)
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
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
#53: Invalid start code 35:a4:f4
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

#9

Updated by Jaroslav Kysela over 4 years ago

Please, provide log for '--trace parser,timeshift' .

#10

Updated by Richard Pavlik over 4 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
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
#69: Invalid start code 7a:a2:56
2016-08-10 02:40:43.027 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65: Invalid start code e0:9b:94
2016-08-10 02:40:43.534 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
#65 Continuity counter error (total 1)
2016-08-10 02:40:43.565 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 1)
2016-08-10 02:40:43.732 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69 Continuity counter error (total 1)
2016-08-10 02:40:43.954 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 1)
2016-08-10 02:40:45.771 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#70: Invalid start code 9c:b3:6e
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
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
#65: Invalid start code 28:07:65
2016-08-10 02:40:53.033 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #69: Invalid start code 08:14:a7
2016-08-10 02:40:53.555 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
#65 Continuity counter error (total 1942)
2016-08-10 02:40:53.555 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 82)
2016-08-10 02:40:53.692 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69 Continuity counter error (total 168)
2016-08-10 02:40:53.932 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 156)
2016-08-10 02:41:02.118 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#68: Invalid start code 26:af:df
2016-08-10 02:41:02.382 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70: Invalid start code f5:d5:52
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
#65: Invalid start code 3d:5b:00
2016-08-10 02:41:03.001 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #69: Invalid start code 65:c6:d9
2016-08-10 02:41:03.566 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO
#65 Continuity counter error (total 3586)
2016-08-10 02:41:03.566 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #70 Continuity counter error (total 152)
2016-08-10 02:41:03.728 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69 Continuity counter error (total 358)
2016-08-10 02:41:04.022 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68 Continuity counter error (total 292)
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
#65 Continuity counter error (total 4791)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #69 Continuity counter error (total 461)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#68 Continuity counter error (total 354)
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: MPEG2VIDEO #65: Invalid start code 7b:cf:d1
2016-08-10 02:41:16.219 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#70 Continuity counter error (total 207)
2016-08-10 02:41:16.420 [WARNING] TS: hdhr/647.028MHz/Think: AC3 #68: Invalid start code 84:95:0c
2016-08-10 02:41:16.487 [WARNING] TS: hdhr/647.028MHz/Think: AC3
#69: Invalid start code 11:68:68
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

#11

Updated by Jaroslav Kysela over 4 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).

#12

Updated by Jaroslav Kysela over 4 years ago

Could you retry with v4.1-2150-gfd72688 ? If things does not work, provide '--trace parser,timeshift,tsfix'.

#13

Updated by Richard Pavlik over 4 years ago

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
#14

Updated by Jaroslav Kysela over 4 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
#15

Updated by Jaroslav Kysela over 4 years ago

Could you retry with v4.1-2154-ge3e8a79 ? Post trace log, if something is wrong.

#16

Updated by Richard Pavlik over 4 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:

[email protected]:~# 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

#17

Updated by Jaroslav Kysela over 4 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.

#18

Updated by Richard Pavlik over 4 years ago

This time I got a core dump. The attached file has the core dump and the trace log

#19

Updated by Jaroslav Kysela over 4 years ago

Pls, do steps described in 'Processing core file'. https://tvheadend.org/projects/tvheadend/wiki/Debugging

#20

Updated by Richard Pavlik over 4 years ago

Attached is the output from gdb

#21

Updated by Jaroslav Kysela over 4 years ago

Pls, use gdb command 'thread apply all bt full' instead 'bt full'. Thanks.

#22

Updated by Richard Pavlik over 4 years ago

As requested.

#23

Updated by Jaroslav Kysela over 4 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.

#24

Updated by Jaroslav Kysela over 4 years ago

Could you test v4.1-2159-g258c913 ?

#25

Updated by Richard Pavlik over 4 years ago

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
#26

Updated by Jaroslav Kysela over 4 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.

#27

Updated by Richard Pavlik over 4 years ago

Attached data is for:

[email protected]:~# 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
[email protected]:~#
#28

Updated by Jaroslav Kysela over 4 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).

Also available in: Atom PDF