[mythtv-users] mythbackend: send oops

Tue May 3 01:27:39 UTC 2016

On Sunday, May 01, 2016 06:50:37 PM Gary Buhrmaster wrote:
> On Sun, May 1, 2016 at 5:33 PM, Jerome Yuzyk <jerome at supernet.ab.ca> wrote:
> > [0.27.6 on Fedora 22]
> >
> > I've been logging a few of these lately, it seems when starting a recording on my DCX-3200M-P3 over Firewire.
> >
> >     May  1 11:00:00 tv mythbackend: send oops
> >
> > What should I be looking for to troubleshoot?
> 
> "send oops" comes from the firewire libraries.  If this is
> a recent occurrence, have you recently updated your
> system (kernel, lib*1394 libraries)?  Or has your
> provider updated their STB (to "enhance" it)?  You
> may need to enable firewire debugging in your kernel
> and (possibly) report the issue upstream.
> 

As far as I can tell, no. I updated my kernel (from 4.3.4-200 to 4.4.6-201) but haven't rebooted, my lib*1394 not for the last month at least. My 1394 libs are:

    libavc1394-0.5.3-16.fc22.x86_64
    libraw1394-2.1.0-4.fc22.x86_64
    libavc1394-devel-0.5.3-16.fc22.x86_64
    libdc1394-2.2.2-3.fc22.x86_64
    libraw1394-devel-2.1.0-4.fc22.x86_64

The most recent updates before I noticed the oopses were to myth 0.27.6. On https://www.mythtv.org/wiki/Release_Notes_-_0.27.6 there's a line that says

    Refs #12524. New firewire ids for DCX-3200M P3

Would that affect me?

If my STB was updated it didn't leave the box powered off as it has done in the past.

Channel-change and recording do work though, and I haven't had to restart mythbackend and it hasn't restarted itself since the upgrade a couple weeks ago.

FWIW here's what was logged just over an hour ago, for a recording that worked (I am currently watching it an hour later):

May  2 17:59:31 tv mythbackend: 2016-05-02 17:59:30.948173 I  TVRec[7]: ASK_RECORDING 7 30 0 0
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.048472 I  TVRec[7]: Changing from None to RecordingOnly
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.048563 I  New DB connection, total: 11
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.050650 I  TVRec[7]: HW Tuner: 7->7

#--> this is new
May  2 18:00:00 tv mythbackend: send oops

May  2 18:00:00 tv kernel: audit: type=1123 audit(1462233600.115:4869): pid=7894 uid=1000 auid=4294967295 ses=4294967295 msg='cwd="/" cmd=2F686F6D652F6D79746874762F62696E2F363230306368202D67203078393436323639666666653930623866382034 terminal=? res=success'
May  2 18:00:00 tv kernel: audit: type=1110 audit(1462233600.116:4870): pid=7894 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
May  2 18:00:00 tv kernel: audit: type=1105 audit(1462233600.129:4871): pid=7894 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
May  2 18:00:00 tv systemd: Started Session c371 of user root.
May  2 18:00:00 tv systemd: Starting Session c371 of user root.

#--> this is new
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: send oops
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.083652 E  FireDev(946269FFFE90B8F8): Power cmd failed (no response)
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.139538 E  FireDev(946269FFFE90B8F8): Power cmd failed (no response)
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.146557 E  FireDev(946269FFFE90B8F8): Power cmd failed (no response)
May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.170269 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min

May  2 18:00:00 tv mythbackend: 2016-05-02 18:00:00.173401 I  Tuning recording: "NHL Hockey":"Washington Capitals at Pittsburgh Penguins": channel 2004 on cardid 7, sourceid 2
May  2 18:00:02 tv kernel: audit: type=1106 audit(1462233602.180:4872): pid=7894 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'
May  2 18:00:02 tv kernel: audit: type=1104 audit(1462233602.180:4873): pid=7894 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'

#--> this is new
May  2 18:00:02 tv mythbackend: libiec61883 warning: No plugs exist on either node; using default broadcast channel 63.

May  2 18:00:02 tv mythbackend: 2016-05-02 18:00:02.305359 I  LFireDev(946269FFFE90B8F8): Buffered packets 2350 (9400 KB)
May  2 18:00:02 tv mythbackend: 2016-05-02 18:00:02.325125 W  LFireDev(946269FFFE90B8F8): No Input in 900 msec...
May  2 18:00:02 tv mythbackend: 2016-05-02 18:00:02.905892 E  DTVSigMon[7](946269FFFE90B8F8): Program #0 not found in PAT!
May  2 18:00:02 tv mythbackend: Program Association Section
May  2 18:00:02 tv mythbackend: PSIP tableID(0x0) length(13) extension(0x1)
May  2 18:00:02 tv mythbackend: version(10) current(1) section(0) last_section(0)
May  2 18:00:02 tv mythbackend: tsid(1) programCount(1)
May  2 18:00:02 tv mythbackend: program number     1 has PID 0x0055
May  2 18:00:02 tv mythbackend: 2016-05-02 18:00:02.905912 E  DTVSigMon[7](946269FFFE90B8F8): But there is only one program in the PAT, so we'll just use it
May  2 18:00:02 tv mythbackend: 2016-05-02 18:00:02.907109 I  Updating status for "NHL Hockey":"Washington Capitals at Pittsburgh Penguins" on cardid 7 (Tuning => Recording)

#--> this is new
May  2 18:00:02 tv mythbackend: libiec61883 warning: No plugs exist on either node; using default broadcast channel 63.

May  2 18:00:03 tv mythbackend: 2016-05-02 18:00:02.968562 I  TVRec[7]: rec->GetPathname(): '/recording/tv/2004_20160503000000.mpg'
May  2 18:00:03 tv mythbackend: 2016-05-02 18:00:02.973669 I  LFireDev(946269FFFE90B8F8): Buffered packets 2350 (9400 KB)
May  2 18:00:03 tv mythbackend: 2016-05-02 18:00:03.040605 I  New DB connection, total: 11
May  2 18:00:04 tv mythbackend: 2016-05-02 18:00:04.043007 I  New DB connection, total: 12
May  2 18:00:04 tv mythbackend: 2016-05-02 18:00:04.678431 I  MainServer::ANN Monitor
May  2 18:00:04 tv mythbackend: 2016-05-02 18:00:04.678460 I  adding: tv as a client (events: 0)
May  2 18:00:04 tv mythbackend: 2016-05-02 18:00:04.684832 I  MainServer::ANN Monitor
May  2 18:00:04 tv mythbackend: 2016-05-02 18:00:04.684850 I  adding: tv as a client (events: 1)
May  2 18:00:41 tv mythbackend: 2016-05-02 18:00:41.143955 I  JobQueue: Commercial Detection Starting for "NHL Hockey":"Washington Capitals at Pittsburgh Penguins" recorded from channel 2004 at 2016-05-03T00:00:00Z

I figure if a recording gets to commflagging it's a good one and this one is, like others over the weekend that logged the same. 

Appreciate your insights.

-- 
A little of Jerome's MythTV World: http://mythtv.bss.ab.ca