Redis data returned is not what was expected

ServiceStack.Redis
1

Using this code:

private string GetKeyForId(int idShipmentRequest)
{
  return $"{key}:{idShipmentRequest}";
}

public DTO.AnnouncedShipment GetById(int id)
{
    using (var client = manager.GetClient())
    {
      var announcedShipments = client.As<DTO.AnnouncedShipment>();
      var key = GetKeyForId(id);
      var announcedShipment = announcedShipments.GetValue(key);
      logger.Info($"GetById for id: {id}. Key: {key}. Announced: {announcedShipment.Dump()}");
      return announcedShipment;
    }
}

we sometime see this in our log:

2019-11-05 12:24:46.0095||ShipmentLogger|INFO|GetById for id: 14443493. Key: AnnouncedShipment:14443493. Announced: {
	idShipmentRequest: 14443493,
	idContact: 65178992,
	idCampagne: 1921,
	packingDetails: 
	[
		{
			idPackingType: 3,
			numberOfItems: 2
			....

This is correct, since the so called idSHipmentRequest should be identical to the id we get the value for.
But sometimes we see this - the same request, different result:

2019-11-05 14:11:14.1342||ShipmentLogger|INFO|GetById for id: 14443493. Key: AnnouncedShipment:14443493. Announced: {
	idShipmentRequest: 14460000,
	idContact: 64795584,
	idCampagne: 1088,
	packingDetails: 
	[
		{
			idPackingType: 4,
			numberOfItems: 2
			...

What can cause this? Is this a REDIS issue? Of could it be ServiceStack?

2

Couldn’t tell you, it’s just reporting what’s stored in Redis, have you verified against what’s stored in Redis?

3

Yes, I verified and double checked. In fact, we have been hunting this ‘feature’ for a couple of months and it happens every now and then. We are now actively monitoring REDIS as well to see if the data returned is actually the wrong value, or if the issue lies with the RedisClient.
Either way, it seems to be a buffering thing. Reason I suspect buffering is that the data returned in a consecutive call to this or another pooled client yields the data for the past request. So basically, if we ask data for 1, 2, 3, 4, 5 we sometimes get 2, 3, 4, 5.
Still looking into this, but it’s not something you have seen before?

4

No, I’ve no idea of what the underlying cause could be.

5

We ran into a similar issue and based on our findings we got a successful return from Redis for a given key but the data returned was from a different key. I was curious about Rob’s setup. We are running the Windows version of Redis (for now) on a 3 node cluster. At the time of this event the primary was failing over to one of the backup nodes and all occurrences of this event happened within a 3 minute window of the failover event. If @Rob is on a Linux instance it may help determine where the issue lies?

6

We run both Linux and Windows version.
Windows for DEV and Linux for PROD. Our findings were with the Linux version.
We ‘fixed’ this by requesting the value after we know it’s not the right value. This seems to fix the issue.

7

Thanks for the info Rob! We are implementing a similar strategy. I feel like the fact that we are on different platforms points to an issue in the component.

8

@Rob one more question. Would you mind sharing what version of ServiceStack you are on? Thanks!

9

5.7.0 but we saw the same behaviour with 5.5.0. I suspect this is a REDIS ‘feature’ though

10

We are using SS 5.9.2 and are running the Windows version of Redis (it’s an older version). We are using the redis client and caching user sessions in Redis and noticed what appeared to be an issue with Redis returning the wrong session user data for a given key. Recycling IIS seemed to fix the issue but are wondering if this is the same thing. We didn’t do enough research before cycling so not positive of what fixed it. Redis had been restarted previously but it didn’t fix the issue.

11

FYI if you’re storing your Sessions in Redis, it’s not being stored in memory and the Sessions would still be preserved across IIS Restarts as the Cooking Session Ids would still be referring to the same value in Redis.

If it happens make sure you capture the full HTTP Request / Response of an /auth request so you can match the sessionId against the session Cookie and the session value stored in Redis.

12

Yes, we are storing our sessions (Custom Auth Session) in Redis. FWIW we upgraded from 4.5.14 to 5.9.2 (various reasons for such a long time between upgrades) and thus made a few necessary changes to our AppHost but not many. One change in our services was to change this:

var cache = ServiceStack.HostContext.Resolve<ServiceStack.Caching.ICacheClient>();
var session = cache.SessionAs<Common.Models.CustomUserSession>();

To just
var session = Request.SessionAs<Common.Models.CustomUserSession>();

We’ve never done any checks on matching the sessionId against the session Cookie, etc. Do you have an example anywhere? Also, are there any known issues in migrating from 4.5.14 to 5.x? We are running in ASP.NET/IIS .Net Framework 4.8 and are using sliding session logic. This issue reported here is on the ASP.NET side, not on the services side.

Thanks for your help,
Gerry

13

FYI - I’ve been able to reproduce this behavior in a test environment. My test is as follows:

  1. Sign 2 different users into the website. In my case I used 2 different computers and 2 different browsers (Firefox & Chrome).
  2. Restart Redis
  3. Refresh browser on each computer–you will get sessions of the other user randomly as you refresh. Note that the ss-id on each browser stays the same as before recycling Redis.

Note that if I restart IIS at this point via iisreset then the sessions start working correctly.

14

Please provide a stand-alone repro I can run locally to repro the issue, I’m assuming you’re doing something like caching either the Request or the session in a singleton dependency, IOC or something else.

The format for the session keys https://docs.servicestack.net/sessions#formatting-of-keys-used-in-cache-providers

15

I’ll see if I can do that today. Note that this is new behavior that we didn’t see in the 4.x versions. I also used the redis-cli to dump the session keys for the 2 users (using dump urn:iauthsession:ss-id) and redis reported the correct values while the web was randomly cycling between the 2.

1 Like
16

I created an empty ASP.NET project and then added in the necessary logic to repro this. Here’s the repo:

The key files are MyAppHost.cs, BasePage.cs & the Default.* - I’m using a stand alone windows Redis vs 3.2.100 fwiw and tested this on a Windows 10 machine.

17

I was able to repro this by running Microsoft’s old v3 port of redis-server that I was only able to repro after restarting the redis-server. It’s very strange, I can see from the redis MONITOR command that the redis-server receiving the correct session id but for some reason it’s responding with the previous retrieved value.

I’ve tried & verified this is not an issue with the recommended redis-server on WSL:

Or on a remote server with a macOS redis-server, which both behave as expected, before & after restarts.

So it’s not due to a mix of sessions as the correct session ids are always sent to ServiceStack which queries the correct sessionId/key down to redis-server but in the debug session if I run the exact command twice, it’s returning the dirty value from the previous retrieved session but will subsequently return the correct value after re-running the same redis operation. So AFAICT it’s due to Microsoft’s a bug in memory redis-server impl that doesn’t appear to maintain proper process isolation, my guess is some dirty memory from their COW hack that’s maintaining a dirty buffer somewhere.

My recommendation is to use the recommended WSL redis-server or every time you restart the Windows Server to also restart your Apps that use it.

Some issues in your custom impl:

This is unnecessary, leave the default unless you have a reason not to:

//container.Register<ISessionFactory>(c => new SessionFactory(c.Resolve<ICacheClient>()));

This is unnecessary as since 2015 in v4.0.44 ServiceStack already generates new Session Cookies for new Authentication requests.

public override IHttpResult OnAuthenticated(IServiceBase authService, IAuthSession session, IAuthTokens tokens, Dictionary<string, string> authInfo)
{
    authService.Request.RemoveSession();
    // Override session options
    authService.Request.AddSessionOptions(SessionOptions.Temporary);
    // Create new session cookies
    session.Id = authService.Request.Response.CreateSessionIds(authService.Request);
}

The API to regenerate cookies is the latest version of ServiceStack is IRequest.GenerateNewSessionCookiesAsync() which should really be called before attempting to authenticate (as done by default) not during/after.

18

I’ve managed to resolve this issue by draining the network stream buffers before returning pooled clients. This change along with some other fixes is available from v5.10.2 that’s now available on NuGet.

1 Like
19

That’s awesome you were able to resolve the issue as I was not looking forward to installing WSL on my server, trying a new REDIS server, etc. I was also going to say it was new behavior since 4.5.14 so something had changed.

Thanks also for your comments on my custom implementation. I will remove the register of the session factory–not sure why that is in there but this goes back to 2014. To also clarify I need to remove the 3 lines from my OnAuthenticated code which I will do.

I will test these changes with 5.10.2 today. Thanks again!

20

We’ve been struggling with this for the past year, too, and we had no clue what was going on. Wish I had come here earlier to search the forums. Our sessions were getting crossed and we have sensitive information at play, so we were really struggling for a fix.

Thanks for the hotfix, mythz. We’re going to deploy it. We’ll report back if we see any incidents after the update.

1 Like