php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #64606 php crashes when wrtiting stream
Submitted: 2013-04-07 19:41 UTC Modified: 2013-04-15 13:55 UTC
From: pbxanime at gmail dot com Assigned:
Status: Open Package: memcache (PECL)
PHP Version: 5.4.14 OS: Centos 5.8
Private report: No CVE-ID:
Have you experienced this issue?
Rate the importance of this bug to you:

 [2013-04-07 19:41 UTC] pbxanime at gmail dot com
Description:
------------
I use the latest stable XCache and the latest stable Lighttpd.

I store sessions with memcache:

session.save_handler = memcache
session.save_path = "unix:///tmp/memcached.socket:0?persistent=1&weight=1&timeout=1&retry_interval=15"

php is compiled with the following, I removed directories, but they are correctly linked:

./configure \
--disable-fileinfo \
--disable-pdo \
--enable-exif \
--enable-fpm \
--enable-ftp \
--enable-gd-native-ttf \
--enable-libxml \
--enable-mbstring \
--enable-zip \
--prefix= \
--with-apxs2= \
--with-bz2 \
--with-curl= \
--with-freetype-dir= \
--with-gd \
--with-gettext \
--with-imap= \
--with-imap-ssl= \
--with-jpeg-dir= \
--with-png-dir= \
--with-kerberos \
--with-libxml-dir= \
--with-mcrypt= \
--with-mysql= \
--with-mysql-sock= \
--with-mysqli= \
--with-openssl= \
--with-openssl-dir= \
--with-pcre-regex= \
--with-png-dir= \
--with-xpm-dir= \
--with-zlib \
--with-zlib-dir=

Test script:
---------------
I store sessions like this:

IF (!ISSET($_SESSION)) {
SESSION_START();
}
IF($_SESSION['user_session_last_access']+180 < TIME()){
$_SESSION['user_session_last_access'] = TIME();

}

It's nothing special and it works normally.

Actual result:
--------------
I don't know how to dupicate this bug, it just happens randomly every few to several hours:

FPM Log:

[07-Apr-2013 08:35:05.926454] DEBUG: pid 25374, fpm_got_signal(), line 72: received SIGCHLD
[07-Apr-2013 08:35:05.926552] WARNING: pid 25374, fpm_children_bury(), line 252: [pool ] child 534 exited on signal 11 (SIGSEGV - core dumped) after 34.242946 seconds from start
[07-Apr-2013 08:35:05.926939] NOTICE: pid 25374, fpm_children_make(), line 421: [pool ] child 575 started
[07-Apr-2013 08:35:05.926980] DEBUG: pid 25374, fpm_event_loop(), line 411: event module triggered 1 events

Backtrace:

#0  0x08304f47 in _php_stream_write (stream=0x9556b88,
    buf=0xb77c5000 "set 0b58f7308927b881bd2d5273f0dc8de7 0 1440 38\r\nuser_session_last_access|i:1365338080;\r\n", count=88)
    at /usr/src/php-5.4.13/main/streams/streams.c:1238
1238            if (buf == NULL || count == 0 || stream->ops->write == NULL) {
(gdb) bt
#0  0x08304f47 in _php_stream_write (stream=0x9556b88,
    buf=0xb77c5000 "set 0b58f7308927b881bd2d5273f0dc8de7 0 1440 38\r\nuser_session_last_access|i:1365338080;\r\n", count=88)
    at /usr/src/php-5.4.13/main/streams/streams.c:1238
#1  0x00764506 in ?? ()
#2  0x09556b88 in ?? ()
#3  0xb77c5000 in ?? ()
#4  0x00000058 in ?? ()
#5  0xbfb79f0e in ?? ()
#6  0x00000000 in ?? ()
(gdb) frame 0
#0  0x08304f47 in _php_stream_write (stream=0x9556b88,
    buf=0xb77c5000 "set 0b58f7308927b881bd2d5273f0dc8de7 0 1440 38\r\nuser_session_last_access|i:1365338080;\r\n", count=88)
    at /usr/src/php-5.4.13/main/streams/streams.c:1238
1238            if (buf == NULL || count == 0 || stream->ops->write == NULL) {


Another Backtrace:


#0  _php_stream_write_filtered (stream=0x95564a8, buf=0x96c9100 "", count=3216473280, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,
(gdb) bt
#0  _php_stream_write_filtered (stream=0x95564a8, buf=0x96c9100 "", count=3216473280, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
#1  0x007620bb in ?? ()
#2  0x00000000 in ?? ()
(gdb) frame 0
#0  _php_stream_write_filtered (stream=0x95564a8, buf=0x96c9100 "", count=3216473280, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2013-04-08 16:10 UTC] sixd@php.net
Does it reproduce without XCache?
Do you have a standalone testcase?
 [2013-04-08 16:10 UTC] sixd@php.net
-Status: Open +Status: Feedback
 [2013-04-08 16:40 UTC] pbxanime at gmail dot com
-Status: Feedback +Status: Open
 [2013-04-08 16:40 UTC] pbxanime at gmail dot com
No, I haven't tested it with Xcache disabled. I didn't even think Xcache would be an issue since it doesn't interact with the writing of the sessions. I will disable Xcache for a few hours and see what results, I get thank you for the response.
 [2013-04-08 20:42 UTC] sixd@php.net
-Status: Open +Status: Feedback
 [2013-04-08 22:57 UTC] pbxanime at gmail dot com
-Status: Feedback +Status: Open
 [2013-04-08 22:57 UTC] pbxanime at gmail dot com
here's php -v:

PHP 5.4.13 (cli) (built: Apr  2 2013 15:57:48)
Copyright (c) 1997-2013 The PHP Group
Zend Engine v2.4.0, Copyright (c) 1998-2013 Zend Technologies


I turned off Xcache and here's results from 5 different core dumps spanning 5 hours:

#0  0x08304f47 in _php_stream_write (stream=0x90f5b08,
    buf=0xb77495bc "set 34e0f7080b10afd7af2e03e9b1536c33 0 1440 38\r\nuser_session_last_access|i:1365458365;\r\n", count=88)
    at /usr/src/php-5.4.13/main/streams/streams.c:1238
1238            if (buf == NULL || count == 0 || stream->ops->write == NULL) {


----------------------------


#0  0x04939510 in ?? ()
(gdb) bt
#0  0x04939510 in ?? ()
#1  0x08303995 in _php_stream_write_buffer (stream=0x90f5b18, buf=0x95e6958 "get 8185df46afa3fa484826ee530507445e\r\n",
    count=38) at /usr/src/php-5.4.13/main/streams/streams.c:1134
#2  0x009a00bb in ?? ()
#3  0x090f5b18 in ?? ()
#4  0x095e6958 in ?? ()
#5  0x00000026 in ?? ()
#6  0x082f5029 in spprintf (pbuf=0x95e9374, max_len=3214955994, format=0x20 <Address 0x20 out of bounds>)
    at /usr/src/php-5.4.13/main/spprintf.c:818
#7  0x009a346a in ?? ()
#8  0x095e9374 in ?? ()
#9  0xbfa055da in ?? ()
#10 0x00000020 in ?? ()
#11 0xbfa055da in ?? ()
#12 0x00000000 in ?? ()
(gdb) frame 1
#1  0x08303995 in _php_stream_write_buffer (stream=0x90f5b18, buf=0x95e6958 "get 8185df46afa3fa484826ee530507445e\r\n",
    count=38) at /usr/src/php-5.4.13/main/streams/streams.c:1134
1134                    justwrote = stream->ops->write(stream, buf, towrite TSRMLS_CC);
(gdb) frame 6
#6  0x082f5029 in spprintf (pbuf=0x95e9374, max_len=3214955994, format=0x20 <Address 0x20 out of bounds>)
    at /usr/src/php-5.4.13/main/spprintf.c:818
818             cc = vspprintf(pbuf, max_len, format, ap);

----------------------------

#0  0x08304eb3 in _php_stream_write_filtered (stream=0x90992a0, buf=<value optimized out>, count=3214964224, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,
(gdb) bt
#0  0x08304eb3 in _php_stream_write_filtered (stream=0x90992a0, buf=<value optimized out>, count=3214964224, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
#1  0x009a2506 in ?? ()
#2  0x00000000 in ?? ()
(gdb) frame 0
#0  0x08304eb3 in _php_stream_write_filtered (stream=0x90992a0, buf=<value optimized out>, count=3214964224, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,

----------------------------

#0  0x30320032 in ?? ()
(gdb) bt
#0  0x30320032 in ?? ()
#1  0x08304ee5 in _php_stream_write_filtered (stream=0x90f5b18, buf=<value optimized out>, count=<value optimized out>, flags=0)
    at /usr/src/php-5.4.13/main/streams/streams.c:1177
#2  0x009a00bb in ?? ()
#3  0x00000000 in ?? ()
(gdb) frame 1
#1  0x08304ee5 in _php_stream_write_filtered (stream=0x90f5b18, buf=<value optimized out>, count=<value optimized out>, flags=0)
    at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,

----------------------------

#0  0x08304eb3 in _php_stream_write_filtered (stream=0x9098890, buf=<value optimized out>, count=3214964224, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,
(gdb) bt
#0  0x08304eb3 in _php_stream_write_filtered (stream=0x9098890, buf=<value optimized out>, count=3214964224, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
#1  0x009a2506 in ?? ()
#2  0x00000000 in ?? ()
(gdb) frame 0
#0  0x08304eb3 in _php_stream_write_filtered (stream=0x9098890, buf=<value optimized out>, count=3214964224, flags=0) at /usr/src/php-5.4.13/main/streams/streams.c:1177
1177                    status = filter->fops->filter(stream, filter, brig_inp, brig_outp,
 [2013-04-11 16:57 UTC] pbxanime at gmail dot com
I don't know what other information I can supply, but if there's anything else I can provide, just tell me.
 [2013-04-14 16:23 UTC] pbxanime at gmail dot com
These same errors still occur in 5.4.14 I think I have a better clue of why this is happening. When I upgraded to 5.4.14 I ran the make test and got these results:

=====================================================================
FAILED TEST SUMMARY
---------------------------------------------------------------------
Bug #43073 (TrueType bounding box is wrong for angle<>0) freetype < 2.4.10 [ext/gd/tests/bug43073.phpt]
Bug #48801 (Problem with imagettfbbox) freetype < 2.4.10 [ext/gd/tests/bug48801.phpt]
Test posix_getgrgid() function : basic functionality [ext/posix/tests/posix_getgrgid_basic.phpt]
Bug #32330 (session_destroy, "Failed to initialize storage module", custom session handler) [ext/session/tests/bug32330.phpt]
Bug #60634 (Segmentation fault when trying to die() in SessionHandler::write()) - fatal error in close during exec [ext/session/tests/bug60634_error_5.phpt]
session rfc1867 [ext/session/tests/rfc1867.phpt]
session rfc1867 [ext/session/tests/rfc1867_cleanup.phpt]
session rfc1867 disabled [ext/session/tests/rfc1867_disabled.phpt]
session rfc1867 disabled 2 [ext/session/tests/rfc1867_disabled_2.phpt]
session rfc1867 [ext/session/tests/rfc1867_inter.phpt]
session rfc1867 no name [ext/session/tests/rfc1867_no_name.phpt]
session rfc1867 sid cookie [ext/session/tests/rfc1867_sid_cookie.phpt]
session rfc1867 sid get [ext/session/tests/rfc1867_sid_get.phpt]
session rfc1867 sid get 2 [ext/session/tests/rfc1867_sid_get_2.phpt]
session rfc1867 sid cookie [ext/session/tests/rfc1867_sid_invalid.phpt]
session rfc1867 sid only cookie [ext/session/tests/rfc1867_sid_only_cookie.phpt]
session rfc1867 sid only cookie 2 [ext/session/tests/rfc1867_sid_only_cookie_2.phpt]
session rfc1867 sid post [ext/session/tests/rfc1867_sid_post.phpt]
Test session_module_name() function : variation [ext/session/tests/session_module_name_variation3.phpt]
Test session_name() function : error functionality [ext/session/tests/session_name_basic.phpt]
Test session_name() function : variation [ext/session/tests/session_name_variation1.phpt]
Test session_save_path() function : error functionality [ext/session/tests/session_save_path_error.phpt]
Test session_save_path() function : variation [ext/session/tests/session_save_path_variation1.phpt]
Test session_set_save_handler() function : basic functionality [ext/session/tests/session_set_save_handler_basic.phpt]
Test session_set_save_handler() function : using closures as callbacks [ext/session/tests/session_set_save_handler_closures.phpt]
Test session_set_save_handler() function : error functionality [ext/session/tests/session_set_save_handler_error3.phpt]
Test session_set_save_handler() function : variation [ext/session/tests/session_set_save_handler_variation4.phpt]
Bug #44394 (Last two bytes missing from output) with session.use_trans_id [ext/standard/tests/general_functions/bug44394_2.phpt]
Test setlocale() function : usage variations - Setting all available locales in the platform [ext/standard/tests/strings/setlocale_variation2.phpt]
=====================================================================

=====================================================================
WARNED TEST SUMMARY
---------------------------------------------------------------------
Bug #52062 (large timestamps with DateTime::getTimestamp and DateTime::setTimestamp) (32 bit) [ext/date/tests/bug52062.phpt] (warn: XFAIL section but test passes)
=====================================================================
 [2013-04-14 16:23 UTC] pbxanime at gmail dot com
-PHP Version: 5.4.13 +PHP Version: 5.4.14
 [2013-04-15 04:32 UTC] laruence@php.net
what the failed diff of these session test scripts?

like the output of:

cat ext/session/tests/ext/session/tests/rfc1867.diff
 [2013-04-15 04:32 UTC] laruence@php.net
-Status: Open +Status: Feedback
 [2013-04-15 04:57 UTC] pbxanime at gmail dot com
-Status: Feedback +Status: Open
 [2013-04-15 04:57 UTC] pbxanime at gmail dot com
Well I commented out memcache as save_handler in php.ini and went back to saving sessions by files. And I haven't had php crash on me since, the output is below for the .diff file.

my problem had to do with memcache though, the php pecl version i'm running is memcache-2.2.7. It almost doesn't make sense though, because now I have 300 plus session files that only take up 15KB total space. And if that's all it was taking up in memcache, I don't know why it would cause php to crash. 

cat /usr/src/php-5.4.14/ext/session/tests/rfc1867.diff:

001+ Fatal error: Unknown: No storage module chosen - failed to initialize session in Unknown on line 0
001- string(%d) "rfc1867-tests"
002- bool(true)
003- array(2) {
004-   [%u|b%"file1"]=>
005-   array(5) {
006-     [%u|b%"name"]=>
007-     %string|unicode%(9) "file1.txt"
008-     [%u|b%"type"]=>
009-     %string|unicode%(0) ""
010-     [%u|b%"tmp_name"]=>
011-     %string|unicode%(%d) "%s"
012-     [%u|b%"error"]=>
013-     int(0)
014-     [%u|b%"size"]=>
015-     int(1)
016-   }
017-   [%u|b%"file2"]=>
018-   array(5) {
019-     [%u|b%"name"]=>
020-     %string|unicode%(9) "file2.txt"
021-     [%u|b%"type"]=>
022-     %string|unicode%(0) ""
023-     [%u|b%"tmp_name"]=>
024-     %string|unicode%(%d) "%s"
025-     [%u|b%"error"]=>
026-     int(0)
027-     [%u|b%"size"]=>
028-     int(1)
029-   }
030- }
031- array(5) {
032-   [%u|b%"start_time"]=>
033-   int(%d)
034-   [%u|b%"content_length"]=>
035-   int(%d)
036-   [%u|b%"bytes_processed"]=>
037-   int(%d)
038-   [%u|b%"done"]=>
039-   bool(true)
040-   [%u|b%"files"]=>
041-   array(2) {
042-     [0]=>
043-     array(7) {
044-       [%u|b%"field_name"]=>
045-       %unicode|string%(5) "file1"
046-       [%u|b%"name"]=>
047-       %unicode|string%(9) "file1.txt"
048-       [%u|b%"tmp_name"]=>
049-       %unicode|string%(%d) "%s"
050-       [%u|b%"error"]=>
051-       int(0)
052-       [%u|b%"done"]=>
053-       bool(true)
054-       [%u|b%"start_time"]=>
055-       int(%d)
056-       [%u|b%"bytes_processed"]=>
057-       int(1)
058-     }
059-     [1]=>
060-     array(7) {
061-       [%u|b%"field_name"]=>
062-       %unicode|string%(5) "file2"
063-       [%u|b%"name"]=>
064-       %unicode|string%(9) "file2.txt"
065-       [%u|b%"tmp_name"]=>
066-       %unicode|string%(%d) "%s"
067-       [%u|b%"error"]=>
068-       int(0)
069-       [%u|b%"done"]=>
070-       bool(true)
071-       [%u|b%"start_time"]=>
072-       int(%d)
073-       [%u|b%"bytes_processed"]=>
074-       int(1)
075-     }
076-   }
077- }
 [2013-04-15 05:26 UTC] pajoye@php.net
Please try using latest memcache release (3.0.8)
 [2013-04-15 05:26 UTC] pajoye@php.net
-Status: Open +Status: Feedback -Package: Streams related +Package: memcache
 [2013-04-15 05:31 UTC] pbxanime at gmail dot com
-Status: Feedback +Status: Open
 [2013-04-15 05:31 UTC] pbxanime at gmail dot com
Okay I'll try it out, only reason I never upgraded was because it was beta and didn't know if it had bugs that the stable wouldn't have.
 [2013-04-15 05:51 UTC] laruence@php.net
then I think it relates to memcache ..

change to pecl memcache related issue
 [2013-04-15 06:04 UTC] pbxanime at gmail dot com
This is way too early to say but I upgraded to version (3.0.8) of memcache and my actual site seems to be loading faster. I also changed the php.ini save handler back to memcache. I'm going to sleep soon, but when I wake up, I'll check for any errors that may have happened. Hopefully none will happen, I'm very glad I made this bug report. It's made me a slightly better troubleshooter, of course with everyone's suggestions.
 [2013-04-15 13:55 UTC] pbxanime at gmail dot com
Okay when I switched back to save handler "memcache" I received some more php crashes and something brand new in my error log. It seems something changed "&" to "&amp;" for a short time, because it's written like this in php.ini:

session.save_path = "unix:///tmp/memcached.socket:0?persistent=1&weight=1&timeout=1&retry_interval=15"

maybe those extra options are not supported through unix socket. Since the error I received was as follows:

[15-Apr-2013 06:15:13 America/New_York] PHP Warning:  Unknown: Failed to write session data (memcache). Please verify that the current setting of session.save_path is correct (unix:///tmp/memcached.socket:0?persistent=1&amp;weight=1&amp;timeout=1&amp;retry_interval=15) in Unknown on line 0

[15-Apr-2013 06:15:14 America/New_York] PHP Warning:  Unknown: Failed to write session data (memcache). Please verify that the current setting of session.save_path is correct (unix:///tmp/memcached.socket:0?persistent=1&amp;weight=1&amp;timeout=1&amp;retry_interval=15) in Unknown on line 0

which only showed up twice.

Also all the core dumps are simpler now, they all look like this:

Program terminated with signal 11, Segmentation fault.
#0  0x04f1a249 in ?? ()
------------------------------------------------------------------ 
Program terminated with signal 11, Segmentation fault.
#0  0x04f1a249 in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x04f1a1ea in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x04e32fb0 in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x04e32f69 in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x04f1a249 in ?? ()
(gdb) frame 0
#0  0x04f1a249 in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x00000089 in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x04f1a249 in ?? ()
------------------------------------------------------------------
Program terminated with signal 11, Segmentation fault.
#0  0x04e32f69 in ?? ()
 
PHP Copyright © 2001-2014 The PHP Group
All rights reserved.
Last updated: Wed Apr 16 22:02:05 2014 UTC