EFCache.CachingReader.GetValues suddenly firing NotImplementedException

[dornstein]

I've been happily using EFCache for years in our web app. Recently we've started to see intermittent failures where a NotImplementedException is getting throw by CachingReader.GetValues. I took a look at the code and it looks like CachingReader always throws this exception so clearly it's reaching this code path now when it didn't used to. Why would it suddenly start hitting this?

I'm stumped about how to diagnose what might be going on. Any ideas?

Here's a stack track for when the exception gets thrown.

System.Data.Entity.Core.EntityCommandExecutionException:
   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Core.Objects.Internal.ObjectQueryExecutionPlan.Execute (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Core.Objects.ObjectContext.ExecuteInTransaction (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Core.Objects.ObjectQuery`1+<>c__DisplayClass7.<GetResults>b__5 (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.SqlServer.DefaultSqlExecutionStrategy.Execute (EntityFramework.SqlServer, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Core.Objects.ObjectQuery`1.GetResults (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Core.Objects.ObjectQuery`1.<System.Collections.Generic.IEnumerable<T>.GetEnumerator>b__0 (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Internal.LazyEnumerator`1.MoveNext (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Linq.Buffer`1..ctor (System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Linq.Enumerable.ToArray (System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at Liquid.BackgroundService.Actions.RunCompactorAction.RunCompactorAction+<InvokeAsync>d__1.MoveNext (Liquid.BackgroundService, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null)
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification (mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at Microsoft.Liquid.CatalogLoaderApp.BackgroundService+<InvokeAction>d__12`1.MoveNext (Microsoft.Liquid.BackgroundService, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null)
Inner exception System.NotImplementedException handled at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands:
   at EFCache.CachingReader.GetValues (EFCache, Version=1.2.1.0, Culture=neutral, PublicKeyToken=46c4868af4307d2c)
   at EFCache.CachingCommand.ExecuteDbDataReader (EFCache, Version=1.2.1.0, Culture=neutral, PublicKeyToken=46c4868af4307d2c)
   at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.Reader (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)
   at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands (EntityFramework, Version=6.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089)

[moozzyk]

Can you show code that is triggering this?

[dornstein]

Well... because it's a release build I can't narrow down the line, but in RunCompactorAction.RunCompactorAction+there are a couple of calls to ToArray() to materialize the results of an IQueryable. For example:

someDbSet.Where(e => e.State != ComplianceRunState.Loading).ToArray()

[moozzyk]

This seems unlikely unless there is something specific about this DbSet - I have a test that has similar logic and it does not fail like this. To be honest without a repro it will be hard for me to move forward with this - I don't know/remember what kind of queries EF decides to use GetValues() in vs. getting specific column.

[dornstein]

OK, I'll dig in further I guess. Thanks.

[moozzyk]

I looked a bit and found that GetValues in scenarios related to streaming/non-streaming. I think I also saw that entities with spatial data may cause using GetValues. Any of these ring a bell?

I will keep this issue open - it's a real issue and maybe someone sees something similar and can provide a repro.

[dornstein]

Doesn't ring a bell (though I'm not sure specifically what you mean by streaming). Not doing anything with spatial data.

[MarcoBroenink]

I ran into this issue. In my case it was caused by the fact that EFCache was initialized twice (once with a DbConfiguration and once with EntityFrameworkCache.Initialize(Cache);).

[moozzyk]

Thanks for the insight @MarcoBroenink! Registering the cache more than once can lead to weird issues indeed.