Stackexchange.redis: Restoring connection to redis

[shvez]

Hi, there.

I use StackExchange.Redis.1.0.281.0
It is turned out that lib can't restore connection to redis in some cases.

My application executes next code every few seconds

{
      var server = this.application.Multiplexer.GetServer(RedisServerAddress);
      var keys = server.Keys(Properties.Settings.Default.BackendRedisDBId);
...............
}
catch(Exception e)
{
  //log exception
}

In order to check how this code works when connection lost and restored, i just stopped Redis and started it again. Most of the time connection restored, but some times does not. The code above fails with exception until i restart Redis again. After restart lib restores connection.

I create ConnectionMultiplexer next way

 var config = ConfigurationOptions.Parse(RedisServerAddress);

 config.KeepAlive = 5;
 config.SyncTimeout = 1000;
 config.AbortOnConnectFail = false;
 config.AllowAdmin = true;

 var muxer = ConnectionMultiplexer.Connect(config);

 muxer.ConfigurationChanged += (sender, args) => log.DebugFormat("ConfigurationChanged with endpoint: {0}", args.EndPoint);
 muxer.ConfigurationChangedBroadcast += (sender, args) => log.DebugFormat("ConfigurationChangedBroadcast with endpoint: {0}", args.EndPoint);
 muxer.ConnectionFailed += (sender, args) => log.DebugFormat("ConnectionFailed with args: {0}", args.Exception.Message);
 muxer.ConnectionRestored += (sender, args) => log.DebugFormat("ConnectionRestored with args: {0}", args.EndPoint);
 muxer.ErrorMessage += (sender, args) => log.DebugFormat("ErrorMessage with args: {0}", args.Message);
 muxer.HashSlotMoved += (sender, args) => log.DebugFormat("HashSlotMoved with args: {0}", args.NewEndPoint);
 muxer.InternalError += (sender, args) => log.DebugFormat("InternalError with args: {0}", args.Exception);

What information yet should i provide in order to help find reason?

[shvez]

I found in logs that connection was restored, but code above fails.
if i debug code, i see that muxer.IsConnected returns false.
log messages are:

ConfigurationChanged with endpoint: 127.0.0.1:6379
StackExchange.Redis.RedisConnectionException: No connection is available to service this operation: KEYS

[coopa]

I ran into the same problem, and have been attempting to get a good reproducible case. It seems it's highly intermittent, but once a ConnectionMultiplexer is broken it's broken for good, it will never reconnect without restarting the process.

[shvez]

For me it reconnects if i restart Redis. I even see report that connection was lost. I mean that getting keys from DB fails, because "No connection is available to service this operation: KEYS", but when i stop redis i see, that connection was lost.

I'm writing simple console application, in order to have simpler way to reproduce this behavior

[shvez]

it is sad, but with simple console app i failed to reproduce this behavior. All what i got this

18:39:54,200 WARN  Program ConnectionFailed with args: SocketFailure on 127.0.0.1:6379/Subscription, input-buffer: 0, outstanding: 0, last-read: 2s ago, last-write: 2s ago, keep-alive: 5s, pending: 0, state: ConnectedEstablished, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago [11]
18:39:54,210 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [11]
18:39:54,212 WARN  Program ConnectionFailed with args: SocketFailure on 127.0.0.1:6379/Interactive, input-buffer: 0, outstanding: 0, last-read: 2s ago, last-write: 2s ago, keep-alive: 5s, pending: 0, state: ConnectedEstablished, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago [11]
18:39:54,223 ERROR Program InternalError with args: System.NullReferenceException: ...
   в StackExchange.Redis.PhysicalConnection.WriteHeader(RedisCommand command, Int32 arguments) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\PhysicalConnection.cs:line 379
   в StackExchange.Redis.Message.CommandKeyMessage.WriteImpl(PhysicalConnection physical) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\Message.cs:line 734
   в StackExchange.Redis.PhysicalBridge.WriteMessageToServer(PhysicalConnection connection, Message message) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\PhysicalBridge.cs:line 766 [11]
18:39:54,239 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [11]

[coopa]

I am getting something semi-reproducible by spinning up a bunch of threads with their own ConnectionMultiplexers instead of a shared one

[coopa]

Alright, so this is a bit of a far shot, but here's a small sample app. This will spin up some amount of threads against a given host (for my testing I used 20 threads against my test VM). I used the latest build of MSOpen redis-server 2.8.4 and latest pull from SE.Redis for this. redis-server was started with a --maxmemory 512mb parameter.

These threads will simply do busy work to simulate usage like listing keys, and getting/setting values. Each thread has a timer that checks IsConnected every second, which will then report an error if a connection does not exist. The connection restore/fail will also mark what type of connection the event handler was called on which keeps track of what connection types were restored, or went down. Curiously, I noticed that every time I was able to reproduce the problem it was the "Interactive" connection that was marked as dead this way.

I ran this test program in Debug from within Studio 2013 (I simply added a new project to the SE.Redis solution locally called Minimus). Once it's running it's a little tricky to see the behavior in question, but I've had decent luck with stopping redis-server via Ctrl-C and then starting it up after 3 seconds. This works with relative consistency on my local machine to get at least one of the threads into the weird "half-connected" state. It's not guaranteed to break on the first try though, so sometimes you have to try it a few times (kill redis-server, wait a few seconds, start it back up).

Hope this helps somewhat, and any input or feedback is more than welcome.

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Threading;
using StackExchange.Redis;

namespace Minimus
{
    class Program
    {
        static void Main()
        {
            Trace.Listeners.Add(new ConsoleTraceListener());
            Trace.AutoFlush = true;

            // Spin up X number of "clients" against provided host
            SpinnersUp(20, "somehost", 7777);
        }

        private static void SpinnersUp(int numSpinners, string host, int port)
        {
            foreach (var i in Enumerable.Range(0, numSpinners))
            {
                new Spinner(host, port, i);
            }
        }
    }

    internal class Spinner
    {
        protected ConnectionMultiplexer Redis { get; private set; }
        private readonly string _localKey;
        private readonly string _host;
        private readonly int _port;
        private readonly int _spinnerNumber;
        private int _notConnectedTicksCount;
        private readonly Dictionary<ConnectionType, bool> _aliveConnections;

        public Spinner(string host, int port, int spinnerNumber)
        {
            _host = host;
            _port = port;
            _spinnerNumber = spinnerNumber;
            _localKey = Guid.NewGuid().ToString(); // just wanted some unique key here
            _aliveConnections = new Dictionary<ConnectionType, bool>();

            var config = new ConfigurationOptions
            {
                AllowAdmin = true,
                EndPoints = { { host, port } },
                AbortOnConnectFail = false
            };
            Redis = ConnectionMultiplexer.Connect(config);
            // Mark connection types alive/not alive for diagnostic purposes
            Redis.ConnectionRestored += (sender, args) => _aliveConnections[args.ConnectionType] = true;
            Redis.ConnectionFailed += (sender, args) => _aliveConnections[args.ConnectionType] = false;

            var connectionWatcher = new Timer(_ => CheckConnection());
            connectionWatcher.Change(TimeSpan.FromSeconds(1), TimeSpan.FromSeconds(1));

            DoBusyWork();
        }

        // Called every second to check that there is a connection
        private void CheckConnection()
        {
            // reset the counter if connection is present
            if (Redis.IsConnected) {_notConnectedTicksCount = 0; return;}
            _notConnectedTicksCount++;
            if (_notConnectedTicksCount < 20 || _notConnectedTicksCount%20 == 0)
            {
                // Will dump out a list of types of connections that are not connected
                Trace.TraceError("Spinner {0} (dead connections: {1}) couldn't connect for {2} ticks", _spinnerNumber, 
                    string.Join(",", _aliveConnections.Where(x=>!x.Value).Select(x=> x.Key)), _notConnectedTicksCount);
            }
        }

        // Just random redis chatter
        public void DoBusyWork()
        {
            new Thread(() => Looper(() => Redis.GetServer(_host, _port).Keys().ToList())).Start();
            new Thread(() => Looper(() => Redis.GetDatabase().StringGet(_localKey))).Start();
            new Thread(() => Looper(() => Redis.GetDatabase().StringSet(_localKey, "value"))).Start();
        }

        public void Looper(Action action)
        {
            while (true)
            {
                try
                {
                    action();
                    Thread.Sleep(500);
                } catch { }
            }
        }
    }
}

[shvez]

I managed to reproduce bug in my sample. here it is: https://dl.dropboxusercontent.com/u/27459474/StackExchangeTest.zip

It started to repeat after i created 3 thereads which use shared ConnectionMultiplexer

In my tests i use SE.Redis.1.0.281.0 and redis Redis-64.2.6.12.1
Redis started with default parameters on localhost. Windows 8.1

Way to reproduce:

1. start Redis
2. start sample
3. stop redis. You will see log in console: GetServerList got exception. this is ok
4. start redis again. Logging about exception should stop. if it does not stop than we faced problem
5. repeat 3 and 4 until reproducing

I managed to reproduce after 3 start of Redis. My PC has only two cores, so may be you need more threads in case of 4 cores. Just add more ThreadPool.QueueUserWorkItem(testBody); in line 30

Hope this will help

[shvez]

After some testing got this error during getting keys. muxer and server are connected

ErrorMessage with args: ERR wrong number of arguments for 'mget' command

[mgravell]

I will see what I can find

On 9 May 2014 08:18, Ilya Shvetsov [email protected] wrote:

After some testing got this error during getting keys. muxer and server
are connected
'''
ErrorMessage with args: ERR wrong number of arguments for 'mget' command
'''

—
Reply to this email directly or view it on GitHubhttps://github.com/StackExchange/StackExchange.Redis/issues/38#issuecomment-42639677
.

Regards,

Marc

[shvez]

Thank you

[shvez]

Hi, Marc
I updated SE.Redis to version 1.0.289.0
now, when i connect to Redis-64 2.8.4 on windows localhost i constantly get this error message

ERR wrong number of arguments for 'mget' command

if i start Redis-64 2.6.12.1 everything works as before

[shvez]

Hire is one more sample, which it seems to me should work, but it does not. May be it will shade some light on what is wrong
https://dl.dropboxusercontent.com/u/27459474/StackExchangeTest2.zip

Use case very simple. Start sample, it will show that it does not have connection to Redis. Start Redis. Sample still continues to show that it does not have connection to redis

if you will start redis first and than sample, connection will be established successfully

Expected by me behaviour is:
After start of sample it writes that there is not connection
After start redis it shold report that connection is established

I believe this is somehow connected to issue we reported here

[mlstubblefield]

I've experienced this issue while performing some load testing.
I believe that the application attempted to establish a connection after being started.
The issue was localized to a single instance of a server farm where all of the servers were configured the same.
The application uses multiple threads (.net async) and a single multiplexer.

[shvez]

is there any news on this issue?

[mfelicio]

I'm also facing a similar issue and I use 1.0.289. I have two instances ConnectionMultiplexers configured to use 127.0.0.1:6379 (abort=false). I started the app with Redis server disconnected, then one of the multiplexers connected but the other didn't. Don't ask why I have two instances for the same server, We use different redis instances, but on our local environments we use only one endpoint..

[RomanTomsk]

I have the same problem,I'm trying to configure the system stability, which will behave correctly in the fall of some or all redis servers as well as could reconnect when the server is restored. But I haven't stability result, sometimes my solution work is well , but not always.

I use 3 ubuntu virtual mashines, and use events ConnectionFailed and ConnectionRestored. I noticed that the status IsConneted not always correctly updated, more precisely it can be updated in the other thread.

We want to use Redis for a big project, with big farm servers. But we cannot ensure the reliability of the system.

[shvez]

is there any news about this issue?

[shvez]

i checked last version with both my tests. and it works. This is very good news. But sometimes i see next behavior. Usualy programm gets connected immiadetly, but some times after few seconds and sometimes it notifies about connection restoring second time after long gap

12:14:48,971 INFO  Program     ConnectionRestored with args: 127.0.0.1:6379 [8]
12:14:48,971 INFO  Program     ConnectionMultiplexer.IsConnected: True [8]
12:14:48,972 INFO  Program     ConfigurationChanged with endpoint: 127.0.0.1:6379 [8]
12:14:53,986 INFO  Program     ConnectionRestored with args: 127.0.0.1:6379 [37]
12:14:53,986 INFO  Program     ConnectionMultiplexer.IsConnected: True [37]
12:14:53,987 INFO  Program     ConfigurationChanged with endpoint: 127.0.0.1:6379 [37]

see program StackExchageTest got two notifications about Connection restored one and five seconds later another one. this gap between notifications can be less. Some times i have only one notifciation that connection is restored, but mostly i have two notifications

12:20:18,119 INFO  Program     ConnectionRestored with args: 127.0.0.1:6379 [19]
12:20:18,120 INFO  Program     ConnectionMultiplexer.IsConnected: False [19]
12:20:18,124 INFO  Program     ConfigurationChanged with endpoint: 127.0.0.1:6379 [19]
12:20:19,039 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [66]
12:20:19,041 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [63]
12:20:19,046 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [65]
12:20:19,050 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [19]
12:20:19,054 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [47]
12:20:22,051 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [19]
12:20:22,056 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [47]
12:20:22,555 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [60]
12:20:22,557 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [66]
12:20:22,578 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [65]
12:20:23,018 ERROR Program     GetServerList exception:No connection is available to service this operation: KEYS [49]
12:20:23,130 INFO  Program     ConnectionRestored with args: 127.0.0.1:6379 [63]
12:20:23,130 INFO  Program     ConnectionMultiplexer.IsConnected: True [63]
12:20:23,130 INFO  Program     ConfigurationChanged with endpoint: 127.0.0.1:6379 [63]

Got NullRef once

12:44:40,634 WARN  Program ConnectionFailed with args: SocketFailure on 127.0.0.1:6379/Subscription, input-buffer: 0, outstanding: 0, last-read: 4s ago, last-write: 4s ago, keep-alive: 5s, pending: 0, state: ConnectedEstablished, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago [16]
12:44:40,635 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [16]
12:44:40,636 WARN  Program ConnectionFailed with args: SocketFailure on 127.0.0.1:6379/Interactive, input-buffer: 0, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 5s, pending: 0, state: ConnectedEstablished, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago [16]
12:44:40,637 ERROR Program InternalError with args: System.NullReferenceException: Reference....
   в StackExchange.Redis.PhysicalConnection.WriteHeader(RedisCommand command, Int32 arguments) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\PhysicalConnection.cs:строка 379
   в StackExchange.Redis.Message.CommandKeyMessage.WriteImpl(PhysicalConnection physical) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\Message.cs:строка 734
   в StackExchange.Redis.PhysicalBridge.WriteMessageToServer(PhysicalConnection connection, Message message) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\PhysicalBridge.cs:строка 796 [16]
12:44:40,643 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [16]
12:44:40,644 INFO  Program ConnectionRestored with args: 127.0.0.1:6379 [16]
12:44:40,644 INFO  Program ConnectionMultiplexer.IsConnected: True [16]
12:44:40,644 INFO  Program ConnectionRestored with args: 127.0.0.1:6379 [16]
12:44:40,645 INFO  Program ConnectionMultiplexer.IsConnected: True [16]
12:44:40,645 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [16]

but anyway eventually connection is restored. This is good news

[shvez]

Question to other people, are you able to reproduce behavior from this issue? I'm not able, even after exeception connection was restored and in working state

[shvez]

just to be sure that you saw this. I found this null ref in 1.0.297

Got NullRef once

12:44:40,634 WARN  Program ConnectionFailed with args: SocketFailure on 127.0.0.1:6379/Subscription, input-buffer: 0, outstanding: 0, last-read: 4s ago, last-write: 4s ago, keep-alive: 5s, pending: 0, state: ConnectedEstablished, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago [16]
12:44:40,635 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [16]
12:44:40,636 WARN  Program ConnectionFailed with args: SocketFailure on 127.0.0.1:6379/Interactive, input-buffer: 0, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 5s, pending: 0, state: ConnectedEstablished, last-heartbeat: 0s ago, last-mbeat: 0s ago, global: 0s ago [16]
12:44:40,637 ERROR Program InternalError with args: System.NullReferenceException: Reference....
   в StackExchange.Redis.PhysicalConnection.WriteHeader(RedisCommand command, Int32 arguments) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\PhysicalConnection.cs:строка 379
   в StackExchange.Redis.Message.CommandKeyMessage.WriteImpl(PhysicalConnection physical) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\Message.cs:строка 734
   в StackExchange.Redis.PhysicalBridge.WriteMessageToServer(PhysicalConnection connection, Message message) в c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\PhysicalBridge.cs:строка 796 [16]
12:44:40,643 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [16]
12:44:40,644 INFO  Program ConnectionRestored with args: 127.0.0.1:6379 [16]
12:44:40,644 INFO  Program ConnectionMultiplexer.IsConnected: True [16]
12:44:40,644 INFO  Program ConnectionRestored with args: 127.0.0.1:6379 [16]
12:44:40,645 INFO  Program ConnectionMultiplexer.IsConnected: True [16]
12:44:40,645 INFO  Program ConfigurationChanged with endpoint: 127.0.0.1:6379 [16]

[tekr]

We're using 1.0.316 and are intermittently seeing the same issue whereby SE.Redis doesn't reconnect properly after the connection to Redis is lost.

We use a single ConnectionMultiplexer instance in a heavily multi-threaded fashion, and occasionally in dev the Redis process crashes (Windows version instability, I guess). We use RedisWatcher to automatically restart it, and typically this is transparent because SE.Redis reconnects.

However occasionally SE.Redis doesn't reconnect properly, and we then get an exception every time we attempt to run a Redis command (e.g. a script) until we restart our service:

StackExchange.Redis.RedisConnectionException: No connection is available to service this operation: EVAL
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor`1 processor, ServerEndPoint server) in c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\ConnectionMultiplexer.cs:line 1738
   at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server) in c:\TeamCity\buildAgent\work\58bc9a6df18a3782\StackExchange.Redis\StackExchange\Redis\RedisBase.cs:line 79

Interestingly, when Redis restarts after the crash, its logs suggest SE.Redis first connects, then disconnects, and then only partially reconnects (bold lines are connections/disconnections by the SE.Redis client in our service):

[5656] 19 Aug 11:15:11.180 # Server started, Redis version 2.8.12
[5656] 19 Aug 11:15:11.555 - Accepted 127.0.0.1:49725
[5656] 19 Aug 11:15:11.713 - Accepted 10.17.176.16:56781
[5656] 19 Aug 11:15:11.834 - Accepted 127.0.0.1:49726
[5656] 19 Aug 11:15:11.947 - Accepted 127.0.0.1:49727
[5656] 19 Aug 11:15:11.947 - Client closed connection
[5656] 19 Aug 11:15:12.083 - Client closed connection
[5656] 19 Aug 11:15:12.084 - Client closed connection
[5656] 19 Aug 11:15:12.202 * DB loaded from append only file: 1.023 seconds
[5656] 19 Aug 11:15:12.202 * The server is now ready to accept connections on port 6380
..
[5656] 19 Aug 11:15:12.836 * Synchronization with slave succeeded
[5656] 19 Aug 11:15:12.935 - Accepted 127.0.0.1:49728

Normally SE.Redis within our service should have two open connections to Redis (one interactive, one pub/sub), but notice above that only one connection is successfully re-established (the last line). This correlates with the disconnection/reconnection events from SE.Redis that we publish to the service logs, which show only the subscription connection was re-established:

11:15:11.795 [15] ERROR - Interactive Redis connection to Unspecified/localhost:6380 lost. Failure type: SocketFailure
11:15:11.851 [14] ERROR - Subscription Redis connection to Unspecified/localhost:6380 lost. Failure type: SocketFailure

11:15:12.941 [15] INFO  - Subscription Redis connection to Unspecified/localhost:6380 restored

Contrast that with the Redis log of another restart following a Redis crash where SE.Redis reconnected properly:

[14768] 19 Aug 13:35:02.229 # Server started, Redis version 2.8.12
[14768] 19 Aug 13:35:02.849 - Accepted 127.0.0.1:50835
[14768] 19 Aug 13:35:02.849 - Accepted 127.0.0.1:50836
[14768] 19 Aug 13:35:03.128 - Client closed connection
[14768] 19 Aug 13:35:03.152 - Accepted 10.17.176.16:59286
[14768] 19 Aug 13:35:03.177 - Client closed connection
[14768] 19 Aug 13:35:03.437 * DB loaded from append only file: 1.208 seconds
[14768] 19 Aug 13:35:03.437 * The server is now ready to accept connections on port 6380
[14768] 19 Aug 13:35:03.554 - Accepted 127.0.0.1:50837
[14768] 19 Aug 13:35:03.554 - DB 0: 36 keys (0 volatile) in 64 slots HT.
[14768] 19 Aug 13:35:03.555 - 2 clients connected (0 slaves), 4830264 bytes in use
[14768] 19 Aug 13:35:03.557 - Accepted 127.0.0.1:50838

Note there are two localhost connections opened in the last 4 lines as expected, and our service logs indicate both connections were re-established:

13:35:03.163 [14] ERROR - Interactive Redis connection to Unspecified/localhost:6380 lost. Failure type: SocketFailure
13:35:03.167 [14] ERROR - Subscription Redis connection to Unspecified/localhost:6380 lost. Failure type: SocketFailure

13:35:03.571 [15] INFO  - Interactive Redis connection to Unspecified/localhost:6380 restored
13:35:03.571 [15] INFO  - Subscription Redis connection to Unspecified/localhost:6380 restored

Anecdotally, we've noticed this only seems to happen to the SE.Redis client within our service, which runs on the same machine as Redis. We also use SE.Redis in our client app, connecting to the same Redis DB over the network, but haven't noticed the same issue. This could just be coincidence, or may indicate that the problem is somehow related to local connections (e.g. could be a race condition that only shows up with very short reconnection intervals, etc.)

[nmehlei]

We have the same problem but from three different Azure-based applications, none of which are on the same machine as our Redis servers. The "No connection is available to service this operation" state occurs every few days and then requires a restart of all roles that are affected. I am not sure why that happens this often, especially because we have 1 master and 1 slave, so either the connectivity must've been interrupted to both of them for the timeframe it takes for StackExchange.Redis to behave like this, or it isn't necessarily always related to connection interruptions.

[nitzmahone]

@k0dem0nkey - that jives with what we see as well. Since we started using SE.Redis a few months ago, our client/server-on-same-box Redis machines will occasionally hit this problem and require a restart of the process that's hosting SE.Redis. We have plenty of boxes using SE.Redis against remote Redis servers as well, and we've never seen it happen on one of those.

[ofirgeller]

for me it is happening on same box and also when using remote. and no restart is needed . it just goes away after a while.

we are using se.redis as a dependency for redis session provider.

StackExchange.Redis.RedisConnectionException: No connection is available to service this operation: EVAL
at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImplT
at StackExchange.Redis.RedisDatabase.ScriptEvaluate(String script, RedisKey[] keys, RedisValue[] values, CommandFlags flags)
at Microsoft.Web.Redis.StackExchangeClientConnection.<>c__DisplayClass4.b__3()
at Microsoft.Web.Redis.StackExchangeClientConnection.RetryForScriptNotFound(Func`1 redisOperation)

[mgravell]

That suggests that the connection was broken, and after a while: was
restored. If the client cannot get TCP connectivity to the server, there
aren't a huge amount of options. However, it might be useful to check:

• was there any known network issue at that time?
• is there anything in the redis-server process's logs at that time?
• is there anything in "slowlog get" at that time?

The last two could suggest reasons why it couldn't reconnect instantly in
the event of a failure.

Marc

On 3 September 2014 04:25, ofirgeller [email protected] wrote:

for me it is happening on same box and also when using remote. and no
restart is needed . it jsut goes away after a while.

we are using se.redis as a dependency for redis session provider.

StackExchange.Redis.RedisConnectionException: No connection is available
to service this operation: EVAL
at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImplT
at StackExchange.Redis.RedisBase.ExecuteSyncT
at StackExchange.Redis.RedisDatabase.ScriptEvaluate(String script,
RedisKey[] keys, RedisValue[] values, CommandFlags flags)
at
Microsoft.Web.Redis.StackExchangeClientConnection.<>c__DisplayClass4.b__3()
at
Microsoft.Web.Redis.StackExchangeClientConnection.RetryForScriptNotFound(Func`1
redisOperation)

—
Reply to this email directly or view it on GitHub
https://github.com/StackExchange/StackExchange.Redis/issues/38#issuecomment-54247838
.

Regards,

Marc

[ofirgeller]

a connection problem will not explain the fact that is is happening when the client and the server are siting on the same machine.

the slow log shows at most 60000 microseconds delay. if i understand correctly this is still fast enough.

the server sits on azure. i don't think i can look at the logs.

when i use a different client (csRedis) this problem goes away.

[micahasmith]

we're also on azure, also getting this error intermittently

@mgravell as an aside, if you're interested in performing any tests on azure to see if its specific to their infrastructure us here at @printdotio would be more than happy to do grunt work (devops/coding/anything), pay for the roles/test, etc, anything. email me at [my first name] @print.io if so.

[Plasma]

I've had "No connection is available to service this operation" errors locally (MacBook Pro, Windows, Redis on same machine as IIS) and once or twice on Azure.

The connection also never recovers.

It's semi-reprodicible after a fresh reboot and immediate load of the IIS website (and pages that use Redis), I don't think its really a regular socket timeout that causes this problem to appear. I think Azure may be a bit more problematic because of the (slower) CPUs that initially load the appdomain and perhaps exhaustion of tasks/threads during startup (and Multiplexer.Connect calls etc) being delayed compared to faster hardware (MacBook Pro, Stackexchange's prod environment on beefy machines etc).

I'm planning to set aside some time to try and reproduce and look at the state of SE.Redis when it happens.

[dot-i]

We just experienced the same problem here, all web machines in our load balancer were throwing exceptions and never recovered. Simply restarting the connection pool on all of them resolved the issue, but this is hardly an acceptable long-term solution of course ;-)

Is anyone still trying to reproduce and fix this? The internal state must indeed be messed up somehow, causing it to never reconnect...

[Plasma]

I've found that breaking into debugger mid request and sitting there for 5 mins causes it to usually break.

Sent from my iPhone

On 30 Sep 2014, at 5:48 pm, Nico Francois [email protected] wrote:

We just experienced the same problem here, all web machines in our load balancer were throwing exceptions and never recovered. Simply restarting the connection pool on all of them resolved the issue, but this is hardly an acceptable long-term solution of course ;-)

Is anyone still trying to reproduce and fix this? The internal state must indeed be messed up somehow, causing it to never reconnect...

—
Reply to this email directly or view it on GitHub.

[dot-i]

OK, that sounds promising at least. Any chance you could actually debug the error at that point to detect what's wrong with the internal state?

[timc13]

StackExchange.Redis.RedisConnectionException: No connection is available to service this operation

Just to chime in, I get the same error every once in awhile and i am NOT using Azure. An app restart fixes it.

[Tazer]

We got the same error, Random occasions . and when it throwed it wont recover until the website is rested / touched web.config. @mgravell found any possible this solutions?

StackExchange.Redis.RedisConnectionException: No connection is available to service this operation

[nmehlei]

I am still observing this problem, although it only occurs relatively rare (gut feeling: every 8-16 days). Sometimes "No connection is available to service this operation" just occurs and then resumes working ( #193 ) or the connection never recovers and it remains in this state indefinitely (=until app restarts), as is described in this ticket. Although it is now very rare, it doesn't seem like this issue is completely resolved.

[volkovku]

I confirm this problem does not solved.
The first error is: StackExchange.Redis.RedisConnectionException: UnableToResolvePhysicalConnection on HSET
After that exception changes to: No connection is available to service this operation
Connection never recovers until application was restarted.

[mehdyh]

the issue still exists in version 1.0.316.0

[davidbetz]

More information: confirmed same problem on 1.0.316.0 using Azure. It's very intermited, but solid for me for the past hour. This is not from a debugger timeout. This is on the StringGetAsync(String) call.

[NickCraver]

Re-opening this and merging in #81

[gsogol]

Getting this in Azure still.

[abhi004]

Still issue exits ..I have checked it today its been a long now

[RemiBou]

Issue still exists, and I'm in Azure, is this issue only on azure ? Maybe it's not a client thing

[yechongbo]

Same error here, on Windows Azure and Version=1.0.316.0

[francescocristallo]

Getting this 2 or 3 times a day, every time I need to redeploy the whole Azure cloud service. I'm switching to Service Fabric Stateful service, I found Azure Redis Cache totally unreliable for high throughput projects.

[Plasma]

I've hardly had this problem now, its only been during Azure cache maintenance events.

My recommendation is to ensure:
1) Your web/worker role (whatever is sending the data) is not CPU or network bound
2) Your redis cache instance is of a good enough size to sustain the workload its getting
3) Check your not sending/receiving huge amounts of data (eg sustained 10MB/sec or something) that could cause network timeouts

The redis cache metrics/advisor menu in the azure portal should hopefully provide some insight if you're reaching some of those limits.

[Misterhex]

Getting this as well from using windows redis. It seems azure redis cache is also running windows redis.

Does anyone get this issue when running against the Linux variant?

Does it make sense to have a pool of connection multiplexer, and checking the connection status before using it?

[mehdyhaghy]

my best guess:
it happens when you store large key values in redis.
for instance we are using redis as asp.net session store and
I've seen Microsoft Report Viewer storing session keys as large as 600 KB.
install RedisDesktopManager and navigate stored keys in redis.

[Misterhex]

We did not experience the issue after we moved from windows redis to linux.

[kent3513]

I got the same issue on the linux.
My Redis servers are Cluster.
After servers decrease memory from 4G to 2G,
The exception : "No connection is available to service this operation" occurs usually a day.

[shvez]

it would be good to know what version is used.
i assume this bug was fixed in last version

[rbbarranco]

We still experience this issue on 1.1.603. We do get "StackExchange.Redis.RedisConnectionException : No connection is available to service this operation:" when doing migration but our services recover after.

But on rare occasions, we get a "StackExchange.Redis.RedisConnectionException : UnableToResolvePhysicalConnection" error. And when it does, some our services fail to recover. Strange thing is that not all of our services fail to recover, only 1 or 2 do not. And it's not the same set of services that fail to recover when we get the exception, it's random.

We don't use Redis Cluster. We have 6 servers in Linux.

[hfar0k]

Getting the same issue when switched to StackExchange, error No connection is available to service this operation:" appears after restart of master node. The only way to fix that atm is to restart all slaves and recycle app pool for client to reconnect.

[minjie-kooboo]

We still have the same problem in Azure platform.
StackExchange.Redis: 1.2.6

[PaitoAnderson]

@minjie-kooboo We had the same issue with the Azure Redis Cache service, I ended up just using a Azure Linux VM and installing redis and the issue went away.

[nguyenchiencong]

Still happen on Azure

[michaellandi]

I am also getting this issue. Im using Redis in Linux containers.

When a container hosting Redis master node is lost unexpectedly (shutdown for example) we do not see the ConnectionFailed event fire. It only fires when the node comes back up and restores (ConnectionRestored). It's almost as if at that SE.Redis realizes that the particular node was down.

This occurs even with KeepAlive intervals set. Not sure how SE.Redis wouldn't know a node is down if sending keep alives....

[matthewacme]

Yep I'm seeing exactly the same problem. Add me to the list

[lciocci]

We're also experiencing intermittent UnableToResolvePhysicalConnection issues. Our applications are deployed to Azure, and we're currently running an older version - 1.2.1. Once the issue occurs it continues to occur until the service is restarted. Anyone know if this issue been fixed in 1.2.6?

[NickCraver]

@lciocci Yep, lots of fixes since then, especially around reconnects. There aren't any breaking changes, so an upgrade is safe to do.

[ryankelley]

@lciocci @NickCraver We are still experiencing the same issue with Azure Redis Cache, with our app on VM's and App Services. We have been using 1.2.6 for several months and have been experiencing this intermittently over that time.

[Plasma]

If you haven't already done it, I recommend setting options.KeepAlive = 10; to ensure on Azure the redis connection is kept alive.

Azure LB will disconnect idle sockets after 4 min by default, which could lead to issues.

[mgravell]

Closing; please see https://github.com/StackExchange/StackExchange.Redis/issues/871

[n1l]

If you haven't already done it, I recommend setting options.KeepAlive = 10; to ensure on Azure the redis connection is kept alive.

Azure LB will disconnect idle sockets after 4 min by default, which could lead to issues.

Hi, can you please describe how keepAlive = 10, and default keepAlive - 60 are related here? Because 10 and 60 are both less then 4 minutes?

[xdrnc]

For anyone who managed to reproduce the NullReferenceException from WriteHeader(RedisCommand command, int arguments), does anyone know which object causes the null? Multiplexer? Multiplexer.CommandMap? or Bridge?