Mythweb waits 12 seconds after establishing a new socket

Have a MythTV related problem? Ask for help from other MythTV users here.

Moderator: Forum Moderators

Post Reply
jlatz
Newcomer
Posts: 8
Joined: Thu Aug 09, 2018 4:48 am
United States of America

Mythweb waits 12 seconds after establishing a new socket

Post by jlatz »

I am hoping someone can help me out, because I'm out of ideas.

If I'm trying to use Mythweb as a remote control, it's about 30 seconds before I see a response from an arrow click. All I can tell from the frontend.log is that the system seems to consistently take 12 seconds to make up its mind after initiating a new connection:

Code: Select all

Aug  8 21:40:27 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext networkcontrol.cpp:372 (newConnection) NetworkControl: New connection established.
Aug  8 21:40:39 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext networkcontrol.cpp:337 (deleteClient) NetworkControl: Client Socket disconnected
Aug  8 21:40:40 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext networkcontrol.cpp:372 (newConnection) NetworkControl: New connection established.
Aug  8 21:40:52 Mythbox mythfrontend.real: mythfrontend[1631]: I HttpServer35 mythfexml.cpp:144 (GetScreenShot) Screen shot requested (960x0), format jpg
Aug  8 21:40:52 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext mythmainwindow.cpp:959 (SaveScreenShot) Saving screenshot to //var/lib/mythtv/tvscreenshots/myth-screenshot-XML.jpg (960x557)
Aug  8 21:40:52 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext mythmainwindow.cpp:963 (SaveScreenShot) MythMainWindow::screenShot succeeded
Aug  8 21:40:52 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext networkcontrol.cpp:337 (deleteClient) NetworkControl: Client Socket disconnected
jlatz
Newcomer
Posts: 8
Joined: Thu Aug 09, 2018 4:48 am
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by jlatz »

Should have included this:

MythTV Version : v29.1-31-g563a4b8
MythTV Branch : fixes/29
Network Protocol : 91
Library API : 29.20180316-1
QT Version : 5.5.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_crystalhd using_dvb using_firewire using_frontend using_hdhomerun using_vbox using_ceton using_hdpvr using_ivtv using_joystick_menu using_libcec 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_taglib using_v4l2 using_x11 using_xrandr using_xv using_profiletype using_systemd_notify using_systemd_journal using_bindings_perl using_bindings_python using_bindings_php using_freetype2 using_mythtranscode using_opengl using_vaapi using_vdpau using_ffmpeg_threads using_mheg using_libass using_libxml2 using_libmp3lame
User avatar
pgbennett
Developer
Posts: 503
Joined: Mon Apr 27, 2015 5:41 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by pgbennett »

I assume you refer to http://servername/mythweb/remote
I tried this, and it is instantaneous for me.
Perhaps you have a slow network. It seems to send screenshots every time, and this may be causing slowdowns if your network is slow.
It is rather a clunky interface. I do not think it can be usefully used as a remote control, expect perhaps for testing or unusual situations.
What are you trying to do? There may be a better solution.
User avatar
bill6502
Developer
Posts: 2307
Joined: Fri Feb 07, 2014 5:28 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by bill6502 »

Don't use it myself, but I do see the delay issue (Ubuntu 16.04/MythTV 30-Pre)

Peter and @ jlatz, would you look in /var/log/apache2/error.log and see if you've got lines similar to the below
(for each button-press.) My initial failure was with IPv6, so I tried IPv4 and see the same error.

Code: Select all

[Sat Aug 11 20:02:20.154121 2018] [:error] [pid 12355] [client 192.168.1.200:41826] PHP Warning:  Unknown: function '0' not found or invalid function name in Unknown on line 0, referer: http://192.168.1.204/mythweb/remote/keys
User avatar
pgbennett
Developer
Posts: 503
Joined: Mon Apr 27, 2015 5:41 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by pgbennett »

I have no error message like that. Very few messages in the log, no message appears more than once. Using Ubuntu 18.04 and MythTV 30-Pre.
User avatar
bill6502
Developer
Posts: 2307
Joined: Fri Feb 07, 2014 5:28 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by bill6502 »

Thanks Peter. I fired up mythweb on my 18.04 host and (after a few configuration fixes)
mine works too. The :error above is now a php7:warn, but there's no delay after
pressing the key. Seem OK to ignore it 'til a PHP guru can spot a fix.

On my 16.04 host, I found an extra link in /etc/apache2/sites-enabled
and it now looks like this:

Code: Select all

lrwxrwxrwx 1 root root 45 Apr 14  2015 000-default-mythbuntu.conf -> ../sites-available/000-default-mythbuntu.conf
lrwxrwxrwx 1 root root 35 Jun  4 07:07 default-ssl.conf -> ../sites-available/default-ssl.conf
lrwxrwxrwx 1 root root 31 Apr 14  2015 mythweb.conf -> ../sites-available/mythweb.conf
I did: sudo a2dissite 000-default.conf and now get the proper action in 16.04 too.
Restarted apache2 of course: sudo systemctl restart apache2.service
jlatz
Newcomer
Posts: 8
Joined: Thu Aug 09, 2018 4:48 am
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by jlatz »

Sorry, been traveling lately.

Actually, I am using https://servername/remote/keys, installed on 16.04.5 LTS

What I am perplexed about is I have had this box up and running for years, and this is new behavior. In the past, as Peter said - nearly instantaneous response. And I'm not sure exactly when this started (I don't use the box as much now that I've dumped cable, but still do to listen to radio and access stored media), so I'm stuck being able to roll back or diagnose properly.

No PHP error, but I am getting these:
[Thu Aug 16 20:55:55.025318 2018] [access_compat:error] [pid 3607] [client IP:60414] AH01797: client denied by server configuration: /var/www/servername/remote, referer: https://servername/remote/keys
[Thu Aug 16 20:55:55.025963 2018] [access_compat:error] [pid 3607] [client IP:60414] AH01797: client denied by server configuration: /var/www/servername/mythweb.php, referer: https://servername/remote/keys
[Thu Aug 16 20:55:55.026713 2018] [access_compat:error] [pid 3607] [client IP:60414] AH01797: client denied by server configuration: /var/www/servername/remote, referer: https://servername/remote/keys
[Thu Aug 16 20:56:07.632208 2018] [access_compat:error] [pid 3607] [client IP:60414] AH01797: client denied by server configuration: /var/www/servername/remote, referer: https://servername/remote/keys
[Thu Aug 16 20:56:07.632795 2018] [access_compat:error] [pid 3607] [client IP:60414] AH01797: client denied by server configuration: /var/www/servername/mythweb.php, referer: https://servername/remote/keys
[Thu Aug 16 20:56:07.633539 2018] [access_compat:error] [pid 3607] [client IP:60414] AH01797: client denied by server configuration: /var/www/servername/remote, referer: https://servername/remote/keys

But after the 12 seconds, it does respond.

I do note, I don't have the directory: /var/www/servername/remote; I do have the file /var/www/servername/modules/remote Issue?
User avatar
bill6502
Developer
Posts: 2307
Joined: Fri Feb 07, 2014 5:28 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by bill6502 »

I had the above errors, look in /etc/apache2/sites-enabled/*
and convert Order to Require similar to these:

Code: Select all

#Order deny,allow
#Deny from all
Require all denied
Require ip 127.0.0.0/8 192.168.0.0/16 ::1/128 fdf9:a66:2cd8:1::0/112
Only with your IPs. I read that just 127 and 192.168 are OK, but haven't
tried. Don't know about abbreviating the IPv6 addresses.
jlatz
Newcomer
Posts: 8
Joined: Thu Aug 09, 2018 4:48 am
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by jlatz »

Not an option for me - I use the same server to serve a couple of other vhosts, and have for a couple of years so I don't think that's the issue. Also, I can't find anything in any log that suggest that's the issue.

I've tried to increase the verbosity of output with
> /usr/bin/mythfrontend --service -v socket,upnp,system,network,http
looking for something implicit in the myth system. Can anyone give me advice on what flags to set to look for something in those twelve seconds between:

Code: Select all

Aug  8 21:40:27 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext networkcontrol.cpp:372 (newConnection) NetworkControl: New connection established.
Aug  8 21:40:39 Mythbox mythfrontend.real: mythfrontend[1631]: I CoreContext networkcontrol.cpp:337 (deleteClient) NetworkControl: Client Socket disconnected
User avatar
pgbennett
Developer
Posts: 503
Joined: Mon Apr 27, 2015 5:41 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by pgbennett »

I did some more testing and this is what I found:
MythTV V29 on Ubuntu 18.04 - very slow response as you have noted. After clicking a button on the screen wait at least 10 seconds before it takes effect on the frontend.
MythTV V30 (master) on Ubuntu 18.04 - instant response, including over wifi.

You can also control the frontend with "telnet computername 6546". I tested this with V29 and V30 and both are instantaneous, so the holdup is in the web server and not the frontend.
jlatz
Newcomer
Posts: 8
Joined: Thu Aug 09, 2018 4:48 am
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by jlatz »

Okay, got my AH01797 error from apache to go away by changing

Code: Select all

         Order              allow,deny
   #    Require all granted
         Satisfy all
to

Code: Select all

   #    Order              allow,deny
         Require all granted
         Satisfy all
But now I'm still left with a 12 second delay. Since in your troubleshooting, the one variable you changed was the MythTV version (29 to 30), but kept your OS & webserver constant, I'm curious to ask why you think this is not something intrinsic to the MythTV code?

I can find the v29 mythweb source code at mythtv.org - can you point me to the v30 mythweb source code so I can attempt to diff my way through to see if I can find something that way?
User avatar
pgbennett
Developer
Posts: 503
Joined: Mon Apr 27, 2015 5:41 pm
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by pgbennett »

MythTV source is at https://github.com/MythTV/mythtv (branch master is V30, brannch fixes/29 is v29)
Mythweb source is at https://github.com/MythTV/mythweb
jlatz
Newcomer
Posts: 8
Joined: Thu Aug 09, 2018 4:48 am
United States of America

Re: Mythweb waits 12 seconds after establishing a new socket

Post by jlatz »

Thanks. Mythweb (v29 or v30) really hasn't changed in a year - my behavior changed in the past couple of weeks. So discounting that for now.

Figured out how to enable verbose logging on mythfrontend (-v socket,network). I'm curious if someone can help me understand this:

Code: Select all

Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:372 (newConnection) NetworkControl: New connection established.
Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I MythSocketThread(-1) mythsocket.cpp:758 (WriteStringListReal) MythSocket(7fbdbc004730:53): write -> 53 58      MESSAGE[]:[]SYSTEM_EVENT NET_CTRL_CONNECTED SENDER servername
Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:434 (readClient) NetworkControl: emit commandReceived(query location)
Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:442 (receiveCommand) NetworkControl: NetworkControl::receiveCommand(query location)
Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I MythSocketThread(-1) mythsocket.cpp:959 (ReadStringListReal) MythSocket(7fbdbc004730:53): read  <- 53 2       OK
Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:434 (readClient) NetworkControl: emit commandReceived(query location)
Aug 19 10:14:22 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:442 (receiveCommand) NetworkControl: NetworkControl::receiveCommand(query location)
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:434 (readClient) NetworkControl: emit commandReceived(key down)
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:442 (receiveCommand) NetworkControl: NetworkControl::receiveCommand(key down)
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:434 (readClient) NetworkControl: emit commandReceived(exit)
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:442 (receiveCommand) NetworkControl: NetworkControl::receiveCommand(exit)
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:337 (deleteClient) NetworkControl: Client Socket disconnected
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I MythSocketThread(-1) mythsocket.cpp:758 (WriteStringListReal) MythSocket(7fbdbc004730:53): write -> 53 61      MESSAGE[]:[]SYSTEM_EVENT NET_CTRL_DISCONNECTED SENDER servername
Aug 19 10:14:34 Mythbox mythfrontend.real: mythfrontend[6949]: I MythSocketThread(-1) mythsocket.cpp:959 (ReadStringListReal) MythSocket(7fbdbc004730:53): read  <- 53 2       OK
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:372 (newConnection) NetworkControl: New connection established.
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I MythSocketThread(-1) mythsocket.cpp:758 (WriteStringListReal) MythSocket(7fbdbc004730:53): write -> 53 58      MESSAGE[]:[]SYSTEM_EVENT NET_CTRL_CONNECTED SENDER servername
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:434 (readClient) NetworkControl: emit commandReceived(query location)
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:442 (receiveCommand) NetworkControl: NetworkControl::receiveCommand(query location)
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:434 (readClient) NetworkControl: emit commandReceived(query location)
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I CoreContext networkcontrol.cpp:442 (receiveCommand) NetworkControl: NetworkControl::receiveCommand(query location)
Aug 19 10:14:35 Mythbox mythfrontend.real: mythfrontend[6949]: I MythSocketThread(-1) mythsocket.cpp:959 (ReadStringListReal) MythSocket(7fbdbc004730:53): read  <- 53 2       OK
Why does NetworkControl::receiveCommand(query location) exist twice, and why does it seem the first instantiation resolves itself instantaneously, and the second takes the 12 seconds to resolve?
Post Reply