SOLVED: Quad HDHR single tuner freezing.

Have a MythTV related problem? Ask for help from other MythTV users here.

Moderator: Forum Moderators

PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

SOLVED: Quad HDHR single tuner freezing.

Post by PhilB »

I have a recurring problem with my quad DVB-T/T2 HDHR tuner. Every couple of weeks it fails and I'd appreciate views.

I'm in the UK and get DVB/T and DVB/T2 transmissions. The tuner claims 100% signal strength and quality and I have good pictures on all
devices in the house.

The backend is a NUC dual i3, 4GB with SSD (root) and a USB drive (/var/lib/mythtv) running xubuntu 20.04/Myth 32.
Both are connected via ethernet to the same 1GB switch. I use EIT active grabbing on the first tuner only.
The HDHR is only accessed from this backend - I don't use it with other devices in the house.

About once every 10 days or so a recording on tuner 1 will fail. Thereafter, everything on tuner 1 fails but tuner 2 (and presumably 3 & 4) are ok. An hdhr reboot is needed to mend it.

Here is an extract from the log (with a column removed for readability).

Code: Select all

The previous recording was successful and it rescheduled the next recording.

Nov  3 15:47:57 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for MATCH 0 2 0 2022-11-10T23:32:30Z EITScanner
Nov  3 15:47:57 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 42 items in 0.1 = 0.04 match + 0.03 check + 0.02 place
Nov  3 15:50:00 myth2 : I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[1]: Changing from RecordingOnly to None
Nov  3 15:50:00 myth2 : N RecThread recorders/recorderbase.cpp:492 (FinishRecording) Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (704x576 A/R: 3 25fps) Audio Codec: mp2
Nov  3 15:50:00 myth2 : I TVRecEvent recordinginfo.cpp:1251 (FinishedRecording) Finished recording I Escaped to the Country: channel 20001
Nov  3 15:50:00 myth2 : I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "I Escaped to the Country" on cardid [1] (Recording => Recorded)
Nov  3 15:50:00 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK -3 4126 0 UpdateRecStatus2 | I Escaped to the Country |  | Jules Hudson and Steve Brown revisit former house-hunters in the Midlands. One couple's home is now a lovely Grade II listed barn conversion. | fp.bbc.co.uk/m/rynq
Nov  3 15:50:00 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.0 = 0.00 match + 0.00 check + 0.02 place
Nov  3 15:50:02 myth2 : I ProcessRequest mainserver.cpp:1811 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Nov  3 15:50:02 myth2 : I ProcessRequest mainserver.cpp:1813 (HandleAnnounce) MainServer: adding: myth2(558eed1e8880) as a client (events: 0)
Nov  3 15:50:02 myth2 : I ProcessRequest mainserver.cpp:1811 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Nov  3 15:50:02 myth2 : I ProcessRequest mainserver.cpp:1813 (HandleAnnounce) MainServer: adding: myth2(558eed1ea7b0) as a client (events: 1)
Nov  3 15:50:10 myth2 : I MythSocketThread(81) mainserver.cpp:7889 (connectionClosed) Monitor sock(558eed1e8880) 'myth2' disconnected
Nov  3 15:50:10 myth2 : I MythSocketThread(84) mainserver.cpp:7889 (connectionClosed) Monitor sock(558eed1ea7b0) 'myth2' disconnected
Nov  3 15:50:16 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for MATCH 0 0 0 2022-11-03T16:20:00Z EITScanner
Nov  3 15:50:16 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.1 = 0.03 match + 0.00 check + 0.02 place
Nov  3 15:51:09 myth2 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[1]: TuningFrequency
Nov  3 15:51:09 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[1](1252CD2F): Added 4 devices from 1252CD2F
Nov  3 15:51:09 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[1](1252CD2F): Connected to device(1252CD2F-0)
Nov  3 15:51:47 myth2 : N Expire autoexpire.cpp:240 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 15.0 GB w/freq: 15 min
Nov  3 15:51:47 myth2 : N Expire autoexpire.cpp:725 (ExpireEpisodesOverMax) Deleting 20001 at 2022-10-25T13:56:00Z => I Escaped to the Country.  Too many episodes, we only want to keep 7.
Nov  3 15:51:47 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK -3 4126 0 ForgetHistory | I Escaped to the Country |  | Jules Hudson revisits two pairs of home-buyers he previously showed around Norfolk. | fp.bbc.co.uk/m/rsgm
Nov  3 15:51:47 myth2 : N CoreContext recordinginfo.cpp:631 (ApplyRecordRecGroupChange) ApplyRecordRecGroupChange: Default to Deleted (3)
Nov  3 15:51:48 myth2 : E CoreContext mainserver.cpp:2158 (SendResponse) MainServer: SendResponse: Unable to write to client socket, as it's no longer there
Nov  3 15:51:48 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.0 = 0.00 match + 0.00 check + 0.02 place
Nov  3 15:51:48 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK 0 4126 0 DoHandleDelete1 | I Escaped to the Country |  | Jules Hudson revisits two pairs of home-buyers he previously showed around Norfolk. | fp.bbc.co.uk/m/rsgm
Nov  3 15:51:48 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.0 = 0.00 match + 0.00 check + 0.02 place

[...]

Next recording failed and was rescheduling on a different channel and second tuner (dvb/t2 not dvb/t) which was successful.

Nov  3 22:35:00 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for PLACE PrepareToRecord
Nov  3 22:35:00 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 40 items in 0.0 = 0.00 match + 0.00 check + 0.02 place
Nov  3 22:35:01 myth2 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[1]: TuningFrequency
Nov  3 22:35:01 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[1](1252CD2F): Added 4 devices from 1252CD2F
Nov  3 22:35:01 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[1](1252CD2F): Connected to device(1252CD2F-0)
Nov  3 22:35:11 myth2 : E TVRecEvent tv_rec.cpp:3891 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: SignalMonitor timed out
Nov  3 22:35:11 myth2 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[1]: TuningFrequency
Nov  3 22:35:11 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[1](1252CD2F): Added 4 devices from 1252CD2F
Nov  3 22:35:11 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[1](1252CD2F): Connected to device(1252CD2F-0)
Nov  3 22:35:11 myth2 : E TVRecEvent channelutil.cpp:1964 (GetChannelData) Could not find channel '' in DB for source '2'.
Nov  3 22:35:11 myth2 : E TVRecEvent recorders/dtvchannel.cpp:209 (SetChannelByString) DTVChan[1](1252CD2F): SetChannelByString(): Unable to find channel in database.
Nov  3 22:35:11 myth2 : E TVRecEvent tv_rec.cpp:3672 (TuningFrequency) TVRec[1]: Failed to set channel to . Reverting to kState_None
Nov  3 22:35:30 myth2 : I Scheduler mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 10
Nov  3 22:35:30 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[7]: ASK_RECORDING 7 149 0 0
Nov  3 22:35:30 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[8]: ASK_RECORDING 8 149 0 0
Nov  3 22:35:30 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[6]: ASK_RECORDING 6 149 0 0
Nov  3 22:35:30 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[5]: ASK_RECORDING 5 149 0 0
Nov  3 22:35:30 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[1]: ASK_RECORDING 1 149 0 0
Nov  3 22:36:00 myth2 : I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[1]: Changing from None to RecordingOnly
Nov  3 22:36:00 myth2 : I CoreContext mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 10
Nov  3 22:36:00 myth2 : E CoreContext programinfo.cpp:2619 (GetPlaybackURL) ProgramInfo(20001_20221103223600.ts): GetPlaybackURL: '20001_20221103223600.ts' should be local, but it can not be found.
Nov  3 22:36:00 myth2 : I CoreContext mythsystemevent.cpp:314 (customEvent) MythSystemEventHandler: Starting thread for command '/usr/local/bin/checkfilm.pl -v --chanid=20001  >>/var/log/mythtv/checkfilm.log  2>&1'
Nov  3 22:36:00 myth2 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[1]: TuningFrequency
Nov  3 22:36:00 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[1](1252CD2F): Added 4 devices from 1252CD2F
Nov  3 22:36:00 myth2 : I SystemEvent mythsystemevent.cpp:50 (run) MythSystemEventHandler: Finished '/usr/local/bin/checkfilm.pl -v --chanid=20001  >>/var/log/mythtv/checkfilm.log  2>&1' result 0
Nov  3 22:36:00 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[1](1252CD2F): Connected to device(1252CD2F-0)
Nov  3 22:36:00 myth2 : I Scheduler scheduler.cpp:2899 (HandleRecordingStatusChange) Tuning recording: "Question Time": channel 20001 on cardid [1], sourceid 2
Nov  3 22:36:07 myth2 : E TVRecEvent tv_rec.cpp:3904 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: Hit pre-fail timeout
Nov  3 22:36:10 myth2 : W TVRecEvent tv_rec.cpp:3932 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: taking more than 10000 ms to get a lock. marking this recording as 'Failing'.
Nov  3 22:36:10 myth2 : W TVRecEvent tv_rec.cpp:3937 (TuningSignalCheck) TVRec[1]: See 'Tuning timeout' in mythtv-setup for this input
Nov  3 22:36:10 myth2 : I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Question Time" on cardid [1] (Tuning => Failing)
Nov  3 22:36:10 myth2 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK -14 5609 0 UpdateRecStatus2 | Question Time |  | Fiona Bruce presents an hour of debate from Horsham in West Sussex. On the panel are Chris Philp MP, Peter Kyle MP, Zanny Minton Beddoes, George the Poet and Lord Stuart. | fp.bbc.co.uk/m/ryqm
Nov  3 22:36:10 myth2 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 40 items in 0.0 = 0.00 match + 0.00 check + 0.02 place
Nov  3 22:36:10 myth2 : I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[2]: Changing from None to RecordingOnly
Nov  3 22:36:10 myth2 : I TVRecEvent mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 10
Nov  3 22:36:10 myth2 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[2]: TuningFrequency
Nov  3 22:36:10 myth2 : E CoreContext programinfo.cpp:2619 (GetPlaybackURL) ProgramInfo(20101_20221103223600.ts): GetPlaybackURL: '20101_20221103223600.ts' should be local, but it can not be found.
Nov  3 22:36:10 myth2 : I CoreContext mythsystemevent.cpp:314 (customEvent) MythSystemEventHandler: Starting thread for command '/usr/local/bin/checkfilm.pl -v --chanid=20101  >>/var/log/mythtv/checkfilm.log  2>&1'
Nov  3 22:36:10 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[2](1252CD2F): Added 4 devices from 1252CD2F
Nov  3 22:36:10 myth2 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[2](1252CD2F): Connected to device(1252CD2F-1)
Nov  3 22:36:10 myth2 : I SystemEvent mythsystemevent.cpp:50 (run) MythSystemEventHandler: Finished '/usr/local/bin/checkfilm.pl -v --chanid=20101  >>/var/log/mythtv/checkfilm.log  2>&1' result 0
Nov  3 22:36:10 myth2 : I Scheduler scheduler.cpp:2899 (HandleRecordingStatusChange) Tuning recording: "Question Time": channel 20101 on cardid [2], sourceid 2
Nov  3 22:36:11 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[10]: ASK_RECORDING 10 108 0 0
Nov  3 22:36:11 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[9]: ASK_RECORDING 9 108 0 0
Nov  3 22:36:11 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[12]: ASK_RECORDING 12 108 0 0
Nov  3 22:36:11 myth2 : I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[11]: ASK_RECORDING 11 108 0 0
Nov  3 22:36:12 myth2 : I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Question Time" on cardid [2] (Tuning => Recording)
Nov  3 22:36:12 myth2 : I TVRecEvent tv_rec.cpp:4146 (TuningNewRecorder) TVRec[2]: rec->GetPathname(): '/var/lib/mythtv/recordings/20101_20221103223600.ts'
Nov  3 22:36:12 myth2 : I TVRecEvent tv_rec.cpp:4179 (TuningNewRecorder) TVRec[2]: TuningNewRecorder - CreateRecorder()
Nov  3 22:36:20 myth2 : W TFWWrite threadedfilewriter.cpp:547 (DiskLoop) TFW(/var/lib/mythtv/recordings/20101_20221103223600.ts:85): write(376) cnt 38 total 2357708 -- took a long time, 6824 ms
Nov  3 22:36:48 myth2 : N Expire autoexpire.cpp:240 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 17.0 GB w/freq: 7 min

Thereafter, all test recordings on tuner 1 fail, all those on tuner 2 work.

Nov  4 07:56:10 myth2 : I  (UpdateRecStatus) Updating status for "Spellbinders Wax Seals" on cardid [1] (Tuning => Failing)
Nov  4 09:01:50 myth2 : I  (UpdateRecStatus) Updating status for "Spellbinders Wax Seals" on cardid [1] (Failing => Recorder Failed)
Nov  4 09:56:10 myth2 : I  (UpdateRecStatus) Updating status for "Critical Incident" on cardid [1] (Tuning => Failing)
Nov  4 09:56:12 myth2 : I  (UpdateRecStatus) Updating status for "Critical Incident" on cardid [2] (Tuning => Recording)
Nov  4 10:46:50 myth2 : I  (UpdateRecStatus) Updating status for "Critical Incident" on cardid [1] (Failing => Recorder Failed)
Nov  4 10:50:00 myth2 : I  (UpdateRecStatus) Updating status for "Critical Incident" on cardid [2] (Recording => Recorded)
Nov  4 14:56:11 myth2 : I  (UpdateRecStatus) Updating status for "I Escaped to the Country" on cardid [1] (Tuning => Failing)
Nov  4 15:46:50 myth2 : I  (UpdateRecStatus) Updating status for "I Escaped to the Country" on cardid [1] (Failing => Recorder Failed)
Nov  4 17:56:10 myth2 : I  (UpdateRecStatus) Updating status for "Paper Boutique Mandala Magic..." on cardid [1] (Tuning => Failing)
Nov  4 18:26:10 myth2 : I  (UpdateRecStatus) Updating status for "The Now Show" on cardid [2] (Tuning => Failing)
Nov  4 19:01:50 myth2 : I  (UpdateRecStatus) Updating status for "Paper Boutique Mandala Magic..." on cardid [1] (Failing => Recorder Failed)
Nov  4 19:01:50 myth2 : I  (UpdateRecStatus) Updating status for "The Now Show" on cardid [2] (Failing => Recorder Failed)
Nov  4 20:56:10 myth2 : I  (UpdateRecStatus) Updating status for "Paper Boutique Mandala Magic..." on cardid [1] (Tuning => Failing)
Nov  4 22:01:50 myth2 : I  (UpdateRecStatus) Updating status for "Paper Boutique Mandala Magic..." on cardid [1] (Failing => Recorder Failed)
Nov  4 22:36:10 myth2 : I  (UpdateRecStatus) Updating status for "The Graham Norton Show" on cardid [2] (Tuning => Failing)
Nov  4 22:56:10 myth2 : I  (UpdateRecStatus) Updating status for "Paper Boutique Mandala Magic..." on cardid [1] (Tuning => Failing)
Nov  4 23:31:50 myth2 : I  (UpdateRecStatus) Updating status for "The Graham Norton Show" on cardid [2] (Failing => Recorder Failed)
I can resusicate it with either a tuner power cycle or a tuner reboot with
hdhomerun_config FFFFFFFF set /sys/restart self A restart of the backend is not needed.

I'm also getting messages saying that writes are taking serveral seconds to start, presumably because the disk needs to spin up to speed.
A 'touch' at start recording system event makes little difference. I don't think this will be an issue though.

Any insights appreciated. Meanwhile, changes I'm considering or doing, all of which are probably wild desperate shots in the dark are:

- run that checkfilm job at another time (it looks for films split by news items - see UK forum).
- upgrade to latest firmware in the tuner (it was on February 2022. now Sept 2022).
- dedicated switch for these two devices
- attenuate the TV signal in case it is marginally overloading the hdhr
- reboot the hdhr regularly in case it's a memory leak.

Phil
Last edited by PhilB on Thu Aug 03, 2023 7:18 am, edited 1 time in total.
User avatar
kmdewaal
Developer
Posts: 641
Joined: Wed Dec 07, 2016 8:01 pm
Netherlands

Re: Quad HDHR single tuner freezing.

Post by kmdewaal »

My 10 cents on HDHomeRun problems....

1. HDHR power supply
In the past many HDHR problems have disappeared after the power supply had been replaced.

2. Firmware version
I do not think this makes any difference, but running the latest firmware is always a good idea. I think that I still have the February 2022 on my HDHRs.

3. Rebooting periodically
I do not expect that this makes a difference. However, it does not cost anything except time and effort to try this.

4. Attenuating TV signal
This might help if you have bad recordings but if your recordings are perfect until tuner 1 fails this is unlikely to be the cause.

5. Dedicated switch
This never hurts. For my production system I have an addition network card in the PC and a point-to-point connection (without switch or anything) from the network card to the HDHomeRun. On the other hand, my test system uses two HDHomeRuns that are part of the general network and I never have issues with them.

6. checkfiilm jobs
I do not think this makes a difference but running this at another time of the day and checking if there is a correlation is easy to do.
If system activity is a possible issue then it might be worth to check if there is a correlation with the daily database backup.

7. Why tuner 1
Tuner 1 runs the EIT and that means tuner 1 is always in use. This is probably the main reason why tuner 1 fails and not one of the other tuners.
With the current software only tuner 1 can do EIT so it is NOT possible to switch the EIT to another tuner on the same HDHDR.
In principle, it can be a software bug in the switching between EIT and ordinary recordings. While this bit of the software is not perfect, as shown by the "Could not find channel '' in DB for source '2'" messages in your log, it does not cause a failing tuner. At least, not in my setup.

8. DVB-T vs DVB-T2
I do not know if switching between DVB-T and DVB-T2 channels can be an issue. That is difficult to test as I have here only DVB-T2.
However, it seems unlikely that this matters.

9. Recovery after errors
There is not much error recovery in the MythTV software. This is true for the HDHR software but also e.g. for the SatIP software.
If everything is perfect then you do not need error recovery. To really test software one can create test a environment which does inject errors but that is a lot of work. Also, it is still not perfect if your system keeps on playing with partially defect hardware, but it would at least give the possibility for better error messages.

10. Input buffer size
The SatIP software needs a big input buffer to work reliable; if the buffer cannot be set to be large enough the following message is given:

Code: Select all

       RTP UDP socket receive buffer size set to 212992 but requested 8000000
       To prevent UDP packet loss increase net.core.rmem_max e.g. with this command:
       sudo sysctl -w net.core.rmem_max=8000000
       and restart mythbackend..
The HDHR software also needs a big buffer and it tries to increase the buffer size to 1Mbyte but if it can only acquire a smaller buffer there is no error message given. You could try to increase the maximum network buffer size to at least 1Mbyte or also 8Mbyte before starting mythbackend.

Hope this helps,
Klaas.
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

Thanks Klaas. very helpful.
I'm shifting that checkfilm to the recording started writing event but with a 20 second delay.
I have updated HDHR firmware to Sept version.
Also added to /etc/sysctl.conf:

Code: Select all

# increase buffer size for HDHR.  15 Nov 2022
net.core.rmem_max=8388608
The tuner and backend are now on the same G/bit switch with nothing else.
Daily reboot - still to be done.
I will then monitor events.

The tuner is just over 12 months old so I hope it is not a power supply problem but will bear it in mind.

I don't think the issue is DVB/T vs DVB/T2 issue but am suspicious of mixing recordings and the EIT.
Is it possible to perhaps to split the 4 tuners into one for EIT only, the other 3 for recordings?
Thanks again for your observations.
Phil
User avatar
kmdewaal
Developer
Posts: 641
Joined: Wed Dec 07, 2016 8:01 pm
Netherlands

Re: Quad HDHR single tuner freezing.

Post by kmdewaal »

Is it possible to perhaps to split the 4 tuners into one for EIT only, the other 3 for recordings?
In the mythtv-setup Capture Card menu the "Use HDHomeRun for active EIT scan" option is to be checked only for tuner 1, which you already should have. In the Input Connections menu you can define Input Priority and Schedule Order for each tuner and with that you can give priority to tuners 2, 3 and 4 above tuner 1. If you schedule recordings on 4 different multiplexes simultaneously then also tuner 1 will be used.
N.B. This is how I understand it to work but I never tried do do this myself.

If the failures keep coming then it might be useful to have a mythbackend log with the "-v channel,record,eit,siparser" logging options enabled.

Hope this helps,
Klaas.
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

Thanks Klass.
If I set EIT on first tuner only and set 'Schedule Order' to zero then EIT still gathers data but the scheduler does not choose it for recordings.
I did this test: Record BBC2 on multiplex 10, ITV on mpx 11, London Love on mpx 14 - all record. Add Dave on mpx 9 and it clashes!
With the channel allocations here in the UK and multirec I will never need all 4 tuners (except when trying to provoke it!).
Phil
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

Klaas,
Even if the change to tuners above fixes it, it is a 'get around'. Would there be interest of a more detailed log if I can provoke the failure again? Do devs have the time/effort to tackle this?
Am I right in thinking that the enhanced logging options enabled would need to be put in /lib/systemd/system/mythtv-backend.service on my xbuntu 20.04 setup?
regards
Phil
User avatar
kmdewaal
Developer
Posts: 641
Joined: Wed Dec 07, 2016 8:01 pm
Netherlands

Re: Quad HDHR single tuner freezing.

Post by kmdewaal »

Hi Phil,

Yes, it is interesting to figure out what is really wrong and if you have a detailed log then I will have a look at it. Of course, no guarantees.....
In the mythtv-backend.service script figure out where mythbackend is started (maybe the ExecStart statement) and then that should be the place to add the "-v channel,record,eit,siparser" logging options.

Thanks,
Klaas.
User avatar
paulh
Developer
Posts: 909
Joined: Thu Feb 06, 2014 6:09 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by paulh »

You can also temporarily change the verbose and log level of the running backend by using --setverbose and --setloglevel. This has the advantage you don't have to stop the backend to change the log verbosity and you don't have to mess with any system files that could potentially stop the backend starting properly. When you are done you can either use the same commands to return the log levels to normal or you can just restart the BE and it will restart with your normal log levels.

Code: Select all

mythbackend  --setverbose channel,record,eit,siparser
For anyone interested it works by starting a new instance of mythbackend that just sends an event message to the master backend telling it to adjust it's logging verbosity and/or debug level and then the new instance just exits immediately.
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

Thanks for your assistance so far.
I have been unable to reproduce the 'locked tuner' symptoms exactly but I have had a recording failure which may be related.
To recap:
The HDHR is the 4 tuner version and is set up with multirec=4 on each. Schedule / liveTV orders are:
40, 40 On the first tuner with EIT enabled.
10,30
20,20
30,10

The HDHR and backend are on same G/Bit switch - nothing else on it - and I have 8MB of buffering -
(net.core.rmem_max=8388608 added to /etc/sysctl.conf).

The API GetProgramList says this:
<StartTime>2022-12-25T21:05:00Z</StartTime>
<EndTime>2022-12-25T22:35:00Z</EndTime>
<Title>Doc Martin Christmas Special</Title>

This recording 'aborted' at 21:54:47 but immediately restarted and there is a gap of just a few seconds missed between the recordings.
There were no other recordings at the time, no 'live tv' active and the network was pretty idle (apart from 'phone home' lookups from
printer, cameras etc).

The log is here: (with redundant columns sed'd out). I'd appreciate any observations.

Seasonal greetings to you all!
Phil

Code: Select all

Dec 25 21:54:40 : I TVRecEvent eitscanner.cpp:227 (StopEITEventProcessing) EITScanner[10]: Stop processing EIT events in active scan
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:2034 (TeardownSignalMonitor) TVRec[10]: TeardownSignalMonitor() -- begin
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrsignalmonitor.cpp:66 (~HDHRSignalMonitor) HDHRSigMon[10](1252CD2F): dtor
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrsignalmonitor.cpp:76 (Stop) HDHRSigMon[10](1252CD2F): Stop() -- begin
Dec 25 21:54:40 : I TVRecEvent recorders/streamhandler.cpp:82 (RemoveListener) SH[10]: RemoveListener(0x7fef381168d8) -- begin
Dec 25 21:54:40 : I TVRecEvent recorders/streamhandler.cpp:94 (RemoveListener) SH[10]: RemoveListener(0x7fef381168d8) -- locked
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:186 (run) HDHRSH[10](1252CD2F): RunTS(): shutdown
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:203 (run) HDHRSH[10](1252CD2F): stream stats: packet_count=33315 network_errors=0 transport_errors=0 sequence_errors=4 overflow_errors=0
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:217 (run) HDHRSH[10](1252CD2F): RunTS(): end
Dec 25 21:54:40 : I TVRecEvent recorders/streamhandler.cpp:111 (RemoveListener) SH[10]: RemoveListener(0x7fef381168d8) -- end
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrsignalmonitor.cpp:82 (Stop) HDHRSigMon[10](1252CD2F): Stop() -- end
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:2053 (TeardownSignalMonitor) TVRec[10]: TeardownSignalMonitor() -- end
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[10]: ClearFlags(SignalMonitorRunning,) -> RunMainLoop,EITScannerRunning, @ tv_rec.cpp:3532
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:79 (Close) HDHRChan[10](1252CD2F): Closing HDHR channel
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:83 (Return) HDHRSH[10]: Closing handler for 10
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:527 (TuneChannel) HDHRSH[10](1252CD2F): Tuning channel none (was auto:514000000)
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[10]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,EITScannerRunning, @ tv_rec.cpp:3578
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3464 (HandleTuning) TVRec[10]: No recorder yet, calling TuningFrequency
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[10]: TuningFrequency
Dec 25 21:54:40 : I TVRecEvent recorders/dtvchannel.cpp:159 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(25): 
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:56 (Open) HDHRChan[10](1252CD2F): Opening HDHR channel
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[10](1252CD2F): Added 4 devices from 1252CD2F
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[10](1252CD2F): Connected to device(1252CD2F-0)
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:46 (Get) HDHRSH[10]: Creating new stream handler 10 for 1252CD2F
Dec 25 21:54:40 : I TVRecEvent recorders/channelbase.cpp:609 (InitializeInput) ChannelBase[10]: Input #10: 'None' schan(1) sourceid(1)
Dec 25 21:54:40 : I TVRecEvent cardutil.cpp:2167 (GetConflictingInputs) CardUtil[10]: GetConflictingInputs(10) 14,15,16
Dec 25 21:54:40 : I TVRecEvent recorders/channelbase.cpp:253 (IsInputAvailable) ChannelBase[10]: Input is free on 0/0
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:170 (Tune) HDHRChan[10](1252CD2F): Tuning to auto:530000000
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:527 (TuneChannel) HDHRSH[10](1252CD2F): Tuning channel auto:530000000 (was none)
Dec 25 21:54:40 : I TVRecEvent recorders/dtvchannel.cpp:320 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(25): success
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:56 (Open) HDHRChan[10](1252CD2F): Opening HDHR channel
Dec 25 21:54:40 : I TVRecEvent recorders/dtvchannel.cpp:159 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(25): 
Dec 25 21:54:40 : I TVRecEvent cardutil.cpp:2167 (GetConflictingInputs) CardUtil[10]: GetConflictingInputs(10) 14,15,16
Dec 25 21:54:40 : I TVRecEvent recorders/channelbase.cpp:253 (IsInputAvailable) ChannelBase[10]: Input is free on 0/0
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:170 (Tune) HDHRChan[10](1252CD2F): Tuning to auto:530000000
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:522 (TuneChannel) HDHRSH[10](1252CD2F): Not Re-Tuning channel auto:530000000
Dec 25 21:54:40 : I TVRecEvent recorders/dtvchannel.cpp:320 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(25): success
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3735 (TuningFrequency) TVRec[10]: Starting Signal Monitor
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:1977 (SetupSignalMonitor) TVRec[10]: SetupSignalMonitor(1, 0)
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:56 (Open) HDHRChan[10](1252CD2F): Opening HDHR channel
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrsignalmonitor.cpp:50 (HDHRSignalMonitor) HDHRSigMon[10](1252CD2F): ctor
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:54 (Get) HDHRSH[10]: Using existing stream handler 10 for 1252CD2F (2 in use)
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:2001 (SetupSignalMonitor) TVRec[10]: Signal monitor successfully created
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:1797 (SetupDTVSignalMonitor) TVRec[10]: Setting up table monitoring.
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4076 (LoadProfile) TVRec[10]: Using profile 'Live TV' to record
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:1872 (SetupDTVSignalMonitor) TVRec[10]: DVB service_id 28096 on net_id 9018 tsid 24640
Dec 25 21:54:40 : I TVRecEvent recorders/dtvsignalmonitor.cpp:231 (SetDVBService) DTVSigMon[10]: SetDVBService(transport_id: 24640, network_id: 9018, service_id: 28096) 
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:1894 (SetupDTVSignalMonitor) TVRec[10]: Successfully set up DVB table monitoring.
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4361 (SetFlags) TVRec[10]: SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,EITScannerRunning, @ tv_rec.cpp:3762
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[10]: ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,EITScannerRunning, @ tv_rec.cpp:3763
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4361 (SetFlags) TVRec[10]: SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,EITScannerRunning, @ tv_rec.cpp:3768
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[10]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,EITScannerRunning, @ tv_rec.cpp:3829
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3946 (TuningSignalCheck) TVRec[10]: TuningSignalCheck: Still waiting.  Will timeout @ 21:54:46.168
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[11]: Changing from RecordingOnly to None
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:1320
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3442 (HandleTuning) TVRec[11]: HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3511 (TuningShutdowns) TVRec[11]: TuningShutdowns(Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,))
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:1125 (TeardownRecorder) TVRec[11]: TeardownRecorder()
Dec 25 21:54:40 : I RecThread recorders/hdhrrecorder.cpp:141 (run) HDHRRec[11]: run -- ending...
Dec 25 21:54:40 : I RecThread recorders/streamhandler.cpp:82 (RemoveListener) SH[11]: RemoveListener(0x7fef3000ad08) -- begin
Dec 25 21:54:40 : I RecThread recorders/streamhandler.cpp:94 (RemoveListener) SH[11]: RemoveListener(0x7fef3000ad08) -- locked
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:186 (run) HDHRSH[11](1252CD2F): RunTS(): shutdown
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:203 (run) HDHRSH[11](1252CD2F): stream stats: packet_count=898736 network_errors=0 transport_errors=0 sequence_errors=0 overflow_errors=0
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:217 (run) HDHRSH[11](1252CD2F): RunTS(): end
Dec 25 21:54:40 : I RecThread recorders/streamhandler.cpp:111 (RemoveListener) SH[11]: RemoveListener(0x7fef3000ad08) -- end
Dec 25 21:54:40 : I RecThread recorders/hdhrrecorder.cpp:54 (Close) HDHRRec[11]: Close() -- begin
Dec 25 21:54:40 : I RecThread recorders/hdhrrecorder.cpp:60 (Close) HDHRRec[11]: Close() -- end
Dec 25 21:54:40 : I RecThread programinfo.cpp:4840 (SaveVideoProperties) SaveVideoProperties(0x04, 0x04)
Dec 25 21:54:40 : N RecThread recorders/recorderbase.cpp:492 (FinishRecording) Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (720x576 A/R: 3 25fps) Audio Codec: mp2
Dec 25 21:54:40 : I RecThread recorders/hdhrrecorder.cpp:155 (run) HDHRRec[11]: run -- end
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(NeedToStartRecorder,RecorderRunning,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:1139
Dec 25 21:54:40 : I TVRecEvent recordingquality.cpp:80 (RecordingQuality) RecordingQuality() start(2022-12-25T21:05:00Z) end(2022-12-25T21:54:40Z) score(1)
Dec 25 21:54:40 : I TVRecEvent recorders/recorderbase.cpp:97 (SetRecording) RecBase[11](1252CD2F): SetRecording(0x0)
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:841 (FinishedRecording) TVRec[11]: FinishedRecording(10003_2022-12-25T21:01:00Z) good recq:#012<RecordingQuality overall_score="1" key="10003_2022-12-25T21:01:00Z" continuity_error_count="0" packet_count="4384380" />
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:885 (FinishedRecording) TVRec[11]: FinishedRecording(10003_2022-12-25T21:01:00Z) Good quality#012#011#011#011title: Doc Martin Christmas Special#012#011#011#011in recgroup: Default status: Recording:Recorded not_dummy finished_now
Dec 25 21:54:40 : I TVRecEvent programinfo.cpp:4840 (SaveVideoProperties) SaveVideoProperties(0x6e1, 0x01)
Dec 25 21:54:40 : I TVRecEvent programinfo.cpp:6390 (GetFilesize) ProgramInfo(10003_20221225210100.ts): RI Filesize=0, DB Filesize=836358232
Dec 25 21:54:40 : I TVRecEvent recordinginfo.cpp:1251 (FinishedRecording) Finished recording Doc Martin Christmas Special: channel 10003
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:955 (FinishedRecording) TVRec[11]: FinishedRecording -- UPDATE_RECORDING_STATUS: Recorded
Dec 25 21:54:40 : I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Doc Martin Christmas Special" on cardid [11] (Recording => Recorded)
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:79 (Close) HDHRChan[11](1252CD2F): Closing HDHR channel
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:83 (Return) HDHRSH[11]: Closing handler for 11
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrstreamhandler.cpp:527 (TuneChannel) HDHRSH[11](1252CD2F): Tuning channel none (was auto:514000000)
Dec 25 21:54:40 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK -3 5776 0 UpdateRecStatus2 | Doc Martin Christmas Special |  | The very last episode of the popular comedy-drama series. The village of Portwenn is alive with festive cheer until Martin has its grotto shut down, so Louisa must save the day. | www.itv.com/1002148898
Dec 25 21:54:40 : I TVRecEvent recorders/hdhrchannel.cpp:79 (Close) HDHRChan[11](1252CD2F): Closing HDHR channel
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:3572 (TuningShutdowns) TVRec[11]: Tearing down RingBuffer
Dec 25 21:54:40 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3578
Dec 25 21:54:40 : I ProcessRequest tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:736
Dec 25 21:54:40 : I ProcessRequest tv_rec.cpp:707 (SetRecordingStatus) TVRec[11]: SetRecordingStatus(Recording->Unknown) on line 738
Dec 25 21:54:40 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 26 items in 0.0 = 0.00 match + 0.00 check + 0.01 place
Dec 25 21:54:40 : I SignalMonitor recorders/hdhrsignalmonitor.cpp:155 (UpdateValues) HDHRSigMon[10](1252CD2F): UpdateValues -- Signal Locked
Dec 25 21:54:40 : I SignalMonitor recorders/streamhandler.cpp:40 (AddListener) SH[10]: AddListener(0x7fef381168d8) -- begin
Dec 25 21:54:40 : I SignalMonitor recorders/streamhandler.cpp:52 (AddListener) SH[10]: AddListener(0x7fef381168d8) -- locked
Dec 25 21:54:40 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:132 (run) HDHRSH[10](1252CD2F): RunTS(): begin
Dec 25 21:54:40 : I SignalMonitor recorders/streamhandler.cpp:74 (AddListener) SH[10]: AddListener(0x7fef381168d8) -- end
Dec 25 21:54:41 : I HDHRStreamHandler mpeg/mpegtables.cpp:463 (Create) Created PMT #012Program Map Section#012  PSIP tableID(0x2) length(75) extension(0x1)#012       version(14) current(1) section(0) last_section(0)#012       pnum(1) pid(0x40f) pcrpid(0x2d1)#012  Stream #0 pid(0x2d1) type(0x02 video-mpeg2)#012    Stream Identifier Descriptor (0x52): ComponentTag=0x1#012  Stream #1 pid(0x2d2) type(0x03 audio-mp1-layer[1,2,3])#012    Stream Identifier Descriptor (0x52): ComponentTag=0x2#012    ISO-639 Language: code(eng) canonical(eng) eng(English)#012    SupplementaryAudioDescriptor (0x7f 0x06) length(2)#012      mix_type(0) editorial_classification(1)#012      language_code_present(1) Dumping#012      000  06 82                                             |..|#012  Stream #2 pid(0x2d4) type(0x03 audio-mp1-layer[1,2,3])#012    Stream Identifier Descriptor (0x52): ComponentTag=0x4#012    ISO-639 Language: code(eng) canonical(eng) eng(English)#012    SupplementaryAudioDescriptor (0x7f 0x06) length(2)#012      mix_type(0) editorial_classification(3)#012      language_code_present(0) Dumping#012      000  06 06                                             |..|#012  Stream #3 pid(0x2d3) type(0x06 private-data)#012    Stream Identifier Descriptor (0x52): ComponentTag=0x3#012    Subtitling Descriptor tag(0x59) length(8)#012      type(0x10) composition_page_id(2) ancillary_page_id(2) lang(eng)
Dec 25 21:54:41 : I HDHRStreamHandler recorders/dtvsignalmonitor.cpp:537 (HandleSDT) DTVSigMon[10]: HandleSDT() tsid = 24640 orig_net_id = 9018
Dec 25 21:54:41 : I TVRecEvent tv_rec.cpp:3857 (TuningSignalCheck) TVRec[10]: TuningSignalCheck: Good signal
Dec 25 21:54:41 : I TVRecEvent tv_rec.cpp:707 (SetRecordingStatus) TVRec[10]: SetRecordingStatus(Recording->Recording) on line 3955
Dec 25 21:54:41 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[10]: ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,EITScannerRunning, @ tv_rec.cpp:3983
Dec 25 21:54:41 : I TVRecEvent eitscanner.cpp:196 (StartEITEventProcessing) EITScanner[10]: Start processing EIT events in active scan for channel 25 chanid 10025
Dec 25 21:54:41 : I ProcessRequest mainserver.cpp:1811 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Dec 25 21:54:41 : I ProcessRequest mainserver.cpp:1813 (HandleAnnounce) MainServer: adding: myth2(561d32ed3620) as a client (events: 0)
Dec 25 21:54:41 : I ProcessRequest mainserver.cpp:1811 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Dec 25 21:54:41 : I ProcessRequest mainserver.cpp:1813 (HandleAnnounce) MainServer: adding: myth2(561d32f19080) as a client (events: 1)
Dec 25 21:54:42 : I HDHRStreamHandler recorders/dtvsignalmonitor.cpp:537 (HandleSDT) DTVSigMon[10]: HandleSDT() tsid = 24640 orig_net_id = 9018
Dec 25 21:54:42 : I EIT eithelper.cpp:108 (ProcessEvents) EITHelper[10]: Added 1 events
Dec 25 21:54:43 : I EIT eithelper.cpp:108 (ProcessEvents) EITHelper[10]: Added 1 events
Dec 25 21:54:43 : I HDHRStreamHandler recorders/dtvsignalmonitor.cpp:506 (HandleNIT) DTVSigMon[10]: HandleNIT() net_id = 12339
Dec 25 21:54:47 : I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for PLACE Reactivate
Dec 25 21:54:47 : I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 26 items in 0.0 = 0.00 match + 0.00 check + 0.01 place
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:305 (RecordPending) TVRec[11]: RecordPending on inputid [11]
Dec 25 21:54:47 : I Scheduler cardutil.cpp:2167 (GetConflictingInputs) CardUtil[11]: GetConflictingInputs(11) 17,18,19
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:305 (RecordPending) TVRec[17]: RecordPending on inputid [11]
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:305 (RecordPending) TVRec[18]: RecordPending on inputid [11]
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:305 (RecordPending) TVRec[19]: RecordPending on inputid [11]
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:417 (StartRecording) TVRec[11]: StartRecording("Doc Martin Christmas Special")
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:707 (SetRecordingStatus) TVRec[11]: SetRecordingStatus(Unknown->Aborted) on line 423
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:487 (StartRecording) TVRec[11]: Checking input group recorders - begin
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:561 (StartRecording) TVRec[11]: Checking input group recorders - done
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:809 (StartedRecording) TVRec[11]: StartedRecording(10003_2022-12-25T21:55:00Z) fn(/var/lib/mythtv/recordings/10003_20221225215500.ts)
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:4076 (LoadProfile) TVRec[11]: Using profile 'Default' to record
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(CancelNextRecording,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:606
Dec 25 21:54:47 : I Scheduler tv_rec.cpp:707 (SetRecordingStatus) TVRec[11]: SetRecordingStatus(Aborted->Tuning) on line 609
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[11]: Changing from None to RecordingOnly
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:1320
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:3442 (HandleTuning) TVRec[11]: HandleTuning Request: Program(ProgramInfo(10003_20221225215500.ts): channame(ITV1)#012             startts(Sun Dec 25 21:05:00 2022 GMT) endts(Sun Dec 25 22:35:00 2022 GMT)#012             recstartts(Sun Dec 25 21:55:00 2022 GMT) recendts(Sun Dec 25 22:37:00 2022 GMT)#012             title(Doc Martin Christmas Special)) channel() input() flags(Recording,)
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:3511 (TuningShutdowns) TVRec[11]: TuningShutdowns(Program(ProgramInfo(10003_20221225215500.ts): channame(ITV1)#012             startts(Sun Dec 25 21:05:00 2022 GMT) endts(Sun Dec 25 22:35:00 2022 GMT)#012             recstartts(Sun Dec 25 21:55:00 2022 GMT) recendts(Sun Dec 25 22:37:00 2022 GMT)#012             title(Doc Martin Christmas Special)) channel(3) input(None) flags(Recording,))
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3578
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:3464 (HandleTuning) TVRec[11]: No recorder yet, calling TuningFrequency
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[11]: TuningFrequency
Dec 25 21:54:47 : I TVRecEvent recorders/dtvchannel.cpp:159 (SetChannelByString) DTVChan[11](1252CD2F): SetChannelByString(3): 
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrchannel.cpp:56 (Open) HDHRChan[11](1252CD2F): Opening HDHR channel
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[11](1252CD2F): Added 4 devices from 1252CD2F
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[11](1252CD2F): Connected to device(1252CD2F-1)
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrstreamhandler.cpp:46 (Get) HDHRSH[11]: Creating new stream handler 11 for 1252CD2F
Dec 25 21:54:47 : I TVRecEvent recorders/channelbase.cpp:609 (InitializeInput) ChannelBase[11]: Input #11: 'None' schan(1) sourceid(1)
Dec 25 21:54:47 : I TVRecEvent cardutil.cpp:2167 (GetConflictingInputs) CardUtil[11]: GetConflictingInputs(11) 17,18,19
Dec 25 21:54:47 : I TVRecEvent recorders/channelbase.cpp:253 (IsInputAvailable) ChannelBase[11]: Input is free on 0/0
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrchannel.cpp:170 (Tune) HDHRChan[11](1252CD2F): Tuning to auto:514000000
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrstreamhandler.cpp:527 (TuneChannel) HDHRSH[11](1252CD2F): Tuning channel auto:514000000 (was none)
Dec 25 21:54:47 : I TVRecEvent recorders/dtvchannel.cpp:320 (SetChannelByString) DTVChan[11](1252CD2F): SetChannelByString(3): success
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrchannel.cpp:56 (Open) HDHRChan[11](1252CD2F): Opening HDHR channel
Dec 25 21:54:47 : I TVRecEvent recorders/dtvchannel.cpp:159 (SetChannelByString) DTVChan[11](1252CD2F): SetChannelByString(3): 
Dec 25 21:54:47 : I TVRecEvent cardutil.cpp:2167 (GetConflictingInputs) CardUtil[11]: GetConflictingInputs(11) 17,18,19
Dec 25 21:54:47 : I TVRecEvent recorders/channelbase.cpp:253 (IsInputAvailable) ChannelBase[11]: Input is free on 0/0
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrchannel.cpp:170 (Tune) HDHRChan[11](1252CD2F): Tuning to auto:514000000
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrstreamhandler.cpp:522 (TuneChannel) HDHRSH[11](1252CD2F): Not Re-Tuning channel auto:514000000
Dec 25 21:54:47 : I TVRecEvent recorders/dtvchannel.cpp:320 (SetChannelByString) DTVChan[11](1252CD2F): SetChannelByString(3): success
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:3735 (TuningFrequency) TVRec[11]: Starting Signal Monitor
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:1977 (SetupSignalMonitor) TVRec[11]: SetupSignalMonitor(1, 0)
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrchannel.cpp:56 (Open) HDHRChan[11](1252CD2F): Opening HDHR channel
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrsignalmonitor.cpp:50 (HDHRSignalMonitor) HDHRSigMon[11](1252CD2F): ctor
Dec 25 21:54:47 : I TVRecEvent recorders/hdhrstreamhandler.cpp:54 (Get) HDHRSH[11]: Using existing stream handler 11 for 1252CD2F (2 in use)
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:2001 (SetupSignalMonitor) TVRec[11]: Signal monitor successfully created
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:1797 (SetupDTVSignalMonitor) TVRec[11]: Setting up table monitoring.
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4076 (LoadProfile) TVRec[11]: Using profile 'Live TV' to record
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:1872 (SetupDTVSignalMonitor) TVRec[11]: DVB service_id 8261 on net_id 9018 tsid 8197
Dec 25 21:54:47 : I TVRecEvent recorders/dtvsignalmonitor.cpp:231 (SetDVBService) DTVSigMon[11]: SetDVBService(transport_id: 8197, network_id: 9018, service_id: 8261) 
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:1894 (SetupDTVSignalMonitor) TVRec[11]: Successfully set up DVB table monitoring.
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4361 (SetFlags) TVRec[11]: SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3762
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3763
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4361 (SetFlags) TVRec[11]: SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3768
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4370 (ClearFlags) TVRec[11]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3829
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:4361 (SetFlags) TVRec[11]: SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3831
Dec 25 21:54:47 : I TVRecEvent tv_rec.cpp:3946 (TuningSignalCheck) TVRec[11]: TuningSignalCheck: Still waiting.  Will timeout @ 22:36:50.000
Dec 25 21:54:47 : I Scheduler scheduler.cpp:2899 (HandleRecordingStatusChange) Tuning recording: "Doc Martin Christmas Special": channel 10003 on cardid [11], sourceid 1
Dec 25 21:54:47 : I SignalMonitor recorders/hdhrsignalmonitor.cpp:155 (UpdateValues) HDHRSigMon[11](1252CD2F): UpdateValues -- Signal Locked
Dec 25 21:54:47 : I SignalMonitor recorders/streamhandler.cpp:40 (AddListener) SH[11]: AddListener(0x7fef3000ad08) -- begin
Dec 25 21:54:47 : I SignalMonitor recorders/streamhandler.cpp:52 (AddListener) SH[11]: AddListener(0x7fef3000ad08) -- locked
Dec 25 21:54:47 : I HDHRStreamHandler recorders/hdhrstreamhandler.cpp:132 (run) HDHRSH[11](1252CD2F): RunTS(): begin
Dec 25 21:54:47 : I SignalMonitor recorders/streamhandler.cpp:74 (AddListener) SH[11]: AddListener(0x7fef3000ad08) -- end
User avatar
kmdewaal
Developer
Posts: 641
Joined: Wed Dec 07, 2016 8:01 pm
Netherlands

Re: Quad HDHR single tuner freezing.

Post by kmdewaal »

The log looks OK to me. It shows EIT channel change on input 10 and on input 11 the end of a recording and the start of a new recording. There is no indication of hardware failure.

Given that there is no recording but that the guide says it should still be recording it is correct that a new recording is started This means that the only issue is why does the first recording stop.

When all the hardware is working OK then the EIT channel change on input 10 should be completely independent of other recordings on input 11.
However, it can be that the EIT is changing the guide data of the program that is being recorded. I sometimes get duplicate recordings because of this.
To analyze what EIT is doing the EIT logging must be set to debug as in "-v channel,eit:debug" and this will generate really large logs, but not too large to be sent with wetransfer.com.

If the guide data is modified by external scripts, i.e. to merge two parts of what is really one program, then you can get behavior as described here when the EIT changes the merged program back to two parts.

Hope this helps,
Klaas.
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

yes, a great help. EIT data in UK has been pretty unreliable this year, though this time they do not have the excuse of Wimbledon, Woman's football, Qatar, the Queen etc.
The 'old' mythtv server which I'm trying to decommision runs mythwelcome and it started late at just before 10pm - another symptom of bad EIT.
Thanks Klaas,
Phil
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

I have finally caught a backend log with a failing recording resulting in a tuner lockup.

To recap: HDHR quad tuner connected via gigabit ether switch to the combined front/backend on an i3 NUC with 4GB of 'RAM'. The only other device on that switch is a Brother printer which may have 'phoned home' but was otherwise not in use.

The backend has recording priorities set in order 11,12,13,10. 10 has active EIT tuning but with multirec at 4/tuner I never expect a recording to be made from 10. I don't use 'live TV' in mythtv.

Tuner timeout is set at a huge 15 secs after a single failure a few weeks ago which did not lock the tuner. Previous suspicion was an interaction between active EIT grabbing and recording but this incident seems to exonerate EIT.

Disclosure: Recordings are held on a usb caddy which 'spins down' but I have not found a mechanism to spin it up just before a recording. I don't think it relevant though.

This is the log (columns sed'ed out). Note the EIT grabbing on [10], the failure on [11] and a good recording on [12].

End of successful previous recording on [11]:

Code: Select all

Jan 23 15:50:00 [1401]: I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[11]: Changing from RecordingOnly to None
Jan 23 15:50:00 [1401]: N RecThread recorders/recorderbase.cpp:492 (FinishRecording) Finished Recording: Container: MPEG2-TS Video Codec: mpeg2video (704x576 A/R: 3 25fps) Audio Codec: mp2
Jan 23 15:50:00 [1401]: I TVRecEvent recordinginfo.cpp:1251 (FinishedRecording) Finished recording Escape to the Country "It's destination Argyll and Bute today": channel 10001
Jan 23 15:50:00 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Escape to the Country":"It's destination Argyll and Bute today" on cardid [11] (Recording => Recorded)
Jan 23 15:50:00 [1401]: I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK -3 4159 0 UpdateRecStatus2 | Escape to the Country | It's destination Argyll and Bute today | Sonali Shah tours this region of Scotland in search of a new home for a couple from a Warwickshire town who have a budget of £340,000. | fp.bbc.co.uk/m/tphq
Jan 23 15:50:00 [1401]: I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.1 = 0.01 match + 0.03 check + 0.02 place
Failure of next recording on [11] at 20:56:10

Code: Select all

Jan 23 20:55:00 [1401]: I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for PLACE PrepareToRecord
Jan 23 20:55:00 [1401]: I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.0 = 0.00 match + 0.00 check + 0.02 place
Jan 23 20:55:11 [1401]: E TVRecEvent tv_rec.cpp:3891 (TuningSignalCheck) TVRec[10]: TuningSignalCheck: SignalMonitor timed out
Jan 23 20:55:11 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[10]: TuningFrequency
Jan 23 20:55:11 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[10](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:55:11 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[10](1252CD2F): Connected to device(1252CD2F-0)
Jan 23 20:55:11 [1401]: E TVRecEvent channelutil.cpp:1964 (GetChannelData) Could not find channel '' in DB for source '1'.
Jan 23 20:55:11 [1401]: E TVRecEvent recorders/dtvchannel.cpp:209 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(): Unable to find channel in database.
Jan 23 20:55:11 [1401]: E TVRecEvent tv_rec.cpp:3672 (TuningFrequency) TVRec[10]: Failed to set channel to . Reverting to kState_None
Jan 23 20:55:30 [1401]: I Scheduler mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 13
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[11]: ASK_RECORDING 11 149 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[17]: ASK_RECORDING 17 149 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[19]: ASK_RECORDING 19 149 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[22]: ASK_RECORDING 22 148 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[21]: ASK_RECORDING 21 148 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[12]: ASK_RECORDING 12 148 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[18]: ASK_RECORDING 18 149 0 0
Jan 23 20:55:30 [1401]: I TVRecEvent tv_rec.cpp:1648 (HandlePendingRecordings) TVRec[20]: ASK_RECORDING 20 148 0 0
Jan 23 20:56:00 [1401]: I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[11]: Changing from None to RecordingOnly
Jan 23 20:56:00 [1401]: I TVRecEvent mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 13
Jan 23 20:56:00 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[11]: TuningFrequency
Jan 23 20:56:00 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[11](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:56:00 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[11](1252CD2F): Connected to device(1252CD2F-0)
Jan 23 20:56:00 [1401]: I Scheduler scheduler.cpp:2899 (HandleRecordingStatusChange) Tuning recording: "Silent Witness": channel 10001 on cardid [11], sourceid 1
Jan 23 20:56:00 [1401]: I TVRecEvent tv_rec.cpp:1077 (HandleStateChange) TVRec[12]: Changing from None to RecordingOnly
Jan 23 20:56:00 [1401]: I TVRecEvent mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 13
Jan 23 20:56:00 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[12]: TuningFrequency
Jan 23 20:56:00 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[12](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:56:00 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[12](1252CD2F): Connected to device(1252CD2F-1)
Jan 23 20:56:00 [1401]: I Scheduler scheduler.cpp:2899 (HandleRecordingStatusChange) Tuning recording: Maternal: channel 10003 on cardid [12], sourceid 1
Jan 23 20:56:00 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for Maternal on cardid [12] (Tuning => Recording)
Jan 23 20:56:00 [1401]: I CoreContext mythdbcon.cpp:423 (PurgeIdleConnections) New DB connection, total: 13
Jan 23 20:56:00 [1401]: I TVRecEvent tv_rec.cpp:4146 (TuningNewRecorder) TVRec[12]: rec->GetPathname(): '/var/lib/mythtv/recordings/10003_20230123205600.ts'
Jan 23 20:56:00 [1401]: I TVRecEvent tv_rec.cpp:4179 (TuningNewRecorder) TVRec[12]: TuningNewRecorder - CreateRecorder()
Jan 23 20:56:01 [1401]: I CoreContext mythsystemevent.cpp:314 (customEvent) MythSystemEventHandler: Starting thread for command 'sleep 10 && /usr/local/bin/checkfilm.pl -v --chanid=10003 --desc=Maternal>> /var/log/mythtv/checkfilm.log 2>&1'
Jan 23 20:56:07 [1401]: W TFWWrite threadedfilewriter.cpp:547 (DiskLoop) TFW(/var/lib/mythtv/recordings/10003_20230123205600.ts:85): write(65424) cnt 19 total 1195304 -- took a long time, 6113 ms
Jan 23 20:56:10 [1401]: E TVRecEvent tv_rec.cpp:3904 (TuningSignalCheck) TVRec[11]: TuningSignalCheck: Hit pre-fail timeout
Jan 23 20:56:11 [1401]: I SystemEvent mythsystemevent.cpp:50 (run) MythSystemEventHandler: Finished 'sleep 10 && /usr/local/bin/checkfilm.pl -v --chanid=10003 --desc=Maternal>> /var/log/mythtv/checkfilm.log 2>&1' result 0
Jan 23 20:56:15 [1401]: W TVRecEvent tv_rec.cpp:3932 (TuningSignalCheck) TVRec[11]: TuningSignalCheck: taking more than 15000 ms to get a lock. marking this recording as 'Failing'.
Jan 23 20:56:15 [1401]: W TVRecEvent tv_rec.cpp:3937 (TuningSignalCheck) TVRec[11]: See 'Tuning timeout' in mythtv-setup for this input
Jan 23 20:56:15 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Silent Witness" on cardid [11] (Tuning => Failing)
Jan 23 20:56:15 [1401]: I Scheduler scheduler.cpp:2330 (HandleReschedule) Reschedule requested for CHECK -14 3782 0 UpdateRecStatus2 | Silent Witness |  | A train crash and a man cut in half expose deep rifts on a country estate. Contains some scenes which some viewers may find upsetting. | fp.bbc.co.uk/m/tpiy
Jan 23 20:56:15 [1401]: I Scheduler scheduler.cpp:2444 (HandleReschedule) Scheduled 41 items in 0.0 = 0.00 match + 0.01 check + 0.02 place
Jan 23 20:57:12 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[10]: TuningFrequency
Jan 23 20:57:12 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[10](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:57:12 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[10](1252CD2F): Connected to device(1252CD2F-0)
Jan 23 20:57:27 [1401]: E TVRecEvent tv_rec.cpp:3891 (TuningSignalCheck) TVRec[10]: TuningSignalCheck: SignalMonitor timed out
Jan 23 20:57:28 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[10]: TuningFrequency
Jan 23 20:57:28 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[10](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:57:28 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[10](1252CD2F): Connected to device(1252CD2F-0)
Jan 23 20:57:28 [1401]: E TVRecEvent channelutil.cpp:1964 (GetChannelData) Could not find channel '' in DB for source '1'.
Jan 23 20:57:28 [1401]: E TVRecEvent recorders/dtvchannel.cpp:209 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(): Unable to find channel in database.
Jan 23 20:57:28 [1401]: E TVRecEvent tv_rec.cpp:3672 (TuningFrequency) TVRec[10]: Failed to set channel to . Reverting to kState_None
Jan 23 20:59:25 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[10]: TuningFrequency
Jan 23 20:59:25 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[10](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:59:25 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[10](1252CD2F): Connected to device(1252CD2F-0)
Jan 23 20:59:40 [1401]: E TVRecEvent tv_rec.cpp:3891 (TuningSignalCheck) TVRec[10]: TuningSignalCheck: SignalMonitor timed out
Jan 23 20:59:40 [1401]: I TVRecEvent tv_rec.cpp:3600 (TuningFrequency) TVRec[10]: TuningFrequency
Jan 23 20:59:40 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:393 (Connect) HDHRSH[10](1252CD2F): Added 4 devices from 1252CD2F
Jan 23 20:59:41 [1401]: I TVRecEvent recorders/hdhrstreamhandler.cpp:410 (Connect) HDHRSH[10](1252CD2F): Connected to device(1252CD2F-0)
Jan 23 20:59:41 [1401]: E TVRecEvent channelutil.cpp:1964 (GetChannelData) Could not find channel '' in DB for source '1'.
Jan 23 20:59:41 [1401]: E TVRecEvent recorders/dtvchannel.cpp:209 (SetChannelByString) DTVChan[10](1252CD2F): SetChannelByString(): Unable to find channel in database.
Jan 23 20:59:41 [1401]: E TVRecEvent tv_rec.cpp:3672 (TuningFrequency) TVRec[10]: Failed to set channel to . Reverting to kState_None
After 20:56, tuner 11 seems to be stuck:

Code: Select all

Jan 23 14:56:01 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Escape to the Country":"It's destination Argyll and Bute today" on cardid [11] (Tuning => Recording)
Jan 23 15:50:00 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Escape to the Country":"It's destination Argyll and Bute today" on cardid [11] (Recording => Recorded)
Jan 23 20:56:00 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for Maternal on cardid [12] (Tuning => Recording)
Jan 23 20:56:15 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Silent Witness" on cardid [11] (Tuning => Failing)
Jan 23 22:01:50 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Silent Witness" on cardid [11] (Failing => Recorder Failed)
Jan 23 22:05:00 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for Maternal on cardid [12] (Recording => Recorded)
Jan 23 23:16:15 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for Hustle:"Eat Yourself Slender" on cardid [11] (Tuning => Failing)
Jan 24 00:41:50 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for Hustle:"Eat Yourself Slender" on cardid [11] (Failing => Recorder Failed)
Jan 24 14:56:15 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Escape to the Country" on cardid [11] (Tuning => Failing)
Jan 24 15:46:50 [1401]: I CoreContext scheduler.cpp:717 (UpdateRecStatus) Updating status for "Escape to the Country" on cardid [11] (Failing => Recorder Failed)
This is what the tuner is telling me:

Code: Select all

phil@myth2:~/temp$ hdhomerun_config FFFFFFFF get /tuner0/status
ch=none lock=none ss=0 snq=0 seq=0 bps=0 pps=0
Ditto for tuners 1,2 and 3
I got it going again by restarting the backend (which with my setup triggers a tuner reboot).
Previous experience is that it's the tuner reboot not the backend restart which is necessary.

I'd appreciate any observations on this.

Phil
User avatar
kmdewaal
Developer
Posts: 641
Joined: Wed Dec 07, 2016 8:01 pm
Netherlands

Re: Quad HDHR single tuner freezing.

Post by kmdewaal »

There are two recordings started on 20:56:00, one on tuner 11 and one on tuner 12. The recording on tuner 11 then fails.

All HDHR tuners are seen as independent (well, mostly) and it could just be that the HDHR is getting confused by receiving two tuning requests simultaneously. I am pretty sure that there is some locking implemented but maybe this needs to be revisited. It could also be that we need a waiting time after each tuning request. This is done for multiple requests on a single tuner but it might be needed for the combination of the tuning requests on all tuners of a single HDHR.

If this theory is correct then it should be possible to reproduce the problem by scheduling recordings starting at the same time.
PhilB
Senior
Posts: 403
Joined: Sun May 11, 2014 6:23 pm
Great Britain

Re: Quad HDHR single tuner freezing.

Post by PhilB »

Thanks Klaas,
I have many instances of two or more recordings starting simultaneously without failing. Many of these involved different tuners.
I have only had two instances of this type of failure in the last month (no logs left before that) so reproducing the fault is tricky.
Both these failures involved simultaneous recordings from different multiplexes/tuners which is consistent with your thoughts. Both caused the first triggered to fail.

If I can provoke the fault again either on different tuners (or all on the same!), would more diagnostics help anyway?

Do you think that the disk spin-up delay is not relevant, or should I be looking at running a job to 'touch' a file on it just before a recording starts?
And is 'Added 4 devices from 1252CD2F' normal?

Phil
User avatar
kmdewaal
Developer
Posts: 641
Joined: Wed Dec 07, 2016 8:01 pm
Netherlands

Re: Quad HDHR single tuner freezing.

Post by kmdewaal »

Hi Phil,
Do you think that the disk spin-up delay is not relevant, or should I be looking at running a job to 'touch' a file on it just before a recording starts?
I do not think this matters because data is buffered in memory first, but on the other hand on my systems the disks are spinning all the time so it is a difference.
And is 'Added 4 devices from 1252CD2F' normal?
Yes

It would help if the problem is easily triggered and if I can reproduce it here on my HDHR. If the hypothesis that it is caused by simultaneous tuning requests is correct then a script that generates lots of simultaneous tuning requests would be useful.
E.g. a script that would do the following:
- create a set of manual recordings
- one set is then four recordings on different multiplexes starting at the same time
- this can be very short recordings, e.g. 1 minutes or so
- then the next set of recordings starting at 5 minutes after the previous set
- repeat for a number of times.
If the cause is really the tuning requests then such a script should trigger it.
Would it be possible for you to have a go at a script that does this?

Thanks,
Klaas.
Post Reply