Project

General

Profile

Actions
Copy link

Bug #5256

closed

DVR: major issue: recordings from Sky.DE often fail with no file written [master git]

Added by da h4xX0rz1sT over 6 years ago. Updated over 6 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
Adam Sutton
Category:
PVR / DVR
Target version:
-
Start date:
2018-10-14
Due date:
% Done:

0%

Estimated time:
Found in version:
4.3-1468~g3f74523d2
Affected Versions:

Description

This is reopen of rejected bug #5211. This issue seems to apply for master as well. Old description (with updates) following.

  • transport errors at the beginning of the recording can cause this
  • descramble or "Unexpected ECM reply" errors can cause this on encrypted channels
  • on start of recording, log does not show the typical "lang resolution aspect ratio sample rate channels" lines (seems it does not detect the streams)
  • on start of recording, trace dvr log does not show (seems to be new trace message on master)
  • during recording, a file size "---" is shown constantly
  • during recording, status shows a output bandwidth of "0"
  • at the end of recording, log shows "time missed"
  • after recording, it shows up in "deleted recordings" with status "file missing"
  • this never happens if the affected channel is already streamed before recording starts (seems not to apply with master, was in 4.2x)
  • most probably retries are missing when recording

Steps to reproduce:
Record from sky.de, at least one of ten recordings fails with that issue, probably more

Environment:
CWs are working, 100% success in oscam

Log from latest master with "--trace dvr" when it worked:

Oct 14 16:18:30 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - assign broadcast 67145163
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) - set timer - schedule
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f "Planet der Affen: Survival" on "Sky Cinema" starting at 2018-10-14 15:54:30, with broadcast id "<noid>", scheduled for recording by "admin" 
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) - set timer - schedule
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) - set timer - schedule
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - set state - state RECORDING rec_state PENDING error 'OK'
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: "Planet der Affen: Survival" on "Sky Cinema" recorder starting
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f original stop 2018-10-14;18:15:00(+0200) stop 2018-10-14;18:15:00(+0200) - stop timer set
Oct 14 16:18:37 TVHserver tvheadend[18803]: mpegts: 11914.5H in DVB-S Astra1x - tuning on SAT>IP OctopusNet S2/4 DVB-S #1 (192.168.XXX.XXX@UDP)
Oct 14 16:18:37 TVHserver tvheadend[18803]: subscription: 048F: "DVR: Planet der Affen: Survival" subscribing on channel "Sky Cinema", weight: 500, adapter: "SAT>IP OctopusNet S2/4 DVB-S #1 (192.168.XXX.XXX@UDP)", network: "DVB-S Astra1x", mux: "11914.5H", provider: "SKY", service: "Sky Cinema HD", profile="matroska" 
Oct 14 16:18:37 TVHserver tvheadend[18803]: dvr: c33bb2d51bce423d41de20cf9da7197f - recoding thread started for "Planet der Affen: Survival" 
Oct 14 16:18:38 TVHserver tvheadend[18803]: TS: DVB-S Astra1x/11914.5H/Sky Cinema HD: H264 @ #1279 Continuity counter error (total 1)
Oct 14 16:18:39 TVHserver tvheadend[18803]: cwc: localhost:XXXXX: Got unexpected ECM reply (seqno: 170)
Oct 14 16:18:39 TVHserver tvheadend[18803]: descrambler: Sky Cinema HD odd stream key[1279] is not valid
Oct 14 16:18:39 TVHserver tvheadend[18803]: cwc: localhost:XXXXX: Got unexpected ECM reply (seqno: 1738)
Oct 14 16:18:40 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - set state - state RECORDING rec_state EPGWAIT error 'OK'
Oct 14 16:18:45 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:18:53 TVHserver tvheadend[18803]: dvr: dvr_autorec_async_reschedule_cb - begin
Oct 14 16:18:53 TVHserver tvheadend[18803]: dvr: dvr_autorec_async_reschedule_cb - end
Oct 14 16:19:00 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: dvr event running check for Die geheimen Akten der NASA on Discovery running 1
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: dvr event running check for Die geheimen Akten der NASA on Discovery running 3
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: dvr event running check for Pfad der Rache on Sky Cinema running 1
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: dvr event running check for Planet der Affen: Survival on Sky Cinema running 3
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: dvr entry c33bb2d51bce423d41de20cf9da7197f event Planet der Affen: Survival on Sky Cinema - EPG marking start
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: c33bb2d51bce423d41de20cf9da7197f - running flag changed from 0 to 1
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - set state - state RECORDING rec_state RUNNING error 'OK'
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - set state - state RECORDING rec_state WAIT error 'OK'
Oct 14 16:19:12 TVHserver tvheadend[18803]: dvr: File "/storage/recordings/Planet-der-Affen_-Survival/Planet-der-Affen_-Survival.Sky-Cinema.2018-10-14.15-55.mkv" -- No such file or directory -- Using for recording
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: /storage/recordings/Planet-der-Affen_-Survival/Planet-der-Affen_-Survival.Sky-Cinema.2018-10-14.15-55.mkv from adapter: "SAT>IP OctopusNet S2/4 DVB-S #1 (192.168.XXX.XXX@UDP)", network: "DVB-S Astra1x", mux: "11914.5H", provider: "SKY", service: "Sky Cinema HD" 
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr:  #  type              lang  resolution  aspect ratio  sample rate  channels
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr:  1  H264                    1920x1080   16:9
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr:  2  AC3               ger                             48000        5.1
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr:  3  AC3               eng                             48000        2
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f stop 2018-10-14;18:15:00(+0200) - set timer - arm
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: c33bb2d51bce423d41de20cf9da7197f - muxing activated
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - set state - state RECORDING rec_state RUNNING error 'OK'
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: dvr event running check for Modern Family on Sky 1 running 1
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: dvr event running check for Modern Family on Sky 1 running 3
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: entry c791958d07260b99f32b621e555b7702 start 2018-10-14;18:24:30(+0200) stop 2018-10-14;20:15:00(+0200) - set timer
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: entry c791958d07260b99f32b621e555b7702 start 2018-10-14;18:24:30(+0200) - set timer - schedule
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: "Dunkirk" on "Sky Cinema Action": Updated (i)
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: dvr event running check for Live DKB HBL: Füchse Berlin - TBV Lemgo Lippe, Topspiel am Sonntag, 9. Spieltag on Sky Sport 1 running 1
Oct 14 16:19:14 TVHserver tvheadend[18803]: dvr: dvr event running check for Live DKB HBL: Sonntags-Konferenz, 9. Spieltag on Sky Sport 1 running 3
Oct 14 16:19:15 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:19:15 TVHserver tvheadend[18803]: dvr: dvr event running check for Die geheimen Akten der NASA on Discovery running 1
Oct 14 16:19:15 TVHserver tvheadend[18803]: dvr: dvr event running check for Space Shuttle - Das Ende einer Ära on Discovery running 3
Oct 14 16:19:20 TVHserver tvheadend[18803]: dvr: entry c397549fc2e1885ac4e6ab91831924ad start 2018-10-14;20:14:30(+0200) stop 2018-10-14;22:05:00(+0200) - set timer
Oct 14 16:19:20 TVHserver tvheadend[18803]: dvr: entry c397549fc2e1885ac4e6ab91831924ad start 2018-10-14;20:14:30(+0200) - set timer - schedule
Oct 14 16:19:20 TVHserver tvheadend[18803]: dvr: "Geostorm" on "Sky Cinema": Updated (i)
Oct 14 16:19:30 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:19:45 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:19:49 TVHserver tvheadend[18803]: subscription: 048F: "DVR: Planet der Affen: Survival" unsubscribing from "Sky Cinema" 
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - set state - state COMPLETED rec_state FINISHED error 'Aborted by user'
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: adding inotify watch to /storage/recordings/Planet-der-Affen_-Survival (fd=112)
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f when 1970-01-01;01:00:00(+0100) - retention arm
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: "Planet der Affen: Survival" on "Sky Cinema": End of program: Aborted by user
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f when 1970-01-01;01:00:00(+0100) - retention arm
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f when 1970-01-01;01:00:00(+0100) - retention arm
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: delete entry c33bb2d51bce423d41de20cf9da7197f "Planet der Affen: Survival" on "Sky Cinema" start time 2018-10-14 15:54:30, scheduled for recording by "admin", retention "On file removal" removal "Forever" 
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: dvr_autorec_async_reschedule
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: entry c33bb2d51bce423d41de20cf9da7197f - unassign broadcast 67145163
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: inotify: moved from_fd: 112 path: "/storage/recordings/Planet-der-Affen_-Survival/Planet-der-Affen_-Survival.Sky-Cinema.2018-10-14.15-55.mkv" to: ".lanet-der-Affen_-Survival.Sky-Cinema.2018-10-14.15-55.mkv.removing" to_fd: 112
Oct 14 16:19:49 TVHserver tvheadend[18803]: dvr: inotify: moved from_fd: 112 path: "/storage/recordings/Planet-der-Affen_-Survival/.lanet-der-Affen_-Survival.Sky-Cinema.2018-10-14.15-55.mkv.removing" to: "<none>" to_fd: -1

(I cancelled recording manually as it worked)

Log from latest master with "--trace dvr" right after it, recording failed:

Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f - assign broadcast 67145163
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f start 2018-10-14;15:54:30(+0200) - set timer - schedule
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f "Planet der Affen: Survival" on "Sky Cinema" starting at 2018-10-14 15:54:30, with broadcast id "<noid>", scheduled for recording by "admin" 
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f start 2018-10-14;15:54:30(+0200) - set timer - schedule
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f start 2018-10-14;15:54:30(+0200) stop 2018-10-14;18:15:00(+0200) - set timer
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f start 2018-10-14;15:54:30(+0200) - set timer - schedule
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f - set state - state RECORDING rec_state PENDING error 'OK'
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: "Planet der Affen: Survival" on "Sky Cinema" recorder starting
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f original stop 2018-10-14;18:15:00(+0200) stop 2018-10-14;18:15:00(+0200) - stop timer set
Oct 14 16:19:56 TVHserver tvheadend[18803]: mpegts: 11914.5H in DVB-S Astra1x - tuning on SAT>IP OctopusNet S2/4 DVB-S #1 (192.168.XXX.XXX@UDP)
Oct 14 16:19:56 TVHserver tvheadend[18803]: subscription: 0490: "DVR: Planet der Affen: Survival" subscribing on channel "Sky Cinema", weight: 500, adapter: "SAT>IP OctopusNet S2/4 DVB-S #1 (192.168.XXX.XXX@UDP)", network: "DVB-S Astra1x", mux: "11914.5H", provider: "SKY", service: "Sky Cinema HD", profile="matroska" 
Oct 14 16:19:56 TVHserver tvheadend[18803]: dvr: 50c95e71ff7e576be6a358b31b4c118f - recoding thread started for "Planet der Affen: Survival" 
Oct 14 16:19:57 TVHserver tvheadend[18803]: TS: DVB-S Astra1x/11914.5H/Sky Cinema HD Transport error indicator (total 1)
Oct 14 16:19:58 TVHserver tvheadend[18803]: dvr: entry 50c95e71ff7e576be6a358b31b4c118f - set state - state RECORDING rec_state EPGWAIT error 'OK'
Oct 14 16:20:00 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:20:15 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:20:30 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:20:33 TVHserver tvheadend[18803]: dvr: entry c791958d07260b99f32b621e555b7702 start 2018-10-14;18:24:30(+0200) stop 2018-10-14;20:15:00(+0200) - set timer
Oct 14 16:20:33 TVHserver tvheadend[18803]: dvr: entry c791958d07260b99f32b621e555b7702 start 2018-10-14;18:24:30(+0200) - set timer - schedule
Oct 14 16:20:33 TVHserver tvheadend[18803]: dvr: "Dunkirk" on "Sky Cinema Action": Updated (i)
Oct 14 16:20:33 TVHserver tvheadend[18803]: dvr: entry c791958d07260b99f32b621e555b7702 start 2018-10-14;18:24:30(+0200) stop 2018-10-14;20:15:00(+0200) - set timer
Oct 14 16:20:33 TVHserver tvheadend[18803]: dvr: entry c791958d07260b99f32b621e555b7702 start 2018-10-14;18:24:30(+0200) - set timer - schedule
Oct 14 16:20:33 TVHserver tvheadend[18803]: dvr: "Dunkirk" on "Sky Cinema Action": Updated (i)
Oct 14 16:20:45 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK
Oct 14 16:20:49 TVHserver tvheadend[18803]: dvr: dvr_autorec_async_reschedule_cb - begin
Oct 14 16:20:49 TVHserver tvheadend[18803]: dvr: dvr_autorec_async_reschedule_cb - end
Oct 14 16:21:00 TVHserver tvheadend[18803]: dvr: checking free and used disk space for config "Default profile" : OK

Please add more robustness for recordings. No output file written, output stream size of 0, no streams detected are all signs of a failed start of recording, TVh should retry then - which I think it does not.

HTH,
/HXZ

Actions
Copy link

Also available in: Atom PDF