Project

General

Profile

Bug #4790

Dvr: Got truncated file, tvh stops to write data to ts file even if it shows "recording in progress" and shows "complete ok" in log.

Added by Antonio Tex almost 7 years ago. Updated almost 7 years ago.

Status:
New
Priority:
Normal
Assignee:
Adam Sutton
Category:
PVR / DVR
Target version:
-
Start date:
2017-12-13
Due date:
% Done:

0%

Estimated time:
Found in version:
4.3-513~g570b0d476
Affected Versions:

Description

Hello, first thanks for your wonderful project and job: i think tvh is the best live tv server among all present softwares.

Now the problem: it's the first time that a thing like this happens because i record a lot of tv channels but i did not have any problem until yesterday. (so a rare condition)
What i've done:
1 On EPG page with browser i've select an event and scheduled a recording from event info. (the recording was scheduled on a x channel, but for convenience after creating it, i've change the recording channel to y, because the event was in simulcast and i don't have epg in that y channel)
2 i've a rule that starts the recording 10 minutes before and ends 10 minutes after the beginning of the event. As you see in log tvh start to record the channel at 22:50.
3 during the recording i've also watch for a few minutes the channel with kodi. (due to some problem to my client i start and restart the subscription a lot of time so i've stressed tvh a lot. Also i've start playing the recording even if it wasn't finished)
4 Today i've checked the recording and i've noticed that the file was truncated.

You can see in tvh log that it (seems) to complete the recording but actually the file is only 55:09 minutes log (scheduled 125min) so if the recording started at 22:50 tvh stops to write near 23:45.
I've included also stats of that file to show that effectively the "last edit time" is 23:45.
And ffmpeg log to show the file's duration.
I will try to reproduce this bug.
Thank as always

Files

stat.log (370 Bytes) stat.log Antonio Tex, 2017-12-13 21:35
tvh.log (62.3 KB) tvh.log Antonio Tex, 2017-12-13 21:35
ffmpeg.log (1.27 KB) ffmpeg.log Antonio Tex, 2017-12-13 21:35
rec.PNG (11.6 KB) rec.PNG saen acro, 2017-12-14 09:17

History

#1

Updated by Jaroslav Kysela almost 7 years ago

It seems to be similar with #4781 . Do you have DvbSky S952 ?

#2

Updated by Antonio Tex almost 7 years ago

Hello @Jaroslav and thanks for you answer! Unfortunately yes DVBSky s952v3... So it's a hardware issue. I was planning to change it: now I have the right reason! Thanks as always and have a nice day!
Antonio

#3

Updated by Antonio Tex almost 7 years ago

Mmm maybe there is also something else :( at last maybe it's my config?
just retested with TBS this time even worst no data at all. (i've manually turn the recording off) And these are "the first times" that i add a recording throught the epg page, i always set manually a timer.

dic 14 08:59:54 TexArchServer tvheadend[383]: mpegts: 11526H in DVB-S Network - tuning on Montage Technology M88RS6000 #4 : DVB-S #0
dic 14 08:59:54 TexArchServer tvheadend[383]: subscription: 0004: "epggrab" subscribing to mux "11526H", weight: 4, adapter: "Montage Technology M88RS6000 #4 : DVB-S #0", netwo
dic 14 08:59:57 TexArchServer tvheadend[383]: dvr: entry eddb9dc6fcffcc7ec1372473a09b4ebc "Agora'" on "Rai 3 HD" starting at 2017-12-14 07:49:30, scheduled for recording by "an
dic 14 08:59:57 TexArchServer tvheadend[383]: dvr: "Agora'" on "Rai 3 HD" recorder starting
dic 14 08:59:57 TexArchServer tvheadend[383]: dvr: About to set stop timer for "Agora'" on "Rai 3 HD" at start 1513234800 and original stop 1513242000 and overall stop at 15132
dic 14 08:59:57 TexArchServer tvheadend[383]: mpegts: 626MHz in DVB-T Network - tuning on TurboSight TBS 6205 DVB-T/T2/C  #3 : DVB-T #0
dic 14 08:59:57 TexArchServer tvheadend[383]: subscription: 0006: "DVR: Agora'" subscribing on channel "Rai 3 HD", weight: 500, adapter: "TurboSight TBS 6205 DVB-T/T2/C  #3 : D
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr: /home/hts/Agora'.ts from adapter: "TurboSight TBS 6205 DVB-T/T2/C  #3 : DVB-T #0", network: "DVB-T Network", mux: "626MHz", p
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr:  1  H264                    1920x1080   ?
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr:  2  AC3               ita                             96000        ?
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr:  3  TELETEXT
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr:  4  TEXTSUB           ita
dic 14 08:59:58 TexArchServer tvheadend[383]: dvr:  5  TEXTSUB           eng
dic 14 09:00:03 TexArchServer tvheadend[383]: subscription: 0004: "epggrab" unsubscribing
dic 14 09:00:04 TexArchServer tvheadend[383]: mpegts: 11880V in DVB-S Network - tuning on Montage Technology M88RS6000 #4 : DVB-S #0
dic 14 09:00:04 TexArchServer tvheadend[383]: subscription: 0007: "epggrab" subscribing to mux "11880V", weight: 4, adapter: "Montage Technology M88RS6000 #4 : DVB-S #0", netwo
dic 14 09:00:15 TexArchServer tvheadend[383]: opentv: opentv-skyit: channels complete
dic 14 09:02:15 TexArchServer tvheadend[383]: opentv: opentv-skyit: titles complete
dic 14 09:08:53 TexArchServer tvheadend[383]: htsp: Got connection from ::ffff:192.168.1.2
dic 14 09:08:53 TexArchServer tvheadend[383]: htsp: ::ffff:192.168.1.2: Welcomed client software: Kodi Media Center (HTSPv25)
dic 14 09:08:53 TexArchServer tvheadend[383]: htsp: ::ffff:192.168.1.2 [ Kodi Media Center ]: Identified as user ''
dic 14 09:09:05 TexArchServer tvheadend[383]: subscription: 0008: "::ffff:192.168.1.2 [  | Kodi Media Center ]" subscribing on channel "Rai 3 HD", weight: 150, adapter: "TurboS
dic 14 09:09:14 TexArchServer tvheadend[383]: subscription: 0008: "::ffff:192.168.1.2 [  | Kodi Media Center ]" unsubscribing from "Rai 3 HD", hostname="::ffff:192.168.1.2", us
dic 14 09:09:20 TexArchServer tvheadend[383]: subscription: 0009: "::ffff:192.168.1.2 [  | Kodi Media Center ]" subscribing on channel "Rai 3 HD", weight: 150, adapter: "TurboS
dic 14 09:09:29 TexArchServer tvheadend[383]: subscription: 0009: "::ffff:192.168.1.2 [  | Kodi Media Center ]" unsubscribing from "Rai 3 HD", hostname="::ffff:192.168.1.2", us
dic 14 09:09:39 TexArchServer tvheadend[383]: subscription: 000A: "::ffff:192.168.1.2 [  | Kodi Media Center ]" subscribing on channel "Rai 3 HD", weight: 150, adapter: "TurboS
dic 14 09:09:47 TexArchServer tvheadend[383]: subscription: 000A: "::ffff:192.168.1.2 [  | Kodi Media Center ]" unsubscribing from "Rai 3 HD", hostname="::ffff:192.168.1.2", us
dic 14 09:10:34 TexArchServer tvheadend[383]: htsp: ::ffff:192.168.1.2 [  | Kodi Media Center ]: Disconnected
dic 14 09:11:59 TexArchServer tvheadend[383]: subscription: 0006: "DVR: Agora'" unsubscribing from "Rai 3 HD" 
dic 14 09:11:59 TexArchServer tvheadend[383]: dvr: "Agora'" on "Rai 3 HD": End of program: Completed OK

Stat:
  File: Agora'.ts
  Dim.: 21244         Blocchi: 48         Blocco di IO: 4096   file regolare
Device: 813h/2067d    Inode: 3146612     Coll.: 1
Accesso: (0664/-rw-rw-r--)  Uid: ( 1337/     hts)   Gid: (   91/   video)
Accesso  : 2017-12-14 08:59:58.348457894 +0100
Modifica : 2017-12-14 08:59:58.348457894 +0100
Cambio   : 2017-12-14 08:59:58.348457894 +0100
Creazione: -

#4

Updated by saen acro almost 7 years ago

I have similar problem with DiBcom 3000MC/P (dvb-t)
Streaming 24/7 to external HLS generator no problems,
but internal in tvh recordings are unreal by size.
2h ~260Mb without transcoding

#5

Updated by Antonio Tex almost 7 years ago

Ok i'm occasionally able to reproduce this bug, more logs with dvr trace: (The last recording "Mattino 5" initialize but stops suddenly ) on status i see "input 5000kb/s" but 0 in output when this happen, and tvh reports all is ok thanks for your time

2017-12-14 09:27:45.978 [   INFO]:dvr: "C'era una volta una casa Ep4" on "Rai 5 HD" recorder starting
2017-12-14 09:27:45.978 [   INFO]:dvr: About to set stop timer for "C'era una volta una casa Ep4" on "Rai 5 HD" at start 1513237740 and original stop 1513241220 and overall stop at 1513241820
2017-12-14 09:27:45.978 [   INFO]:mpegts: 11013H in DVB-S Network - tuning on Montage Technology M88RS6000 #5 : DVB-S #0
2017-12-14 09:27:46.154 [   INFO]:subscription: 0019: "DVR: C'era una volta una casa Ep4" subscribing on channel "Rai 5 HD", weight: 500, adapter: "Montage Technology M88RS6000 #5 : DVB-S #0", network: "DVB-S Network", mux: "11013H", provider: "Rai", service: "Rai 5 HD", profile="pass" 
2017-12-14 09:27:46.825 [  TRACE]:dvr: dvr event running check for Il pasticciere on Rai Movie HD running 2
2017-12-14 09:27:47.203 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 - set state - state RECORDING rec_state RUNNING error 'OK'
2017-12-14 09:27:47.203 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 - set state - state RECORDING rec_state WAIT error 'OK'
2017-12-14 09:27:47.203 [  DEBUG]:dvr: File "/home/hts/C'era una volta una casa Ep4.ts" -- File o directory non esistente -- Using for recording
2017-12-14 09:27:47.203 [   INFO]:dvr: /home/hts/C'era una volta una casa Ep4.ts from adapter: "Montage Technology M88RS6000 #5 : DVB-S #0", network: "DVB-S Network", mux: "11013H", provider: "Rai", service: "Rai 5 HD" 
2017-12-14 09:27:47.203 [   INFO]:dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
2017-12-14 09:27:47.203 [   INFO]:dvr:  1  H264                    1920x1080   ?                                    
2017-12-14 09:27:47.203 [   INFO]:dvr:  2  MPEG2AUDIO        ita                             96000        ?         
2017-12-14 09:27:47.203 [   INFO]:dvr:  3  AC3               und                             96000        ?         
2017-12-14 09:27:47.203 [   INFO]:dvr:  4  MPEG2AUDIO        eng                             96000        ?         
2017-12-14 09:27:47.203 [   INFO]:dvr:  5  CA                                                                       
2017-12-14 09:27:47.203 [   INFO]:dvr:  6  CA                                                                       
2017-12-14 09:27:47.204 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 - set state - state RECORDING rec_state RUNNING error 'OK'
2017-12-14 09:27:47.818 [  TRACE]:dvr: dvr event running check for Il pasticciere on Rai Movie HD running 2
2017-12-14 09:27:48.836 [  TRACE]:dvr: dvr event running check for Il pasticciere on Rai Movie HD running 2
2017-12-14 09:27:50.822 [  TRACE]:dvr: dvr event running check for Il pasticciere on Rai Movie HD running 2
2017-12-14 09:27:52.833 [  TRACE]:dvr: dvr event running check for Il pasticciere on Rai Movie HD running 2
2017-12-14 09:27:56.269 [  TRACE]:dvr: checking free and used disk space for config "Default profile" : OK
2017-12-14 09:28:00.563 [   INFO]:subscription: 0019: "DVR: C'era una volta una casa Ep4" unsubscribing from "Rai 5 HD" 
2017-12-14 09:28:00.563 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 - set state - state COMPLETED rec_state FINISHED error 'OK'
2017-12-14 09:28:00.563 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 when 1970-01-01;01:00:00(+0100) - retention arm
2017-12-14 09:28:00.563 [   INFO]:dvr: "C'era una volta una casa Ep4" on "Rai 5 HD": End of program: Completed OK
2017-12-14 09:28:00.563 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 start 2017-12-14;08:38:30(+0100) stop 2017-12-14;09:57:00(+0100) - set timer
2017-12-14 09:28:00.563 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 when 1970-01-01;01:00:00(+0100) - retention arm
2017-12-14 09:28:00.563 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 when 1970-01-01;01:00:00(+0100) - retention arm
2017-12-14 09:28:00.563 [  TRACE]:dvr: entry d6d4f6a2fb687efd5c633462201095b0 - retention timer - disarm
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - assign broadcast 616394
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) stop 2017-12-14;11:10:00(+0100) - set timer
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) - set timer - schedule
2017-12-14 09:28:10.752 [   INFO]:dvr: entry 315385caaaf14a1830936a723f166b52 "Mattino Cinque" on "Canale5 HD" starting at 2017-12-14 08:34:30, scheduled for recording by "antonio" 
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) stop 2017-12-14;11:10:00(+0100) - set timer
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) - set timer - schedule
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) stop 2017-12-14;11:10:00(+0100) - set timer
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) - set timer - schedule
2017-12-14 09:28:10.752 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - set state - state RECORDING rec_state PENDING error 'OK'
2017-12-14 09:28:10.752 [   INFO]:dvr: "Mattino Cinque" on "Canale5 HD" recorder starting
2017-12-14 09:28:10.752 [   INFO]:dvr: About to set stop timer for "Mattino Cinque" on "Canale5 HD" at start 1513237500 and original stop 1513245600 and overall stop at 1513246200
2017-12-14 09:28:10.752 [   INFO]:mpegts: 602MHz in DVB-T Network - tuning on TurboSight TBS 6205 DVB-T/T2/C  #3 : DVB-T #0
2017-12-14 09:28:10.752 [   INFO]:subscription: 001A: "DVR: Mattino Cinque" subscribing on channel "Canale5 HD", weight: 500, adapter: "TurboSight TBS 6205 DVB-T/T2/C  #3 : DVB-T #0", network: "DVB-T Network", mux: "602MHz", service: "Canale5 HD", profile="pass" 
2017-12-14 09:28:11.180 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - set state - state RECORDING rec_state RUNNING error 'OK'
2017-12-14 09:28:11.180 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - set state - state RECORDING rec_state WAIT error 'OK'
2017-12-14 09:28:11.180 [  DEBUG]:dvr: File "/home/hts/Mattino Cinque.ts" -- File o directory non esistente -- Using for recording
2017-12-14 09:28:11.180 [   INFO]:dvr: /home/hts/Mattino Cinque.ts from adapter: "TurboSight TBS 6205 DVB-T/T2/C  #3 : DVB-T #0", network: "DVB-T Network", mux: "602MHz", provider: "<N/A>", service: "Canale5 HD" 
2017-12-14 09:28:11.180 [   INFO]:dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
2017-12-14 09:28:11.180 [   INFO]:dvr:  1  H264                    1920x1080   ?                                    
2017-12-14 09:28:11.180 [   INFO]:dvr:  2  AC3               ita                             96000        ?         
2017-12-14 09:28:11.234 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - set state - state RECORDING rec_state RUNNING error 'OK'
2017-12-14 09:28:11.269 [  TRACE]:dvr: checking free and used disk space for config "Default profile" : OK
2017-12-14 09:28:26.269 [  TRACE]:dvr: checking free and used disk space for config "Default profile" : OK
2017-12-14 09:28:38.637 [   INFO]:subscription: 001A: "DVR: Mattino Cinque" unsubscribing from "Canale5 HD" 
2017-12-14 09:28:38.637 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - set state - state COMPLETED rec_state FINISHED error 'OK'
2017-12-14 09:28:38.637 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 when 1970-01-01;01:00:00(+0100) - retention arm
2017-12-14 09:28:38.637 [   INFO]:dvr: "Mattino Cinque" on "Canale5 HD": End of program: Completed OK
2017-12-14 09:28:38.637 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 start 2017-12-14;08:34:30(+0100) stop 2017-12-14;11:10:00(+0100) - set timer
2017-12-14 09:28:38.637 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 when 1970-01-01;01:00:00(+0100) - retention arm
2017-12-14 09:28:38.637 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 when 1970-01-01;01:00:00(+0100) - retention arm
2017-12-14 09:28:38.637 [  TRACE]:dvr: entry 315385caaaf14a1830936a723f166b52 - retention timer - disarm
2017-12-14 09:28:41.270 [  TRACE]:dvr: checking free and used disk space for config "Default profile" : OK

#6

Updated by Jaroslav Kysela almost 7 years ago

Upgrade to latest and show the logs (like before) from recent with the description. Thanks.

#7

Updated by Joe User almost 7 years ago

Antonio Tex wrote:

1 On EPG page with browser i've select an event and scheduled a recording from event info. (the recording was scheduled on a x channel, but for convenience after creating it, i've change the recording channel to y, because the event was in simulcast and i don't have epg in that y channel)

You can set "Reuse EPG from:" to channel x in the config for channel y.

And these are "the first times" that i add a recording throught the epg page, i always set manually a timer.

Do you have "Use EPG running state:" set for the channel and/or the recording profile?

Not sure what will happen with EPG running state if recording is switched to a channel with not EPG/EIt info???

#8

Updated by Antonio Tex almost 7 years ago

Jaroslav Kysela wrote:

Upgrade to latest and show the logs (like before) from recent with the description. Thanks.

Good evening, i've upgrade to 4.3-790 but for now it doesn't show up (i've started near 100 recordings): maybe it was a bug present in 4.3-513, or maybe because it is not simple to reproduce as described.
I will leave trace dvr and debug on these days so if it appears again i'll update this issue.
Thanks again @Jaroslav

Joe User wrote:

You can set "Reuse EPG from:" to channel x in the config for channel y.

Yes thank you, i'm using it for other channels but for this as it is "experimental" and transmits rarely i manually set the recording :)

Do you have "Use EPG running state:" set for the channel and/or the recording profile?

No i don't but anyway it doesn't have EIT so this shouldn't be the problem :)
Thanks

#9

Updated by Joe User almost 7 years ago

Antonio Tex wrote:

Joe User wrote:

Do you have "Use EPG running state:" set for the channel and/or the recording profile?

No i don't but anyway it doesn't have EIT so this shouldn't be the problem :)

"shouldn't", but possibly is. I have seen where even though "Use EPG running state:" is not set, it still may be used.
These two issues may be related...
[[http://tvheadend.org/issues/4760]]
[[http://tvheadend.org/issues/4299]]

#10

Updated by saen acro almost 7 years ago

Is ffprobe report something as this 

[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] decode_slice_header error
[h264 @ 0x862ca80] no frame!
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] decode_slice_header error
[h264 @ 0x862ca80] no frame!
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] decode_slice_header error
[h264 @ 0x862ca80] no frame!
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] non-existing SPS 0 referenced in buffering period
[h264 @ 0x862ca80] non-existing PPS 0 referenced
[h264 @ 0x862ca80] decode_slice_header error
[h264 @ 0x862ca80] no frame!
[mpegts @ 0x8628b00] PES packet size mismatch
  Duration: 00:16:10.69, start: 14667.639167, bitrate: 2697 kb/s
  Program 1
    Metadata:
      service_name    : NOVA TV
      service_provider: NURTS Digital
    Stream #0:0[0x1402]: Video: h264 (High) ([27][0][0][0] / 0x001B), yuv420p(tv, bt470bg), 720x576 [SAR 12:11 DAR 15:11], 25 fps, 25 tbr, 90k tbn, 50 tbc
    Stream #0:1[0x1403]: Audio: mp2 ([3][0][0][0] / 0x0003), 48000 Hz, stereo, s16p, 192 kb/s

FTA program duration must be 40min

Also available in: Atom PDF