You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Rainer Jung <ra...@kippdata.de> on 2016/12/19 22:08:41 UTC
Strange http2 test error on Solaris with static linking
The test t/modules/http2.t fails consistently on Solaris when httpd is
statically linked. Results are based on 2.4.25.
Here is an excerpt from the truss output for the first test in http2.t
(all fail) starting around the first difference between the good and bad
case. The first log line indicating the problem is:
[Mon Dec 19 22:39:20.178603 2016] [http2:debug] [pid 9984:tid 52]
h2_session.c(1592): [client 127.0.0.1:64013] AH03466: h2_stream(215-1):
no response, RST_STREAM, err=1
Fail:
9984/20: open(".../t/htdocs/index.html", O_RDONLY|O_LARGEFILE) = 39
9984/20: fcntl(39, F_GETFD, 0x00000000) = 0
9984/20: fcntl(39, F_SETFD, 0x00000001) = 0
9984/20: getpid() = 9984
[9960]
9984/20: write(2, 0xFCE77970, 134) = 134
9984/20: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 7 4 8 8
2 0 1 6
9984/20: ] [ h e a d e r s : t r a c e 2 ] [ p i d 9 9 8
4 : t i d
9984/20: 2 0 ] m o d _ h e a d e r s . c ( 8 7 5 ) : A H
0 1 5 0 2
9984/20: : h e a d e r s : a p _ h e a d e r s _ o u t p u
t _ f i l
9984/20: t e r ( )\n
9984/20: getpid() = 9984
[9960]
9984/20: write(2, 0xFCE76AA8, 167) = 167
9984/20: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 7 9 0 9
2 0 1 6
9984/20: ] [ h t t p 2 : d e b u g ] [ p i d 9 9 8 4 : t
i d 2 0
9984/20: ] h 2 _ t a s k . c ( 8 8 ) : [ c l i e n t 1 2
7 . 0 . 0
9984/20: . 1 : 6 4 0 1 3 ] A H 0 3 3 4 8 : h 2 _ t a s k (
2 1 5 - 1
9984/20: ) : o p e n o u t p u t t o G E T l o c a l
h o s t :
9984/20: 8 5 4 6 /\n
9984/20: lwp_unpark(52) = 0
9984/52: lwp_park(0xFAE7BAA8, 0) Err#62 ETIME
9984/52: timeout: 0.000000000 sec
9984/20: lwp_unpark(52) = 0
9984/52: lwp_park(0x00000000, 0) = 0
9984/52: read(38, 0x00684688, 8000) Err#11
EAGAIN
9984/52: getpid() = 9984
[9960]
9984/52: write(2, 0xFAE77938, 169) = 169
9984/52: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 8 6 0 3
2 0 1 6
9984/52: ] [ h t t p 2 : d e b u g ] [ p i d 9 9 8 4 : t
i d 5 2
9984/52: ] h 2 _ s e s s i o n . c ( 1 5 9 2 ) : [ c l i e
n t 1 2
9984/52: 7 . 0 . 0 . 1 : 6 4 0 1 3 ] A H 0 3 4 6 6 : h 2 _
s t r e a
9984/52: m ( 2 1 5 - 1 ) : n o r e s p o n s e , R S T _
S T R E A
9984/52: M , e r r = 1\n
9984/52: getpid() = 9984
[9960]
9984/52: write(2, 0xFAE778D0, 206) = 206
9984/52: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 8 8 2 5
2 0 1 6
9984/52: ] [ h t t p 2 : d e b u g ] [ p i d 9 9 8 4 : t
i d 5 2
9984/52: ] h 2 _ s e s s i o n . c ( 6 6 1 ) : [ c l i e n
t 1 2 7
9984/52: . 0 . 0 . 1 : 6 4 0 1 3 ] A H 0 3 0 6 8 : h 2 _ s
e s s i o
9984/52: n ( 2 1 5 ) : s e n t F R A M E [ R S T _ S T R E
A M [ l e
9984/52: n g t h = 4 , f l a g s = 0 , s t r e a m = 1 ] ]
, f r a
9984/52: m e s = 3 / 3 ( r / s )\n
OK:
10047/11: open(".../t/htdocs/index.html", O_RDONLY|O_LARGEFILE) = 39
10047/11: fcntl(39, F_GETFD, 0x00000000) = 0
10047/11: fcntl(39, F_SETFD, 0x00000001) = 0
10047/11: getpid() = 10047
[10039]
10047/11: write(2, 0xFC377970, 135) = 135
10047/11: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 1 6 8 5 9
2 0 1 6
10047/11: ] [ h e a d e r s : t r a c e 2 ] [ p i d 1 0 0
4 7 : t i
10047/11: d 1 1 ] m o d _ h e a d e r s . c ( 8 7 5 ) : A
H 0 1 5 0
10047/11: 2 : h e a d e r s : a p _ h e a d e r s _ o u t p
u t _ f i
10047/11: l t e r ( )\n
10047/52: lwp_park(0xF9A7BAA8, 0) Err#62 ETIME
10047/52: timeout: 0.000000000 sec
10047/52: read(38, 0x003196D8, 8000) Err#11
EAGAIN
10047/11: getpid() = 10047
[10039]
10047/52: getpid() = 10047
[10039]
10047/11: write(2, 0xFC376AA8, 167) = 167
10047/11: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 3 6 5 4 5
2 0 1 6
10047/11: ] [ h t t p 2 : d e b u g ] [ p i d 1 0 0 4 7 :
t i d 1
10047/11: 1 ] h 2 _ t a s k . c ( 8 8 ) : [ c l i e n t 1
2 7 . 0 .
10047/11: 0 . 1 : 6 4 0 1 8 ] A H 0 3 3 4 8 : h 2 _ t a s k
( 8 7 - 1
10047/11: ) : o p e n o u t p u t t o G E T l o c a l
h o s t :
10047/11: 8 5 4 6 /\n
10047/52: write(2, 0xF9A77A00, 166) = 166
10047/52: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 3 6 5 7 0
2 0 1 6
10047/52: ] [ c o r e : t r a c e 6 ] [ p i d 1 0 0 4 7 :
t i d 5
10047/52: 2 ] c o r e _ f i l t e r s . c ( 5 2 5 ) : [ c l
i e n t
10047/52: 1 2 7 . 0 . 0 . 1 : 6 4 0 1 8 ] c o r e _ o u t p u
t _ f i l
10047/52: t e r : f l u s h i n g b e c a u s e o f F L
U S H b
10047/52: u c k e t\n
10047/52: read(38, 0x003196D8, 8000) Err#11
EAGAIN
10047/52: getpid() = 10047
[10039]
10047/52: write(2, 0xF9A77920, 184) = 184
10047/52: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 3 7 0 9 7
2 0 1 6
10047/52: ] [ h t t p 2 : d e b u g ] [ p i d 1 0 0 4 7 :
t i d 5
10047/52: 2 ] h 2 _ s e s s i o n . c ( 1 4 5 7 ) : [ c l i
e n t 1
10047/52: 2 7 . 0 . 0 . 1 : 6 4 0 1 8 ] A H 0 3 0 7 3 : h 2
_ s t r e
10047/52: a m ( 8 7 - 1 ) : s u b m i t r e s p o n s e 2
0 0 , R
10047/52: E M O T E _ W I N D O W _ S I Z E = 6 5 5 3 5\n
The communication seems to work in principle, so at least no obvious SSL
compatibility problem. Any ideas?
Regards,
Rainer
Re: Strange http2 test error on Solaris with static linking
Posted by Stefan Eissing <st...@greenbytes.de>.
Rainer,
this was sitting on my "to be investigated" pile for some time now. Sorry about that.
The log line indicates a code restructuring in processing responses that has since gotten 2 fixes in regard exactly such log lines. If you by occasion re-run the recent trunk/2.4.x again, I'd like to hear back if this is now also resolved. Thanks!
Cheers, Stefan
> Am 19.12.2016 um 23:08 schrieb Rainer Jung <ra...@kippdata.de>:
>
> The test t/modules/http2.t fails consistently on Solaris when httpd is statically linked. Results are based on 2.4.25.
>
> Here is an excerpt from the truss output for the first test in http2.t (all fail) starting around the first difference between the good and bad case. The first log line indicating the problem is:
>
> [Mon Dec 19 22:39:20.178603 2016] [http2:debug] [pid 9984:tid 52] h2_session.c(1592): [client 127.0.0.1:64013] AH03466: h2_stream(215-1): no response, RST_STREAM, err=1
>
> Fail:
>
> 9984/20: open(".../t/htdocs/index.html", O_RDONLY|O_LARGEFILE) = 39
> 9984/20: fcntl(39, F_GETFD, 0x00000000) = 0
> 9984/20: fcntl(39, F_SETFD, 0x00000001) = 0
> 9984/20: getpid() = 9984 [9960]
> 9984/20: write(2, 0xFCE77970, 134) = 134
> 9984/20: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 7 4 8 8 2 0 1 6
> 9984/20: ] [ h e a d e r s : t r a c e 2 ] [ p i d 9 9 8 4 : t i d
> 9984/20: 2 0 ] m o d _ h e a d e r s . c ( 8 7 5 ) : A H 0 1 5 0 2
> 9984/20: : h e a d e r s : a p _ h e a d e r s _ o u t p u t _ f i l
> 9984/20: t e r ( )\n
> 9984/20: getpid() = 9984 [9960]
> 9984/20: write(2, 0xFCE76AA8, 167) = 167
> 9984/20: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 7 9 0 9 2 0 1 6
> 9984/20: ] [ h t t p 2 : d e b u g ] [ p i d 9 9 8 4 : t i d 2 0
> 9984/20: ] h 2 _ t a s k . c ( 8 8 ) : [ c l i e n t 1 2 7 . 0 . 0
> 9984/20: . 1 : 6 4 0 1 3 ] A H 0 3 3 4 8 : h 2 _ t a s k ( 2 1 5 - 1
> 9984/20: ) : o p e n o u t p u t t o G E T l o c a l h o s t :
> 9984/20: 8 5 4 6 /\n
> 9984/20: lwp_unpark(52) = 0
> 9984/52: lwp_park(0xFAE7BAA8, 0) Err#62 ETIME
> 9984/52: timeout: 0.000000000 sec
> 9984/20: lwp_unpark(52) = 0
> 9984/52: lwp_park(0x00000000, 0) = 0
> 9984/52: read(38, 0x00684688, 8000) Err#11 EAGAIN
> 9984/52: getpid() = 9984 [9960]
> 9984/52: write(2, 0xFAE77938, 169) = 169
> 9984/52: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 8 6 0 3 2 0 1 6
> 9984/52: ] [ h t t p 2 : d e b u g ] [ p i d 9 9 8 4 : t i d 5 2
> 9984/52: ] h 2 _ s e s s i o n . c ( 1 5 9 2 ) : [ c l i e n t 1 2
> 9984/52: 7 . 0 . 0 . 1 : 6 4 0 1 3 ] A H 0 3 4 6 6 : h 2 _ s t r e a
> 9984/52: m ( 2 1 5 - 1 ) : n o r e s p o n s e , R S T _ S T R E A
> 9984/52: M , e r r = 1\n
> 9984/52: getpid() = 9984 [9960]
> 9984/52: write(2, 0xFAE778D0, 206) = 206
> 9984/52: [ M o n D e c 1 9 2 2 : 3 9 : 2 0 . 1 7 8 8 2 5 2 0 1 6
> 9984/52: ] [ h t t p 2 : d e b u g ] [ p i d 9 9 8 4 : t i d 5 2
> 9984/52: ] h 2 _ s e s s i o n . c ( 6 6 1 ) : [ c l i e n t 1 2 7
> 9984/52: . 0 . 0 . 1 : 6 4 0 1 3 ] A H 0 3 0 6 8 : h 2 _ s e s s i o
> 9984/52: n ( 2 1 5 ) : s e n t F R A M E [ R S T _ S T R E A M [ l e
> 9984/52: n g t h = 4 , f l a g s = 0 , s t r e a m = 1 ] ] , f r a
> 9984/52: m e s = 3 / 3 ( r / s )\n
>
>
> OK:
>
> 10047/11: open(".../t/htdocs/index.html", O_RDONLY|O_LARGEFILE) = 39
> 10047/11: fcntl(39, F_GETFD, 0x00000000) = 0
> 10047/11: fcntl(39, F_SETFD, 0x00000001) = 0
> 10047/11: getpid() = 10047 [10039]
> 10047/11: write(2, 0xFC377970, 135) = 135
> 10047/11: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 1 6 8 5 9 2 0 1 6
> 10047/11: ] [ h e a d e r s : t r a c e 2 ] [ p i d 1 0 0 4 7 : t i
> 10047/11: d 1 1 ] m o d _ h e a d e r s . c ( 8 7 5 ) : A H 0 1 5 0
> 10047/11: 2 : h e a d e r s : a p _ h e a d e r s _ o u t p u t _ f i
> 10047/11: l t e r ( )\n
> 10047/52: lwp_park(0xF9A7BAA8, 0) Err#62 ETIME
> 10047/52: timeout: 0.000000000 sec
> 10047/52: read(38, 0x003196D8, 8000) Err#11 EAGAIN
> 10047/11: getpid() = 10047 [10039]
> 10047/52: getpid() = 10047 [10039]
> 10047/11: write(2, 0xFC376AA8, 167) = 167
> 10047/11: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 3 6 5 4 5 2 0 1 6
> 10047/11: ] [ h t t p 2 : d e b u g ] [ p i d 1 0 0 4 7 : t i d 1
> 10047/11: 1 ] h 2 _ t a s k . c ( 8 8 ) : [ c l i e n t 1 2 7 . 0 .
> 10047/11: 0 . 1 : 6 4 0 1 8 ] A H 0 3 3 4 8 : h 2 _ t a s k ( 8 7 - 1
> 10047/11: ) : o p e n o u t p u t t o G E T l o c a l h o s t :
> 10047/11: 8 5 4 6 /\n
> 10047/52: write(2, 0xF9A77A00, 166) = 166
> 10047/52: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 3 6 5 7 0 2 0 1 6
> 10047/52: ] [ c o r e : t r a c e 6 ] [ p i d 1 0 0 4 7 : t i d 5
> 10047/52: 2 ] c o r e _ f i l t e r s . c ( 5 2 5 ) : [ c l i e n t
> 10047/52: 1 2 7 . 0 . 0 . 1 : 6 4 0 1 8 ] c o r e _ o u t p u t _ f i l
> 10047/52: t e r : f l u s h i n g b e c a u s e o f F L U S H b
> 10047/52: u c k e t\n
> 10047/52: read(38, 0x003196D8, 8000) Err#11 EAGAIN
> 10047/52: getpid() = 10047 [10039]
> 10047/52: write(2, 0xF9A77920, 184) = 184
> 10047/52: [ M o n D e c 1 9 2 2 : 4 1 : 3 6 . 9 3 7 0 9 7 2 0 1 6
> 10047/52: ] [ h t t p 2 : d e b u g ] [ p i d 1 0 0 4 7 : t i d 5
> 10047/52: 2 ] h 2 _ s e s s i o n . c ( 1 4 5 7 ) : [ c l i e n t 1
> 10047/52: 2 7 . 0 . 0 . 1 : 6 4 0 1 8 ] A H 0 3 0 7 3 : h 2 _ s t r e
> 10047/52: a m ( 8 7 - 1 ) : s u b m i t r e s p o n s e 2 0 0 , R
> 10047/52: E M O T E _ W I N D O W _ S I Z E = 6 5 5 3 5\n
>
> The communication seems to work in principle, so at least no obvious SSL compatibility problem. Any ideas?
>
> Regards,
>
> Rainer
Stefan Eissing
<green/>bytes GmbH
Hafenstrasse 16
48155 Münster
www.greenbytes.de