Newsgroups: php.internals Path: news.php.net Xref: news.php.net php.internals:45528 Return-Path: Mailing-List: contact internals-help@lists.php.net; run by ezmlm Delivered-To: mailing list internals@lists.php.net Received: (qmail 7997 invoked from network); 9 Sep 2009 03:10:36 -0000 Received: from unknown (HELO lists.php.net) (127.0.0.1) by localhost with SMTP; 9 Sep 2009 03:10:36 -0000 Authentication-Results: pb1.pair.com header.from=hack988@dev.htwap.com; sender-id=unknown Authentication-Results: pb1.pair.com smtp.mail=hack988@dev.htwap.com; spf=permerror; sender-id=unknown Received-SPF: error (pb1.pair.com: domain dev.htwap.com from 209.85.132.251 cause and error) X-PHP-List-Original-Sender: hack988@dev.htwap.com X-Host-Fingerprint: 209.85.132.251 an-out-0708.google.com Received: from [209.85.132.251] ([209.85.132.251:12377] helo=an-out-0708.google.com) by pb1.pair.com (ecelerity 2.1.1.9-wez r(12769M)) with ESMTP id 0E/ED-26597-AAC17AA4 for ; Tue, 08 Sep 2009 23:10:35 -0400 Received: by an-out-0708.google.com with SMTP id d14so1615852and.38 for ; Tue, 08 Sep 2009 20:10:32 -0700 (PDT) MIME-Version: 1.0 Received: by 10.100.40.2 with SMTP id n2mr5927158ann.7.1252465831707; Tue, 08 Sep 2009 20:10:31 -0700 (PDT) X-Originating-IP: [59.175.25.15] In-Reply-To: References: Date: Wed, 9 Sep 2009 11:10:31 +0800 Message-ID: <4d03254c0909082010n16abd56dt41ce849109203e94@mail.gmail.com> To: Eloy Bote Falcon Cc: internals@lists.php.net Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: quoted-printable Subject: Re: [PHP-DEV] SSL streams switching to blocking socket From: hack988@dev.htwap.com (hack988 hack988) I found same problem in IIS recently. When SSL connection established and read to eof,I can't write anything to stream again. It's trow :SSL operation failed with code 1. OpenSSL Error messages: error:140D00CF:SSL routines:func(208):reason(207). My php version is 5.2.9 2009/9/8 Eloy Bote Falcon : > Hi everybody! > > Three months ago one of my PHP applications started to hang webserver > processes. The schema of the application is as follows (it's a webservice= ): > > -Main server, with LINUX, Apache and PHP, handles the requests from the > clients. > -Once the client is authenticated, and the request is valid, it relays th= e > request to one of the four slave servers (let's call them nodes). > -One of the nodes uses PHP4 (works fine), and the other three use LINUX, > Apache and PHP 5.1.6 with the following SSL configuration: > OpenSSL support =3D> enabled > OpenSSL Version =3D> OpenSSL 0.9.8e-fips-rhel5 01 Jul 2008 > > -The nodes send the request to a remote webservice, and reply it back to = the > main server. > -The main server processes the response and sends back the response to th= e > client. > > > The problem is that, eventually, the PHP5 nodes ends with blocked (sleepi= ng) > processes from Apache. Finally the system runs out of resources because a= ll > the blocked-sleeping processes have a ESTABLISHED socket. > First I noticed that, at least in that version of PHP, the blocking socke= ts > can have a send and recive timeout. Then I switched to non blocking socke= ts > and select. Now the application works fine in the upper level of the > communication with the other webservices, but I noticed that it still end= s > with sleeping processes. I "straced" the Apache and this is what I found > (the bound IP and the remote webservice IP are not real; the second one i= s > from google.com): > > Block 1 - > > 5503 =A0socket(PF_INET, SOCK_STREAM, IPPROTO_IP) =3D 20 > 5503 =A0bind(20, {sa_family=3DAF_INET, sin_port=3Dhtons(0), > sin_addr=3Dinet_addr("10.6.0.11")}, 16) =3D 0 > 5503 =A0fcntl64(20, F_GETFL) =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 0x2 (flags O_= RDWR) > 5503 =A0fcntl64(20, F_SETFL, O_RDWR|O_NONBLOCK) =3D 0 > 5503 =A0connect(20, {sa_family=3DAF_INET, sin_port=3Dhtons(443), > sin_addr=3Dinet_addr("74.125.127.100")}, 16) =3D -1 EINPROGRESS (Operatio= n now > in progress) > 5503 =A0poll([{fd=3D20, events=3DPOLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 137= 0327) =3D 1 > ([{fd=3D20, revents=3DPOLLOUT}]) > > Block 2 - > > 5503 =A0getsockopt(20, SOL_SOCKET, SO_ERROR, [0], [4]) =3D 0 > 5503 =A0fcntl64(20, F_SETFL, O_RDWR) =A0 =A0 =A0=3D 0 > 5503 =A0time(NULL) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 125= 1911098 > 5503 =A0brk(0xb9e39000) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0xb9e3900= 0 > 5503 =A0time(NULL) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 125= 1911098 > 5503 =A0write(20, > "\200d\1\3\1\0K\0\0\0\20\0\0009\0\0008\0\0005\0\0\26\0\0\23\0\0\n\7\0\300= "..., > 102) =3D 102 > 5503 =A0read(20, "\26\3\1\0J\2\0", 7) =A0 =A0 =3D 7 > 5503 =A0time(NULL) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 125= 1911098 > 5503 =A0time(NULL) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 125= 1911098 > 5503 =A0read(20, > "\0F\3\1J\236\245\273^\v\375\357<\205\223\334n}\226k\232\\\311\300\21Q\25= 6\267\304\257o#"..., > 72) =3D 72 > 5503 =A0read(20, "\26\3\1\6\252", 5) =A0 =A0 =A0=3D 5 > 5503 =A0read(20, > "\v\0\6\246\0\6\243\0\3\2400\202\3\2340\202\3\5\240\3\2\1\2\2\4<\260Eh0\r= \6"..., > 1706) =3D 1376 > 5503 =A0read(20, " 2 CA1\r0\v\6\3U\4\3\23\4CRL10+\6\3U\35\20\4$0\"\200"..= ., > 330) =3D 330 > 5503 =A0read(20, "\26\3\1\1^", 5) =A0 =A0 =A0 =A0 =3D 5 > 5503 =A0read(20, "\r\0\1V\3\1\2@\1P\0M0K1\v0\t\6\3U\4\6\23\2ES1\0170\r\6"= ..., > 350) =3D 350 > 5503 =A0write(20, > "\26\3\1\0\7\v\0\0\3\0\0\0\26\3\1\0\206\20\0\0\202\0\200\215\30 > \tT\312\313\255\210"..., 210) =3D 210 > 5503 =A0read(20, "\24\3\1\0\1", 5) =A0 =A0 =A0 =A0=3D 5 > 5503 =A0read(20, "\1", 1) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 1 > 5503 =A0read(20, "\26\3\1\0000", 5) =A0 =A0 =A0 =3D 5 > 5503 =A0read(20, > "\364\35k\17\25\224\314]|\263Y\307z\310\223\314\210\235h\224t\345\305\373= \267\241\377\t\1s\345\250"..., > 48) =3D 48 > > Block 3 - > > 5503 =A0fcntl64(20, F_GETFL) =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 0x2 (flags O_= RDWR) > 5503 =A0fcntl64(20, F_SETFL, O_RDWR|O_NONBLOCK) =3D 0 > > Block 4 - > > 5503 =A0select(21, [], [20], [], {44320, 0}) =3D 1 (out [20], left {44320= , 0}) > 5503 =A0gettimeofday({1251911098, 885029}, NULL) =3D 0 > 5503 =A0write(13, "[Wed Sep 02 19:04:58 2009] [erro"..., 161) =3D 161 > 5503 =A0write(20, > "\27\3\1\2\240\10\260\325k\v\37{\251\355t_R\274\312\16\354r\315\1\277\204= b\342xU\30L"..., > 677) =3D 677 > 5503 =A0select(21, [20], [], [], {44320, 0} > 5503 =A0<... select resumed> ) =A0 =A0 =A0 =A0 =A0 =A0=3D 1 (in [20], lef= t {44319, 828000}) > 5503 =A0read(20, "\27\3\1\0\240", 5) =A0 =A0 =A0=3D 5 > 5503 =A0read(20, > "\304\310\273s\370\304e\335\273\1\346\376N\234\376\226\276\0\fG9T\313\235= \2&\31\340B=3D\f\""..., > 160) =3D 160 > 5503 =A0select(21, [20], [], [], {44320, 0}) =3D 1 (in [20], left {44320,= 0}) > 5503 =A0read(20, "\27\3\1\4P", 5) =A0 =A0 =A0 =A0 =3D 5 > 5503 =A0read(20, > "\333`\341\212},\215\3476\370\325\273\"\260\340\234\365\324\324\10a\25v\3= 27\266'+\340\34\1\317\364"..., > 1104) =3D 1104 > > Block 5 - > > 5503 =A0write(20, "\25\3\1\0 > \305\10\236\5\10\226JS\330\365\204\21\230\246\362\247R\332\220:\210o\2\33= 3\10.\27"..., > 37) =3D 37 > 5503 =A0brk(0xb9e2d000) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0xb9e2d00= 0 > 5503 =A0close(20) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0 > > Block 6 - > > 5503 =A0brk(0xb9e2b000) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0xb9e2b00= 0 > 5503 =A0chdir("/") =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 0 > 5503 =A0setitimer(ITIMER_PROF, {it_interval=3D{0, 0}, it_value=3D{0, 0}},= NULL) =3D > 0 > 5503 =A0writev(19, > [{"\27\3\1\0\260n?\301\204\263\0341yi\204\v\273\332\335\263\277\335M\t\22= 3\364$\266\214\212c\362"..., > 714}], 1) =3D 714 > 5503 =A0gettimeofday({1251911099, 58549}, NULL) =3D 0 > 5503 =A0write(14, "10.6.0.1 - noone [02/Sep"..., 97) =3D 97 > 5503 =A0gettimeofday({1251911099, 58696}, NULL) =3D 0 > 5503 =A0times({tms_utime=3D1, tms_stime=3D0, tms_cutime=3D0, tms_cstime= =3D0}) =3D > 369262016 > 5503 =A0gettimeofday({1251911099, 58799}, NULL) =3D 0 > 5503 =A0writev(19, [{"\25\3\1\0 > MJi\215B\321Q\2657E\30cw\341n\264o\215\17\237{ej\342n\222\202"..., 37}], = 1) > =3D 37 > 5503 =A0brk(0xb9e2a000) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0xb9e2a00= 0 > 5503 =A0shutdown(19, 1 /* send */) =A0 =A0 =A0 =A0=3D 0 > 5503 =A0poll([{fd=3D19, events=3DPOLLIN}], 1, 2000) =3D 1 ([{fd=3D19, > revents=3DPOLLIN}]) > 5503 =A0read(19, "\25\3\1\0 > \230\220\315\210n\342zc\201\367H\r'xPt\277\243\346\227\320g\2223;U\352"..= ., > 512) =3D 37 > 5503 =A0gettimeofday({1251911099, 59317}, NULL) =3D 0 > 5503 =A0gettimeofday({1251911099, 59372}, NULL) =3D 0 > 5503 =A0poll([{fd=3D19, events=3DPOLLIN}], 1, 2000) =3D 1 ([{fd=3D19, > revents=3DPOLLIN|POLLERR|POLLHUP}]) > 5503 =A0read(19, 0xbf81c504, 512) =A0 =A0 =A0 =A0 =3D -1 ECONNRESET (Conn= ection reset by > peer) > 5503 =A0close(19) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0 > 5503 =A0read(7, 0xbf81c713, 1) =A0 =A0 =A0 =A0 =A0 =A0=3D -1 EAGAIN (Reso= urce temporarily > unavailable) > 5503 =A0close(18) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D 0 > 5503 =A0close(8) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 0 > 5503 =A0close(7) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0=3D 0 > 5503 =A0exit_group(0) =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =A0 =3D ? > > As you can see I devided in 6 blocks this piece of strace output. In the > first block, the socket it's created, its bound to a network interface, a= nd > it's connected to the remote host; fine. But in the block 2 the socket it= 's > switched back to blocking and then starts the SSL communication. In the > block 3 the socket it's switched to non blocking (this is the first time > that our application have chenged the socket options, because we don't ha= ve > the stream until the stream_socket_client function returns). Then, in the > block 4, the PHP that I wrote starts to work and the send / receive takes > place. In the block 5 there is a write without select... why? Well, I thi= nk > that is another "feature" of the underlaying socket communications, relat= ed > to the fclose of the stream. At last, the application ends in the block 6 > sending the result back to the main server and closing resources. > > After saying all of this, my question is... why the SSL implementation us= es > potentially blocking code? The only work around that I found (inside > PHP/Apache) for facing this issue is setting a max execution time of the > apache processes because the PHP max_execution_time doesn't count the > sleeping time. I can't test right now this code in a latest version of PH= P, > but I'm afraid that the strace output will be the same. > > > Regards, > > Eloy Bote. >