You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Stefan Eissing <st...@greenbytes.de> on 2018/02/14 16:16:18 UTC

something amiss in 2.4.x

In my h2 test suite, I get on the 2.4.x branch a no longer working propxy setup.

error_log shows
[Wed Feb 14 17:11:35.996712 2018] [proxy:warn] [pid 69638:tid 123145425334272] [client 127.0.0.1:50616] AH01144: No protocol handler was valid for the URL /proxy/index.html (scheme 'balancer'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule.

Same setup works flawlessly on trunk.

config basically is

    <Proxy "balancer://http-local">
        BalancerMember "http://127.0.0.1:12345" hcmethod=GET hcuri=/
    </Proxy>

    <VirtualHost...>

      ProxyPass "/proxy" "balancer://http-local"
      ProxyPassReverse "/proxy" "balancer://http-local"
    </VirtualHost>

Compiled clean several times already. Did we miss something on the backport?

-Stefan


Re: something amiss in 2.4.x

Posted by Yann Ylavic <yl...@gmail.com>.
On Thu, Feb 15, 2018 at 2:16 PM, Stefan Eissing
<st...@greenbytes.de> wrote:
> Yep, that's it. Should listen to you more... :)
>
> I think we need that backported than, right?

+1

Re: something amiss in 2.4.x

Posted by Jim Jagielski <ji...@jaguNET.com>.
+1 (plus after all this is done, a ap_mmn.h bump to accommodate
all the struct changes).

> On Feb 15, 2018, at 8:16 AM, Stefan Eissing <st...@greenbytes.de> wrote:
> 
> Yep, that's it. Should listen to you more... :)
> 
> I think we need that backported than, right?
> 
>> Am 15.02.2018 um 14:11 schrieb Yann Ylavic <yl...@gmail.com>:
>> 
>> On Thu, Feb 15, 2018 at 2:03 PM, Stefan Eissing
>> <st...@greenbytes.de> wrote:
>>> On my MacOS:
>>> 
>>> r1824180 of mod_slotmem_shm.c exhibits the problem described
>>> r1824179 of mod_slotmem_shm.c works
>>> 
>>> This is really strange since r1824180 in 2.4.x is identical trunk, afaict.
>>> 
>>> Tried restarting server, manually deleting the slotmem files, rebooting
>>> the machine, all the same.
>>> 
>>> Anyone a guess where I should look?
>> 
>> Did you try applying r1667707 ?
>> Your previous log showed empty workers ("AH01172:
>> balancer://https-local: worker () rewritten to /002.jpg"), which looks
>> symptomatic to me.
>> 
>> With new mod_slotmem_shm it's really crucial to not have duplicates,
>> previously maybe the attach worked around this (not debugged there
>> though, only a guess).
> 


Re: something amiss in 2.4.x

Posted by Stefan Eissing <st...@greenbytes.de>.
Yep, that's it. Should listen to you more... :)

I think we need that backported than, right?

> Am 15.02.2018 um 14:11 schrieb Yann Ylavic <yl...@gmail.com>:
> 
> On Thu, Feb 15, 2018 at 2:03 PM, Stefan Eissing
> <st...@greenbytes.de> wrote:
>> On my MacOS:
>> 
>> r1824180 of mod_slotmem_shm.c exhibits the problem described
>> r1824179 of mod_slotmem_shm.c works
>> 
>> This is really strange since r1824180 in 2.4.x is identical trunk, afaict.
>> 
>> Tried restarting server, manually deleting the slotmem files, rebooting
>> the machine, all the same.
>> 
>> Anyone a guess where I should look?
> 
> Did you try applying r1667707 ?
> Your previous log showed empty workers ("AH01172:
> balancer://https-local: worker () rewritten to /002.jpg"), which looks
> symptomatic to me.
> 
> With new mod_slotmem_shm it's really crucial to not have duplicates,
> previously maybe the attach worked around this (not debugged there
> though, only a guess).


Re: something amiss in 2.4.x

Posted by Yann Ylavic <yl...@gmail.com>.
On Thu, Feb 15, 2018 at 2:03 PM, Stefan Eissing
<st...@greenbytes.de> wrote:
> On my MacOS:
>
> r1824180 of mod_slotmem_shm.c exhibits the problem described
> r1824179 of mod_slotmem_shm.c works
>
> This is really strange since r1824180 in 2.4.x is identical trunk, afaict.
>
> Tried restarting server, manually deleting the slotmem files, rebooting
> the machine, all the same.
>
> Anyone a guess where I should look?

Did you try applying r1667707 ?
Your previous log showed empty workers ("AH01172:
balancer://https-local: worker () rewritten to /002.jpg"), which looks
symptomatic to me.

With new mod_slotmem_shm it's really crucial to not have duplicates,
previously maybe the attach worked around this (not debugged there
though, only a guess).

Re: something amiss in 2.4.x

Posted by Stefan Eissing <st...@greenbytes.de>.
On my MacOS:

r1824180 of mod_slotmem_shm.c exhibits the problem described
r1824179 of mod_slotmem_shm.c works

This is really strange since r1824180 in 2.4.x is identical trunk, afaict.

Tried restarting server, manually deleting the slotmem files, rebooting
the machine, all the same.

Anyone a guess where I should look?



> Am 15.02.2018 um 01:03 schrieb Yann Ylavic <yl...@gmail.com>:
> 
> On Wed, Feb 14, 2018 at 6:08 PM, Stefan Eissing
> <st...@greenbytes.de> wrote:
>> 
>> This looks not right, certainly? Seems like the balancer hook is not invoked on the request. But later on connection release, it is?
> 
> Different PIDs, the error is in the main server while hcheck
> (watchdog) is running.
> 
>> 
>> Not really the expert here. Need to run now, will check this again tomorrow.
> 
> You may need http://svn.apache.org/r1667707
> Without it, I got strange mergings with your configuration (global
> <Proxy balancer:...> ProxyPass'ed in <VirtualHost>), where each global
> balancer is added twice in the vhost config (the second is
> empty/incomplete and makes SHMs names collide, so the first one gets
> reset because of wrong sizes). Kind of "undefined behaviour" land, I
> suppose :/


Re: something amiss in 2.4.x

Posted by Yann Ylavic <yl...@gmail.com>.
On Wed, Feb 14, 2018 at 6:08 PM, Stefan Eissing
<st...@greenbytes.de> wrote:
>
> This looks not right, certainly? Seems like the balancer hook is not invoked on the request. But later on connection release, it is?

Different PIDs, the error is in the main server while hcheck
(watchdog) is running.

>
> Not really the expert here. Need to run now, will check this again tomorrow.

You may need http://svn.apache.org/r1667707
Without it, I got strange mergings with your configuration (global
<Proxy balancer:...> ProxyPass'ed in <VirtualHost>), where each global
balancer is added twice in the vhost config (the second is
empty/incomplete and makes SHMs names collide, so the first one gets
reset because of wrong sizes). Kind of "undefined behaviour" land, I
suppose :/

Re: something amiss in 2.4.x

Posted by Stefan Eissing <st...@greenbytes.de>.
Adding
Index: modules/proxy/mod_proxy_balancer.c
===================================================================
--- modules/proxy/mod_proxy_balancer.c	(revision 1824256)
+++ modules/proxy/mod_proxy_balancer.c	(working copy)
@@ -1117,6 +1117,7 @@
     const char *action;
     apr_status_t rv;
 
+    ap_log_rerror(APLOG_MARK, APLOG_TRACE1, 0, r, "check, if request for balancer");
     /* is this for us? */
     if (strcmp(r->handler, "balancer-manager")) {
         return DECLINED;

and config
LogLevel proxy:trace1
LogLevel proxy_balancer:trace1

I get for a request against https://test.example.org:12346/proxy/002.jpg

[Wed Feb 14 18:04:09.231668 2018] [proxy:trace1] [pid 62513:tid 123145351254016] mod_proxy.c(749): [client 127.0.0.1:51975] AH03464: URI path '/proxy/002.jpg' matches proxy handler 'proxy:balancer://https-local/002.jpg', referer: https://test.example.org:12346/
[Wed Feb 14 18:04:09.231800 2018] [proxy_balancer:trace1] [pid 62513:tid 123145351254016] mod_proxy_balancer.c(85): [client 127.0.0.1:51975] canonicalising URL //https-local/002.jpg, referer: https://test.example.org:12346/
[Wed Feb 14 18:04:09.231821 2018] [proxy_balancer:debug] [pid 62513:tid 123145351254016] mod_proxy_balancer.c(632): [client 127.0.0.1:51975] AH01172: balancer://https-local: worker () rewritten to /002.jpg, referer: https://test.example.org:12346/
[Wed Feb 14 18:04:09.231830 2018] [proxy:debug] [pid 62513:tid 123145351254016] proxy_util.c(1772): AH00924: worker  shared already initialized
[Wed Feb 14 18:04:09.231837 2018] [proxy:debug] [pid 62513:tid 123145351254016] proxy_util.c(1814): AH00926: worker  local already initialized
[Wed Feb 14 18:04:09.231845 2018] [proxy:debug] [pid 62513:tid 123145351254016] mod_proxy.c(1229): [client 127.0.0.1:51975] AH01143: Running scheme balancer handler (attempt 0), referer: https://test.example.org:12346/
[Wed Feb 14 18:04:09.231854 2018] [proxy:warn] [pid 62513:tid 123145351254016] [client 127.0.0.1:51975] AH01144: No protocol handler was valid for the URL /proxy/002.jpg (scheme 'balancer'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule., referer: https://test.example.org:12346/
[Wed Feb 14 18:04:09.231862 2018] [proxy_balancer:debug] [pid 62513:tid 123145351254016] mod_proxy_balancer.c(689): [client 127.0.0.1:51975] AH01176: proxy_balancer_post_request for (balancer://https-local), referer: https://test.example.org:12346/
[Wed Feb 14 18:04:34.139205 2018] [proxy:debug] [pid 62476:tid 123145336594432] proxy_util.c(2154): AH00942: HCOH: has acquired connection for (127.0.0.1)
[Wed Feb 14 18:04:34.139506 2018] [proxy:debug] [pid 62476:tid 123145336594432] proxy_util.c(2883): AH02824: HCOH: connection established with 127.0.0.1:12345 (127.0.0.1)
[Wed Feb 14 18:04:34.139546 2018] [proxy:debug] [pid 62476:tid 123145336594432] proxy_util.c(3053): AH00962: HCOH: connection complete to 127.0.0.1:12345 (127.0.0.1)
[Wed Feb 14 18:04:34.139673 2018] [proxy_balancer:trace1] [pid 62513:tid 123145356083200] mod_proxy_balancer.c(1120): [client 127.0.0.1:51985] check, if request for balancer
[Wed Feb 14 18:04:34.139876 2018] [proxy:debug] [pid 62476:tid 123145336594432] proxy_util.c(2169): AH00943: HCOH: has released connection for (127.0.0.1)

This looks not right, certainly? Seems like the balancer hook is not invoked on the request. But later on connection release, it is?

Not really the expert here. Need to run now, will check this again tomorrow.
Cheers,

-Stefan


> Am 14.02.2018 um 17:36 schrieb Yann Ylavic <yl...@gmail.com>:
> 
> On Wed, Feb 14, 2018 at 5:16 PM, Stefan Eissing
> <st...@greenbytes.de> wrote:
>> In my h2 test suite, I get on the 2.4.x branch a no longer working propxy setup.
>> 
>> error_log shows
>> [Wed Feb 14 17:11:35.996712 2018] [proxy:warn] [pid 69638:tid 123145425334272] [client 127.0.0.1:50616] AH01144: No protocol handler was valid for the URL /proxy/index.html (scheme 'balancer'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule.
>> 
>> Same setup works flawlessly on trunk.
>> 
>> config basically is
>> 
>>    <Proxy "balancer://http-local">
>>        BalancerMember "http://127.0.0.1:12345" hcmethod=GET hcuri=/
>>    </Proxy>
>> 
>>    <VirtualHost...>
>> 
>>      ProxyPass "/proxy" "balancer://http-local"
>>      ProxyPassReverse "/proxy" "balancer://http-local"
>>    </VirtualHost>
>> 
>> Compiled clean several times already. Did we miss something on the backport?
> 
> Hmm, this works here.
> Don't you have some builtin mod_proxy_* module (e.g.
> enable-proxy_balancer=static or alike)?


Re: something amiss in 2.4.x

Posted by Yann Ylavic <yl...@gmail.com>.
On Wed, Feb 14, 2018 at 5:16 PM, Stefan Eissing
<st...@greenbytes.de> wrote:
> In my h2 test suite, I get on the 2.4.x branch a no longer working propxy setup.
>
> error_log shows
> [Wed Feb 14 17:11:35.996712 2018] [proxy:warn] [pid 69638:tid 123145425334272] [client 127.0.0.1:50616] AH01144: No protocol handler was valid for the URL /proxy/index.html (scheme 'balancer'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule.
>
> Same setup works flawlessly on trunk.
>
> config basically is
>
>     <Proxy "balancer://http-local">
>         BalancerMember "http://127.0.0.1:12345" hcmethod=GET hcuri=/
>     </Proxy>
>
>     <VirtualHost...>
>
>       ProxyPass "/proxy" "balancer://http-local"
>       ProxyPassReverse "/proxy" "balancer://http-local"
>     </VirtualHost>
>
> Compiled clean several times already. Did we miss something on the backport?

Hmm, this works here.
Don't you have some builtin mod_proxy_* module (e.g.
enable-proxy_balancer=static or alike)?

Re: something amiss in 2.4.x

Posted by Stefan Eissing <st...@greenbytes.de>.
balancer is loaded and has the same creation times than the others in my modules directory. hmm...

> Am 14.02.2018 um 17:19 schrieb Graham Leggett <mi...@sharp.fm>:
> 
> On 14 Feb 2018, at 6:16 PM, Stefan Eissing <st...@greenbytes.de> wrote:
> 
>> In my h2 test suite, I get on the 2.4.x branch a no longer working propxy setup.
>> 
>> error_log shows
>> [Wed Feb 14 17:11:35.996712 2018] [proxy:warn] [pid 69638:tid 123145425334272] [client 127.0.0.1:50616] AH01144: No protocol handler was valid for the URL /proxy/index.html (scheme 'balancer'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule.
> 
> Looks like mod_proxy_balancer module is missing from the test - did you include mod_proxy_balancer in your v2.4.x build? I suspect httpd-test isn’t skipping the test if mod_proxy_balancer doesn’t exist.
> 
> Regards,
> Graham
> —
> 


Re: something amiss in 2.4.x

Posted by Graham Leggett <mi...@sharp.fm>.
On 14 Feb 2018, at 6:16 PM, Stefan Eissing <st...@greenbytes.de> wrote:

> In my h2 test suite, I get on the 2.4.x branch a no longer working propxy setup.
> 
> error_log shows
> [Wed Feb 14 17:11:35.996712 2018] [proxy:warn] [pid 69638:tid 123145425334272] [client 127.0.0.1:50616] AH01144: No protocol handler was valid for the URL /proxy/index.html (scheme 'balancer'). If you are using a DSO version of mod_proxy, make sure the proxy submodules are included in the configuration using LoadModule.

Looks like mod_proxy_balancer module is missing from the test - did you include mod_proxy_balancer in your v2.4.x build? I suspect httpd-test isn’t skipping the test if mod_proxy_balancer doesn’t exist.

Regards,
Graham
—