Linux Ending Tuner Recording Early For New Recording Despite Idle Tuners Available

[LinuxDVR]

This is a newer problem that started in late September 2022 after I updated to NextPVR 6.0.0.220904 Available (5th Sept 2022) and Linux Mint 21(.0 ie latest version in late September) at the same time, but I was likely still on the Jan or Feb  2022 release of NextPVR before late September. The assignment of recordings to available tuners hadn't been a problem during the prior 1-2 years of NextPVR releases.

Logs of the issue happening at 2 separate times are attached, this has been a nearly nightly problem of early recording termination while the tuner is reassigned to the next recording on a different channel while idle tuners are still available, so I can ~easily retest with any alternate log levels and settings. I've tested recording 4 different channel's recordings at once in the same NextPVR server instance (without restarting to clear any potential problems) and the four tuners are active and used as expected by NextPVR without errors.

I thought in the distant past I had come across a setting something like 'favor newer recordings over ending recordings on tuner conflicts' but haven't been able to locate that setting in the current NextPVR config xml files or interface. The closest setting in name is a <ForceRecordingServiceUse>true</ForceRecordingServiceUse> defaulted to true as it has been set in NextPVR versions since at least 2020-12 per incomplete history I've tracked.

The first occurrence of the tuner assignment issue can be found in nrecord.log search for timestamp 13:25:01.017
The 2nd occurrence of the tuner assignment issue can be found in nrecord.log search for timestamp 16:55:01.374

The log messages indicate the new recording fails on stream unavailable (presume means tuner in use?) so it ends the in-process recording to start the newer recording (when on a different channel frequency), rather than assign it to an idle tuner. I presume the service status (included below) errors are after affects of the tuner-in-use root cause and not truly the errors indicated of Can't retrieve DVB information for the new delivery system.: Bad file descriptor and adapterX.log entries of [ERROR] dvb_fe_set_parms failed and similar errors that stem from the Tuner In Use issue.


The systemctl status nextpvr-server output is below, I don't believe this gets captured into some of the NextPVR logs

● nextpvr-server.service - NextPVRServer
    Loaded: loaded (/lib/systemd/system/nextpvr-server.service; enabled; vendor preset: enabled)
    Active: active (running) since Sun 2022-11-13 08:29:47 PST; 9h ago
    Process: 1633 ExecStart=/opt/nextpvr/shell/server.sh start (code=exited, status=0/SUCCESS)
  Main PID: 1664 (dotnet)
      Tasks: 55 (limit: 9284)
    Memory: 3.5G
        CPU: 47min 35.997s
    CGroup: /system.slice/nextpvr-server.service
            ├─ 1664 /opt/dotnet/dotnet /opt/nextpvr/system/NextPVRServer.dll
            ├─ 2380 /opt/nextpvr/system/DeviceHost/x64/DeviceHostLinux -listen:34295 -type:ATSC -device:adapter2/frontend0 -instance:1 -parent:1664
            ├─ 2433 /opt/nextpvr/system/DeviceHost/x64/DeviceHostLinux -listen:32843 -type:ATSC -device:adapter3/frontend0 -instance:1 -parent:1664
            ├─ 2512 /opt/nextpvr/system/DeviceHost/x64/DeviceHostLinux -listen:40103 -type:ATSC -device:adapter1/frontend0 -instance:1 -parent:1664
            └─ 4372 /opt/nextpvr/system/DeviceHost/x64/DeviceHostLinux -listen:41313 -type:ATSC -device:adapter0/frontend0 -instance:1 -parent:1664

Nov 13 16:58:00 ota-dvr-i7b server.sh[4372]: ERROR    Can't retrieve DVB information for the new delivery system.: Bad file descriptor
Nov 13 16:58:00 ota-dvr-i7b server.sh[4372]: ERROR    FE_SET_PROPERTY: Bad file descriptor
Nov 13 16:58:00 ota-dvr-i7b server.sh[2433]: ERROR    Can't retrieve DVB information for the new delivery system.: Bad file descriptor
Nov 13 16:58:00 ota-dvr-i7b server.sh[2433]: ERROR    FE_SET_PROPERTY: Bad file descriptor
Nov 13 17:00:00 ota-dvr-i7b server.sh[2433]: ERROR    Can't retrieve DVB information for the new delivery system.: Bad file descriptor
Nov 13 17:00:00 ota-dvr-i7b server.sh[2433]: ERROR    FE_SET_PROPERTY: Bad file descriptor
Nov 13 17:00:00 ota-dvr-i7b server.sh[4372]: ERROR    Can't retrieve DVB information for the new delivery system.: Bad file descriptor
Nov 13 17:00:00 ota-dvr-i7b server.sh[4372]: ERROR    FE_SET_PROPERTY: Bad file descriptor
Nov 13 17:00:00 ota-dvr-i7b server.sh[2433]: ERROR    Can't retrieve DVB information for the new delivery system.: Bad file descriptor
Nov 13 17:00:00 ota-dvr-i7b server.sh[2433]: ERROR    FE_SET_PROPERTY: Bad file descriptor

In late Sep when I updated Linux Mint 20.3 to 21.0 it wiped out the installed software including NextPVR, so NextPVR was a clean install and the LOG_LEVEL was defaulted to DEBUG but let me know if you want additional flags set to capture info during another instance of the tuner assignments. Thanks for your assistance!

[mvallevand]

I'd prefer to get all the logs that you get from the server web page download, this only has the current log.

I do know there was an issue on multi-rec but I don't know if it is new and I don't know if libdvbv5 or you tuner card supports it. Also you need to check for DeviceHostLinux crashed in journalctl recently and if so report the time and I can link that when you send the proper logs.

Here is a related issue https://forums.nextpvr.com/showthread.ph...#pid576050

Martin

[LinuxDVR]

What is the NextPVR server web page URL to use for the extended logs download, or the linux commands or log files I should upload.

I have the one command sudo journalctl | grep DeviceHostLinux from the link above, for the past day and a half, without seqfaults related to the tuner stopping one recording to start another. The 03:57 timestamp is the daily NextPVR service restart timestamp.

Nov 13 03:57:02 ota-dvr-i7b kernel: DeviceHostLinux[11996]: segfault at 208e0 ip 00007f8163c18ee0 sp 00007ffce6c98378 error 4 in libdvbv5.so.0[7f8163c00000+48000]
Nov 13 03:57:02 ota-dvr-i7b kernel: DeviceHostLinux[14593]: segfault at 7fb378000840 ip 00007fb378000840 sp 00007ffd74cbbab8 error 15
Nov 13 03:57:02 ota-dvr-i7b systemd-coredump[35784]: Process 14593 (DeviceHostLinux) of user 999 dumped core.
Found module DeviceHostLinux with build-id: 135d9aa762e9dc0f9e9cc3ceec8ef322fc5c151f
Nov 13 03:57:03 ota-dvr-i7b systemd-coredump[35785]: Process 11996 (DeviceHostLinux) of user 999 dumped core.
Found module DeviceHostLinux with build-id: 135d9aa762e9dc0f9e9cc3ceec8ef322fc5c151f
#1 0x0000556411607f88 _ZN7Adapter4StopEv (DeviceHostLinux + 0x7f88)
#2 0x000055641160aa9a _Z13sigIntHandleri (DeviceHostLinux + 0xaa9a)
#7 0x0000556411604d9f _Z8sleep_msi (DeviceHostLinux + 0x4d9f)
#10 0x000055641160571a _start (DeviceHostLinux + 0x571a)
Nov 13 17:29:57 ota-dvr-i7b kernel: DeviceHostLinux[4372]: segfault at 7f7f2803ec10 ip 00007f7f2803ec10 sp 00007ffe37b47038 error 15
Nov 13 17:29:57 ota-dvr-i7b kernel: DeviceHostLinux[2433]: segfault at 7f345803ec00 ip 00007f345803ec00 sp 00007fff011d0f78 error 15
Nov 13 17:29:57 ota-dvr-i7b systemd-coredump[22766]: Process 4372 (DeviceHostLinux) of user 999 dumped core.
Found module DeviceHostLinux with build-id: 135d9aa762e9dc0f9e9cc3ceec8ef322fc5c151f
Nov 13 17:29:57 ota-dvr-i7b systemd-coredump[22765]: Process 2433 (DeviceHostLinux) of user 999 dumped core.
Found module DeviceHostLinux with build-id: 135d9aa762e9dc0f9e9cc3ceec8ef322fc5c151f
Nov 14 03:57:01 ota-dvr-i7b kernel: DeviceHostLinux[22957]: segfault at 208e0 ip 00007f1e94018ee0 sp 00007ffc1a52a438 error 4 in libdvbv5.so.0[7f1e94000000+48000]
Nov 14 03:57:02 ota-dvr-i7b systemd-coredump[42412]: Process 22957 (DeviceHostLinux) of user 999 dumped core.
Found module DeviceHostLinux with build-id: 135d9aa762e9dc0f9e9cc3ceec8ef322fc5c151f
#1 0x000055f5fda07f88 _ZN7Adapter4StopEv (DeviceHostLinux + 0x7f88)
#2 0x000055f5fda0aa9a _Z13sigIntHandleri (DeviceHostLinux + 0xaa9a)
#7 0x000055f5fda04d9f _Z8sleep_msi (DeviceHostLinux + 0x4d9f)
#10 0x000055f5fda0571a _start (DeviceHostLinux + 0x571a)
Nov 14 14:26:49 ota-dvr-i7b kernel: DeviceHostLinux[3239]: segfault at 7f2d9c000840 ip 00007f2d9c000840 sp 00007fff5962f9f8 error 15
Nov 14 14:26:49 ota-dvr-i7b kernel: DeviceHostLinux[4285]: segfault at 208e0 ip 00007f6997018ee0 sp 00007ffee177e538 error 4 in libdvbv5.so.0[7f6997000000+48000]
Nov 14 14:26:49 ota-dvr-i7b kernel: DeviceHostLinux[4737]: segfault at 208e0 ip 00007fa8dea18ee0 sp 00007ffe956d51f8 error 4 in libdvbv5.so.0[7fa8dea00000+48000]

[mvallevand]

The zip file is on the Settings General page

A server restart should not generate a segfault though.

Martin

[LinuxDVR]

I clear the logs from the NextPVR directory each nightly restart around 3:57am, but the attached log zips above were created from the NextPVR settings.html Log Files button, there isn't enough activity in a day to always create the prior archive logs nrecord.log.[1-4] and all four tuner device-adapter[0-3].log that you might expect to see in the zip.

The sudo journalctl | grep DeviceHostLinux output for the timeperiod around the NextPVR server log zip is copied into a reply above.

Within the logs, it indicates it allocates the recording to presumably the highest priority tuner which is already in-use, so it begins to allocate to an alternate tuner, but if it encounters a real or imagined error on the 2nd tuner (all tuners can successfully record if tested soon after a reported error), it seems to end the recording on the 1st tuner rather than check tuner 3 and tuner 4, in order to begin recording the newer request. 

Does the tuner assignment code intend to iterate through all tuners on the system?

During the initial server start up when it assigns Scheduled Recordings to tuners, does the tuner assigned at that point take into account the pre-padding and post-padding variables of the start and end time, it appears like shows on different frequencies, one ending as the other begins, are assigned to the same tuner, but the pre and post-padding force the need to reassign tuners on the fly at recording time rather than during initial schedule creation during NextPVR startup?

Are there logging settings I can set to get more detail on the errors begin generated by the tuners via DeviceHostLinux - what is behind the error messages:
device-adapterX.log: [ERROR] dvb_fe_set_parms failed
server.sh[130163]: ERROR    Can't retrieve DVB information for the new delivery system.: Bad file descriptor

Thanks for your assistance!

[mvallevand]

Stop clearing the logs that makes no sense and they help us.  

We need to see if dvb_fe_set_parms errors can be duplicated or if the are simply driver errors which is also possible 

Martin