Re: svn commit: r1676417 - /perl/modperl/trunk/src/modules/perl/modperl_interp.c

On 28 April 2015 at 07:51,  <[email protected]> wrote:
> Author: jkaluza
> Date: Tue Apr 28 06:51:12 2015
> New Revision: 1676417
>
> URL: http://svn.apache.org/r1676417
> Log:
> Initialize interp->refcnt to 1 in modperl_interp_select.
>
> Reasoning:
> 1. All calls of MP_INTERPa do not increment interp->refcnt, so refcnt
>    used to be 0 before this commit. But there is always matching
>    MP_INTERP_PUTBACK, which calls modperl_interp_unselect which decreases
>    the refcnt, so it was possible to get negative refcnt or crash with
>    threaded MPMs, because reference counting has been broken.
> 2. modperl_interp_select increases the refcount if it finds the PerlInterp in
>    ccfg, so it makes sense to increase it (it means set to 1) during
>    initialization too. Otherwise the refcnt would be incremented for the caller
>    in some cases, but wouldn't be in other.
>
> This commit fixes the crash seen on worker MPM when PerlInterp has been used
> by two threads and the first one freed PerlInterp during
> modperl_interp_unselect.
>
> Modified:
>     perl/modperl/trunk/src/modules/perl/modperl_interp.c
>

I cannot understand why, but since this patch was applied I find that
t\modules\proxy.t fails every time when I run the full "nmake test",
but it always succeeds when I run it in isolation so I'm at a loss to
find out what is going wrong. All other tests (apart from those known
Win32-specific failures documented in README) still pass. Reverting
the patch "fixes" the proxy.t problem, but probably isn't the right
solution.

Here's the output from "nmake test":

t\modules\proxy.t ....................... request has failed (the
response code was: 502)
see t/logs/error_log for more details
t\modules\proxy.t ....................... Dubious, test returned 9
(wstat 2304, 0x900)
Failed 1/1 subtests

And here's the verbose output:

t\modules\proxy.t .......................
# connecting to http://HPWIN7:8538/TestModules__proxy
1..1
# Running under perl version 5.020002 for MSWin32
# Current time local: Sun May 10 13:40:45 2015
# Current time GMT:   Sun May 10 12:40:45 2015
# Using Test.pm version 1.26
# Using Apache/Test.pm version 1.39
request has failed (the response code was: 502)
see t/logs/error_log for more details
Dubious, test returned 9 (wstat 2304, 0x900)
Failed 1/1 subtests

Finally I have this in the error_log, which clearly shows a one minute
timeout from 13:40:49 to 13:41:50:

[Sun May 10 13:40:47.913364 2015] [example_hooks:notice] [pid
49036:tid 1404] x_create_connection()
[Sun May 10 13:40:47.914364 2015] [example_hooks:notice] [pid
49036:tid 1404] x_create_request()
[Sun May 10 13:40:47.914364 2015] [authz_core:debug] [pid 49036:tid
1404] mod_authz_core.c(834): [client 192.168.1.3:51023] AH01628:
authorization result: granted (no directives)
[Sun May 10 13:40:47.914364 2015] [proxy:debug] [pid 49036:tid 1404]
mod_proxy.c(1161): [client 192.168.1.3:51023] AH01143: Running scheme
http handler (attempt 0)
[Sun May 10 13:40:47.914364 2015] [proxy_fcgi:debug] [pid 49036:tid
1404] mod_proxy_fcgi.c(859): [client 192.168.1.3:51023] AH01076: url:
http://hpwin7:8538/TestModules__proxy_real proxyname: (null)
proxyport: 0
[Sun May 10 13:40:47.914364 2015] [proxy_fcgi:debug] [pid 49036:tid
1404] mod_proxy_fcgi.c(864): [client 192.168.1.3:51023] AH01077:
declining URL http://hpwin7:8538/TestModules__proxy_real
[Sun May 10 13:40:47.914364 2015] [proxy_scgi:debug] [pid 49036:tid
1404] mod_proxy_scgi.c(516): [client 192.168.1.3:51023] AH00865:
declining URL http://hpwin7:8538/TestModules__proxy_real
[Sun May 10 13:40:47.914364 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2138): AH00942: HTTP: has acquired connection for (*)
[Sun May 10 13:40:47.914364 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2192): [client 192.168.1.3:51023] AH00944: connecting
http://hpwin7:8538/TestModules__proxy_real to hpwin7:8538
[Sun May 10 13:40:47.915364 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2393): [client 192.168.1.3:51023] AH00947: connected
/TestModules__proxy_real to hpwin7:8538
[Sun May 10 13:40:48.915421 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2758): (OS 10061)No connection could be made because the
target machine actively refused it.  : AH00957: HTTP: attempt to
connect to [fe80::cd76:804d:5c68:ef8c]:8538 (*) failed
[Sun May 10 13:40:49.916479 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2758): (OS 10061)No connection could be made because the
target machine actively refused it.  : AH00957: HTTP: attempt to
connect to [fe80::183a:1874:3f57:fefc]:8538 (*) failed
[Sun May 10 13:40:49.917479 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2767): AH02824: HTTP: connection established with
192.168.1.3:8538 (*)
[Sun May 10 13:40:49.917479 2015] [example_hooks:notice] [pid
49036:tid 1404] x_create_connection()
[Sun May 10 13:40:49.917479 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2921): AH00962: HTTP: connection complete to
[fe80::cd76:804d:5c68:ef8c]:8538 (hpwin7)
[Sun May 10 13:40:49.919479 2015] [example_hooks:notice] [pid
49036:tid 1440] x_create_connection()
[Sun May 10 13:40:49.919479 2015] [example_hooks:notice] [pid
49036:tid 1440] x_create_request()
[Sun May 10 13:41:50.418939 2015] [proxy_http:error] [pid 49036:tid
1404] (OS 10060)A connection attempt failed because the connected
party did not properly respond after a period of time, or established
connection failed because connected host has failed to respond.  :
[client 192.168.1.3:51023] AH01102: error reading status line from
remote server hpwin7:8538
[Sun May 10 13:41:50.418939 2015] [proxy_http:debug] [pid 49036:tid
1404] mod_proxy_http.c(1314): [client 192.168.1.3:51023] AH01103: read
timeout
[Sun May 10 13:41:50.418939 2015] [proxy_http:debug] [pid 49036:tid
1404] mod_proxy_http.c(1369): [client 192.168.1.3:51023] AH01105: NOT
Closing connection to client although reading from backend server
hpwin7:8538 failed.
[Sun May 10 13:41:50.418939 2015] [proxy:error] [pid 49036:tid 1404]
[client 192.168.1.3:51023] AH00898: Error reading from remote server
returned by http://HPWIN7:8538/TestModules__proxy_real
[Sun May 10 13:41:50.418939 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2153): AH00943: HTTP: has released connection for (*)
[Sun May 10 13:41:50.418939 2015] [proxy:debug] [pid 49036:tid 1404]
proxy_util.c(2863): [remote 192.168.1.3:8538] AH02642: proxy:
connection shutdown
[Sun May 10 13:41:50.418939 2015] [optional_fn_export:error] [pid
49036:tid 1404] AH01871: Optional function test said: GET
/TestModules__proxy HTTP/1.1
[Sun May 10 13:41:50.418939 2015] [optional_hook_import:error] [pid
49036:tid 1404] AH01866: Optional hook test said: GET
/TestModules__proxy HTTP/1.1
[Sun May 10 13:41:50.420939 2015] [authz_core:debug] [pid 49036:tid
1440] mod_authz_core.c(834): [client 192.168.1.3:51026] AH01628:
authorization result: granted (no directives)
[Sun May 10 13:41:50.420939 2015] [optional_fn_export:error] [pid
49036:tid 1440] AH01871: Optional function test said: GET
/TestModules__proxy_real HTTP/1.1
[Sun May 10 13:41:50.420939 2015] [optional_hook_import:error] [pid
49036:tid 1440] AH01866: Optional hook test said: GET
/TestModules__proxy_real HTTP/1.1