Help needed with RavenDB lock up

[Piers Lawson]

On our test system we have twice in a month experienced a lockup of the RavenDB. Both times, killing the service (as it refused to stop) and restarting it got us running again. Here is some of the background.

 

We are running Build-2333 on Win 2003 Server R2 Service Pack 2.

 

Our event log contains lots of these warnings (when the system appears to be running OK):

 

Event Type: Warning
Event Source: ESENT
Event Category: System Parameter Settings
Event ID: 808
Date:  19/06/2013
Time:  11:18:30
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (672) 131-1jccx5-C:\Databases\PSP1307.Directory.Cache\Data: System parameter preferred version pages (209664) is greater than max version pages (32768). Preferred version pages was changed from 209664 to 32768.

I presume these are harmless?

When the crash happens we get the following two errors in the event log, repeated every 30 seconds:

Event Type: Error
Event Source: ESENT
Event Category: General
Event ID: 490
Date:  19/06/2013
Time:  11:17:25
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (672) 1-2CiuA8-C:\Databases\System\Data: An attempt to open the file "C:\Databases\System\system\RVN.chk" for read / write access failed with system error 3 (0x00000003): "The system cannot find the path specified. ".  The open file operation will fail with error -1023 (0xfffffc01).

Event Type: Error
Event Source: ESENT
Event Category: Logging/Recovery
Event ID: 439
Date:  19/06/2013
Time:  11:17:25
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (672) 1-2CiuA8-C:\Databases\System\Data: Unable to write a shadowed header for file C:\Databases\System\system\RVN.chk. Error -1023.

As I tried to stop the service using NET stop RavenDB the following error was reported and the service refused to stop:

Event Type: Error
Event Source: RavenService
Event Category: None
Event ID: 0
Date:  19/06/2013
Time:  11:21:15
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Failed to stop service. System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> System.AggregateException: One or more errors occurred. ---> Microsoft.Isam.Esent.Interop.EsentInvalidPathException: Invalid file path
   at Microsoft.Isam.Esent.Interop.Api.Check(Int32 err) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 2739
   at Microsoft.Isam.Esent.Interop.Api.JetTerm2(JET_INSTANCE instance, TermGrbit grbit) in C:\Work\ravendb\SharedLibs\Sources\managedesent-61618\EsentInterop\Api.cs:line 206
   at Raven.Storage.Esent.TransactionalStorage.<Dispose>b__0() in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Storage\Esent\TransactionalStorage.cs:line 123
   at Raven.Database.Impl.ExceptionAggregator.Execute(Action action) in c:\Builds\RavenDB-Unstable-v2.0\Raven.Database\Impl\ExceptionAggregator.cs:line 23
   --- End of inner exception stack trace ---
   at Raven.Databas...

Using Task Manager I killed the service then restarted it using Services. As Raven came back up it reported some of the warnings mentioned at the top of this post, and also these information events:

Event Type: Information
Event Source: ESENT
Event Category: General
Event ID: 100
Date:  19/06/2013
Time:  11:23:17
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven.Server (364) The database engine 5.02.3790.3959 started.

Event Type: Information
Event Source: ESENT
Event Category: General
Event ID: 101
Date:  19/06/2013
Time:  11:23:17
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven.Server (364) The database engine stopped.

Event Type: Information
Event Source: ESENT
Event Category: General
Event ID: 100
Date:  19/06/2013
Time:  11:23:17
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven.Server (364) The database engine 5.02.3790.3959 started.

Event Type: Information
Event Source: ESENT
Event Category: General
Event ID: 102
Date:  19/06/2013
Time:  11:23:17
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (364) 1-2D8unQ-C:\Databases\System\Data: The database engine started a new instance (0).

Event Type: Information
Event Source: ESENT
Event Category: Logging/Recovery
Event ID: 300
Date:  19/06/2013
Time:  11:23:18
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (364) 1-2D8unQ-C:\Databases\System\Data: The database engine is initiating recovery steps.

Event Type: Information
Event Source: ESENT
Event Category: Logging/Recovery
Event ID: 301
Date:  19/06/2013
Time:  11:23:20
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (364) 1-2D8unQ-C:\Databases\System\Data: The database engine has begun replaying logfile C:\Databases\System\logs\RVN.log.

Event Type: Information
Event Source: ESENT
Event Category: Logging/Recovery
Event ID: 302
Date:  19/06/2013
Time:  11:23:20
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Raven (364) 1-2D8unQ-C:\Databases\System\Data: The database engine has successfully completed recovery steps.

Event Type: Information
Event Source: RavenService
Event Category: None
Event ID: 0
Date:  19/06/2013
Time:  11:23:23
User:  N/A
Computer: TEST-RAVEN-DB
Description:
Service started successfully.

The database then seemed to be running fine (though still recording the warnings).

Any thoughts would be welcomed!

[Oren Eini (Ayende Rahien)]

Did you modify the configuration in any way?

It looks like something killed some of the files we needed while running.

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

[Piers Lawson]

The Raven.Server.exe.config file (copied below) has not been modified for over 2 months:

 

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <appSettings>
    <add key="Raven/Port" value="*"/>
    <add key="Raven/DataDir" value="C:\Databases\System"/>
    <add key="Raven/AnonymousAccess" value="None"/>
  </appSettings>
 <runtime>
  <loadFromRemoteSources enabled="true"/>
  <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
   <probing privatePath="Analyzers;Plugins"/>
  </assemblyBinding>
 </runtime>
</configuration>

 

The second time the issue happened was a few minutes (perhaps 20 minutes) after a developer had used Raven Studio to create a new database and delete some old databases. The system had appeared to be working fine after he had finished his work, then locked up.

[Oren Eini (Ayende Rahien)]

Anything else that might be interfering? AV / FireWall, and the like?

[Piers Lawson]

I was just going through that sort of list. There is no antivirus or firewall on the machine. It is virtualised which made me wonder if there was an I/O speed issue. There were no errors in the Event Log regarding IO errors. Also, once the error occurred, it kept repeating every 30 seconds, which seems to indicate it wasn't an intermittent error... unless one thread in RavenDB had its access to the file interrupted, which then locked out all other threads from accessing the file until RavenDB was terminated and restarted. As mentioned, after starting RavenDB up again, all was well (with no other change on the machine).

 

Should I be worried about the ESENT warnings we see in the event log regarding "System parameter preferred version pages"?

[Oren Eini (Ayende Rahien)]

The prerferred version pages is strange, that is why I asked about your config, but you didn't change it there.

Is it possible you change it for a particular db?

[Piers Lawson]

I don't know how it is changed. Looking online, the only mention of it is regarding Exchange Server set up and it appears to be an Active Directory setting. As far as I know, we would never have changed it. We get the same ESENT warnings on other servers and they don't appear to have experienced the lock up issue.

--
You received this message because you are subscribed to a topic in the Google Groups "ravendb" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/ravendb/nj6sizXvfos/unsubscribe.
To unsubscribe from this group and all its topics, send an email to ravendb+u...@googlegroups.com.

[Oren Eini (Ayende Rahien)]

Yeah, that doesn't really explains it.

do you have the logs?

[Piers Lawson]

Which logs? I have Event Logs, copies of which I put into my first post in this thread. Any other logs you'd like to see I'd be happy to supply.

[Oren Eini (Ayende Rahien)]

The RDBMS debug logs

[Oren Eini (Ayende Rahien)]

Ravendb logs

On Thursday, June 20, 2013, Piers Lawson wrote:

[Piers Lawson]

Where do I find them and what can I use to view them? Sorry for the dumb questions!

--

[Piers Lawson]

If you mean the log tab in Raven Studio, it is empty. When the service is restarted, are the logs cleared?

[Oren Eini (Ayende Rahien)]

I meant the debug logs, you can configure them here:

http://ravendb.net/docs/2.0/server/deployment/docs-debug-logging

You received this message because you are subscribed to the Google Groups "ravendb" group.

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

[Piers Lawson]

Is there a way to have a live ravendb start logging without restarting it? Just dropping NLog.config in the base directory appears to have no effect until I restart, which would mean the issue would be missed (or we'll have to leave logging on permanently in test).

 

Secondly, under what circumstances would RavenDb be trying to write to RVN.chk? I'd like to try forcing the error by moving the file myself, but I don't kno how to get RavenDb to try and use the file.

 

Thanks, for your help... we want to go live in about two weeks with the new features supported by RavenDB, so people are understandably nervous that we haven't found a root cause!

[Kijana Woodard]

Side note: Are you really running 2333 or 2330? 2333 isn't a stable version. 

Any chance on testing latest stable as well?

http://hibernatingrhinos.com/builds/ravendb-stable

--

[Piers Lawson]

Yes, I'm using 2333 as there was a show stopping issue with 2330. There was an authentication bug that Ayende fixed immediately in 2332... however that build introduced a problem that meant RavenStudio didn't work. 2333 fixed both issues:

 

https://groups.google.com/d/msg/ravendb/ygxptrviwXI/CddDfDYpioUJ

 

We would have moved to a newer stable build had it come out in the next few days / week, but it looks like there wasn't another stable release until 7 May. I'd rather not move versions right now since we have been through a lot of test cycles. If the error was easy to reproduce I would give it a go on my machine, but I can't reproduce it at will... hence my questions about RVN.chk.

 

Thanks for your help.