Random error when using a dynamic query: Could not load file or assembly raven.metrics

Jens Pettersson

unread,

Mar 14, 2017, 10:01:40 AM3/14/17

to RavenDB - 2nd generation document database

Hello!

First, I know of this thread: https://groups.google.com/forum/#!topic/ravendb/xz3sZzDMgEk but it kind of died and nothing there worked for me so instead of resurrecting an old one, I'm creating a new.

Just recently, Raven has begun to throw the following exception after an application (web api) as been running a couple of hours. To fix it, we have to recycle the Application Pool. We've never seen this before and we do have around 20 different applications that's been running Raven for years.

14:12:18.3398 | Debug | Executing query '' on index 'dynamic/PeriodStates' in 'http://SERVERNAME(DB: DATABASENAME);DATABASENAME' | QueryOperation

14:12:18.3711 | Error | System.TypeInitializationException: The type initializer for 'Raven.Abstractions.Extensions.JsonExtensions' threw an exception. ---> System.IO.FileNotFoundException: Could not load file or assembly 'raven.metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=37f41c7f99471593' or one of its dependencies. The system cannot find the file specified.
   at Raven.Abstractions.Extensions.JsonExtensions..cctor()
   --- End of inner exception stack trace ---
   at Raven.Abstractions.Extensions.JsonExtensions.JsonDeserialization[T](RavenJToken self)
   at Raven.Client.Connection.SerializationHelper.ToQueryResult(RavenJObject json, Etag etag, String tempRequestTime, Int64 numberOfCharactersRead) in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\SerializationHelper.cs:line 136
   at Raven.Client.Connection.Async.AsyncServerClient.<QueryAsyncAsGet>d__1dc.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\Async\AsyncServerClient.cs:line 1373
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.ReplicationInformerBase`1.<TryOperationAsync>d__29`1.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\ReplicationInformerBase.cs:line 439
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)
   at Raven.Client.Connection.ReplicationInformerBase`1.<ExecuteWithReplicationAsync>d__19`1.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\ReplicationInformerBase.cs:line 334
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Connection.Async.AsyncServerClient.<ExecuteWithReplication>d__2ce`1.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Connection\Async\AsyncServerClient.cs:line 0
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Document.AbstractDocumentQuery`2.<ExecuteActualQueryAsync>d__29.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 1872
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Document.AbstractDocumentQuery`2.<InitAsync>d__a.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 796
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Raven.Client.Document.AbstractDocumentQuery`2.<ToListAsync>d__48.MoveNext() in c:\Builds\RavenDB-Stable-3.0\Raven.Client.Lightweight\Document\AbstractDocumentQuery.cs:line 2309
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at <NAMESPACE>.GetPeriodsHandler.<HandleRequest>d__2.MoveNext() in C:\Jenkins-Jobs\...\GetPeriodsHandler.cs:line 21

This is a super simple query, directly against the document (no streaming, no paging, we know that there will be at a maximum 10 docs in that collection so we just query them all from this API Controller). Just a:

session.Query<PeriodState>().ToListAsync();

(hence the debug log: Executing query '' on index 'dynamic/PeriodStates')

It works great, for a couple of hours, but then just out of the blue the exception above happens EVERY time. When this occurs, we can issue other queries, so the database is up and running and most of the things is working. The only difference is that these are queries against an index instead of directly against a document state (i.e. the 'dynamic/PeriodStates').

This application is running the RavenDB.Client version 3.0.30165 and we don't have any mixed versions of RavenDB in this solution. (The server is however running #30155 still, but we've tried to downgrade the client to the same version but it still happened after a couple of hours). The application has been redeployed several times, and we always purge when deploying, so there shouldn't be any old files that might cause trouble.

We can't reproduce this in a reliable manner, it just happens randomly on our environments which is kind of frustrating. This is also one of our least complicated applications using Raven. Nothing out of the ordinary, which is even more frustrating.

Any ideas?

//J

Jens Pettersson

unread,

Mar 15, 2017, 2:48:54 AM3/15/17

to RavenDB - 2nd generation document database

Some more info: Yesterday I change the query that randomly started to throw to use a regular index instead and it worked after deployment, but this morning it started to throw the same error again...

Jens Pettersson

unread,

Mar 15, 2017, 3:03:55 AM3/15/17

to RavenDB - 2nd generation document database

Sorry guys, I found what it MUST be... As I said, we always purge the directory we deploy to BUT our build server didn't clean properly so it kept a lot of old dlls in its workspace and those got packed up into our deployables...

Still curious how some of the queries continued to work when one (as we know of) was starting to fail after some time.

//J

Oren Eini (Ayende Rahien)

unread,

Mar 15, 2017, 3:36:34 AM3/15/17

to ravendb

Okay, strange, but good to know you found it

Hibernating Rhinos Ltd

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

--
You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Jens Pettersson

unread,

Mar 15, 2017, 4:31:58 AM3/15/17

to RavenDB - 2nd generation document database

Sorry to say that this DIDN'T solve it... After about 1,5 hours, the error happens once again and ONLY for one query... I'm still sure there's a conflicting version somewhere, but I'm not sure how to debug it... Trying dotPeek now to see if I can find anything, but not really sure what I'm looking for...

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+u...@googlegroups.com.

Jens Pettersson

unread,

Mar 15, 2017, 11:43:14 AM3/15/17

to RavenDB - 2nd generation document database

After almost a full day of debugging I finally found a possible reason for this, and also, a somewhat reliable way of reproducing this... Bear with me, this will be a long one!

TL;DR; It seems to be that an application pool that has "Enable 32-bit applications: TRUE" will cause this error to happen after a couple of application pool restarts.

First of all, we're still using RavenDB 3.0 as we can't upgrade to 3.5 just yet. This example uses the latest stable 3.0 release (RavenDB.Client 3.0.30171). It seems that this bug is not apparent in the latest 3.5.3 release.

In my github repo on https://github.com/jenspettersson/RavenPerfs/tree/master/Bugs/Raven.Metrics.Bug there is a default .NET 4.6 WebAPI project. The only nuget reference apart from whatever WebAPI throws at you by default is RavenDB.Client 3.0.30171.

To reproduce you have to do the following:

Have a RavenDB instance up and running on http://localhost:8080 (otherwise, change the initializer in Global.asax.cs)
In your IIS, create an ApplicationPool (v4.0, integrated, etc... standard stuff). In my script it's called "RAVENBUGS"
Open Advanced Settings for this application pool and set Enable 32-bit applications to True.
Create a virtual directory for the WebAPI project from my github repo and set the Application Pool to the one created in step 2.
Create a powershell script on your computer, use this as a template: https://github.com/jenspettersson/RavenPerfs/blob/master/Bugs/Raven.Metrics.Bug/readme.md - Change the uri to whatever your IIS gave you and use the appPool name you created.
Run the script and wait...

The script will restart the application pool and then invoke a controller that issues a query with ToListAsync() to Raven (it doesn't matter if there's any actual documents present, an empty db is enough. In my example, Raven is running as a Windows Service on port 8080).

If all goes well, it will just repeat the loop until it fails. Sometimes it takes a couple of seconds, sometimes up to about 1 minute.

My extremely limited powershell skills prevented me from catching the actual exception here, so in order to see what the exception is, use postman or a browser (without restarting the app pool) and hit the same uri:

This will be thrown every request until you recycle the application pool again...

I didn't really know that our Application Pools were set to "Enable 32-bit applications" but when I looked at what our version of Octopus Deploy (2.5.something) defaults in the process step "Create IIS Application Pool" it, sure enough, has ticked the box "Enable 32-bit applications"...

So the solution for us seems to simply be to disable the 32-bit application thingie on the app pool, but I'm reporting this here as there might be others with this unfortunate combo where the stars aligns in the exact wrong positions just as an application pool, where 32-bit applications are enable, gets recycled...

Hope this will give some insight...

//Jens

Jens Pettersson

unread,

Mar 16, 2017, 2:49:22 AM3/16/17

to RavenDB - 2nd generation document database

After some additional research, I've found that this behavior was introduced in version 3.0.30153. Alos, it's only affecting the AsyncDocumentSession, in my scenario when using a query with .ToListAsync(). The DocumentSession with a regular ToList() works across all versions.

3.0.30115: Works! (this is the version we've been using for quite some time, hence we've never seen this before)
3.0.30143: Works!
3.0.30152: Works!
3.0.30153: "Could not load file or assembly 'metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=ca6c6ef570198eba' or one of its dependencies. The system cannot find the file specified."
3.0.30154: "Could not load file or assembly 'metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=ca6c6ef570198eba' or one of its dependencies. The system cannot find the file specified."
3.0.30155: "Could not load file or assembly 'metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=ca6c6ef570198eba' or one of its dependencies. The system cannot find the file specified."
3.0.30165: "Could not load file or assembly 'raven.metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=37f41c7f99471593' or one of its dependencies. The system cannot find the file specified."
3.0.30171: "Could not load file or assembly 'raven.metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=37f41c7f99471593' or one of its dependencies. The system cannot find the file specified.",

//J

Oren Eini (Ayende Rahien)

unread,

Mar 16, 2017, 8:18:31 AM3/16/17

to ravendb

Thanks for the research, we'll look at this further, but if the workaround is just running on 64 bits, that is the general recommended way to run anyway

Hibernating Rhinos Ltd

Oren Eini l CEO l Mobile: + 972-52-548-6969

Office: +972-4-622-7811 l Fax: +972-153-4-622-7811

--

You received this message because you are subscribed to the Google Groups "RavenDB - 2nd generation document database" group.

To unsubscribe from this group and stop receiving emails from it, send an email to ravendb+unsubscribe@googlegroups.com.

Jens Pettersson

unread,

Mar 21, 2017, 6:50:40 AM3/21/17

to RavenDB - 2nd generation document database

Any issue# that I can track? We actually have a system that requires the 32-bit-setting and I don't want to update to latest 3.0 by mistake if this isn't resolved.

Paweł Pekról

unread,

Mar 22, 2017, 6:02:47 AM3/22/17

to RavenDB - 2nd generation document database

Hi Jens,

I've tried to reproduce the issue using your steps without any luck.

I've triple-checked if everything is set as it should be (appropriate appPools with 32-bit set to true and assigned to the web app), but after 30min 'restart script' run the application was still working fine.

The tests were done on two Windows 10 machines (on SSD and HDD) and one Windows Server 2008 R2 (HDD). Each run as I wrote took 30min.

On what OS you were performing the tests? All Windows updates installed? Any unusual software installed there? Antivirus? Firewall?

P.

Jens Pettersson

unread,

Mar 22, 2017, 7:03:32 AM3/22/17

to RavenDB - 2nd generation document database

Hello Paweł.

My development machine, here at my client, where I reproduced this is still a Windows 7 Enterprise (64-bit), Internet Information Services (Version 7.5.7600.16385).

The two environments where this was deployed and where the exception was first spotted is Windows Server 2012 R2 Standard, Internet Information Services (Version 8.5.9600.16384).

No unusual software installed...

What RavenDB version are you testing? Note that this exception only occurs on 3.0 between builds 30153 and latest 30171...

I can try this on my other development computer at home with a Win 10 installation. Not sure when I will manage to do it though.

//J

Paweł Pekról

unread,

Mar 22, 2017, 7:35:53 AM3/22/17

to RavenDB - 2nd generation document database

Thanks for reply.

I will also check the W7, maybe it is somehow platform specific issue.

I've been using your application with 3.0.30171 version so it should throw.

P.

Jens Pettersson

unread,

Mar 23, 2017, 10:54:21 AM3/23/17

to RavenDB - 2nd generation document database

Hello again.

I just reproduced this at a different computer, this time running Windows 10 Enterprise with IIS 10.0.14393.0.

Note! I had to uninstall a couple of .NET Core VS2015 Toolings to be able to even run the Application Pool with Enable 32-bit applications set to TRUE.

So my track record is as follows:

Windows 7/IIS7 at my client: Fails

2 different Windows Server 2012 R2/IIS8: Fails

My personal Windows 10/IIS10: Fails

//J

Oren Eini (Ayende Rahien)

unread,

Mar 23, 2017, 10:55:49 AM3/23/17

to ravendb

Can you try this with fusion logs?

--

Message has been deleted

Jens Pettersson

unread,

Mar 23, 2017, 11:27:00 AM3/23/17

to RavenDB - 2nd generation document database

Sorry, last message had the log truncated. It said "Not sure this is what you want, but this is what I found using Fusion Log":

*** Assembly Binder Log Entry (3/23/2017 @ 4:19:24 PM) ***

The operation failed.

Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll

Running under executable C:\WINDOWS\SysWoW64\inetsrv\w3wp.exe

--- A detailed error log follows.

=== Pre-bind state information ===

LOG: DisplayName = raven.metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=37f41c7f99471593

(Fully-specified)

LOG: Appbase = file:///C:/dev/_Lab/RavenPerfs/Bugs/Raven.Metrics.Bug/Raven.Metrics.Bug/

LOG: Initial PrivatePath = C:\dev\_Lab\RavenPerfs\Bugs\Raven.Metrics.Bug\Raven.Metrics.Bug\bin

LOG: Dynamic Base = C:\Windows\Microsoft.NET\Framework\v4.0.30319\Temporary ASP.NET Files\raven.metrics.bug\b1ab1bb9

LOG: Cache Base = C:\Windows\Microsoft.NET\Framework\v4.0.30319\Temporary ASP.NET Files\raven.metrics.bug\b1ab1bb9

LOG: AppName = 93f94222

Calling assembly : Raven.Abstractions, Version=3.0.0.0, Culture=neutral, PublicKeyToken=37f41c7f99471593.

===

LOG: This bind starts in default load context.

LOG: Using application configuration file: C:\dev\_Lab\RavenPerfs\Bugs\Raven.Metrics.Bug\Raven.Metrics.Bug\web.config

LOG: Using host configuration file: C:\Windows\Microsoft.NET\Framework\v4.0.30319\aspnet.config

LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework\v4.0.30319\config\machine.config.

LOG: Post-policy reference: raven.metrics, Version=1.0.0.0, Culture=neutral, PublicKeyToken=37f41c7f99471593

LOG: GAC Lookup was unsuccessful.

LOG: Attempting download of new URL file:///C:/Windows/Microsoft.NET/Framework/v4.0.30319/Temporary ASP.NET Files/raven.metrics.bug/b1ab1bb9/93f94222/raven.metrics.DLL.

LOG: Attempting download of new URL file:///C:/Windows/Microsoft.NET/Framework/v4.0.30319/Temporary ASP.NET Files/raven.metrics.bug/b1ab1bb9/93f94222/raven.metrics/raven.metrics.DLL.

LOG: Attempting download of new URL file:///C:/dev/_Lab/RavenPerfs/Bugs/Raven.Metrics.Bug/Raven.Metrics.Bug/bin/raven.metrics.DLL.

LOG: Attempting download of new URL file:///C:/dev/_Lab/RavenPerfs/Bugs/Raven.Metrics.Bug/Raven.Metrics.Bug/bin/raven.metrics/raven.metrics.DLL.

LOG: Attempting download of new URL file:///C:/Windows/Microsoft.NET/Framework/v4.0.30319/Temporary ASP.NET Files/raven.metrics.bug/b1ab1bb9/93f94222/raven.metrics.EXE.

LOG: Attempting download of new URL file:///C:/Windows/Microsoft.NET/Framework/v4.0.30319/Temporary ASP.NET Files/raven.metrics.bug/b1ab1bb9/93f94222/raven.metrics/raven.metrics.EXE.

LOG: Attempting download of new URL file:///C:/dev/_Lab/RavenPerfs/Bugs/Raven.Metrics.Bug/Raven.Metrics.Bug/bin/raven.metrics.EXE.

LOG: Attempting download of new URL file:///C:/dev/_Lab/RavenPerfs/Bugs/Raven.Metrics.Bug/Raven.Metrics.Bug/bin/raven.metrics/raven.metrics.EXE.

LOG: All probing URLs attempted and failed.