Error while reading line from the server

[abesto]

CommunicationExceptions are thrown with the message 'Error while reading line from the server' from time to time. The Predis part of an example stack trace:

Message: Error while reading line from the server
Thrown at: /var/www/lib/redis/Predis.php:1568
Trace:
#0 /var/www/lib/redis/Predis.php(1636): Predis\Connection->onCommunicationException('Error while rea...')
#1 /var/www/lib/redis/Predis.php(724): Predis\Connection->readLine()
#2 /var/www/lib/redis/Predis.php(1577): Predis\FastResponseReader->read(Object(Predis\Connection))
#3 /var/www/lib/redis/Predis.php(1586): Predis\Connection->readResponse(Object(Predis\Commands\Auth))
#4 /var/www/lib/redis/Predis.php(225): Predis\Connection->executeCommand(Object(Predis\Commands\Auth))
#5 /var/www/lib/redis/RedisProxy.php(21): Predis\Client->__call('auth', Array)
#6 /var/www/lib/redis/RedisProxy.php(21): Predis\Client->auth('password')

We couldn't find anything in common in the affected scripts. Some errors are from a local Redis server, some from a remote one. An example that sometimes generates this error:

The script is run by Apache, browsers call it directly by URL, so there can be a lot of instances running at once. The following Redis commands are run via Predis (in this order; a, b , c and d are different tables):

• AUTH
• SELECT a
• EXISTS
• (if a condition is met) SETEX
• SELECT b
• RPUSH
• if a condition is met
  • SELECT b
  • INCR
  • SELECT c
  • GET
  • SELECT d
  • RPUSH

The bold commands are those that have ever generated the error. The majority (99%) is on AUTH.

Environment:

$ redis-server -v
Redis server version 2.2.4 (00000000:0)

Predis version 0.6.6

$ php -v
PHP 5.3.3-0.dotdeb.1 with Suhosin-Patch (cli) (built: Oct  1 2010 08:49:29) 
Copyright (c) 1997-2009 The PHP Group
Zend Engine v2.3.0, Copyright (c) 1998-2010 Zend Technologies
    with Xdebug v2.1.0, Copyright (c) 2002-2010, by Derick Rethans

$ /usr/sbin/apache2ctl -v
Server version: Apache/2.2.9 (Debian)
Server built:   Apr 20 2010 15:40:17

[nrk]

Your issue is quite strange. That kind of exception is usually thrown when the socket (which is already connected) reaches a timeout during read or write operations, but the fact that you are seeing these kind of errors even when dealing with a local instance of Redis makes it indeed weird. Did you use a custom (and low) value for the read_write_timeout parameter to configure the connection to Redis?

[abesto]

No, we didn't. The only configuration parameter passed to the client is connection_timeout with a value of 30 (which is higher than the default).

This may not be interesting, but I hacked the client a bit to try to read again at the moment the exception occurs, and append the read string to the exception text. I didn't take too many samples, but the read string looked to be a few characters of valid output (didn't actually verify). Anyway, it wasn't empty.

Edit. Another data point: there's usually a whole bunch of error instances within about one second, but nothing before or after it. I realize this could point towards a problem in Redis; is there a way to rule out Predis as the culprit (other than rewriting the calls to use another language/client)?

[nrk]

Can you try to wrap the calls that usually end up generating the exception in a try ... catch block with a code that looks like the following one?

<?php
try {
    // Redis commands
}
catch (Predis\CommunicationException $exception) {
    $stream = $exception->getConnection()->getSocket();
    $metadata = var_export(stream_get_meta_data($stream), true);
    // log the $metadata string somewhere so that you can retrieve it
    throw $exception;
}

With $metadata we should get some useful details about the state of the underlying PHP stream to start guessing what's happening on your server when those exceptions are thrown.

By the way the value of connection_timeout has effects only on the connect operation of the client socket stream to a remote endpoint. Instead read_write_timeout is used to set the timeout of read and write operations over a connected socket (the default should be 30 seconds if I remember correctly). You could try to set an higher value for read_write_timeout just to see if you notice some changes, but do that only after having captured a few samples of the stream metadata like described above.

[abesto]

Very well, we'll try both. Work starts about 12 hours from now (we're on CET), I'll report back with the results.

Thank you.

[nrk]

Sorry, I just noticed that the current behaviour of Predis doesn't play nice with that snippet of code. You should temporarily modify this line of code to return false so that the underlying stream resource is not closed before the exception is allowed to propagate out.

[abesto]

OK, done. There was no exception yet.

[abesto]

Got a few errors, here's an example (they all look the same):

Message: Predis socket metadata dump: array (
  'stream_type' => 'tcp_socket/ssl',
  'mode' => 'r+',
  'unread_bytes' => 0,
  'seekable' => false,
  'timed_out' => true,
  'blocked' => true,
  'eof' => false,
)

The timed_out => true confirms your theory, and raising read_write_timeout should fix the problem, right? (or at least make it go away for now)

[nrk]

Raising the value of read_write_timeout might help alleviate the issue, but it really depends on the source of the timeouts and the default value is 60 seconds anyway (verified right now) which already is a very high value. Also, the fact that your scripts can connect successfully to Redis leaves out problems related to ephemeral TCP/IP port exhaustion.

How many concurrent client are connected to your Redis instances on average? Would it be possible for you to use UNIX domain sockets instead of TCP/IP to connect to the Redis instances that run on the locahost and see if you still get those random errors out of them?

[abesto]

On two Redis servers with the issue there are 17 +/- 5 connections. One had a maximal spike of 30, the other has a daily spike of 60-100 (both last for a few minutes, and they don't match the times of the errors). I'll try using UNIX sockets for one of the servers.

We got a very small number of errors similar to the following:

Message: Connection timed out
Thrown at: /var/www/lib/redis/Predis.php:1568
Trace:
#0 /var/www/lib/redis/Predis.php(1518): Predis\Connection->onCommunicationException('Connection time...', 110)
#1 /var/www/lib/redis/Predis.php(1494): Predis\Connection->redisStreamInitializer(Object(Predis\ConnectionParameters))
#2 /var/www/lib/redis/Predis.php(1648): Predis\Connection->connect()
#3 /var/www/lib/redis/Predis.php(1599): Predis\Connection->getSocket()
#4 /var/www/lib/redis/Predis.php(1573): Predis\Connection->writeBytes('*2??$4??AUTH??$...')
#5 /var/www/lib/redis/Predis.php(1582): Predis\Connection->writeCommand(Object(Predis\Commands\Auth))
#6 /var/www/lib/redis/Predis.php(225): Predis\Connection->executeCommand(Object(Predis\Commands\Auth))
#7 /var/www/lib/redis/RedisProxy.php(21): Predis\Client->__call('auth', Array)

This could be just because of this change, but maybe it has some extra info for you.

[nrk]

Well, seeing that you get timeouts also during connect() operations is somewhat reassuring, it would have been totally weird otherwise :-) Anyway, 100 simultaneous connections to Redis shouldn't pose any problem (at least on Redis-side).

By the way I just noticed that you are running PHP with Xdebug loaded. Aside from the fact that Xdebug can slow your PHP code down quite a bit for a production environment, I don't know if it could mess with PHP streams or something under load. You should try to disable it, if possible, and if even doing this doesn't solve the problem... well, I'm at loss for words.

From how things are turning out this doesn't seem a bug of Predis, and the only things left I can think of are:

• connectivity issues (but this wouldn't make much sense for connections on the localhost)
• some sort of misconfiguration of the PHP + Apache environment (I don't use Apache since years, so I can't be of any help)

[abesto]

Very well, if disabling Xdebug doesn't solve the problem, then I'll try to reproduce this with another client library. Hopefully that will narrow things down enough for the Redis folks to figure this out. We'll use unix sockets for loopback connections, even if they don't solve this (speedup is good for the health), so thanks for that pointer as well.

Thank you for your time :)

[nrk]

Let me know how things go, now I'm curious :-)

[abesto]

Sure, I'll write here with the results. There weren't any errors since I disabled Xdebug, I hope it'll stay that way.

[nrk]

Just adding a link to an ongoing discussion on this matter (timeouts) from the Redis mailing list since it has some interesting tips.

[abesto]

Actually, I wrote the OP of that thread :) It was still very nice of you to post the link.

[abesto]

The cause of the issue was a faulty Realtek driver (r8169 before kernel 2.6.30 is buggy, have to use r8168). Nothing to do with Redis or Predis.

[nrk]

Thanks for the update, this might be a valuable information for others. Debugging these kind of weird issues can be hard and time consuming when the cause is somewhere at a lower level.

[rookie7799]

Abesto, sorry to bother - but we are experiencing the same issue i was wondering how did u go about find out that "The cause of the issue was a faulty Realtek driver" ??

Thanks!

[abesto]

@rookie7799 No problem at all. /var/log/kernel.log contained "interface up" messages at the same times that the errors occured; the link was down for some time before these messages.

Mention of the problem and a detailed solution at Hetzner: http://wiki.hetzner.de/index.php/Installation_des_r8168-Treibers/en

Sorry for taking so long to answer.

[terry8416]

I got the same issue when I use command "brpop bar 0" in code. setting read_write_timeout to -1 can solve it but...are there any better solutions? or can this solution cause other unknown issues?by the way,for our system, 60s timeout is not enough:(

[abesto]

You could do blocking operations with a non-zero second argument. This releases the block once that "timeout" is reached. You can then run some checks, and issue the blocking command again. This way you also avoid having to configure the server for not dropping very long connections.

[terry8416]

It's a good idea, thanks for your answer:)

[razvanphp]

Sorry for bringing this up again after so much time, but I think I have a different reason why I get this error message. I tried debugging the stream as mentioned earlier and got this:

array(7) {
  ["stream_type"]=>
  string(14) "tcp_socket/ssl"
  ["mode"]=>
  string(2) "r+"
  ["unread_bytes"]=>
  int(0)
  ["seekable"]=>
  bool(false)
  ["timed_out"]=>
  bool(false)
  ["blocked"]=>
  bool(true)
  ["eof"]=>
  bool(false)
}

read_write_timeout is set to -1, and we use one master and one slave with replication => true. Judging by the IP address, the error is triggered on the master.

Any idea about blocking mode connection? I saw other PHP Redis library has this configurable.

We just switched from phpredis and this is a cron job, the error happens exactly after 60 seconds.

Thank you!

[pravindahal]

This is how I managed to capture the debug info:

          catch (Predis\CommunicationException $exception) {
                $stream = $exception->getConnection()->getResource();
                $errorMessage = var_export(stream_get_meta_data($stream), true);
                //Log::info($errorMessage);
                continue;
            }

I get the following:

array (
  'timed_out' => false,
  'blocked' => true,
  'eof' => false,
  'stream_type' => 'tcp_socket/ssl',
  'mode' => 'r+',
  'unread_bytes' => 0,
  'seekable' => false,
)

I have set read_write_timeout to -1, timeout in redis.conf to 0, second param to blpop as 0. Has anyone managed to find out more about this?

More info:
Using redis 3 (docker image, alpine variant) with Laravel 5.1 in a long running artisan command.

[pravindahal]

No Ben, I haven't been able to resolve this. Ben Cromwell wrote:

…

Hi @pravindahal <https://github.com/pravindahal> Thanks for posting the debug capturing code. Did you get anywhere towards a resolution? I have a similar issue:- |array ( 'stream_type' => 'tcp_socket/ssl', 'mode' => 'r+', 'unread_bytes' => 0, 'seekable' => false, 'timed_out' => false, 'blocked' => true, 'eof' => false, ) | — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#32 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA2nC7YRPNChZdEOx9c1N3pBJNbr0KW3ks5rDT5XgaJpZM4HN5ze>.

[bencromwell]

Apologies, I deleted my comment as I wasn't sure the issue was the same after more debugging. It might be though. I swapped out Predis for phpredis and experienced the same error. After more searching I found the setting `default_socket_timeout` and set it to -1. This is in php.ini http://php.net/manual/en/filesystem.configuration.php#ini.default-socket-timeout That did the trick. It seems that is necessary despite setting the connection parameter read_write_timeout. PHP's setting trumps it, both are required by the looks of things.

…

On 30 November 2016 at 11:43, Pravin Dahal ***@***.***> wrote: No Ben, I haven't been able to resolve this. Ben Cromwell wrote: > > Hi @pravindahal <https://github.com/pravindahal> > > Thanks for posting the debug capturing code. Did you get anywhere > towards a resolution? > > I have a similar issue:- > > |array ( > 'stream_type' => 'tcp_socket/ssl', > 'mode' => 'r+', > 'unread_bytes' => 0, > 'seekable' => false, > 'timed_out' => false, > 'blocked' => true, > 'eof' => false, > ) > | > > — > You are receiving this because you were mentioned. > Reply to this email directly, view it on GitHub > <#32 (comment)>, or > mute the thread > <https://github.com/notifications/unsubscribe-auth/ AA2nC7YRPNChZdEOx9c1N3pBJNbr0KW3ks5rDT5XgaJpZM4HN5ze>. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#32 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AApvTxieAw1-Jfa6NvXJbwKTW8VP9rgfks5rDWFYgaJpZM4HN5ze> .

[bencromwell]

I find myself back here almost a year later and feel compelled to comment.

Composer doesn't work (install/update packages) with that socket setting changed.

No idea why the package doesn't seem to respect the configuration settings and is unable to override PHP's default. Leaving this comment here in case anyone is reading this and knows the solution!

[ZekiJohn]

default_socket_timeout

In my case configuring Redis was not enough setting default_socket_timeout=-1 in php.ini makes it work.
thanks @bencromwell.