search

garybuhrmaster / mythhdhrrecorder

MythTV External Recorder for the SiliconDust HDHR tuners
Apache License 2.0
8 stars 1 forks source link

"stream FIFO queue full, dropped chunk of " #3

Open dlasher opened 2 years ago

dlasher commented 2 years ago

Love the project, works almost perfectly, ran into my first odd issue tonight.

All recordings were failing, HDHR's were up, pingable, web interface was up.

Feb 24 21:09:27 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 340844 bytes Feb 24 21:09:31 backend1 mythhdhrrecorder[1002441]: message repeated 6 times: [ stream FIFO queue full, dropped chunk of 340844 bytes]

That was spammed repeatedly in the logs. Digging back through the logs, it looks like it started with a recording at 14:00:

Feb 24 13:00:00 backend1 mythhdhrrecorder[590427]: Streaming stopped Feb 24 13:00:00 backend1 mythhdhrrecorder[590427]: Recorder stopping Feb 24 13:00:00 backend1 mythhdhrrecorder[590427]: Recorder stopped Feb 24 13:00:00 backend1 mythhdhrrecorder[920006]: Recorder starting, args: --hdhr 10.4.11.206 --devicename Comcast2c -v general --syslog daemon --verbose general --loglevel info --quiet --syslog local7 Feb 24 13:00:01 backend1 mythhdhrrecorder[920006]: Tuner at IP address 10.4.11.206 added to the eligible list by explicit user request Feb 24 13:00:01 backend1 mythhdhrrecorder[920006]: Tuner at IP address 10.4.11.206 has 425 enabled channels Feb 24 13:00:01 backend1 mythhdhrrecorder[920006]: Tuning request for channel 729 accepted Feb 24 13:00:01 backend1 mythhdhrrecorder[920006]: Tuning in progress Feb 24 13:00:01 backend1 mythhdhrrecorder[920006]: Tuning in progress Feb 24 13:00:02 backend1 mythhdhrrecorder[920006]: message repeated 8 times: [ Tuning in progress] Feb 24 13:00:02 backend1 mythhdhrrecorder[920006]: Tuning successful, connection 10.4.11.100:41446 -> 10.4.11.206:5004, tuner tuner0 Feb 24 13:00:02 backend1 mythhdhrrecorder[920006]: Streaming started Feb 24 14:00:00 backend1 mythhdhrrecorder[919133]: Streaming stopped Feb 24 14:00:00 backend1 mythhdhrrecorder[919133]: Recorder stopping Feb 24 14:00:00 backend1 mythhdhrrecorder[919133]: Recorder stopped

all good up to here

Feb 24 14:00:00 backend1 mythhdhrrecorder[1002441]: Recorder starting, args: --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon --verbose general --loglevel info --quiet --syslog local7 Feb 24 14:00:01 backend1 mythhdhrrecorder[1002441]: Tuner at IP address 10.4.11.206 added to the eligible list by explicit user request Feb 24 14:00:01 backend1 mythhdhrrecorder[1002441]: Tuner at IP address 10.4.11.206 has 425 enabled channels Feb 24 14:00:01 backend1 mythhdhrrecorder[1002441]: Tuning request for channel 748 accepted Feb 24 14:00:01 backend1 mythhdhrrecorder[1002441]: Tuning in progress Feb 24 14:00:01 backend1 mythhdhrrecorder[1002441]: Tuning in progress Feb 24 14:00:02 backend1 mythhdhrrecorder[1002441]: message repeated 10 times: [ Tuning in progress] Feb 24 14:00:02 backend1 mythhdhrrecorder[1002441]: Tuning successful, connection 10.4.11.100:34446 -> 10.4.11.206:5004, tuner tuner1 Feb 24 14:00:02 backend1 mythhdhrrecorder[1002441]: Streaming started Feb 24 14:01:11 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 214508 bytes Feb 24 14:01:12 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 235564 bytes Feb 24 14:01:12 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 257936 bytes Feb 24 14:01:13 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 282940 bytes Feb 24 14:01:14 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 310576 bytes Feb 24 14:01:47 backend1 mythhdhrrecorder[1002441]: message repeated 50 times: [ stream FIFO queue full, dropped chunk of 310576 bytes] Feb 24 14:01:48 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 310576 bytes Feb 24 14:01:58 backend1 mythhdhrrecorder[1002441]: message repeated 15 times: [ stream FIFO queue full, dropped chunk of 310576 bytes] Feb 24 14:01:59 backend1 mythhdhrrecorder[1002441]: stream FIFO queue full, dropped chunk of 310576 bytes ** repeated again and again. Feb 24 16:00:30 backend1 mythhdhrrecorder[1002441]: message repeated 24 times: [ stream FIFO queue full, dropped chunk of 340844 bytes] Feb 24 16:00:30 backend1 mythhdhrrecorder[920006]: Streaming stopped Feb 24 16:00:30 backend1 mythhdhrrecorder[920006]: Recorder stopping Feb 24 16:00:30 backend1 mythhdhrrecorder[920006]: Recorder stopped

On a whim, I stopped the MythTV service, and then rebooted the backend.. Once it came back up, everything started up correctly.

So unfortunately that's all the data I have. Any ideas what went sideways? Connectivity was up, the backend was able to tune successfully?

garybuhrmaster commented 2 years ago

Any ideas what went sideways?

This logs are insufficient to provide any clear ideas, but the only time I have seen something like that happen is the backend itself is having issues (the recorder only provides that stream, it can't make the backend accept the stream).

I would first look at the backend (BE) logs themselves during that timeframe to see if there are any (interesting) entries during that timeframe, and if so, address them first. That restarting the backend "fixed" things suggests it was a BE related issue.

I will note that the developer who is responsible for the BE external recorder code has (over time) improved the external recorder to make it more robust/reliable, so do make sure you are running a recent supported version with all fixes.

dlasher commented 2 years ago

Hit again on the 15th.

Mar 15 18:59:30 backend1 mythhdhrrecorder[2172104]: Recorder starting, args: --hdhr 10.4.11.206 --devicename Comcast2c -v general --syslog daemon --verbose general --loglevel info --quiet --syslog local7 Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Tuner at IP address 10.4.11.206 added to the eligible list by explicit user request Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Tuner at IP address 10.4.11.206 has 425 enabled channels Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Tuning request for channel 729 accepted Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Tuning in progress Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Tuning in progress Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: message repeated 8 times: [ Tuning in progress] Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Tuning successful, connection 10.4.11.100:53518 -> 10.4.11.206:5004, tuner tuner0 Mar 15 18:59:31 backend1 mythhdhrrecorder[2172104]: Streaming started Mar 15 19:59:30 backend1 mythhdhrrecorder[2248249]: Recorder starting, args: --hdhr 10.4.11.206 --devicename Comcast2a -v general --syslog daemon --verbose general --loglevel info --quiet --syslog local7 Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Tuner at IP address 10.4.11.206 added to the eligible list by explicit user request Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Tuner at IP address 10.4.11.206 has 425 enabled channels Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Tuning request for channel 748 accepted Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Tuning in progress Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Tuning in progress Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: message repeated 9 times: [ Tuning in progress] Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Tuning successful, connection 10.4.11.100:42674 -> 10.4.11.206:5004, tuner tuner1 Mar 15 19:59:31 backend1 mythhdhrrecorder[2248249]: Streaming started Mar 15 20:59:30 backend1 mythhdhrrecorder[2324425]: Recorder starting, args: --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon --verbose general --loglevel info --quiet --syslog local7 Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuner at IP address 10.4.11.206 added to the eligible list by explicit user request Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuner at IP address 10.4.11.206 has 425 enabled channels Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuning request for channel 708 accepted Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuning in progress Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuning in progress Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuning in progress Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: message repeated 7 times: [ Tuning in progress] Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Tuning successful, connection 10.4.11.100:60084 -> 10.4.11.206:5004, tuner tuner2 Mar 15 20:59:31 backend1 mythhdhrrecorder[2324425]: Streaming started Mar 15 21:01:00 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 659316 bytes Mar 15 21:01:01 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:02 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:03 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:04 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:05 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:05 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:06 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:07 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:08 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:09 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:10 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:10 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:11 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:12 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes Mar 15 21:01:13 backend1 mythhdhrrecorder[2324425]: stream FIFO queue full, dropped chunk of 725116 bytes

I noted that this is the recorder failing.

Myth Backend seems fine: Mar 15 20:59:30 backend1 mythbackend: mythbackend[698]: I TVRecEvent tv_rec.cpp:1090 (HandleStateChange) TVRec[12]: Changing from None to RecordingOnly Mar 15 20:59:30 backend1 mythbackend: mythbackend[698]: I TVRecEvent mythdbcon.cpp:431 (PurgeIdleConnections) New DB connection, total: 15 Mar 15 20:59:30 backend1 mythbackend: mythbackend[698]: I TVRecEvent tv_rec.cpp:3665 (TuningFrequency) TVRec[12]: TuningFrequency Mar 15 20:59:30 backend1 mythbackend: mythbackend[698]: C CoreContext programinfo.cpp:340 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0. Mar 15 20:59:31 backend1 mythbackend: mythbackend[698]: I Scheduler scheduler.cpp:2923 (HandleRecordingStatusChange) Tuning recording: "This Is Us":"The Guitar Man": channel 2708 on cardid [12], sourceid 2 Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: E ExternSH recorders/dtvsignalmonitor.cpp:323 (HandlePAT) DTVSigMon[12](/usr/bin/mythhdhrrecorder --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon): Program #0 not found in PAT!#01 2Program Association Section#012 PSIP tableID(0x0) length(13) extension(0x0)#012 version(0) current(1) section(0) last_section(0)#012 tsid(0) programCount(1)#012 program number 7 has PID 0x0090 Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: E ExternSH recorders/dtvsignalmonitor.cpp:329 (HandlePAT) DTVSigMon[12](/usr/bin/mythhdhrrecorder --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon): But there is only one program in the PAT, so we'll just use it Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: N ExternSH recorders/dtvsignalmonitor.cpp:368 (HandlePMT) DTVSigMon[12](/usr/bin/mythhdhrrecorder --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon): PMT says program 7 is encrypted Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: I CoreContext scheduler.cpp:734 (UpdateRecStatus) Updating status for "This Is Us":"The Guitar Man" on cardid [12] (Tuning => Recording) Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: I TVRecEvent tv_rec.cpp:4204 (TuningNewRecorder) TVRec[12]: rec->GetPathname(): '/raid/myth/tv/2708_20220316040000.ts' Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: I TVRecEvent tv_rec.cpp:4236 (TuningNewRecorder) TVRec[12]: TuningNewRecorder - CreateRecorder() Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: E TVRecEvent recorders/recorderbase.cpp:232 (SetStrOption) RecBase[12](/usr/bin/mythhdhrrecorder --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon): SetStrOption(...recordingtype): Option not in profile. Mar 15 20:59:32 backend1 mythbackend: mythbackend[698]: E TVRecEvent recorders/recorderbase.cpp:222 (SetIntOption) RecBase[12](/usr/bin/mythhdhrrecorder --hdhr 10.4.11.206 --devicename Comcast2b -v general --syslog daemon): SetIntOption(...recordmpts): Opt ion not in profile. Mar 15 20:59:44 backend1 mythbackend: mythbackend[698]: I Metadata_78919 jobqueue.cpp:2157 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for "This Is Us":"The Guitar Man" recorded from channel 2708 at 2022-03-16T04:00:00Z

No END recording appears in the log, and there's never a menu entry for a recording. Vanished and gone.

While this failure is occurring, I can tune live TV on all tuners EXCEPT the "hung" one. Stopping the back end takes a LONG time, the delay is trying to kill the "hung" recording process.

Stopping/starting the MythTV-Backend DOES resolve the problem - however, next time I'm going to try killing the recording process first, see if it "clears" up.

For now I may have to add some sort of syslog monitoring for mythhdhrrecorder complaining about FIFO queues. Any other ideas?

dlasher commented 2 years ago

Running : 29.1+fixes.201909121531.4c432df~ubuntu18.04.1

garybuhrmaster commented 2 years ago

Any other ideas?

Unfortunately your BE logs did not extend to beyond the point where the external recorder indicated issues, although it is unclear that really matters.

You first step should almost certainly be to upgrade to a supported version of MythTV. v29 has not been supported for many years (the project itself basically supports the most recent release (v32 at the time of this post), and may, at its option, support the previous one with "critical" fixes, but one should not depend on it). v30 (released Jan 2019), and v31 (released in March 2020 ) and v32 (released in Februrary 2022) had, along the way, many fixes in the support of external recorders including a few hangs/stalls, but as with all major MythTV upgrades, there is a lot more fixes along the way.

I do not use ubuntu, but I believe the mythbuntu ppa provides the upgraded versions (you may want to ask on the mythtv forum or email list requesting advice before proceeding, as moving from v29 to v32 may have some changes one needs to be aware of).

As I understand it, the magic would be: sudo add-apt-repository ppa:mythbuntu/3[012] ; sudo apt-get update

dlasher commented 2 years ago

Thanks for the suggestions, appreciate it.

I've avoided leaving 0.29 because it removed support for VDPAU, which is which all my frontends are using for video playback. However, looking at the v31 release notes, it's back (odd..) so I have a weekend project now.

In the mean time I'll be watching syslog and killing processes..

garybuhrmaster commented 2 years ago

Thanks for the suggestions, appreciate it.

I've avoided leaving 0.29 because it removed support for VDPAU, which is which all my frontends are using for video playback. However, looking at the v31 release notes, it's back (odd..) so I have a weekend project now.

Again, I would strongly recommend asking on the forum or email list about others experience upgrading with ubuntu, as while I do not often pay attention to ubuntu discussions (since I don't use that distro, my interest, and knowledge, of the what/why/how is limited), I have seen others having mentioning having done such upgrades with (as is typical) substantially different experiences, and there is no reason to not learn from others successes and failures.

dlasher commented 2 years ago

FWIW - it still happens in 0.31, no real clue as to why it starts either.

MythTV Version : v31.0+fixes.202203040618.7e4ce1ba98~ubuntu20.04.1 MythTV Branch : fixes/31

Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning request for channel 708 accepted Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning in progress Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning in progress Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning in progress Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning in progress Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: message repeated 13 times: [ Tuning in progress] Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning completed Sep 25 17:14:30 backend1 mythhdhrrecorder[209668]: Tuning successful, connection 10.4.11.100:51188 -> 10.4.11.204:5004, tuner tuner0 Sep 25 18:00:31 backend1 mythcommflag: message repeated 98 times: [ mythcommflag[231865]: E Decoder decoders/avformatdecoder.cpp:4975 (GetFrame) decoding error End of file (-541478725)] Sep 25 18:01:39 backend1 mythcommflag: message repeated 99 times: [ mythcommflag[237264]: E Decoder decoders/avformatdecoder.cpp:4975 (GetFrame) decoding error End of file (-541478725)] Sep 25 18:03:54 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes Sep 25 18:04:08 backend1 mythhdhrrecorder[209668]: message repeated 18 times: [ stream FIFO queue full, dropped chunk of 660632 bytes] Sep 25 18:04:09 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes Sep 25 18:05:08 backend1 mythhdhrrecorder[209668]: message repeated 75 times: [ stream FIFO queue full, dropped chunk of 660632 bytes] Sep 25 18:05:09 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes Sep 25 18:06:08 backend1 mythhdhrrecorder[209668]: message repeated 76 times: [ stream FIFO queue full, dropped chunk of 660632 bytes] Sep 25 18:06:09 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes Sep 25 18:07:08 backend1 mythhdhrrecorder[209668]: message repeated 76 times: [ stream FIFO queue full, dropped chunk of 660632 bytes] Sep 25 18:07:09 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes Sep 25 18:08:08 backend1 mythhdhrrecorder[209668]: message repeated 75 times: [ stream FIFO queue full, dropped chunk of 660632 bytes] Sep 25 18:08:09 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes Sep 25 18:08:10 backend1 mythhdhrrecorder[209668]: stream FIFO queue full, dropped chunk of 660632 bytes

This is the only thing off I can find in the myth-backend logs:

Sep 25 18:01:22 backend1 mythbackend: mythbackend[152419]: W ExternSH recorders/ExternalStreamHandler.cpp:711 (run) ExternSH[41](mythhdhrrecorder (pid #209668) streaming channel 708 from 10.4.11.204 tuner tuner0): No data for 50 seconds, Restarting stream.

For now I've cobbled together a bash script to watch the logs for "stream FIFO queue full|No data for" - which should at least tell me when it starts happening.

Next time it pages me, what would be useful for me to grab, data wise, to help with this problem?