[mythtv-users] Metadata lookup failing status 140 on first run only

Mark Perkins perkins1724 at hotmail.com
Sun Mar 19 23:43:05 UTC 2017


I am currently seeing about half of my metadata lookup jobs failing on first execution with status 140 (as seen in mythweb) - however the metadata job actually completes and metadata is found, downloaded and updated correctly. And, rerunning the job back-to-back without any other intervention completes successfully on the second and all subsequent attempts.

I suspect that something that may be contributing (causing) this is that I am pre-populating my xmltv files with imdb, tmdb and thetvdb episode_num elements which may be unusual although perhaps Schedules Direct users get that data by default, I don't know for sure. However MythTV appears to be correctly parsing and importing at least the tmdb and thetvdb values so that the inetref field contains the correct data before the first metadata lookup job even runs. I have included a log of back-to-back runs demonstrating this below.

Before this first run I confirmed that the inetref was pre-populated from the xmltv mythfilldatabase import by selecting the recording -> Menu -> Recording Options -> Change Recording Metadata. I escaped back to main screen without saving changes.
No cover images / banners / posters / backdrops etc are present so all that shows on the frontend is the preview image extracted from the recording and the text elements (title, subtitle, description, recording length etc etc). I have photos of a couple of the screens if that would be useful but haven't included for now.

This is the backend log from the first run started by selecting the recording -> Menu -> Job Options -> Begin Metadata Lookup

2017-03-20 09:32:29.208267 I [17533/6393] Metadata_47726 jobqueue.cpp:2157 (DoMetadataLookupThread) - JobQueue: Metadata Lookup Starting for "Labor Day" recorded from channel 1009 at 2017-03-17T09:57:00Z
2017-03-20 09:32:30.433917 I [17533/4059] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Monitor
2017-03-20 09:32:30.433950 I [17533/4059] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: angelica.theperkinsfamily.id.au(1ed5cc0) as a client (events: 0)
2017-03-20 09:32:30.435965 I [17533/4330] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Monitor
2017-03-20 09:32:30.435994 I [17533/4330] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: angelica.theperkinsfamily.id.au(1f19b10) as a client (events: 1)
2017-03-20 09:32:56.328506 I [17533/4330] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Playback
2017-03-20 09:32:56.328513 I [17533/4330] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: angelica.theperkinsfamily.id.au(1efbc20) as a client (events: 0)
2017-03-20 09:32:56.340588 W [17533/4330] ProcessRequest ringbuffer.cpp:698 (Start) - RingBuf(/mnt/servertwo/Myth_Cover_Art//tmdb3.py_130150_coverart.jpg): Not starting read ahead thread, this is a write only RingBuffer
2017-03-20 09:32:56.342634 I [17533/6462] MythSocketThread(116) mainserver.cpp:7684 (connectionClosed) - FileTransfer sock(1efbcf0) disconnected
2017-03-20 09:32:56.345871 I [17533/6460] MythSocketThread(112) mainserver.cpp:7656 (connectionClosed) - Playback sock(1efbc20) 'angelica.theperkinsfamily.id.au' disconnected
2017-03-20 09:32:56.747602 I [17533/4059] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Playback
2017-03-20 09:32:56.747609 I [17533/4059] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: angelica.theperkinsfamily.id.au(1d9e510) as a client (events: 0)
2017-03-20 09:32:56.760151 W [17533/4059] ProcessRequest ringbuffer.cpp:698 (Start) - RingBuf(/mnt/servertwo/Myth_Fan_Art//tmdb3.py_130150_fanart.jpg): Not starting read ahead thread, this is a write only RingBuffer
2017-03-20 09:32:56.761501 I [17533/6468] MythSocketThread(116) mainserver.cpp:7684 (connectionClosed) - FileTransfer sock(1c53160) disconnected
2017-03-20 09:32:56.765555 I [17533/6466] MythSocketThread(112) mainserver.cpp:7656 (connectionClosed) - Playback sock(1d9e510) 'angelica.theperkinsfamily.id.au' disconnected
2017-03-20 09:32:58.809004 I [17533/4059] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Playback
2017-03-20 09:32:58.809027 I [17533/4059] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: felicia.theperkinsfamily.id.au(1d9f650) as a client (events: 0)
2017-03-20 09:32:59.067286 I [17533/4059] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Playback
2017-03-20 09:32:59.067309 I [17533/4059] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: felicia.theperkinsfamily.id.au(1c89160) as a client (events: 0)
2017-03-20 09:32:59.069810 I [17533/6474] MythSocketThread(116) mainserver.cpp:7684 (connectionClosed) - FileTransfer sock(1c4cd30) disconnected
2017-03-20 09:32:59.070834 I [17533/6473] MythSocketThread(112) mainserver.cpp:7656 (connectionClosed) - Playback sock(1d9f650) 'felicia.theperkinsfamily.id.au' disconnected
2017-03-20 09:32:59.394858 I [17533/6476] MythSocketThread(112) mainserver.cpp:7684 (connectionClosed) - FileTransfer sock(1c89030) disconnected
2017-03-20 09:32:59.395901 I [17533/6475] MythSocketThread(120) mainserver.cpp:7656 (connectionClosed) - Playback sock(1c89160) 'felicia.theperkinsfamily.id.au' disconnected
2017-03-20 09:32:59.898080 I [17533/6437] MythSocketThread(108) mainserver.cpp:7656 (connectionClosed) - Monitor sock(1ed5cc0) 'angelica.theperkinsfamily.id.au' disconnected
2017-03-20 09:32:59.898651 I [17533/6439] MythSocketThread(110) mainserver.cpp:7656 (connectionClosed) - Monitor sock(1f19b10) 'angelica.theperkinsfamily.id.au' disconnected
2017-03-20 09:33:00.102144 E [17533/6393] Metadata_47726 jobqueue.cpp:2221 (DoMetadataLookupThread) - JobQueue: Metadata Lookup Errored: "Labor Day" recorded from channel 1009 at 2017-03-17T09:57:00Z (Failed with exit status 140)

At this point the line above shows "Failed with exit status 140". However once the frontend refreshes after a few(ish) seconds the cover images and backgrounds automatically load into the theme.
I trigger the second run by selecting the recording -> Menu -> Job Options -> Begin Metadata Lookup as before.

2017-03-20 09:34:14.269458 I [17533/6503] Metadata_47727 jobqueue.cpp:2157 (DoMetadataLookupThread) - JobQueue: Metadata Lookup Starting for "Labor Day" recorded from channel 1009 at 2017-03-17T09:57:00Z
2017-03-20 09:34:15.373604 I [17533/4330] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Monitor
2017-03-20 09:34:15.373626 I [17533/4330] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: angelica.theperkinsfamily.id.au(1bf0ad0) as a client (events: 0)
2017-03-20 09:34:15.375665 I [17533/4059] ProcessRequest mainserver.cpp:1730 (HandleAnnounce) - MainServer: MainServer::ANN Monitor
2017-03-20 09:34:15.375692 I [17533/4059] ProcessRequest mainserver.cpp:1735 (HandleAnnounce) - MainServer: adding: angelica.theperkinsfamily.id.au(1ed5cc0) as a client (events: 1)
2017-03-20 09:34:19.802773 I [17533/6547] MythSocketThread(108) mainserver.cpp:7656 (connectionClosed) - Monitor sock(1bf0ad0) 'angelica.theperkinsfamily.id.au' disconnected
2017-03-20 09:34:19.803147 I [17533/6549] MythSocketThread(110) mainserver.cpp:7656 (connectionClosed) - Monitor sock(1ed5cc0) 'angelica.theperkinsfamily.id.au' disconnected
2017-03-20 09:34:50.975480 N [17533/17577] Expire autoexpire.cpp:251 (CalcParams) - AutoExpire: CalcParams(): Max required Free Space: 7.0 GB w/freq: 14 min

There appear to be no completion messages logged by default but mythweb now shows Status: Finished. Comments: Metadata Lookup Complete.

It is obviously a very low impact issue because, other than some red error lines in mythweb, the failure is invisible because everything updates correctly despite the reported failure. But it is curious.

Any suggestions or guidance greatly appreciated.

I am on fixes/0.28.
MythTV Version : v0.28.1-6-g7de03a9-dirty
MythTV Branch : fixes/0.28
Network Protocol : 88
Library API : 0.28.20161120-1
QT Version : 5.6.1
Options compiled in:
 linux profile use_hidesyms using_alsa using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_bindings_python using_bindings_php using_dvb using_frontend using_hdhomerun using_vbox using_ceton using_hdpvr using_ivtv using_joystick_menu using_libcrypto using_libdns_sd using_libfftw3 using_libxml2 using_lirc using_mheg using_opengl using_opengl_video using_opengl_themepainter using_qtwebkit using_qtscript using_qtdbus using_sdl using_taglib using_v4l2 using_x11 using_xrandr using_xv using_profiletype using_systemd_notify using_bindings_perl using_bindings_python using_bindings_php using_freetype2 using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads using_mheg using_libass using_libxml2



More information about the mythtv-users mailing list