[mythtv-users] how to log mythmetadatalookup output?

Wed Dec 13 12:31:32 UTC 2017

I too, since upgrading to 29 am having mythmetadatalookup issues.  It
runs fine from the command prompt as the mythtv user and the backend
logs don't report that it's failing:

Dec 12 20:59:07 pvr mythbackend: mythbackend[26321]: I Metadata_67460 mythsystemunix.cpp:948 (Fork) Managed child (PID: 27370) has started! * command=/usr/bin/mythmetadatalookup -j 67460 --verbose general,system --loglevel info --quiet --syslog local7, timeout=0
...
Dec 12 20:59:26 pvr mythbackend: mythbackend[26321]: I SystemManager mythsystemunix.cpp:354 (run) Managed child (PID: 27370) has exited! command=/usr/bin/mythmetadatalookup -j 67460 --verbose general,system --loglevel info --quiet --syslog local7, status=0, result=0

However even after that run, season and episode data for that recording
are not updated.  If I run that command manually as the mythtv user it
does update though:

$ /usr/bin/mythmetadatalookup -j 67460 --verbose general,system --loglevel info
2017-12-13 07:22:48.155219 C  mythmetadatalookup version: fixes/29 [v29.0-64-g39b2062] www.mythtv.org
2017-12-13 07:22:48.155284 C  Qt version: compile: 5.2.1, runtime: 5.2.1
2017-12-13 07:22:48.155306 N  Enabled verbose msgs:  general system
2017-12-13 07:22:48.155345 N  Setting Log Level to LOG_INFO
2017-12-13 07:22:48.167497 I  Added logging to the console
2017-12-13 07:22:48.169429 I  Setup Interrupt handler
2017-12-13 07:22:48.169462 I  Setup Terminated handler
2017-12-13 07:22:48.169502 I  Setup Segmentation fault handler
2017-12-13 07:22:48.169583 I  Setup Aborted handler
2017-12-13 07:22:48.169617 I  Setup Bus error handler
2017-12-13 07:22:48.169644 I  Setup Floating point exception handler
2017-12-13 07:22:48.169676 I  Setup Illegal instruction handler
2017-12-13 07:22:48.169706 I  Setup Real-time signal 0 handler
2017-12-13 07:22:48.169740 I  Setup Hangup handler
2017-12-13 07:22:48.170072 N  Using runtime prefix = /usr
2017-12-13 07:22:48.170087 N  Using configuration directory = /home/mythtv/.mythtv
2017-12-13 07:22:48.170277 I  Assumed character encoding: en_CA.UTF-8
2017-12-13 07:22:48.171347 I  Using localhost value of pvr
2017-12-13 07:22:48.171476 I  Start up testing connections. DB fd31:aeb1:48df:0:214:d1ff:fe13:52fb, BE , attempt 0, status dbAwake
QMYSQLDriver::open: Illegal connect option value 'MYSQL_OPT_READ_TIMEOUT=300'
QMYSQLDriver::open: Illegal connect option value 'MYSQL_OPT_READ_TIMEOUT=300'
2017-12-13 07:22:48.750038 N  Setting QT default locale to EN_US
2017-12-13 07:22:48.750082 I  Current locale EN_US
2017-12-13 07:22:48.750224 N  Reading locale defaults from /usr/share/mythtv//locales/en_us.xml
2017-12-13 07:22:48.760225 I  Loading en_us translation for module mythfrontend
2017-12-13 07:22:48.760712 I  Testing grabbers and metadata sites for functionality...
2017-12-13 07:22:48.761954 I  Starting process signal handler
2017-12-13 07:22:48.762019 I  Starting IO manager (read)
2017-12-13 07:22:48.762230 I  Starting IO manager (write)
2017-12-13 07:22:48.764704 I  Managed child (PID: 3013) has started! * command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, timeout=0
2017-12-13 07:22:48.761900 I  Starting process manager
2017-12-13 07:22:48.885641 I  Managed child (PID: 3013) has exited! command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, status=0, result=0
2017-12-13 07:22:48.915293 I  Managed child (PID: 3015) has started! * command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, timeout=0
2017-12-13 07:22:49.016184 I  Managed child (PID: 3015) has exited! command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, status=0, result=0
2017-12-13 07:22:49.066458 I  Managed child (PID: 3017) has started!  command=/usr/share/mythtv/metadata/Movie/tmdb3.py -t, timeout=0
2017-12-13 07:22:49.389092 I  Managed child (PID: 3017) has exited! command=/usr/share/mythtv/metadata/Movie/tmdb3.py -t, status=0, result=0
2017-12-13 07:22:49.417936 I  Managed child (PID: 3021) has started! * command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, timeout=0
2017-12-13 07:22:49.799913 I  Managed child (PID: 3021) has exited! command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, status=0, result=0
2017-12-13 07:22:49.818235 I  Managed child (PID: 3027) has started! * command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, timeout=0
2017-12-13 07:22:50.141113 I  Managed child (PID: 3027) has exited! command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, status=0, result=0
2017-12-13 07:22:50.169107 I  Managed child (PID: 3032) has started!  command=/usr/share/mythtv/metadata/Television/ttvdb.py -t, timeout=0
2017-12-13 07:22:50.551101 I  Managed child (PID: 3032) has exited! command=/usr/share/mythtv/metadata/Television/ttvdb.py -t, status=0, result=0
2017-12-13 07:22:50.567684 I  All grabbers tested and working.  Continuing...
2017-12-13 07:22:50.572605 I  Managed child (PID: 3036) has started! * command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, timeout=0
2017-12-13 07:22:50.673636 I  Managed child (PID: 3036) has exited! command=/usr/share/mythtv/metadata/Movie/tmdb3.py -v, status=0, result=0
2017-12-13 07:22:50.721466 I  Managed child (PID: 3038) has started! * command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, timeout=0
2017-12-13 07:22:51.123760 I  Managed child (PID: 3038) has exited! command=/usr/share/mythtv/metadata/Television/ttvdb.py -v, status=0, result=0
2017-12-13 07:22:51.173279 I  Managed child (PID: 3043) has started! * command=/usr/share/mythtv/metadata/Television/tvdb_test.conf -v, timeout=0
2017-12-13 07:22:51.193842 I  Managed child (PID: 3043) has exited! command=/usr/share/mythtv/metadata/Television/tvdb_test.conf -v, status=32256, result=126
2017-12-13 07:22:51.225988 I  Managed child (PID: 3045) has started! * command=/usr/share/mythtv/metadata/Musicmbutils.py -v, timeout=0
2017-12-13 07:22:51.247054 I  Managed child (PID: 3045) has exited! command=/usr/share/mythtv/metadata/Musicmbutils.py -v, status=32512, result=127
2017-12-13 07:22:51.280788 I  MythCoreContext::ConnectCommandSocket(): Connecting to backend server: 10.75.22.2:6543 (try 1 of 5)
2017-12-13 07:22:51.284163 I  MythCoreContext::CheckProtoVersion(): Using protocol version 91 BuzzOff
2017-12-13 07:22:51.289201 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -a US -N 281511 Sugar Daddy
2017-12-13 07:22:51.293408 I  Managed child (PID: 3052) has started!  command=/usr/share/mythtv/metadata/Television/ttvdb.py -l en -a US -N 281511 Sugar Daddy, timeout=0
2017-12-13 07:22:55.693902 I  Managed child (PID: 3052) has exited! command=/usr/share/mythtv/metadata/Television/ttvdb.py -l en -a US -N 281511 Sugar Daddy, status=0, result=0
2017-12-13 07:22:55.743453 I  Result Found, Season 4 Episode 9
2017-12-13 07:22:55.743930 I  Returning Metadata Results: blackish 0 0
2017-12-13 07:22:56.497006 I  Metadata Image Download: http://www.thetvdb.com/banners/seasons/281511-4.jpg -> myth://Coverart@pvr/black-ish Season 4_coverart.jpg
QIODevice::read: device not open
2017-12-13 07:23:58.807043 E  Tried to write http://www.thetvdb.com/banners/seasons/281511-4.jpg, but it appears to be an HTML redirect or corrupt file (filesize 0).
2017-12-13 07:24:00.479321 N  MythMetadataLookup run complete.
2017-12-13 07:24:00.479344 I  Waiting for threads to exit.

Notice that it found "Season 4 Episode 9" where that information was
not in the database after the run done at "Dec 12 20:59:26" last night.

So clearly there is something different about the backend running it. 
But what is the question.

Logging that output above from the BE's run of the command would be
useful I think.  How can I get that logged?

Cheers,
b.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 488 bytes
Desc: This is a digitally signed message part
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20171213/60f22351/attachment.sig>