<div dir="ltr"><div dir="ltr"><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Fri, Feb 12, 2021 at 4:35 AM Peter Carlsson <<a href="mailto:maillist.peter@home.se">maillist.peter@home.se</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">On Thu, Feb 11, 2021 at 04:12:40PM -0700, John P Poet wrote:<br>
> On Thu, Feb 11, 2021 at 3:00 PM Peter Carlsson <<a href="mailto:maillist.peter@home.se" target="_blank">maillist.peter@home.se</a>><br>
> wrote:<br>
> <br>
> ><br>
> > <trimmed><br>
> ><br>
> > ps aux | grep mythexternrecorder<br>
> > root 15820 0.0 0.0 7868 676 pts/0 S+ 22:51 0:00 grep<br>
> > mythexternrecorder<br>
> ><br>
> > > What does the mythexternrecorder log file have in it?<br>
> ><br>
> > To be honest I have never really managed to have separate logs in<br>
> > /var/log/mythtv/ even though I have tried to.<br>
> ><br>
> > ls -ld /var/log/mythtv<br>
> > drwxr-sr-x 2 root adm 20480 feb 11 20:36 /var/log/mythtv<br>
> ><br>
> > ps ax | grep mythbackend | grep -v grep<br>
> > 15605 ? Ssl 0:00 /usr/bin/mythbackend --logpath<br>
> > /var/log/mythtv/ --verbose channel,record<br>
> ><br>
> > systemctl status mythtv-backend<br>
> > ● mythtv-backend.service - MythTV Backend<br>
> > Loaded: loaded (/lib/systemd/system/mythtv-backend.service;<br>
> > enabled; vendor preset: enabled)<br>
> > Drop-In: /etc/systemd/system/mythtv-backend.service.d<br>
> > └─override.conf<br>
> > Active: active (running) since Thu 2021-02-11 22:42:27 CET; 1min<br>
> > 23s ago<br>
> > Docs: <a href="https://www.mythtv.org/wiki/Mythbackend" rel="noreferrer" target="_blank">https://www.mythtv.org/wiki/Mythbackend</a><br>
> > <a href="https://www.mythtv.org/wiki/Mythbackend" rel="noreferrer" target="_blank">https://www.mythtv.org/wiki/Mythbackend</a><br>
> > Main PID: 15605 (mythbackend)<br>
> > Tasks: 34 (limit: 4915)<br>
> > Memory: 44.0M<br>
> > CGroup: /system.slice/mythtv-backend.service<br>
> > └─15605 /usr/bin/mythbackend --logpath /var/log/mythtv/<br>
> > --verbose channel,record<br>
> ><br>
> > cat /etc/rsyslog.d/mythtv-backend.conf<br>
> > $FileOwner mythtv<br>
> > $FileGroup mythtv<br>
> > $FileCreateMode 0644<br>
> ><br>
> > # Specify a log file name format. Ensure one of the following<br>
> > templates is<br>
> > # uncommented.<br>
> > # - Use a single log file for all logging from any MythTV application:<br>
> > #$template mythtvFile,"/var/log/mythtv/mythtv.log"<br>
> > # - Use a single log file per application:<br>
> > $template mythtvFile,"/var/log/mythtv/%programname%.log"<br>
> > # - Use a separate log file per process:<br>
> > #$template<br>
> > mythtvFile,"/var/log/mythtv/%programname%.%syslogtag:R,ERE,1,ZERO:\[([[:digit:]]{1,})\]--end%.log"<br>
> ><br>
> > # Send all logging on local6 facility to mythtvFile (filename created<br>
> > according<br>
> > # to the template specified, above), then discard (so the message is<br>
> > not also<br>
> > # written to system other log files).<br>
> > # This should catch any output from MythTV applications, assuming they<br>
> > are<br>
> > # started with:<br>
> > # --syslog local6<br>
> > local6.* ?mythtvFile<br>
> > & ~<br>
> ><br>
> > $FileOwner root<br>
> > $FileGroup adm<br>
> > $FileCreateMode 0640<br>
> ><br>
> > Thanks again!<br>
> ><br>
> > Best regards,<br>
> > Peter Carlsson<br>
> ><br>
> <br>
> <br>
> You don't have a mythtv user and group? I strongly recommend having<br>
> mythbackend, etc, run as mythtv:mythtv instead of root. You would need to<br>
> change the ownership of /var/log/mythtv accordingly. It is very possible<br>
> that is your whole problem. If mythexternrecorder does not have permission<br>
> to write its log files to the same directory as mythbackend, it will refuse<br>
> to run.<br>
> That being said, I don't use syslog for mythbackend logs and have never<br>
> tried to use mythexternrecorder that way. I guess it should work, I just<br>
> can't be sure.<br>
<br>
I was under the impression that I always run the backend as user mythtv<br>
and I think I still does. But you were right about the permissions of<br>
/var/log/mythtv which I have now fixed. So all logs end up there. Thanks!<br>
<br>
But fixing that did not fix the problem with mythexternrecorder.<br>
<br>
Below you can see part of the log files. I can provide the full log<br>
files but was not sure I could send attachments to the mailing list.<br>
<br>
Will these excerpts give any clues?<br>
<br>
Thanks again for all your help!<br>
<br>
Best regards,<br>
Peter Carlsson<br>
<br>
cat /tmp/mythexternrecorder.20210212104722.32675.log<br>
2021-02-12 11:47:22.145760 C [32675/32675] thread_unknown mythcommandlineparser.cpp:2611 (ConfigureLogging) - mythexternrecorder version: [v31.0] <a href="http://www.mythtv.org" rel="noreferrer" target="_blank">www.mythtv.org</a><br>
2021-02-12 11:47:22.145793 C [32675/32675] thread_unknown mythcommandlineparser.cpp:2613 (ConfigureLogging) - Qt version: compile: 5.11.3, runtime: 5.11.3<br>
2021-02-12 11:47:22.145847 I [32675/32675] thread_unknown mythcommandlineparser.cpp:2615 (ConfigureLogging) - Debian GNU/Linux 10 (buster) (i386)<br>
2021-02-12 11:47:22.145851 N [32675/32675] thread_unknown mythcommandlineparser.cpp:2617 (ConfigureLogging) - Enabled verbose msgs: general channel record<br>
2021-02-12 11:47:22.145947 N [32675/32675] thread_unknown logging.cpp:725 (logStart) - Setting Log Level to LOG_INFO<br>
2021-02-12 11:47:22.156735 I [32675/32678] Logger logging.cpp:280 (run) - Added logging to the console<br>
2021-02-12 11:47:22.157080 I [32675/32679] thread_unknown MythExternControl.cpp:565 (Run) - : Buffer: Ready for data.<br>
2021-02-12 11:47:22.157268 I [32675/32680] thread_unknown MythExternControl.cpp:450 (Run) - : Command parser ready.<br>
2021-02-12 11:47:22.157356 I [32675/32677] LogForward loggingserver.cpp:129 (FileLogger) - Added logging to /var/log/mythtv/mythexternrecorder.20210212104722.32675.log<br>
2021-02-12 11:47:22.157410 I [32675/32680] thread_unknown MythExternControl.cpp:215 (SendStatus) - : Processing 'APIVersion?' --> 'OK:2'<br>
2021-02-12 11:47:22.157636 I [32675/32680] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing '1:APIVersion:2' --> '1:OK:2'<br>
2021-02-12 11:47:22.157763 I [32675/32680] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing '2:Version?' --> '2:OK:0.6'<br>
2021-02-12 11:47:22.157880 I [32675/32680] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing '3:Description?' --> '3:WARN:Not set'<br>
2021-02-12 11:47:22.163536 I [32675/32675] thread_unknown MythExternRecApp.cpp:50 (MythExternRecApp) - Channels in '/home/peter/delat/script/mythtv-svtplay-external-recorder-channels.conf', Tuner: '', Scanner: ''<br>
2021-02-12 11:47:26.167121 I [32675/32675] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing 'HasTuner' --> '5:OK:Yes'<br>
2021-02-12 11:47:26.177351 I [32675/32675] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing 'HasPictureAttributes' --> '6:OK:No'<br>
2021-02-12 11:47:26.177552 I [32675/32680] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing '7:FlowControl?' --> '7:OK:XON/XOFF'<br>
2021-02-12 11:47:26.187588 I [32675/32675] thread_unknown MythExternControl.cpp:240 (SendStatus) - : Processing 'BlockSize' --> '8:OK'<br>
2021-02-12 11:52:27.189668 N [32675/32679] thread_unknown MythExternControl.cpp:591 (Run) - : Not streaming.<br>
<br>
cat /tmp/mythbackend.20210212104435.32334.log<br>
2021-02-12 11:47:21.885916 I [32334/32405] TVRecEvent tv_rec.cpp:1057 (HandleStateChange) - TVRec[21]: Changing from None to WatchingLiveTV<br>
2021-02-12 11:47:21.885970 I [32334/32405] TVRecEvent tv_rec.cpp:4434 (ClearFlags) - TVRec[21]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop, @ tv_rec.cpp:1291<br>
2021-02-12 11:47:21.885996 I [32334/32405] TVRecEvent tv_rec.cpp:3502 (HandleTuning) - TVRec[21]: HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)<br>
2021-02-12 11:47:21.886014 I [32334/32405] TVRecEvent cardutil.cpp:2055 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() input 21<br>
2021-02-12 11:47:21.887648 I [32334/32405] TVRecEvent cardutil.cpp:2087 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() got input 22<br>
2021-02-12 11:47:21.887683 I [32334/32405] TVRecEvent cardutil.cpp:2087 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() got input 23<br>
2021-02-12 11:47:21.887694 I [32334/32405] TVRecEvent cardutil.cpp:2087 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() got input 24<br>
2021-02-12 11:47:21.887741 I [32334/32405] TVRecEvent recorders/channelbase.cpp:259 (IsInputAvailable) - ChannelBase[21]: Input is free on 0/0<br>
2021-02-12 11:47:21.889052 I [32334/32405] TVRecEvent tv_rec.cpp:3571 (TuningShutdowns) - TVRec[21]: TuningShutdowns(Program(NULL) channel(1) input() flags(LiveTV,))<br>
2021-02-12 11:47:21.889071 I [32334/32405] TVRecEvent tv_rec.cpp:4434 (ClearFlags) - TVRec[21]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop, @ tv_rec.cpp:3640<br>
2021-02-12 11:47:21.889083 I [32334/32405] TVRecEvent tv_rec.cpp:3524 (HandleTuning) - TVRec[21]: No recorder yet, calling TuningFrequency<br>
2021-02-12 11:47:21.889092 I [32334/32405] TVRecEvent tv_rec.cpp:3662 (TuningFrequency) - TVRec[21]: TuningFrequency<br>
2021-02-12 11:47:21.889728 I [32334/32405] TVRecEvent recorders/ExternalChannel.cpp:21 (Open) - ExternChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): Open()<br>
2021-02-12 11:47:21.891806 I [32334/32405] TVRecEvent recorders/channelbase.cpp:618 (InitializeInput) - ChannelBase[21]: Input #21: 'MPEG2TS' schan(1) sourceid(4)<br>
2021-02-12 11:47:21.891880 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:550 (ExternalStreamHandler) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): args "--conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --verbose general,channel,record --logpath /var/log/mythtv --loglevel info --quiet --inputid 21"<br>
2021-02-12 11:47:21.891942 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:913 (OpenApp) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): Spawn '/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf'<br>
2021-02-12 11:47:21.891950 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:231 (Run) - ExternIO::Run()<br>
2021-02-12 11:47:21.910956 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:321 (Fork) - ExternIO::Fork 'mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf --verbose general,channel,record --logpath /var/log/mythtv --loglevel info --quiet --inputid 21'<br>
2021-02-12 11:47:21.914682 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:379 (Fork) - Spawned<br>
2021-02-12 11:47:22.157517 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1319 (ProcessVer1) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessCommand('APIVersion?') = 'OK:2' took 232ms<br>
2021-02-12 11:47:22.157678 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('1:APIVersion:2') = 'OK:2' took 0ms<br>
2021-02-12 11:47:22.157785 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('2:Version?') = 'OK:0.6' took 0ms<br>
2021-02-12 11:47:22.157917 W [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('3:Description?') = 'WARN:Not set' took 0ms <-- NOTE<br>
2021-02-12 11:47:26.161611 E [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1423 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessVer2: Giving up waiting for response for command '4:HasTuner?'<br>
2021-02-12 11:47:26.167204 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('5:HasTuner?') = 'OK:Yes' took 5ms<br>
2021-02-12 11:47:26.177405 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('6:HasPictureAttributes?') = 'OK:No' took 10ms<br>
2021-02-12 11:47:26.177584 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('7:FlowControl?') = 'OK:XON/XOFF' took 0ms<br>
2021-02-12 11:47:26.177599 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:970 (OpenApp) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): App opened successfully<br>
2021-02-12 11:47:26.177615 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:978 (OpenApp) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): Capabilities: tuner(yes) Picture attributes(no) Flow control(XON/XOFF)<br>
2021-02-12 11:47:26.187687 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:1460 (ProcessVer2) - ExternSH[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): ProcessV2('8:BlockSize:1540096') = 'OK' took 10ms<br>
2021-02-12 11:47:26.187718 I [32334/32405] TVRecEvent recorders/ExternalStreamHandler.cpp:470 (Get) - ExternSH[21]: Creating new stream handler 21 for /usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf<br>
2021-02-12 11:47:26.187734 I [32334/32405] TVRecEvent recorders/ExternalChannel.cpp:52 (Open) - ExternChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): Opened<br>
2021-02-12 11:47:26.187748 I [32334/32405] TVRecEvent recorders/dtvchannel.cpp:159 (SetChannelByString) - DTVChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): SetChannelByString(1):<br>
2021-02-12 11:47:26.187759 I [32334/32405] TVRecEvent cardutil.cpp:2055 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() input 21<br>
2021-02-12 11:47:26.188661 I [32334/32405] TVRecEvent cardutil.cpp:2087 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() got input 22<br>
2021-02-12 11:47:26.188682 I [32334/32405] TVRecEvent cardutil.cpp:2087 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() got input 23<br>
2021-02-12 11:47:26.188698 I [32334/32405] TVRecEvent cardutil.cpp:2087 (GetConflictingInputs) - CardUtil[21]: GetConflictingInputs() got input 24<br>
2021-02-12 11:47:26.188765 I [32334/32405] TVRecEvent recorders/channelbase.cpp:259 (IsInputAvailable) - ChannelBase[21]: Input is free on 0/0<br>
2021-02-12 11:47:26.190694 E [32334/32405] TVRecEvent dtvmultiplex.cpp:412 (ParseTuningParams) - DTVMux: ParseTuningParams -- Unknown tuner type = 0xffffffff80000000<br>
2021-02-12 11:47:26.190750 E [32334/32405] TVRecEvent recorders/dtvchannel.cpp:290 (SetChannelByString) - DTVChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): SetChannelByString(1): Failed to initialize multiplex options<br>
2021-02-12 11:47:26.190761 I [32334/32405] TVRecEvent recorders/dtvchannel.cpp:320 (SetChannelByString) - DTVChan[21](/usr/bin/mythexternrecorder --conf /home/peter/delat/script/mythtv-svtplay-external-recorder.conf): SetChannelByString(1): failure<br>
2021-02-12 11:47:26.190774 E [32334/32405] TVRecEvent tv_rec.cpp:3737 (TuningFrequency) - TVRec[21]: Failed to set channel to 1. Reverting to kState_None<br>
2021-02-12 11:47:26.190803 I [32334/32405] TVRecEvent tv_rec.cpp:1057 (HandleStateChange) - TVRec[21]: Changing from WatchingLiveTV to None<br></blockquote><div><br></div><div>Are you running v31 or v31-latest (v31-fixes)? If you are not running the latest version of v31 you may be hitting a bug preventing it from handling the situation where there are channels but no tuner. I had forgotten about that because it was fixed so long ago.</div><div><br></div><div>John<br></div></div></div>