Page MenuHomePhabricator

Broken pipe when redis set to 'persistent' => true,
Open, Needs TriagePublic

Description

When redis set to 'persistent' => true,. User login failed with error message:

There seems to be a problem with your login session; this action has been canceled as a precaution against session hijacking. Please resubmit the form.

The user cookies session will change every time with web page refresh due to ID reset caused by redis connection broken pipe.

What I could confirm and reproduce is that when using
Mediawiki 1.31
redis_version:3.2.11
php7.0: Installed: 7.0.31-1~dotdeb+8.1
php7.0-redis: Installed: 3.1.3-1~dotdeb+8.1

and set Mediawiki to storage cookies sessions in redis like following:

$wgObjectCaches['redis'] = array(
    'class'                => 'RedisBagOStuff',
    'servers'              => array( '192.168.0.1:6379' ),
    'connectTimeout'    => 10,
    'persistent' => true, 
);

There will be error message like:

ErrorException from line 95 of /mediawiki-1.31/includes/libs/redis/RedisConnRef.php: PHP Notice: Redis::get(): send of 75 bytes failed with errno=32 Broken pipe

Although disable redis connection persistent will "solve" this error, our wiki become extremely unstable under heavy load due to redis connection overflow.


Here is a part of debug log for reference

Start request GET /Mainpage
HTTP HEADERS:
CF-CONNECTING-IP: "deleted for security"
COOKIE: "deleted for security"
ACCEPT-LANGUAGE: en-US,en
REFERER: https://example.com/index.php?title=Special:UserLogin&returnto=Special%3ABadtitle
ACCEPT: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8
DNT: 1
USER-AGENT: "deleted for security"
UPGRADE-INSECURE-REQUESTS: 1
CACHE-CONTROL: max-age=0
CF-VISITOR: {"scheme":"https"}
X-FORWARDED-PROTO: https
CF-RAY: "deleted for security"
X-FORWARDED-FOR: "deleted for security"
CF-IPCOUNTRY: US
ACCEPT-ENCODING: gzip
CONNECTION: Keep-Alive
HOST: example.com
CONTENT-LENGTH:
[caches] cluster: RedisBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: RedisBagOStuff, session: RedisBagOStuff
[caches] LocalisationCache: using store LCStoreCDB
[session] Session "mjm60cuvq7u6ugb9u2ofeennnooffor0" requested without UserID cookie
[error] [7d696906149ca1fb5a4f89e5] /Mainpage ErrorException from line 95 of /mediawiki-1.31/includes/libs/redis/RedisConnRef.php: PHP Notice: Redis::get(): send of 75 bytes failed with errno=32 Broken pipe
[session] SessionBackend "mjm60cuvq7u6ugb9u2ofeennnooffor0" is unsaved, marking dirty in constructor
[CryptRand] 0 bytes of randomness leftover in the buffer.
[error] [7d696906149ca1fb5a4f89e5] /Mainpage ErrorException from line 95 of /mediawiki-1.31/includes/libs/redis/RedisConnRef.php: PHP Notice: Redis::get(): send of 75 bytes failed with errno=32 Broken pipe
[session] SessionBackend "4g74s5i37or3f5jspn7hpu95v9noknmd" metadata dirty due to ID reset (formerly "mjm60cuvq7u6ugb9u2ofeennnooffor0")
[error] [7d696906149ca1fb5a4f89e5] /Mainpage ErrorException from line 95 of /mediawiki-1.31/includes/libs/redis/RedisConnRef.php: PHP Notice: Redis::delete(): send of 75 bytes failed with errno=32 Broken pipe
[session] SessionBackend "4g74s5i37or3f5jspn7hpu95v9noknmd" save: dataDirty=1 metaDirty=1 forcePersist=0
[cookie] setcookie: "examplecom_session", "4g74s5i37or3f5jspn7hpu95v9noknmd", "0", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "examplecomUserID", "", "1504228209", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "examplecomToken", "", "1504228209", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "forceHTTPS", "", "1504228209", "/", ".examplecom.com", "", "1"
[session] SessionBackend "4g74s5i37or3f5jspn7hpu95v9noknmd" save: dataDirty=1 metaDirty=1 forcePersist=0
[cookie] already set setcookie: "examplecom_session", "4g74s5i37or3f5jspn7hpu95v9noknmd", "0", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "examplecomUserID", "", "1504228209", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "examplecomToken", "", "1504228209", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "forceHTTPS", "", "1504228209", "/", ".examplecom.com", "", "1"
[cookie] already set setcookie: "examplecom_session", "4g74s5i37or3f5jspn7hpu95v9noknmd", "0", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "examplecomUserID", "", "1504228209", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "examplecomToken", "", "1504228209", "/", ".examplecom.com", "1", "1"
[cookie] already deleted setcookie: "forceHTTPS", "", "1504228209", "/", ".examplecom.com", "", "1"
[error] [7d696906149ca1fb5a4f89e5] /Mainpage ErrorException from line 95 of /mediawiki-1.31/includes/libs/redis/RedisConnRef.php: PHP Notice: Redis::setex(): send of 388 bytes failed with errno=32 Broken pipe
[session] SessionBackend "4g74s5i37or3f5jspn7hpu95v9noknmd" Taking over PHP session
[DBConnection] Wikimedia\Rdbms\LoadBalancer::openConnection: calling initLB() before first connection.
[DBReplication] Cannot use ChronologyProtector with EmptyBagOStuff.

Event Timeline

Zoglun created this task.Sep 1 2018, 3:04 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 1 2018, 3:04 AM
Zoglun renamed this task from Broken pipe for session storage to redis when 'persistent' => true, to Broken pipe when redis set to 'persistent' => true,.Sep 1 2018, 4:05 AM
Zoglun added a comment.EditedSep 1 2018, 6:35 PM

With further test, same problem could be reproduced with Mediawiki 1.30. The problem is not limited to session storage, it happens when $wgMainCacheType = redis too.

What might cause this error?

[02-Sep-2018 02:32:47 Asia/Shanghai] PHP Notice:  Redis::setex(): send of 1854 bytes failed with errno=32 Broken pipe in /var/www/wiki/includes/libs/redis/RedisConnRef.php on line 95
[02-Sep-2018 02:32:47 Asia/Shanghai] PHP Notice:  Redis::get(): send of 79 bytes failed with errno=32 Broken pipe in /var/www/wiki/includes/libs/redis/RedisConnRef.php on line 95
Zoglun updated the task description. (Show Details)Sep 2 2018, 5:45 AM