0.31 backend constant crashes and/or non responsive

[mikenick42]

I just upgrade from Ubuntu 16.04 to 20.04 and from mythtv 0.30 to 0.31. Now I'm getting this email every 10 minutes:

Subject: Cron <root@host> [ -x /usr/sbin/mythtv-update-motd ] && /usr/sbin/mythtv-update-motd > /dev/null

Our child has stopped talking to us, kill it off.
Unknown error during retrieval of status from the MythTV backend.

Running mythtv-status on that machine gives the same message.

Any help is appreciated.

[bill6502]

mythtv-status isn't a MythTV product, but looking at it, the test seems to be
the equivalent of:

Code: Select all

curl localhost:6544/Status/GetStatus?xml # From the commandline
http://localhost:6544/Status/GetStatus?xml # From your favorite browser

I'd one or both of the above for starters. localhost can be replaced by an IP or hostname
and run from another machine.

[mikenick42]

Oh wow, I've been using mythtv for probably 15 years and just assumed mythtv-status was part of it.
Running those commands is a bit slower than I would expect, but they both put out basically http://mythweb/status without the pretty formatting. I guess that means it's working and I should figure out how to kill off/uninstall mythtv-status?

[bill6502]

I should ask is the backend really down? systemctl status mythtv-backend

My tests were on a 20.04 host on master (v32-Pre) and mythtv-status --version
returns 1.0.1.

Could be that I don't speak Perl enough. I'm looking at line 1317 in /usr/bin/mythtv-status
and an alarm is set for 10 seconds. If your response was slower than that, I'd look for the
cause if it.

When I run /usr/bin/mythtv-status from the command line, the response is nearly immediate.

You can increase the logging on a running backend with: mythbackend --setverbose http,upnp

Lines like these should be there, with reasonable timestamps:

Code: Select all

2020-06-01 19:57:40.621044 I [7854/7854] CoreContext httpserver.cpp:460 (HttpWorker) - HttpWorker(43): New connection
2020-06-01 19:57:40.637462 I [7854/27611] HttpServer43 httprequest.cpp:1308 (ParseRequest) - (Request Header) connection: TE, close
2020-06-01 19:57:40.637464 I [7854/27611] HttpServer43 httprequest.cpp:1308 (ParseRequest) - (Request Header) host: localhost:6544
2020-06-01 19:57:40.637465 I [7854/27611] HttpServer43 httprequest.cpp:1308 (ParseRequest) - (Request Header) te: deflate,gzip;q=0.3
2020-06-01 19:57:40.637467 I [7854/27611] HttpServer43 httprequest.cpp:1308 (ParseRequest) - (Request Header) user-agent: libwww-perl/6.43
2020-06-01 19:57:40.637489 I [7854/27611] HttpServer43 httprequest.cpp:1620 (ExtractMethodFromURL) - ExtractMethodFromURL(end) : GetStatus : /Status
2020-06-01 19:57:40.641357 I [7854/27611] HttpServer43 httprequest.cpp:343 (SendResponse) - HTTPRequest::SendResponse(xml/html) () :200 OK -> 127.0.0.1: 1
2020-06-01 19:57:40.642505 W [7854/27611] HttpServer43 httpserver.cpp:637 (run) - HttpWorker(43): Error The remote host closed the connection (1)
2020-06-01 19:57:40.642511 I [7854/27611] HttpServer43 httpserver.cpp:685 (run) - HttpWorker(43): Connection -1 closed. 1 requests were handled

Turn off the extra logging with: mythbackend --setverbose http:alert,upnp:alert

[mikenick42]

With that, /var/log/mythtv/mythbackend.log offers this. So after 20 seconds, the client calls it off.
mythbackend --version gives v31.0+fixes.202005251708.fc90482~ubuntu20.04.1, it's the latest from the ppa.
mythtv-status is also giving 1.0.1.

It looks like the backend is running, but is not as responsive as it used to be. According to htop, mysqld is pegging one of the processors at 100% during that curl command. During the upgrade I did have to comment out the query_cache_type and query_cache_size lines from mythtv-tweaks.cnf
My backend is running on an E7400 Core2Duo with 4GB or RAM, so not exactly the latest-and-greatest, but up until now has been fast enough to not cause any problems.

Code: Select all

Jun  1 21:36:43 backend mythbackend: mythbackend[2671]: I CoreContext httpserver.cpp:460 (HttpWorker) HttpWorker(47): New connection
Jun  1 21:36:43 backend mythbackend: mythbackend[2671]: I HttpServer47 httprequest.cpp:1118 (GetParameters) sParams: 'xml'
Jun  1 21:36:43 backend mythbackend: mythbackend[2671]: I HttpServer47 httprequest.cpp:1308 (ParseRequest) (Request Header) accept: */*
Jun  1 21:36:43 backend mythbackend: mythbackend[2671]: I HttpServer47 httprequest.cpp:1308 (ParseRequest) (Request Header) host: backend:6544
Jun  1 21:36:43 backend mythbackend: mythbackend[2671]: I HttpServer47 httprequest.cpp:1308 (ParseRequest) (Request Header) user-agent: curl/7.68.0
Jun  1 21:36:43 backend mythbackend: mythbackend[2671]: I HttpServer47 httprequest.cpp:1620 (ExtractMethodFromURL) ExtractMethodFromURL(end) : GetStatus : /Status
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I CoreContext httpserver.cpp:460 (HttpWorker) HttpWorker(50): New connection
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) connection: close
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) content-length: 0
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) host: backend-ip:6544
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1620 (ExtractMethodFromURL) ExtractMethodFromURL(end) : getDeviceDesc : /
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:343 (SendResponse) HTTPRequest::SendResponse(xml/html) () :200 OK -> upnp(I think): 1
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httpserver.cpp:685 (run) HttpWorker(50): Connection 50 closed. 1 requests were handled
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I CoreContext httpserver.cpp:460 (HttpWorker) HttpWorker(50): New connection
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) connection: close
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) content-length: 0
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) host: backend-ip:6544
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1620 (ExtractMethodFromURL) ExtractMethodFromURL(end) : getDeviceDesc : /
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:343 (SendResponse) HTTPRequest::SendResponse(xml/html) () :200 OK -> upnp(I think): 1
Jun  1 21:37:00 backend mythbackend: mythbackend[2671]: I HttpServer50 httpserver.cpp:685 (run) HttpWorker(50): Connection 50 closed. 1 requests were handled
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I CoreContext httpserver.cpp:460 (HttpWorker) HttpWorker(50): New connection
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) connection: close
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) content-length: 0
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) host: backend-ip:6544
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1620 (ExtractMethodFromURL) ExtractMethodFromURL(end) : getDeviceDesc : /
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:343 (SendResponse) HTTPRequest::SendResponse(xml/html) () :200 OK -> upnp(I think): 1
Jun  1 21:37:01 backend mythbackend: mythbackend[2671]: I HttpServer50 httpserver.cpp:685 (run) HttpWorker(50): Connection 50 closed. 1 requests were handled
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I CoreContext httpserver.cpp:460 (HttpWorker) HttpWorker(50): New connection
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) connection: close
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) content-length: 0
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1308 (ParseRequest) (Request Header) host: backend-ip:6544
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:1620 (ExtractMethodFromURL) ExtractMethodFromURL(end) : getDeviceDesc : /
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I HttpServer50 httprequest.cpp:343 (SendResponse) HTTPRequest::SendResponse(xml/html) () :200 OK -> upnp(I think): 1
Jun  1 21:37:02 backend mythbackend: mythbackend[2671]: I HttpServer50 httpserver.cpp:685 (run) HttpWorker(50): Connection 50 closed. 1 requests were handled
Jun  1 21:37:03 backend mythbackend: mythbackend[2671]: I HttpServer47 httprequest.cpp:343 (SendResponse) HTTPRequest::SendResponse(xml/html) () :200 OK -> client: 1
Jun  1 21:37:03 backend mythbackend: mythbackend[2671]: W HttpServer47 httpserver.cpp:637 (run) HttpWorker(47): Error The remote host closed the connection (1)
Jun  1 21:37:03 backend mythbackend: mythbackend[2671]: I HttpServer47 httpserver.cpp:685 (run) HttpWorker(47): Connection -1 closed. 1 requests were handled

[bill6502]

sudo /usr/bin/mysqlcheck --defaults-extra-file=/etc/mysql/debian.cnf mythconverg (and mysqlrepair)
for starters.

Could be clues in /etc/log/mysql/error.log.

I haven't heard of it causing an issue, but do you have an /etc/mysql/conf.d/mythconverg.cnf file
with:

Code: Select all

[mysqld]
binlog-ignore-db=mythconverg

in it (to turn off binary logging.)

[mikenick42]

mysqlcheck seems to indicate that everything is ok.
mysqlrepair returns mostly ok, with some instances of

Code: Select all

note  : The storage engine for the table doesn't support repair

I do have a mythconverg.cnf file with

Code: Select all

binlog-ignore-db=mythconverg

in it.

[bill6502]

You can add the .cnf file. It was intended to be done automatically. Then stop the backend and restart SQL.

Anything clues in /etc/log/mysql/error.log. Or: journalctl -b --unit mysql --unit mariadb

[mikenick42]

I'm not sure what you mean by add the cnf file, it already exists. Should it be included by my.cnf? I didn't check to see if that were the case.

The last error log with anything useful is a couple days old, and the only stuff that looked relevant was this that showed up from time to time:

Code: Select all

2020-06-01T22:05:50.324481Z 0 [Warning] [MY-000081] [Server] option 'net_buffer_length': unsigned value 8388608 adjusted to 1048576.
2020-06-01T22:05:50.324533Z 0 [Warning] [MY-011068] [Server] The syntax 'expire-logs-days' is deprecated and will be removed in a future release. Please use binlog_expire_logs_seconds instead.
2020-06-01T22:05:50.332484Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.20-0ubuntu0.20.04.1) starting as process 2419
2020-06-01T22:05:50.399318Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2020-06-01T22:05:53.027797Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2020-06-01T22:05:53.727946Z 0 [ERROR] [MY-013180] [Server] Function 'archive' already exists.
2020-06-01T22:05:53.728335Z 0 [Warning] [MY-010736] [Server] Couldn't load plugin named 'archive' with soname 'ha_archive.so'.
2020-06-01T22:05:53.728558Z 0 [ERROR] [MY-013180] [Server] Function 'blackhole' already exists.
2020-06-01T22:05:53.728747Z 0 [Warning] [MY-010736] [Server] Couldn't load plugin named 'blackhole' with soname 'ha_blackhole.so'.
2020-06-01T22:05:53.728944Z 0 [ERROR] [MY-013180] [Server] Function 'federated' already exists.
2020-06-01T22:05:53.729205Z 0 [Warning] [MY-010736] [Server] Couldn't load plugin named 'federated' with soname 'ha_federated.so'.
2020-06-01T22:05:53.730312Z 0 [ERROR] [MY-013180] [Server] Function 'innodb' already exists.
2020-06-01T22:05:53.730577Z 0 [Warning] [MY-010736] [Server] Couldn't load plugin named 'innodb' with soname 'ha_innodb.so'.

[mikenick42]

One thing I have noticed in the past is that when it's attempting to record a channel that I don't get, it can get sluggish briefly.
That is happening a lot right now because I need to clean up my listings. Could that be related?

Edit: Nope, that wasn't it.

[mikenick42]

I ended up uninstalling mythtv-status and have at least stopped getting the emails.
On mythweb, it seems like loading the "Backend Status" page goes really slowly compared to "Listings", "Upcoming Recordings", or "Recorded Programs"
The Database settings page is also slow compared to the other settings pages.

It feels like there's a bad/corrupt table somewhere (though I'm certainly no expert) is there more troubleshooting and/or repair work that can be done on mysql to see what's slowing it down?

[wesnewell]

I had a corrupt mysql db recently and used phpmyadmin to repair it. mysqlrepair wouldn't repair it.

[mikenick42]

Ok, I have phpMyAdmin installed and can look a the database. I have no idea what to look for though.

[wesnewell]

Select mythconverg in the left panel. In the right panel, go to bottom and select check all. Then in the with selected box select check tables. If they all come back OK, you're good. If not, select the bad ones and try the repair tables.
A quicker option would be:
sudo mysqlcheck mythconverg from a terminal.

[mikenick42]

That comes back pretty quickly with everything ok.
At the page with a list of all databases, mythconverg is the only one reporting "not replicated" if that means anything.