LibreElec Rpi4 TVHat TVHeadend - Recording Problems

    My set up (as in the title) is a Rpi4 with TVHat for UK Freeview.

    I have been having recording problems for some time now so yesterday I enabled debugging, rebooted and set up a recording to test. This particular recording was for a Ghostbusters film on BBC One HD (19.00 - 21.00). I encountered the recording problem as expected.

    Something is happening during recordings where there is some kind of error and the recording continues in a second file (name ending -1). The TVHeadend GUI sees the recording as complete, no errors - but only sees the last file. Looking at the actual file manager reveals there are 2 files, but there always is a gap in time between the first file ending and the second file beginning.

    In the case of this test recording the first file is 1 hour 21 mins long (I think the film started 5 minutes late as well) and the second file 53s long and the content of it seems to be the programme following the film at 21.00 (I have a 3 minute end buffer for recording). So about 40 minutes has been lost between the error and the recording restarting.

    I used putty and run pastekodi to get this:

    https://paste.libreelec.tv/credible-robin.log

    Does anyone have any idea what the problem is?

    Currently the recording medium is a 32GB usb stick (Sandisk microfit) formatted as ext3 called AVUSB. Before using this usb stick I had attached an external usb hard drive (old laptop disc) and recordings worked OK for at least a year. Things started to go wrong last year when the Womens World Cup Football was on. I was recording games and this was when the errors leading to the 'split file' recordings happened. Eventually this hard disc seemed to get corrupted and I could not access it with any PC so replaced it with the usb stick.

    Any number of updates could have happened in this period so maybe some update around this time caused the recording problem?

    I appreciate anyone taking the time to look at this as I don't have a clue!!! It's very frustrating!!!

    Check your NTP settings.

    Code
    Mar 30 02:59:01.277963 PiKodi nmbd[901]: [2024/03/30 02:59:01.277774,  0] ../../source3/nmbd/nmbd_namequery.c:109(query_name_response)
Mar 30 02:59:01.277982 PiKodi nmbd[901]:   query_name_response: Multiple (2) responses received for a query on subnet 192.168.31.101 for name LANGCLAN<1d>.
Mar 30 02:59:01.278020 PiKodi nmbd[901]:   This response was from IP 192.168.31.123, reporting an IP address of 192.168.31.123.
Mar 30 02:59:47.922456 PiKodi connmand[588]: ntp: adjust (slew): -0.023922 sec
Mar 30 03:02:02.004453 PiKodi tvheadend[1388]: epgdb: snapshot start
Mar 30 03:02:02.155433 PiKodi tvheadend[1388]: epgdb: queued to save (size 7908898)
Mar 30 03:02:02.155525 PiKodi tvheadend[1388]: epgdb:   broadcasts 20339
Mar 30 03:02:02.155551 PiKodi tvheadend[1388]: epgdb: save start
Mar 30 03:02:02.412209 PiKodi tvheadend[1388]: epgdb: stored (size 1727297)

    Just checked that and I have two ntp servers set, which I have on all devices that might need it. I saw an error on the rpi4 device - incorrectly entered ntp.cis.strath.ac.uk without the i in cis, so have set it correctly and rebooted and then set up another test recording which should be a good test as it is a really long film (Ben Hur) at 4 hours 20 minutes long (with adverts).

    So is it possible that this simple mistype could cause the recordings problem? The second ntp I have set is ntppub.le.ac.uk. I 've never bothered with the third and leave it blank. Should I put a third entry in as well?

    I've no idea if NTP is the cause here, but I would leave nothing set so the OS defaults to pool.ntp.org servers. There's really no need to set custom NTP servers unless ntp.org is blocked for some reason.

    I have always used these ntp servers on anything I set up so after the correction of that mistyped one earlier I have left as is for now.

    Well just back home and checking on the recording I set. This film was in 2 parts (about 2 hours first part) with some short programme of maybe 5 minutes in between so had to set the second part to record as well. The same problem - I have ended up with 5 files lengths 51m21s, 19m8s, 5m19s and 28m8s, 26m1s.

    pastekodi gives this:

    https://paste.libreelec.tv/noble-grouper.log.

    I don't know if there is other information I can obtain - I will need some guidance of what to do.

    I think that's when the stream gets interrupted:

    Code
    2024-03-31 14:31:57.930 T:957     error <general>: CAESinkALSA - snd_pcm_writei(-32) Broken pipe - trying to recover
2024-03-31 14:31:57.930 T:994     debug <general>: UpdateInProgressSize: Updating recordings size
2024-03-31 14:31:57.930 T:1951    debug <general>: Thread JobWorker 3595555456 terminating (autodelete)
2024-03-31 14:31:57.930 T:990     debug <general>: AddOnLog: pvr.hts: new connection requested

    Can you update your NAS from NFS 3 to NFS 4?

    Code
    2024-03-31 10:07:59.358 T:962     debug <general>: NFS: Context for 192.168.31.123/mnt/user/films not open - get a new context.
2024-03-31 10:07:59.358 T:962     debug <general>: NFS: version: 3
...
Feb 16 18:10:56.635496 LibreELEC kernel: RPC: Registered tcp NFSv4.1 backchannel transport module.

    I use unraid server (current version 6.12.9) as NAS - I'll have to look into that. I assume that you mention this as you noticed as I don't see how it would relate to the recording errors.

    The part where the stream is broken - related to audio somehow? My rpi4 is connected to a Denon AVR which then goes into a Panasonic OLED TV so the sound is set up as passthrough to the Denon for all the digital formats . I don't understand what the error is, unless it is either a data transmission problem from TV signal or a software component failing.

    Probably obvious but when I boot up the rpi4 (or reboot) I need to have the TV on, the AVR on and set as rpi4 source so it can produce a picture - if the rpi4 was to restart without actively passing through to the TV then it would run with a blank screen as the EDID would not be detected. This happened recently when there had been a power cut while I had been at work, so had booted back up with everything else powered down - I could access the shares and TVheadend gui over LAN but the screen was blank until I pulled the power and reconnected with TV, etc on.

    I've looked at my unraid server and run in the terminal the command nfsstat and it shows server version as NFS V3. I've done some searching and came across various articles and V4 is does seem to be the default version to use as seen in the nfsmount.conf on the server [extract]:

    [ NFSMount_Global_Options ]
    # This statically named section defines global mount
    # options that can be applied on all NFS mount.
    #
    # Protocol Version [3,4]
    # This defines the default protocol version which will
    # be used to start the negotiation with the server.
    # limetech - start negotiation with v4
    #Defaultvers=3
    Defaultvers=4
    #
    # Setting this option makes it mandatory the server supports the
    # given version. The mount will fail if the given version is
    # not support by the server.
    # limetech - support v4
    # Nfsvers=4

    I don't know if this file has to be altered where Nfsvers=4 to uncomment it. The majority of this conf file is commented out which I find a bit confusing.

    Also my media shares are exported by SMB as well as NFS. I'm not sure if this makes any difference to the NFS version used. I've only updated to this latest version of Unraid on Sunday morning so it has had a reboot. I've also just stopped the array and restarted it to see if the NFS version changes but is stays at V3. I created a new test share and exported it as NFS only but it still seems to use V3. I'm not sure what I can do to make everything V4 unless I need to delete all NFS exports and then redo them all fresh.

    I also looked around for information on the broken pipe on sound. To me this seems as if it should be related to actual sound output, but at this time (14:31) of the recording the TV and AVR where powered down from about 13:00. I'm not sure what to make of this.

    The recording itself started at 12:03 to 14:08 then the second part of the film was 14:08 to 16:23 (the odd minutes will be padding to start and end). So the first error must have happened 51 mins in (first of the 5 files) so about 12.54.

    Looking at the log file myself I see this:

    Code
    2024-03-31 12:04:00.034 T:989     debug <general>: AddOnLog: pvr.hts: recording id:13092243, state:recording, title:Ben Hur, error:n/a
    Code
    2024-03-31 12:56:16.091 T:989     debug <general>: AddOnLog: pvr.hts: recording id:2099750975, state:scheduled, title:Ben Hur, error:n/a

    I think this entry at 12:56 must have been when I was checking on the recording in the TV Guide and noticed it was actually only recording the first part so I scheduled the second part to record as I hadn't noticed the short programme breaking up the film into 2 parts.

    I've looked at the log file myself and it seems like there is a lot going on and too difficult for me to understand.

    Code
    2024-03-31 14:32:11.677 T:2011     info <general>: AddOnLog: pvr.hts: Request async EPG (8 days)


    I'm also wondering if asynchronous epg might be an issue?

    Quote from boragthung

    The part where the stream is broken - related to audio somehow?

    TV signals aren't always consistent. So maybe your setup is fine, and the stream gets interrupted by a short interrupt of the TV signal. It would be interesting, how TVHeadend handles such interruptions. Does it create a new recording file? Does it have a setting for such situations?

    Other than that, no idea. You're already at log level 2, and no better explanation for creating a new recording file.

    I will have to try TVHeadend forum as you say. I just wasn't sure if it was purely down to a TvHeadend problem or something within kodi or something to do with the usb stick. I am sure I did come across something during the past year I have spent looking at this issue to see if anyone else had it - that TVHeadend by design creates another recording after an interruption. I think this probably is the case as typically a recording I have made that has this error usually creates 2 files, for example:

    Ghostbusters_ Afterlife-BBC ONE WMidHD2024-03-29

    Ghostbusters_ Afterlife-BBC ONE WMidHD2024-03-29-1

    The gui itself shows no errors and lists the runtime as correct , but the file size represents the second file downloading from the gui will only download the second one. In the client interface on the pi TV playback will only see the last file. It is only when I look at file manager I see all files created. Also there is always some ( often quite significant) amount of time missing between the end of the first file and the second.

    The strange thing is these errors first started during the Womens Football World Cup last year which I was recording while at work. Although (I've mentioned previously) the recording device at that time was an old 2.5" mechanical disc from a laptop inside an external usb case, which later became corrupted.

    Something that updated around this time may be the cause - I have no idea. libreelec itself was probably updated as well as TVHeadend plus any firmware / usb for the pi4.

    Thanks for having a look at the logs anyway. When I enabled debugging - I set it as persistent and also enabled specifics - audio ,video , pvr. I wasn't sure how many of these specifics I should select.

    Would there be information elsewhere that would be useful? I know there are a number of different log files in the zipped file that is saved. I have 9 of these zipped log files since 30.3.24 (older ones deleted), including 2 today and I've not even used the pi today.

    I recorded a 1 hour program off Blaze (SD) yesterday and checking on it now shows no problems with that recording. I have set up a couple more recordings to see what happens - a 30 minute HD programme and a 100 minute SD programme.

    One thing I noticed looking at the .ts files with mediainfo there is information regarding the times of programmes:

    Excerpt from last successful (SD Channel) recording:

    Service name : Blaze
    Service type : MPEG-2 HD digital television
    2024-04-03 00:00:00 UTC : en:Swamp Mysteries With Troy... / en:...Landry: Hogzilla: Troy searches for a monster threatening residents of a small Texas community. / show/game show / / 01:00:00 /
    2024-04-03 01:00:00 UTC : en:Blaze is back at 5am / en: / show/game show / / 03:00:00 /

    *Note All in clear text.

    Compared to a bad recording made previous (HD Channel):

    Service name : Channel 5 HD
    Service type : MPEG-2 HD digital television
    2024-03-31 01:00:00 UTC : en:ËX"ÄòR»'á¸ììÙ»J_¡ / en:- / show/game show / / 02:00:00 /
    2024-03-31 03:00:00 UTC : en:«ÃÖæ³{èSð¯FËà / en:¶þ}Ý>[vTpV-m6})ùtõ=ÎðvWiè;×°9È×k6ìqó½q靈¾vì㸮ZKÎ×eƪå©xvé'ìFlxq: [à / social/political issues/economics / / 00:45:00 /
    2024-03-31 03:45:00 UTC : en:Êr¨9N¾ýµÚ£©+¹à / en:qL¹lÓö{:c¡Ïx¿T£Ü#vÆþ¶=fÒ"¿³$^ñÎðvÇAëüª3ö{:c·¯¹K}$¾ªþ\/ÑÛU/ÓJ]QÞkâÀ¨o / social/political issues/economics / / 00:50:00 /

    *Note the strange mixture of text. I don't know if this is some encryption (but all channels are free to air), or possibly corruption?

    Did you made any adjustments to get proper recordings?

    Quote from boragthung

    I don't know if this is some encryption (but all channels are free to air), or possibly corruption?

    My theory: The text wasn't corrupted, it just uses a character encoding system, which is unknown / not implemented by TVHeadend. Please ask at the TVHeadend forum.

    I did make some adjustments to cache. The details are on my main PC but I set it as something like 96 MB cache and 96 MB video ram and I think 4 read. I can't remember the exact wording of the variables off the top of my head.

    I was just checking the latest test recording and saw the same text encoding in the mediainfo file. I have seen this before with good recordings on my freesat libreelec athlon box. I just mentioned it in case it meant a possilble error. It may only happen on HD files or possibly depends on original source. Some of the mediainfo data shows things like 19.2E sat even though these are from terrestial aerial recordings, so I can only assume information is from the original source file that is being reused for different output mediums.

    Anyway the latest recording (HD) should have been 34 mins (with pre and post buffers). The gui lists as 34 mins no errors. The actual file is just under 27 mins long. It plays back and the ending breaks up a little and finishes. So it seems some corruption may have occurred and stopped the recording but only one file exists - so I have to assume whatever the error is did not recover in time to continue the recording as there was only 7 mins to recover. I think there is sometimes a gap of 30-40 mins between a fail and restart.

    I shall make a post on TVH Forum at the weekend and see what they advise to troublshoot.

    The next recording of an SD film completed OK with no errors according to the gui. It should have had a length of 1 h 44 m. The actual file was 1 h 36 m in length - only one file and it had the whole film to the end, mainly because the channel Film 4 usually has a fair bit of time between the end of one programme and then start of the next.. So I think there must have been another problem seeing as it missed 8 minutes recording time. Hopefully the forum at TVH might have some ideas when I put a post up.

    These are the adjusted settings I made by the way (2GB Rpi4):

    <advancedsettings>
    <cache>
    <buffermode>1</buffermode>
    <memorysize>33554432/memorysize>
    <readfactor>10</readfactor>
    <chunksize>65536</chunksize>
    </cache>
    </advancedsettings>