Tvheadend

I've noticed this too, but it only appears on older programming where the broadcaster switches aspect for adverts.

I think it would be nice to (have an option to?) ignore aspect changes when deciding if a source has been reconfigured.

Another short-term solution is to use pass instead of mkv.

In the example I pasted, the reconfigure happens 54 minutes into the show, so at least the commercials during the actual show did not disrupt the format of the transmission.
I also got this message on a modern show:

Jan 23 04:09:30 sat tvheadend[32457]: dvr: "The Shannara Chronicles" on "5*" recorder starting
Jan 23 04:09:30 sat tvheadend[32457]: mpegts: 10964.25H in 28.2E - tuning on STV0910 : DVB-S #0
Jan 23 04:09:30 sat tvheadend[32457]: subscription: 05BC: "DVR: The Shannara Chronicles" subscribing on channel "5*", weight: 300, adapter: "STV0910 : DVB-S #0", network: "28.2E", mux: "10964.25H", provider: "BSkyB", service: "5STAR", profile="matroska" 
Jan 23 04:09:59 sat tvheadend[32457]: mpegts: 10964.25H in 28.2E scan complete
Jan 23 04:10:00 sat tvheadend[32457]: dvr: /data/tv/recordings/The Shannara Chronicles/5_-The Shannara Chronicles.2018-01-23.04-15.mkv from adapter: "STV0910 : DVB-S #0", network: "28.2E", mux: "10964.25H", provider: "BSkyB", service: "5STAR" 
Jan 23 04:10:00 sat tvheadend[32457]: dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
Jan 23 04:10:00 sat tvheadend[32457]: dvr:  1  MPEG2VIDEO              704x576     16:9                                 
Jan 23 04:10:00 sat tvheadend[32457]: dvr:  2  MPEG2AUDIO        nar                             48000        2         
Jan 23 04:10:00 sat tvheadend[32457]: dvr:  3  MPEG2AUDIO        eng                             48000        2         
Jan 23 04:10:00 sat tvheadend[32457]: dvr:  4  DVBSUB            eng                                                    
Jan 23 04:10:00 sat tvheadend[32457]: dvr:  6  TEXTSUB           eng                                                    
Jan 23 04:24:40 sat tvheadend[32457]: epggrab: EIT: DVB Grabber - data completion timeout for 10964.25H in 28.2E
Jan 23 04:24:40 sat tvheadend[32457]: epggrab: UK: Freesat - data completion timeout for 10964.25H in 28.2E
Jan 23 05:04:01 sat tvheadend[32457]: subscription: 0610: "epggrab" subscribing to mux "10964.25H", weight: 4, adapter: "STV0910 : DVB-S #0", network: "28.2E", service: "Raw PID Subscription" 
Jan 23 05:09:49 sat tvheadend[32457]: dvr: Unable to reconfigure "/data/tv/recordings/The Shannara Chronicles/5_-The Shannara Chronicles.2018-01-23.04-15.mkv" 
Jan 23 05:09:51 sat tvheadend[32457]: dvr: "The Shannara Chronicles" on "5*": End of program: Source reconfigured
Jan 23 05:09:51 sat tvheadend[32457]: dvr: "The Shannara Chronicles" on "5*" recorder starting
Jan 23 05:09:51 sat tvheadend[32457]: dvr: /data/tv/recordings/The Shannara Chronicles/5_-The Shannara Chronicles.2018-01-23.05-09.mkv from adapter: "STV0910 : DVB-S #0", network: "28.2E", mux: "10964.25H", provider: "BSkyB", service: "5STAR" 
Jan 23 05:09:51 sat tvheadend[32457]: dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
Jan 23 05:09:51 sat tvheadend[32457]: dvr:  1  MPEG2VIDEO              704x576     16:9                                 
Jan 23 05:09:51 sat tvheadend[32457]: dvr:  2  MPEG2AUDIO        nar                             48000        2         
Jan 23 05:09:51 sat tvheadend[32457]: dvr:  3  MPEG2AUDIO        eng                             48000        2         
Jan 23 05:09:51 sat tvheadend[32457]: dvr:  4  DVBSUB            eng                                                    
Jan 23 05:09:51 sat tvheadend[32457]: dvr:  6  TEXTSUB           eng                                                    
Jan 23 05:10:00 sat tvheadend[32457]: subscription: 05BC: "DVR: The Shannara Chronicles" unsubscribing from "5*" 
Jan 23 05:10:00 sat tvheadend[32457]: dvr: "The Shannara Chronicles" on "5*": End of program: Completed OK

I use mkv in a feeble attempt to keep the subtitle information, which is usually inaccessible with Kodi when recording from Pick, Spike and 5*.

I have the same issue. Normaly the record is splitted at 59m:31s or 59m:32s and continues then with a new file. At this moment, no commercial is recorded. But I don't know, when this behavior started.

This was also present in 4.2.4, I reported in https://tvheadend.org/issues/4772 a little while ago.

Although, I ended up with the recording marked failed, but two separate mkv files (before and after the event) on disk.

It was discussed many times, the source reconfiguration means that the stream parameters were changed. The MKV handles only streams with 'fixed' parameters (except the multi-segmented MKV, but it's a question, which clients supports it). So TVH tries to create multiple files for those recordings. No information should be lost. If you like to have this output as separate recordings, use 'DVR clone' settings in the DVR config.

For reporter: Use $n in your format string (DVR config) to make sure that different files are created in this case, otherwise TVH cannot create a different file, thus the original will be overwritten.

I use this pattern to specify the mkv filename $t/$c$-t.%F.%R$.e$n.$x

You are right, the old file was saved (that means, the recording was not lost):
/data/tv/recordings/The Shannara Chronicles/5_-The Shannara Chronicles.2018-01-23.04-15.mkv (867MB)
/data/tv/recordings/The Shannara Chronicles/5_-The Shannara Chronicles.2018-01-23.05-09.mkv (3MB)

So a new file is created with a new time (%R) value, and not with a unique number ($n). And my mistake was to rely on the "Finished recordings" overview that only showed the last (3MB) file. Thank you for setting me straight. So the esthetic issue is that the partial recording files are unknown and inaccessible from tvheadend, but they are there (via nfs or smb). I will look at DVR clone.

I have "Clone scheduled entry on error" already selected, so is that the reason a file is created with a different %R value, instead of a $n unique number?

If you have activated the cloning, the previous recordings are in the failed grid. You can move it to finished and remove the 3MB trailing data through webui. $n is used only if the filename already exists. If you use %R, the filename is already different in this case.

While Matroska can only handle fixed streams, tvheadend did previously work without creating multiple files.

As Mark Clarkstone suggests, when using Matroska as the profile tvheadend should ignore aspect changes when deciding if a source has been reconfigured and then perhaps set the streams aspect ratio depending on majority broadcast or lowest aspect ratio (such as 4:3) detected.

I'm still running an early November master as when git bisecting (between 517bc485d33f4d012a1d3a70730439f80ec56d3f [2-Nov] and 342409d3689545addf5fa8ea3ca22f7937d1d3b1 [15-Nov]) when this change occurred, I couldn't consistently confirm good commits as had not realised the cause was aspect changes and not all the multiple programs tested with each bisect had them. Had been meaning to retry bisecting

And logically commit "service: use s_pending_restart more properly, issue #4701" 910fef46754fb11055a664fc950eb10db57bc2f7 should be the cause of change in behaviour.

Looking over my notes, it was the first bad commit in one of my bisects but I'd (somehow) thought the last build was with a good commit and when issue reoccurred I thought it wasn't the cause and was a failed bisect...

Aspect changes are ignored. I found the 60min problem - it was caused by other changes. Could you retest with master?

Actually, the restart can be caused only by two things now:

1) video resolution change (aspect is ignored)
2) mpeg audio layer change

Jaroslav Kysela wrote:

Aspect changes are ignored. I found the 60min problem - it was caused by other changes. Could you retest with master?

Actually, the restart can be caused only by two things now:

1) video resolution change (aspect is ignored)
2) mpeg audio layer change

I've upgraded, switched back to mkv & recording from channels that suffered with this issue, will post the result :).

Thank you for your hardwork as always Jaroslav!

Unfortunately still failing with "source reconfigured" on some recordings when using Matroska profile. It happens in the middle of a program (or advert) and not at any transitions.

I forgot that there might be also PMT changes. It should be visible using '--trace tbl-base'.

It does not help. I added some more traces to parser code (--trace parser). v4.3-1006-gd381d71e3

Shouldn't the tvhtrace for audio version change be above "st->es_audio_version = layer;" otherwise val always equals old?

Anyway, it looks as though the cause is the audio descriptive stream being enabled during the program. Oddly, on some programs/channels/networks the audio descriptive stream is always enabled and on others always disabled until used causing the source reconfiguration.

2018-01-26 18:59:00.949 [ INFO]:dvr: /srv/tvheadend/Last Man Standing--2018-01-26-19-00.mkv from adapter: "TurboSight TBS 6205 DVB-T/T2/C #1 : DVB-T #0", network: "Craigkelly", mux: "642MHz", provider: "<N/A>", service: "5STAR"
2018-01-26 18:59:00.949 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2018-01-26 18:59:00.949 [ INFO]:dvr: 1 MPEG2VIDEO 544x576 16:9
2018-01-26 18:59:00.949 [ INFO]:dvr: 2 MPEG2AUDIO eng 48000 2
2018-01-26 18:59:00.949 [ INFO]:dvr: 3 MPEG2AUDIO eng 96000 ? <disabled, no valid input>
2018-01-26 18:59:00.949 [ INFO]:dvr: 4 DVBSUB eng
....
2018-01-26 18:59:41.927 [ TRACE]:parser: audio version change 02: val=3 (old=3)
...
2018-01-26 18:59:42.197 [WARNING]:dvr: Unable to reconfigure "/srv/tvheadend/Last Man Standing--2018-01-26-19-00.mkv"
...
2018-01-26 18:59:42.199 [ INFO]:dvr: "Last Man Standing" on "5STAR": End of program: Source reconfigured
2018-01-26 18:59:42.199 [ INFO]:dvr: "Last Man Standing" on "5STAR" recorder starting
2018-01-26 18:59:42.200 [ INFO]:dvr: /srv/tvheadend/Last Man Standing--2018-01-26-18-59.mkv from adapter: "TurboSight TBS 6205 DVB-T/T2/C #1 : DVB-T #0", network: "Craigkelly", mux: "642MHz", provider: "<N/A>", service: "5STAR"
2018-01-26 18:59:42.200 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2018-01-26 18:59:42.200 [ INFO]:dvr: 1 MPEG2VIDEO 544x576 16:9
2018-01-26 18:59:42.200 [ INFO]:dvr: 2 MPEG2AUDIO eng 48000 2
2018-01-26 18:59:42.200 [ INFO]:dvr: 3 MPEG2AUDIO eng 48000 1
2018-01-26 18:59:42.200 [ INFO]:dvr: 4 DVBSUB eng

Looking at commit "service: use s_pending_restart more properly, issue #4701" would the following change have caused this change in behaviour when using the Matroska profile?

src/parsers/parsers.c
@@ parse_mpa123(service_t *t, elementary_stream_t *st)
- if (fsize && st->es_audio_version != layer) {
+ if (fsize && st->es_audio_version < layer) {

And looks like original bug reporter Rob vh whose "dvr" log lines show no audio changes would be the 60min fix while my audio descriptive issue is an additional issue (so perhaps DVT-S audio descriptive streams are always enabled versus DVT-T here).

A few more failures with random recordings and with tvhtrace for "audio version moved" above the "st->es_audio_version = layer;" line. Not showing the "disabled, no valid input" for (I've been assuming) audio descriptive stream in initial dvr log for these two though.

2018-01-27 18:04:00.015 [ INFO]:dvr: /srv/tvheadend/Storage Wars--2018-01-27-18-05.mkv from adapter: "TurboSight TBS 6205 DVB-T/T2/C #3 : DVB-T #0", network: "Craigkelly", mux: "498MHz", provider: "<N/A>", service: "ITV4"
2018-01-27 18:04:00.015 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2018-01-27 18:04:00.015 [ INFO]:dvr: 1 MPEG2VIDEO 720x576 16:9
2018-01-27 18:04:00.015 [ INFO]:dvr: 2 MPEG2AUDIO eng 48000 2
2018-01-27 18:04:00.015 [ INFO]:dvr: 3 MPEG2AUDIO eng 48000 1
2018-01-27 18:04:00.015 [ INFO]:dvr: 4 DVBSUB eng
....
2018-01-27 18:04:19.969 [ TRACE]:parser: audio version change 02: val=3 (old=2)
....
2018-01-27 18:04:20.842 [ INFO]:dvr: "Storage Wars" on "ITV4": End of program: Source reconfigured
2018-01-27 18:04:20.842 [ INFO]:dvr: "Storage Wars" on "ITV4" recorder starting
2018-01-27 18:04:20.843 [ INFO]:dvr: /srv/tvheadend/Storage Wars--2018-01-27-18-04.mkv from adapter: "TurboSight TBS 6205 DVB-T/T2/C #3 : DVB-T #0", network: "Craigkelly", mux: "498MHz", provider: "<N/A>", service: "ITV4"
2018-01-27 18:04:20.843 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2018-01-27 18:04:20.843 [ INFO]:dvr: 1 MPEG2VIDEO 720x576 16:9
2018-01-27 18:04:20.843 [ INFO]:dvr: 2 MPEG2AUDIO eng 48000 2
2018-01-27 18:04:20.843 [ INFO]:dvr: 3 MPEG2AUDIO eng 48000 1
2018-01-27 18:04:20.843 [ INFO]:dvr: 4 DVBSUB eng

2018-01-28 05:58:55.014 [ INFO]:dvr: "Murder, She Wrote" on "ITV3" recorder starting
2018-01-28 05:58:57.917 [ TRACE]:parser: vparam 01: w=544 h=576 d=3600 (old w=544 h=576 d=3600 meta=0)
2018-01-28 05:58:59.372 [ TRACE]:parser: vparam 01: w=544 h=576 d=3600 (old w=544 h=576 d=3600 meta=0)
2018-01-28 05:59:00.961 [ INFO]:dvr: /srv/tvheadend/Murder, She Wrote--2018-01-28-06-00.mkv from adapter: "TurboSight TBS 6205 DVB-T/T2/C #3 : DVB-T #0", network: "Craigkelly", mux: "642MHz", provider: "<N/A>", service: "ITV3"
2018-01-28 05:59:00.961 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2018-01-28 05:59:00.961 [ INFO]:dvr: 1 MPEG2VIDEO 544x576 16:9
2018-01-28 05:59:00.961 [ INFO]:dvr: 2 MPEG2AUDIO eng 48000 2
2018-01-28 05:59:00.961 [ INFO]:dvr: 3 MPEG2AUDIO eng 96000 ? <disabled, no valid input>
2018-01-28 05:59:00.961 [ INFO]:dvr: 4 DVBSUB eng
....
2018-01-28 06:22:41.028 [ TRACE]:parser: audio version change 03: val=3 (old=2)
....
2018-01-28 06:22:41.895 [WARNING]:dvr: Unable to reconfigure "/srv/tvheadend/Murder, She Wrote--2018-01-28-06-00.mkv"
2018-01-28 06:22:41.903 [ INFO]:dvr: "Murder, She Wrote" on "ITV3": End of program: Source reconfigured
2018-01-28 06:22:41.904 [ INFO]:dvr: "Murder, She Wrote" on "ITV3" recorder starting
2018-01-28 06:22:41.904 [ INFO]:dvr: /srv/tvheadend/Murder, She Wrote--2018-01-28-06-22.mkv from adapter: "TurboSight TBS 6205 DVB-T/T2/C #3 : DVB-T #0", network: "Craigkelly", mux: "642MHz", provider: "<N/A>", service: "ITV3"
2018-01-28 06:22:41.904 [ INFO]:dvr: # type lang resolution aspect ratio sample rate channels
2018-01-28 06:22:41.904 [ INFO]:dvr: 1 MPEG2VIDEO 544x576 4:3
2018-01-28 06:22:41.904 [ INFO]:dvr: 2 MPEG2AUDIO eng 48000 2
2018-01-28 06:22:41.904 [ INFO]:dvr: 3 MPEG2AUDIO eng 48000 1
2018-01-28 06:22:41.905 [ INFO]:dvr: 4 DVBSUB eng

I haven't seen any "source reconfigured" messages since the "60 minutes" fix was applied (4 days ago). I guess my choice of recordings does not run into Alan's audio layer issues. Thank you both for persevering.

I’m having the same as you Alan with this on DVB-T/DVB-T2 in the UK (Freeview HD).

You’re right about the audio description - via satellite (Freesat) the UK channels have an ‘always on’ audio description track as it also carries the programme audio in the background even when there’s no AD present. On DVB-T/T2 the audio description track is just the audio description itself (it’s meant to be added to the main audio track at our end - mixed by the receiver) and when there’s no audio description this track disappears.

I’ve seen the errors on Channel 4 HD. I saw one on Channel 5 HD too but I think this was the 60 minute issue which is now fixed.

I found some issues with the mpeg audio parser. Please, retest with latest.

hi
pretty new here so at first: sorry.
I just compiled tvheadend from source and hit new inserted assertion:

Thread 25 "tvh:mi-main" hit Breakpoint 1, parse_mpa123 (st=0x710060, t=0x70bed0)
    at src/parsers/parsers.c:702
702      assert(i <= st->es_buf_a.sb_ptr);
(gdb) c
Continuing.
2018-02-10 00:14:10.076 [WARNING] linuxdvb: Realtek RTL2832 (DVB-T) #0 : master for #0 - read() EOVERFLOW
tvheadend: src/parsers/parsers.c:702: parse_mpa123: Assertion `i <= st->es_buf_a.sb_ptr' failed.

here more details as running within gdb stopping just before the assertion:

2018-02-10 00:31:22.744 [   INFO] mpegts: 498MHz in DVB-T Network - tuning on Realtek RTL2832 (DVB-T) #0 : master for #0
2018-02-10 00:31:22.744 [   INFO] subscription: 0002: "10.0.0.50 [ michele | Kodi Media Center ]" subscribing on channel "Rai 1", weight: 100, adapter: "Realtek RTL2832 (DVB-T) #0 : master for #0", network: "DVB-T Network", mux: "498MHz", provider: "RAI", service: "Rai 1", profile="htsp", hostname="10.0.0.50", username="michele", client="Kodi Media Center" 
[New Thread 0xae6feff0 (LWP 2679)]
[Switching to Thread 0xae8feff0 (LWP 2674)]

Thread 25 "tvh:mi-main" hit Breakpoint 1, parse_mpa123 (st=0x70eb48, t=0x70beb8)
    at src/parsers/parsers.c:702
702      assert(i <= st->es_buf_a.sb_ptr);
(gdb) bt
#0  parse_mpa123 (st=0x70eb48, t=0x70beb8) at src/parsers/parsers.c:702
#1  parse_mpa (t=0x70beb8, st=0x70eb48, ilen=<optimized out>, next_startcode=<optimized out>, 
    sc_offset=0) at src/parsers/parsers.c:719
#2  0x004cba22 in parse_pes (t=0x70beb8, st=0x70eb48, data=<optimized out>, len=184, start=1, 
    vp=0x4caead <parse_mpa>) at src/parsers/parsers.c:429
#3  0x004feba0 in ts_recv_packet0 (t=t@entry=0x70beb8, st=st@entry=0x70eb48, 
    tsb=tsb@entry=0xaf03c1f9 "GB\212\033", len=len@entry=188)
    at src/input/mpegts/tsdemux.c:204
#4  0x004ff1f8 in ts_recv_packet1 (t=0x70beb8, tsb=tsb@entry=0xaf03c1f9 "GB\212\033", 
    len=len@entry=188, table=0) at src/input/mpegts/tsdemux.c:357
#5  0x004fc84e in mpegts_input_process (mpkt=0xaf038148, mi=<optimized out>)
    at src/input/mpegts/mpegts_input.c:1419
#6  mpegts_input_thread (p=0x6e9768) at src/input/mpegts/mpegts_input.c:1658
#7  0x00481ca0 in thread_wrapper (p=0xaf000740) at src/wrappers.c:181
#8  0xb5ad05e8 in start_thread () from /lib/arm-linux-gnueabihf/libpthread.so.0
#9  0xb59e354a in ?? () from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) print i
$1 = <optimized out>
(gdb) print st
$2 = (elementary_stream_t *) 0x70eb48
(gdb) print st->es_buf_a 
$3 = {
  sb_data = 0xaf044348 "\214(\225\227\365\263\203\225)\021\211\307#\215\022\"U\371\273\301\003\345J\237%\254\365\v8k\302\240\377\374\244", sb_ptr = 5872, sb_size = 23488, sb_err = 0, 
  sb_bswap = 0 '\000'}
(gdb) print st->es_buf_a.sb_ptr 
$4 = 5872
(gdb) n
2018-02-10 00:35:51.575 [WARNING] linuxdvb: Realtek RTL2832 (DVB-T) #0 : master for #0 - read() EOVERFLOW
tvheadend: src/parsers/parsers.c:702: parse_mpa123: Assertion `i <= st->es_buf_a.sb_ptr' failed.

Thread 25 "tvh:mi-main" received signal SIGABRT, Aborted.
0xb59656f6 in ?? () from /lib/arm-linux-gnueabihf/libc.so.6

Issue manifest itself in a particular condition as I'm trying to start a channel streaming from a client (Kodi plugin)

@Micio Macio : Fixed in v4.3-1049-g088be1abe .

Fixed. Many thanks