Need help with strange and random bug

php.internals

Andrey E Baranov

9 years ago
Hi all, I have problem, debug is not yet finished, and for now do not can reproduce, problem occurs only in production (after migrate to PHP7). perhaps someone else can help :) PHP 7.0.13 (Ubuntu 16.04 package repository), php-fpm For simplify: ``` ... Log::debug('1:' . print_r($video, true)); Log::debug('2:' . json_encode($video) . ' json_last_error: ' . json_last_error() . ' json_last_error_msg: ' . json_last_error_msg()); $video['delivery'] = [2]; // after this line: serialize and json_encode do not work as expected Log::debug('3:' . print_r($video, true)); Log::debug('4:' . serialize($video)); Log::debug('5:' . json_encode($video) . ' json_last_error: ' . json_last_error() . ' json_last_error_msg: ' . json_last_error_msg()); ... ``` log with bug: ``` DEBUG: 1:Array ( [mimes] => Array ( [0] => video/mp4 ) [linearity] => 1 [minduration] => 5 [maxduration] => 60 [protocols] => Array ( [0] => 2 [1] => 3 ) [w] => 818 [h] => 460 [minbitrate] => 100 [maxbitrate] => 1200 ) DEBUG: 2: {"mimes":["video/mp4"],"linearity":1,"minduration":5,"maxduration":60,"protocols":[2,3],"w":818,"h":460,"minbitrate":100,"maxbitrate":1200} DEBUG: 3:Array ( [mimes] => Array ( [0] => video/mp4 ) [linearity] => 1 [minduration] => 5 [maxduration] => 60 [protocols] => Array ( [0] => 2 [1] => 3 ) [w] => 818 [h] => 460 [minbitrate] => 100 [maxbitrate] => 1200 [delivery] => Array ( [0] => 2 ) ) DEBUG: 4:a:10:{s:5:"mimes";a:1:{i:0;s:9:"video/mp4";}s:9:"linearity";i:1;s:11:"minduration";i:5;s:11:"maxduration";i:60;s:9:"protocols";a:2:{i:0;i:2;i:1;i:3;}s:1:"w";i:818;s:1:"h";i:460;s:10:"minbitrate";i:100;s:10:"maxbitrate";i:1200;s:8:"delivery";N;} DEBUG: 5: json_last_error: 6 json_last_error_msg: Recursion detected ``` - 4: `serialize($video)` - `"delivery";N;` - it is mean that `delivery` is Null - that is not true - 5: `json_encode($video)` - Recursion detected Problem occurs in random period after start fpm process (after 10..30 min), and remains constant until restart fpm Same problem as I see in http://stackoverflow.com/questions/37456845/what-does-json-error-recursion-mean-from-json-encode After deep analyze: php_json_encode_array: ``` ``` if (myht && ZEND_HASH_GET_APPLY_COUNT(myht) > 1) { JSON_G(error_code) = PHP_JSON_ERROR_RECURSION; smart_str_appendl(buf, "null", 4); return; } ``` serialize: ``` if (... || (Z_TYPE_P(data) == IS_ARRAY && Z_ARRVAL_P(data)->u.v.nApplyCount > 1) ) { smart_str_appendl(buf, "N;", 2); ... ``` so looks like problem in `HashTable.v.nApplyCount` Also I am find commit - https://github.com/php/php-src/commit/d26ca894020bc28eb55b153fac5548374d5ce16d In this commit added ``` target->u.flags = (source->u.flags & ~(...|ZEND_HASH_APPLY_COUNT_MASK))... ``` But not added to case if `if (GC_FLAGS(source) & IS_ARRAY_IMMUTABLE)` - maybe need fix in this place? :) I guess that the problem in immutable arrays. I do not have experience with PHP-SRC - and I could be wrong thanks!

Nikita Popov

9 years ago
On Sun, Feb 5, 2017 at 3:03 PM, Andrey E Baranov <andrey@andb.name> wrote:
> Hi all, > > I have problem, debug is not yet finished, and for now do not can > reproduce, problem occurs only in production (after migrate to PHP7). > perhaps someone else can help :) > PHP 7.0.13 (Ubuntu 16.04 package repository), php-fpm > > For simplify: > ``` > ... > Log::debug('1:' . print_r($video, true)); > Log::debug('2:' . json_encode($video) . ' json_last_error: ' . > json_last_error() . ' json_last_error_msg: ' . json_last_error_msg()); > > $video['delivery'] = [2]; // after this line: serialize and json_encode do > not work as expected > > Log::debug('3:' . print_r($video, true)); > Log::debug('4:' . serialize($video)); > Log::debug('5:' . json_encode($video) . ' json_last_error: ' . > json_last_error() . ' json_last_error_msg: ' . json_last_error_msg()); > ... > ``` > > log with bug: > ``` > DEBUG: 1:Array > ( > [mimes] => Array > ( > [0] => video/mp4 > ) > > [linearity] => 1 > [minduration] => 5 > [maxduration] => 60 > [protocols] => Array > ( > [0] => 2 > [1] => 3 > ) > > [w] => 818 > [h] => 460 > [minbitrate] => 100 > [maxbitrate] => 1200 > ) > DEBUG: 2: {"mimes":["video/mp4"],"linearity":1,"minduration":5,"maxdur > ation":60,"protocols":[2,3],"w":818,"h":460,"minbitrate": > 100,"maxbitrate":1200} > DEBUG: 3:Array > ( > [mimes] => Array > ( > [0] => video/mp4 > ) > > [linearity] => 1 > [minduration] => 5 > [maxduration] => 60 > [protocols] => Array > ( > [0] => 2 > [1] => 3 > ) > > [w] => 818 > [h] => 460 > [minbitrate] => 100 > [maxbitrate] => 1200 > [delivery] => Array > ( > [0] => 2 > ) > > ) > DEBUG: 4:a:10:{s:5:"mimes";a:1:{i:0;s:9:"video/mp4";}s:9:"linearity > ";i:1;s:11:"minduration";i:5;s:11:"maxduration";i:60;s:9:"p > rotocols";a:2:{i:0;i:2;i:1;i:3;}s:1:"w";i:818;s:1:"h";i:460; > s:10:"minbitrate";i:100;s:10:"maxbitrate";i:1200;s:8:"delivery";N;} > DEBUG: 5: json_last_error: 6 json_last_error_msg: Recursion detected > ``` > > - 4: `serialize($video)` - `"delivery";N;` - it is mean that `delivery` is > Null - that is not true > - 5: `json_encode($video)` - Recursion detected > > Problem occurs in random period after start fpm process (after 10..30 > min), and remains constant until restart fpm > > Same problem as I see in http://stackoverflow.com/quest > ions/37456845/what-does-json-error-recursion-mean-from-json-encode > > After deep analyze: > > php_json_encode_array: > ``` > ``` > if (myht && ZEND_HASH_GET_APPLY_COUNT(myht) > 1) { > JSON_G(error_code) = PHP_JSON_ERROR_RECURSION; > smart_str_appendl(buf, "null", 4); > return; > } > ``` > > serialize: > ``` > if (... || (Z_TYPE_P(data) == IS_ARRAY && Z_ARRVAL_P(data)->u.v.nApplyCount > > 1) > ) { > smart_str_appendl(buf, "N;", 2); > ... > ``` > > so looks like problem in `HashTable.v.nApplyCount` > > > Also I am find commit - https://github.com/php/php-src > /commit/d26ca894020bc28eb55b153fac5548374d5ce16d > > In this commit added > ``` > target->u.flags = (source->u.flags & ~(...|ZEND_HASH_APPLY_COUNT_MASK))... > ``` > But not added to case if `if (GC_FLAGS(source) & IS_ARRAY_IMMUTABLE)` - > maybe need fix in this place? :) I guess that the problem in immutable > arrays. >
The apply count on immutable arrays is always zero, so this shouldn't be a problem. However, it may be that some other code is incrementing the apply count on an immutable array. Can you please check whether running with opcache.protect_memory=1 gives you any segmentation faults or bus errors? Nikita

Andrey E Baranov

9 years ago
Nikita Popov at 2017-02-05 21:44 wrote:
> On Sun, Feb 5, 2017 at 3:03 PM, Andrey E Baranov <andrey@andb.name> > wrote: > >> Hi all, >> >> I have problem, debug is not yet finished, and for now do not can >> reproduce, problem occurs only in production (after migrate to PHP7). >> perhaps someone else can help :) >> PHP 7.0.13 (Ubuntu 16.04 package repository), php-fpm >> >> For simplify: >> ``` >> ... >> Log::debug('1:' . print_r($video, true)); >> Log::debug('2:' . json_encode($video) . ' json_last_error: ' . >> json_last_error() . ' json_last_error_msg: ' . json_last_error_msg()); >> >> $video['delivery'] = [2]; // after this line: serialize and >> json_encode do >> not work as expected >> >> Log::debug('3:' . print_r($video, true)); >> Log::debug('4:' . serialize($video)); >> Log::debug('5:' . json_encode($video) . ' json_last_error: ' . >> json_last_error() . ' json_last_error_msg: ' . json_last_error_msg()); >> ... >> ``` >> >> log with bug: >> ``` >> DEBUG: 1:Array >> ( >> [mimes] => Array >> ( >> [0] => video/mp4 >> ) >> >> [linearity] => 1 >> [minduration] => 5 >> [maxduration] => 60 >> [protocols] => Array >> ( >> [0] => 2 >> [1] => 3 >> ) >> >> [w] => 818 >> [h] => 460 >> [minbitrate] => 100 >> [maxbitrate] => 1200 >> ) >> DEBUG: 2: {"mimes":["video/mp4"],"linearity":1,"minduration":5,"maxdur >> ation":60,"protocols":[2,3],"w":818,"h":460,"minbitrate": >> 100,"maxbitrate":1200} >> DEBUG: 3:Array >> ( >> [mimes] => Array >> ( >> [0] => video/mp4 >> ) >> >> [linearity] => 1 >> [minduration] => 5 >> [maxduration] => 60 >> [protocols] => Array >> ( >> [0] => 2 >> [1] => 3 >> ) >> >> [w] => 818 >> [h] => 460 >> [minbitrate] => 100 >> [maxbitrate] => 1200 >> [delivery] => Array >> ( >> [0] => 2 >> ) >> >> ) >> DEBUG: 4:a:10:{s:5:"mimes";a:1:{i:0;s:9:"video/mp4";}s:9:"linearity >> ";i:1;s:11:"minduration";i:5;s:11:"maxduration";i:60;s:9:"p >> rotocols";a:2:{i:0;i:2;i:1;i:3;}s:1:"w";i:818;s:1:"h";i:460; >> s:10:"minbitrate";i:100;s:10:"maxbitrate";i:1200;s:8:"delivery";N;} >> DEBUG: 5: json_last_error: 6 json_last_error_msg: Recursion detected >> ``` >> >> - 4: `serialize($video)` - `"delivery";N;` - it is mean that >> `delivery` is >> Null - that is not true >> - 5: `json_encode($video)` - Recursion detected >> >> Problem occurs in random period after start fpm process (after 10..30 >> min), and remains constant until restart fpm >> >> Same problem as I see in http://stackoverflow.com/quest >> ions/37456845/what-does-json-error-recursion-mean-from-json-encode >> >> After deep analyze: >> >> php_json_encode_array: >> ``` >> ``` >> if (myht && ZEND_HASH_GET_APPLY_COUNT(myht) > 1) { >> JSON_G(error_code) = PHP_JSON_ERROR_RECURSION; >> smart_str_appendl(buf, "null", 4); >> return; >> } >> ``` >> >> serialize: >> ``` >> if (... || (Z_TYPE_P(data) == IS_ARRAY && >> Z_ARRVAL_P(data)->u.v.nApplyCount >> > 1) >> ) { >> smart_str_appendl(buf, "N;", 2); >> ... >> ``` >> >> so looks like problem in `HashTable.v.nApplyCount` >> >> >> Also I am find commit - https://github.com/php/php-src >> /commit/d26ca894020bc28eb55b153fac5548374d5ce16d >> >> In this commit added >> ``` >> target->u.flags = (source->u.flags & >> ~(...|ZEND_HASH_APPLY_COUNT_MASK))... >> ``` >> But not added to case if `if (GC_FLAGS(source) & IS_ARRAY_IMMUTABLE)` >> - >> maybe need fix in this place? :) I guess that the problem in immutable >> arrays. >> > > The apply count on immutable arrays is always zero, so this shouldn't > be a > problem. However, it may be that some other code is incrementing the > apply > count on an immutable array. Can you please check whether running with > opcache.protect_memory=1 gives you any segmentation faults or bus > errors? > > Nikita
Nikita thanks! looks like `opcache.protect_memory=1` is usefull :) ``` #0 phongo_bson_append (bson=bson@entry=0x7fff0d47e220, flags=flags@entry=PHONGO_BSON_NONE, key=0x7fabe79ec070 "$in", key_len=3, entry=entry@entry=0x7fabe7f79a00) at /tmp/pear/temp/mongodb/src/bson.c:1027 ... ``` and it is fixed in https://github.com/mongodb/mongo-php-driver/commit/129753881a223b8378fc7b8137104c65d8d8828f so, with PHP7 need use mongodb >= 1.1.10 (as minimum :) we missed that mongodb is outdated in our production, but the relationship between our bug and mongodb was not the obvious)