lms icon indicating copy to clipboard operation
lms copied to clipboard
verified publisher icon epoupon

Web UI unresponsive with Apache reverse proxy

Open MetroWind opened this issue 4 years ago • 4 comments

I run LMS 3.25.0 behind an Apache reverse proxy. But sometime the web UI would freeze when it was playing, i.e. there would be no response if I click any link, with a red "loading..." at the top right corner. I think it is a problem with my Apache configuration, because there was no problem when I directly connected to LMS. But I'm not sure what the correct config is.

My Apache config looks like this:

<VirtualHost *:9006>
    SSLCertificateFile ...
    SSLCertificateKeyFile ...
    <Proxy *>
         Order allow,deny
         Allow from all
    </Proxy>
    ProxyPreserveHost On
    AllowEncodedSlashes NoDecode
    ProxyPass /music http://10.10.10.30:5082/music nocanon
    ProxyPassReverse /music http://10.10.10.30:5082/music
</VirtualHost>

In the Apache error log, I see lines like these:

[proxy_http:error] [pid 84001:tid 140516231734848] (70007)The timeout specified has expired: [client 10.10.10.1:6727] AH01102: error reading status line from remote server 10.10.10.30:5082, referer: https://proxy.host:9006/music/release/243
[proxy:error] [pid 84001:tid 140516231734848] [client 10.10.10.1:6727] AH00898: Error reading from remote server returned by /music/, referer: https://proxy.host:9006/music/release/243

Not sure if this is relavent: the 10.10.10.1 IP in the log is my router. The client, server, and proxy are in 10.10.10.0/24.

Any ideas?

MetroWind avatar May 01 '21 00:05 MetroWind

Hi! Do you notice something in lms logs? Ìf not, can you try with all lms logs enabled? (Set log-config to "*" in lms.conf) Is it working again if you hit F5? By the way, do you use transcoding when the problem occurs?

epoupon avatar May 01 '21 06:05 epoupon

So, in the lms log this kind of message is repeated a lot:

[2021-May-04 22:26:37.807] 1 - [debug] - [UTILS] Job not complete! Next chunk offset = 46399488
[2021-May-04 22:26:37.809] 1 - [debug] - [UTILS] Written 65536 bytes
[2021-May-04 22:26:37.809] 1 - [debug] - [UTILS] Progress: 65536/60130476

When I refresh, the page reloads, and is responsive again, but the playback stops. And the log looks like this:

[2021-May-04 22:27:02.412] 1 - [error] "Http::ResponseContinuation: WebWriteEvent::Error"
[2021-May-04 22:27:02.412] 1 - [info] "WebRequest: took 26674.4 ms"
[2021-May-04 22:27:02.412] 1 - [info] "Wt: session created (#sessions = 3)"
[2021-May-04 22:27:02.412] 1 [/music/ wouH2nA9WSiBeWTa] [info] "WEnvironment: UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:88.0) Gecko/20100101 Firefox/88.0"
[2021-May-04 22:27:02.413] 1 - [info] "WebRequest: took 0.37 ms"
...

I don’t think it was transcoding. If I understand correctly there would be a exclamation mark somewhere in the playback control if it was transcoding?

MetroWind avatar May 04 '21 22:05 MetroWind

Yes indeed, something like that: image Looks like you are trying to read a big file? Does the problem occur only on big files? When you see "Http::ResponseContinuation: WebWriteEvent::Error" in the logs, what are the previous and when are they written?

I don't really know Apache, but getting logs would definitely help to understand why the connection is dropped

epoupon avatar May 05 '21 12:05 epoupon

In my tests it did seem to only occur on larger files.

I found a way to reliably reproduce it.

  1. Go into an album with some large files
  2. Restart LMS, the web UI also reloads
  3. Play a large file
  4. Jump to ~2 minutes
  5. Click the “Albums” link in the nav area at the top.

If I’m connected via my reverse proxy, the web UI hangs at this point. I have recorded the log files in both cases (connect directly and via reverse proxy), doing this. See https://gist.github.com/MetroWind/ac84d15a1f5068bb147526d0cccb9f6d. The gist contains two files:

  • bare.log, which is the log in the direct connection case,
  • and proxied.log for the reverse proxy case.

Also I noticed that in both logs there are occurrences of WebWriteEvent::Error, so maybe that’s not related.

In the Apache log, the only relevant error lines are

[Fri Jun 11 17:14:07.609533 2021] [proxy_http:error] [pid 259064:tid 139748542408256] (70007)The timeout specified has expired: [client 10.10.10.123:63120] AH01102: error reading status line from remote server 10.10.10.30:5082, referer: https://brighid.xeno:9006/music/release/89
[Fri Jun 11 17:14:07.609586 2021] [proxy:error] [pid 259064:tid 139748542408256] [client 10.10.10.123:63120] AH00898: Error reading from remote server returned by /music/, referer: https://brighid.xeno:9006/music/release/89

(Of course this is from the reverse proxy case.)

And the Apache access log from that test goes

10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 335872
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 729088
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 401408
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 1384448
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 794624
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 729088
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 270336
10.10.10.123 - - [11/Jun/2021:17:13:15 -0700] "GET /music/release/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvxy&rand=2&trackid=726 HTTP/2.0" 206 270336
10.10.10.123 - - [11/Jun/2021:17:13:07 -0700] "POST /music/?wtd=1bsHiT1YGnsuRiSw HTTP/2.0" 500 -
10.10.10.123 - - [11/Jun/2021:17:13:18 -0700] "POST /music/?wtd=1bsHiT1YGnsuRiSw HTTP/2.0" 200 227
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "POST /music/?wtd=1bsHiT1YGnsuRiSw HTTP/2.0" 200 -
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "POST /music/?wtd=1bsHiT1YGnsuRiSw HTTP/2.0" 200 2978
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=39&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=28&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=48&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=116&size=512 HTTP/2.0" 200 29467
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=20&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=50&size=512 HTTP/2.0" 200 86672
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=197&size=512 HTTP/2.0" 200 40241
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=109&size=512 HTTP/2.0" 200 53124
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=25&size=512 HTTP/2.0" 200 73934
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=167&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=42&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=124&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=234&size=512 HTTP/2.0" 200 18977
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=162&size=512 HTTP/2.0" 200 14418
10.10.10.123 - - [11/Jun/2021:17:14:07 -0700] "GET /music/?wtd=1bsHiT1YGnsuRiSw&request=resource&resource=oylyvy2&rand=0&releaseid=135&size=512 HTTP/2.0" 200 57870

MetroWind avatar Jun 12 '21 00:06 MetroWind

A lot of updates have been done since the issue has been created (on both lms and Wt sides) Please reopen if needed.

epoupon avatar Dec 17 '23 17:12 epoupon