Failed Recordings. Status: Time missed ?

[mingus]

Hello,

I replaced the SSD last week in the IceBox and am back in action ok, recorded a few shows during the week.
I had Sherwood scheduled for last Friday night at 8.30PM on ABC.

No recording appeared.

Via the Tvheadend web interface I see a Failed Recording with the status of "Time missed".

Any clues?

Thanks.

[DeltaMikeCharlie]

Was your IceBox left powered-on when the programme was due to be recorded?

The IceBox will not wake up to record a programme, it must be powered-on 24x7.

[mingus]

Yes, as far as I know - I never power it off.
But that is not to say it didn't go off for some unknown reason I guess.
Maybe some logs could show that?

[DeltaMikeCharlie]

To the best of my knowledge, TVH (tvheadend, the software that does the actual recording) does not enable logging by default.  Logging needs to be intentionally enabled for various subsystems.

Kodi (the software that provides the user interface) does log some things by default, but only keeps the current log plus the last one.

If you have not powered-off your IceBox since the incident, perhaps you could go into Config -> Settings -> System -> Logging and have a look to see if anything shows.  You can also enable PVR component level logging from this screen, however, I have never used this feature.

When you created the recording, did you do so via:

1) IceTV web site (either as a once -off, keywork search or part of a series);
2) Kodi; or
3) Directly on TVH via its web interface?

[mingus]

Thanks for the reply.

Unfortunately I did reboot as part of my diagnosis.

The recording was part of a series recording made on the IceTV website.

[DeltaMikeCharlie]

I have not looked into the TVH code close enough to verify my hypothesis, so what follows is pure, untested speculation on my part:

If the IceTV add-on creates the TVH timer via the 'dvr/entry/create_by_event' API call, then the TVH timer will be linked to the EPG event ID.

If the EPG entry is deleted, or the event ID changes for that channel/timeslot, then perhaps TVH will search all timers that pointed to the now defunct event ID and remove those timers.

Perhaps creating the TVH timer via the 'dvr/entry/create' API call instead will create a timer that TVH treats as a manual timer.  The event title/description, etc, could still be added by the IceTV add-on, just not the event ID.  The IceTV add-on would also have to modify the timer when the event start/stop times change, etc.

[DeltaMikeCharlie]

Maybe some logs could show that?

I just found some archived logfiles on my IceBox.

I used my computer to browse to the IceBox via the network, and found them zipped in the 'Logfiles' share.  I have about 30 with named with date/time.  I just created a timer and a new log file appeared.

Perhaps you can look in there for some clues.

[vader1111]

Maybe some logs could show that?

I just found some archived logfiles on my IceBox.

I used my computer to browse to the IceBox via the network, and found them zipped in the 'Logfiles' share.  I have about 30 with named with date/time.  I just created a timer and a new log file appeared.

Perhaps you can look in there for some clues.

The logfiles folder is setup to create a new Log File every time the folder is accessed.

[mingus]

Yes, I had a poke about through the logs yesterday.

It's a little hard when it's not clear exactly what to search for, I grepped the logs for various things to no avail so far.

[DeltaMikeCharlie]

I have not looked into the TVH code close enough to verify my hypothesis, so what follows is pure, untested speculation on my part:

If the IceTV add-on creates the TVH timer via the 'dvr/entry/create_by_event' API call, then the TVH timer will be linked to the EPG event ID.

If the EPG entry is deleted, or the event ID changes for that channel/timeslot, then perhaps TVH will search all timers that pointed to the now defunct event ID and remove those timers.

Perhaps creating the TVH timer via the 'dvr/entry/create' API call instead will create a timer that TVH treats as a manual timer.  The event title/description, etc, could still be added by the IceTV add-on, just not the event ID.  The IceTV add-on would also have to modify the timer when the event start/stop times change, etc.

I did some testing feeding XMLTV data into TVH (directly via sockets, not via file), both the bleeding-edge version and the IceBox/LibreELEC version.

I could create a timer from the EPG and it showed up as linked in the EPG window.  Looking that the JSON API, the timer had a 'broadcast' field set.

I changed my XMLTV data to advance the start time by 5 minutes.  As the events were all created with a 10 minute duration, this should allow for overlap.  However, all of the XMLTV entries showed as new on the console.

The timer still existed, but its broadcast field was empty and the timer link icon no longer showed in the EPG screen.  Once the link had been broken, the timer start/stop was not updated when the EPG was updated.

On both my bleeding-edge system and IceBox system, these timers still recorded without issue.

In order for an event to be recognised as modified via XMLTV, it must have the same start/stop as the original.  I was able to demonstrate this by only modifying the even description and leaving the start/stop unchanged and the TVH console reported modifications rather than creations.

Start/Stop changed

Code Select Expand

[   INFO] xmltv: xmltv: grab took 0 seconds
[   INFO] xmltv: xmltv: parse took 0 seconds
[   INFO] xmltv: xmltv:  channels   tot=    1 new=    0 mod=    0
[   INFO] xmltv: xmltv:  brands     tot=    0 new=    0 mod=    0
[   INFO] xmltv: xmltv:  seasons    tot=    0 new=    0 mod=    0
[   INFO] xmltv: xmltv:  episodes   tot=    0 new=    0 mod=    0
[   INFO] xmltv: xmltv:  broadcasts tot=   15 new=   15 mod=    0 <=======
Description changed

Code Select Expand

[   INFO] xmltv: xmltv: grab took 0 seconds
[   INFO] xmltv: xmltv: parse took 0 seconds
[   INFO] xmltv: xmltv:  channels   tot=    1 new=    0 mod=    0
[   INFO] xmltv: xmltv:  brands     tot=    0 new=    0 mod=    0
[   INFO] xmltv: xmltv:  seasons    tot=    0 new=    0 mod=    0
[   INFO] xmltv: xmltv:  episodes   tot=    0 new=    0 mod=    0
[   INFO] xmltv: xmltv:  broadcasts tot=   15 new=    0 mod=   15 <=======
Conclusion: The timers were recorded successfully, but only based on their original start/stop and not on any updates subsequently received.  Missing EPG entries would not appear to be the cause of the "time missed" timers.

[mingus]

The weirdness continues ...

Last night's (Friday) Sherwood which was set to record, according to the web/app, at 8.30PM did not record.
It was the only thing set to record.
Instead it is recording today at 2PM.
Who knows?!

Also, Shetland is showing as set to record on Sunday night, on the web/app.
No recording is scheduled on the IceBox.
Instead an old episode of Shetland is set to record tonight.
Who knows?!

[IanL-S]

Take a deep breath - you are doing nothing wrong.

This is an example of a known problem. When a timer is updated, it for some reason either schedules a recording for a repeat some time after, or more worrying sets a time at an earlier time (invariably for a previous episode).

Unfortunately there is no ETA for a fix.

Sherwood did not record on my IceBox, but did on my Beyonwiz. Shetland Season 7 Episode 1 is not scheduled for tonight; however Season 6 Episode 6 recorded twice last night (as it is set for repeats and first showing). The repeat on the coming Friday is scheduled.

[MD]

But believe me when I say Dan is trying all sorts of tests! So far no certainty because it is random, so we only find out afterwards. We will keep testing every day until we do track it down.

[mingus]

Thanks for the responses.

I have managed to schedule Shetland ok by explicitly choosing to Record This Airing.

It is now set for tonight ok on the IceBox and the repeat from next Friday has been removed, so all good ... for now.

[DeltaMikeCharlie]

Has anyone thought about implementing a level of logging in TVH that would make a fascist dictator blush?

Kodi and IceTV are really just pretty frontends to TVH.  TVH is were all the action happens.

Consider enabling logging for: START,STOP,dvr,epg,epgdb,uuid,idnode,api.

The EPG-related logging should give an idea of when EPG updates are received.  The DVR logging should report when timers are created/recorded/deleted.

The UUID/IDNODE should catch anything that is not logged by the DVR.  It will be mind-numbingly boring, but if a timer is deleted and not logged by the DVR, it should be trapped by the UUID and IDNODE logging.

Finally, the API logging should record anything coming in via JSON and HTSP.

The log file will get big, fast, but it will give the end user a good chance of seeing when their timer failed (after the event) and more importantly, the events leading up to the timer being missed.  Perhaps the log will have to be manually restarted daily, assuming that no recordings were missed on that day.

The log could even be written to an external USB drive if the correct path is given.

Also,

If ICE know the name and date/time of the programme(s) in question, they should be able to find the unique event ID and then track updates in their EPG database to see if the event start/duration had changed at all, etc.


A list of subsystems:

Code Select Expand

  START           START
  STOP            STOP
  CRASH           CRASH
  main            Main
  tprof           Time profiling
  qprof           Queue profiling
  CPU             CPU
  thread          Thread
  tvhpoll         Poll multiplexer
  time            Time
  spawn           Spawn
  fsmonitor       Filesystem monitor
  lock            Locking
  uuid            UUID
  idnode          Node subsystem
  url             URL
  tcp             TCP Protocol
  rtsp            RTSP Protocol
  upnp            UPnP Protocol
  settings        Settings
  config          Configuration
  access          Access (ACL)
  cron            Cron
  dbus            DBUS
  avahi           Avahi
  bonjour         Bonjour
  api             API
  http            HTTP Server
  httpc           HTTP Client
  htsp            HTSP Server
  htsp-sub        HTSP Subscription
  htsp-req        HTSP Request
  htsp-ans        HTSP Answer
  imagecache      Image Cache
  tbl             DVB SI Tables
  tbl-base        Base DVB SI Tables (PAT,CAT,PMT,SDT etc.)
  tbl-csa         DVB CSA (descrambling) Tables
  tbl-eit         DVB EPG Tables
  tbl-time        DVB Time Tables
  tbl-atsc        ATSC SI Tables
  tbl-pass        Passthru Muxer SI Tables
  tbl-satip       SAT>IP Server SI Tables
  fastscan        Fastscan DVB
  pcr             PCR Clocks
  parser          MPEG-TS Parser
  TS              Transport Stream
  globalheaders   Global Headers
  tsfix           Time Stamp Fix
  hevc            HEVC - H.265
  muxer           Muxer
  pass            Pass-thru muxer
  audioes         Audioes muxer
  mkv             Matroska muxer
  service         Service
  channel         Channel
  subscription    Subscription
  service-mapper  Service Mapper
  bouquet         Bouquet
  esfilter        Elementary Stream Filter
  profile         Streaming Profile
  descrambler     Descrambler
  descrambler-emm Descrambler EMM
  caclient        CA (descrambling) Client
  csa             CSA (descrambling)
  capmt           CAPMT CA Client
  cwc             CWC CA Client
  cccam           CWC CCCam Client
  dvbcam          DVB CAM Client
  dvr             Digital Video Recorder
  dvr-inotify     DVR Inotify
  epg             Electronic Program Guide
  epgdb           EPG Database
  epggrab         EPG Grabber
  charset         Charset
  dvb             DVB
  mpegts          MPEG-TS
  muxsched        Mux Scheduler
  libav           libav / ffmpeg
  transcode       Transcode
  iptv            IPTV
  iptv-pcr        IPTV PCR
  iptv-sub        IPTV Subcription
  linuxdvb        LinuxDVB Input
  diseqc          DiseqC
  en50221         CI Module
  en50494         Unicable (EN50494)
  satip           SAT>IP Client
  satips          SAT>IP Server
  tvhdhomerun     TVHDHomeRun Client
  psip            ATSC PSIP EPG
  opentv          OpenTV EPG
  pyepg           PyEPG Import
  xmltv           XMLTV EPG Import
  webui           Web User Interface
  timeshift       Timeshift
  scanfile        Scanfile
  tsfile          MPEG-TS File
  tsdebug         MPEG-TS Input Debug
  codec           Codec
  vaapi           VA-API
  ddci            DD-CI
  udp             UDP Streamer
  ratinglabels    Rating Labels