Linq Exception on First connection

[jeroenpot]

I upgraded from 4.0.5 to 5.0.1 and while testing had no issues, but when i deployed to production environment i see these errors pop up:

System.InvalidOperationException: Sequence contains no matching element
at System.Linq.Enumerable.First[TSource](IEnumerable1 source, Func2 predicate)
at StackExchange.Redis.Extensions.Core.Implementations.RedisCacheConnectionPoolManager.GetConnection()
at StackExchange.Redis.Extensions.Core.Abstractions.RedisCacheClient.GetDb(Int32 dbNumber, String keyPrefix)
at MyNamespace.Cache.RedisCacheService.<>c__DisplayClass22_1`1.<b__1>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---

At the location of my code i'm calling the AddAsync method similar as this:
cacheClient.Db0.AddAsync("my cache key", user, DateTimeOffset.Now.AddMinutes(10));

Can't reproduce it locally at all, and not sure if it always happens.
I've recorded some new relic stats: The second green lines is where i deployed my application with the 5.0.1 version and the last green line is where i reverted the upgrade:

[jeroenpot]

The config i'm using also seems to be ok:
"Redis": {
"AllowAdmin": true,
"Ssl": false,
"ConnectTimeout": 6000,
"ConnectRetry": 2,
"SyncTimeout": 5000,
"Database": 0,
"Hosts": [
{
"Host": "host1.euw1.cache.amazonaws.com",
"Port": "6379"
},
{
"Host": "host2.euw1.cache.amazonaws.com",
"Port": "6379"
},
{
"Host": "host3.euw1.cache.amazonaws.com",
"Port": "6379"
},
{
"Host": "host4.euw1.cache.amazonaws.com",
"Port": "6379"
}
]
}

[imperugo]

I think the problem is here

StackExchange.Redis.Extensions/src/StackExchange.Redis.Extensions.Core/Implementations/RedisCacheConnectionPoolManager.cs

Lines 42 to 46 in d093397

	response = connections.First(lazy => lazy.Value.GetCounters().TotalOutstanding == minValue);
	}
	else
	{
	response = connections.First(lazy => !lazy.IsValueCreated);

But I didn't understand exactly why it happens

[jeroenpot]

I also had a look at the code and i see not nothing strange there indeed. I'll see if i can dig further into this in a few weeks (have a deadline to meet). My initial suspect is that the it's the 1st of these 2 linq statements, unexpected value given by the GetCounters().TotalOutstranding? Which results into the where clause not having a result.

[imperugo]

is IRedisCacheConnectionPoolManager registered as singleton?

[jeroenpot]

Yes it was (screenshot of my revert commit)

[imperugo]

Could you try something like this?

using System;
using System.Collections.Concurrent;
using System.Linq;
using StackExchange.Redis.Extensions.Core.Abstractions;
using StackExchange.Redis.Extensions.Core.Configuration;

namespace StackExchange.Redis.Extensions.Core.Implementations
{
	public class CustomRedisCacheConnectionPoolManager : IRedisCacheConnectionPoolManager
	{
		private const int POOL_SIZE = 10;
		private static ConcurrentBag<Lazy<ConnectionMultiplexer>> connections;
		private readonly RedisConfiguration redisConfiguration;
        private readonly ILogger<CustomRedisCacheConnectionPoolManager> logger;

		public CustomRedisCacheConnectionPoolManager(RedisConfiguration redisConfiguration, ILogger<CustomRedisCacheConnectionPoolManager> logger)
		{
			this.redisConfiguration =  redisConfiguration;
            this.logger = logger;
			Initialize();
		}

		public void Dispose()
		{
			var activeConnections = connections.Where(lazy => lazy.IsValueCreated).ToList();

			foreach (var connection in activeConnections)
			{
				connection.Value.Dispose();
			}

			Initialize();
		}

		public IConnectionMultiplexer GetConnection()
		{
			Lazy<ConnectionMultiplexer> response;

			var loadedLazys = connections.Where(lazy => lazy.IsValueCreated);

			if (loadedLazys.Count() == connections.Count)
			{
				var minValue = connections.Min(lazy => lazy.Value.GetCounters().TotalOutstanding);
				response = connections.FirstOrDefault(lazy => lazy.Value.GetCounters().TotalOutstanding == minValue);

                if(response == null)
                {
                    logger.LogError("Problem retrieving the connection.")
                }
                
			}
			else
			{
				response = connections.First(lazy => !lazy.IsValueCreated);
			}

			return response.Value;
		}

		private void Initialize()
		{
			connections = new ConcurrentBag<Lazy<ConnectionMultiplexer>>();

			for (int i = 0; i < POOL_SIZE; i++)
			{
				connections.Add(new Lazy<ConnectionMultiplexer>(() => ConnectionMultiplexer.Connect(redisConfiguration.ConfigurationOptions)));
			}
		}

	}
}

of course log also info like GetCounters and so on.
Thx

[jeroenpot]

Thnx for the suggestion. Somewhere next week i hope to have some more time for dig into it. But i do need to find a way to reproduce the error on our staging environment, i'll see i can do that with our load-test of the application. If that is the case i can try you suggestion. Will let you know.

[imperugo]

Thanks, appreciated

[oleg-varlamov]

Hi! I have the same problem in our system.

System.InvalidOperationException: Sequence contains no matching element
   at System.Linq.Enumerable.First[TSource](IEnumerable`1 source, Func`2 predicate)
   at StackExchange.Redis.Extensions.Core.Implementations.RedisCacheConnectionPoolManager.GetConnection()
   at StackExchange.Redis.Extensions.Core.Abstractions.RedisCacheClient.GetDb(Int32 dbNumber, String keyPrefix)
   at StackExchange.Redis.Extensions.Core.Implementations.RedisDefaultCacheClient.GetAsync[T](String key, CommandFlags flag)

Reproduced locally in Debug and Release mode.

[jeroenpot]

Have you tried to use the code @imperugo provided above to shed some light on the cause? I haven't been able to reproduce.

[imperugo]

Rarely I got the same error, but didn't find a way to reproduce.
@oleg-varlamov if you can, please provider us more information will be very helpful in order to fix the bug.

For example where it happens exactly? into this:

if (loadedLazys.Count() == connections.Count)

or into the else statement?

Thanks

[oleg-varlamov]

Slightly rewrote the code:

public IConnectionMultiplexer GetConnection() {
	Lazy<ConnectionMultiplexer> response;
	var loadedLazys = connections.Where(lazy => lazy.IsValueCreated);
	var loadedLazysCount = loadedLazys.Count();
	if (loadedLazysCount == connections.Count) {
		var minValue = connections.Min(lazy => lazy.Value.GetCounters().TotalOutstanding);
		response = connections.FirstOrDefault(lazy => lazy.Value.GetCounters().TotalOutstanding == minValue);
		var actualConnectionsCount = connections.Count;
		if (response == null) {
			logger.LogError("Problem retrieving the connection in IF statement: {loadedLazysCount} {minValue} {actualConnectionsCount}", 
				loadedLazysCount, minValue, actualConnectionsCount);
		}
	} else {
		response = connections.FirstOrDefault(lazy => !lazy.IsValueCreated);
		if (response == null) {
			logger.LogError("Problem retrieving the connection in ELSE statement: {loadedLazysCount}", loadedLazysCount);
		}
	}

	return response.Value;
}

There are several entries in the logs:
15:41:22.992 ERR Problem retrieving the connection in IF statement: 10 1 10

[imperugo]

Intresting.
I've some ideas. Could you tell me exactly how do you reproduce it?

Because just running it on my environment doesn't work, and I want to try different solutions

[oleg-varlamov]

Redis is used in my project with large parallelism (about 200-300 simultaneous requests per second) like that:

public static async Task<T> SafeGetAsync<T>(this IRedisDefaultCacheClient cacheClient, string key) where T : class {
	return await LoggableTryAsync(async () => await cacheClient.GetAsync<T>(key), nameof(SafeGetAsync), () => null);
}
private static async Task<TResult> LoggableTryAsync<TResult>(Func<Task<TResult>> func, string name, Func<TResult> invalid) {
	try {
		return await func();
	}
	catch (RedisTimeoutException e) {
		Serilog.Log.Warning(e, $"{name}:");
	}
	catch (Exception e) {
		Serilog.Log.Warning(e, $"{name}:");
	}
	return invalid();
}

and somewhere in the code:

var state = await redis.SafeGetAsync<CashboxState>(cashboxId);

There is nothing more special.
Write, if you need more detailed logs or you may need to conduct some kind of experiment.

[oleg-varlamov]

Wouldn't this search for a connection be more correct:

public IConnectionMultiplexer GetConnection() {
	Lazy<ConnectionMultiplexer> response;
	var loadedLazys = connections.Where(lazy => lazy.IsValueCreated);
	if (loadedLazys.Count() == connections.Count) {
		response = connections.OrderBy(x=>x.Value.GetCounters().TotalOutstanding).First();
	}
	else {
		response = connections.First(lazy => !lazy.IsValueCreated);
	}
	return response.Value;
}

[oleg-varlamov]

Or even:

public IConnectionMultiplexer GetConnection() {
	Lazy<ConnectionMultiplexer> response;
	if (_allConnectionsInitialized || connections.Count(lazy => lazy.IsValueCreated) == connections.Count) {
		// for some performance improvements
		_allConnectionsInitialized = true;
		response = FetchConnectionWithMinimumOutstanding();
	}
	else {
		response = connections.FirstOrDefault(lazy => !lazy.IsValueCreated);
		if(response == null) {
			// for case when all connections was initialized after enter to ELSE
			response = FetchConnectionWithMinimumOutstanding();
		}
	}
	return response.Value;
}

private Lazy<ConnectionMultiplexer> FetchConnectionWithMinimumOutstanding() {
	return connections.OrderBy(x => x.Value.GetCounters().TotalOutstanding).First();
}

But I'm a little worried about LINQ ordering. I do not know how productive it is in conditions of great parallelism.

[imperugo]

Ok,
I'm able to reproduce the problem (running 1000 parallel tasks on my laptop I got the error).
The solution suggested by @oleg-varlamov works here

public IConnectionMultiplexer GetConnection()
        {
	        Lazy<ConnectionMultiplexer> response;
	        var loadedLazys = connections.Where(lazy => lazy.IsValueCreated);
	        if (loadedLazys.Count() == connections.Count) {
		        response = connections.OrderBy(x=>x.Value.GetCounters().TotalOutstanding).First();
	        }
	        else {
		        response = connections.First(lazy => !lazy.IsValueCreated);
	        }
	        return response.Value;
        }

I'm going to release a new version in few minutes. Let me know it it works also for you (seems fine here)

[imperugo]

5.0.3 is on nuget (wait few minutes for the cache)

[oleg-varlamov]

My problem has been fixed after upgrading to version 5.0.3.

Thank you!

[imperugo]

Seems to work also for me.
Going to close this issue.

Thanks to all