search

Particular / ServiceControl

Backend for ServiceInsight and ServicePulse
https://docs.particular.net/servicecontrol/
Other
51 stars 46 forks source link

Strange Behavior in v4.9.0 #2031

Closed TraGicCode closed 4 years ago

TraGicCode commented 4 years ago

Hey Guys,

It looks like there is something strange that got introduced in v4.9.0. When you try and start an instance a few seconds after you stopped it it will fail to start. Below is the servicecontrol log that contains nothing but info.

2020-05-31 23:56:52.5306|1|Info|ServiceBus.Management.Infrastructure.Settings.Settings|No settings found for error log queue to import, default name will be used
2020-05-31 23:56:53.2037|1|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Loading Embedded RavenDB license
2020-05-31 23:56:54.8076|1|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Index creation started
2020-05-31 23:56:58.6181|1|Info|NServiceBus.LicenseManager|Selected active license from C:\ProgramData\ParticularSoftware\license.xml
License Expiration: 202X-0X-X
2020-05-31 23:56:59.2912|4|Info|ServiceBus.Management.Infrastructure.Settings.Settings|No settings found for error log queue to import, default name will be used
2020-05-31 23:56:59.6301|4|Info|Particular.ServiceControl.Bootstrapper|
-------------------------------------------------------------
ServiceControl Version:             4.9.0+0.Branch.release-4.9.Sha.05662e568bdb5b7f9170dbdd7653480d921596c7
Audit Retention Period (optional):  
Error Retention Period:             15.00:00:00
Ingest Error Messages:              True
Forwarding Error Messages:          False
Database Size:                      1056768 bytes
ServiceControl Logging Level:       Info
RavenDB Logging Level:              Warn
Selected Transport Customization:   ServiceControl.Transports.RabbitMQ.RabbitMQConventionalRoutingTransportCustomization, ServiceControl.Transports.RabbitMQ
-------------------------------------------------------------
2020-05-31 23:56:59.9351|4|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Loading Embedded RavenDB license
2020-05-31 23:57:01.8971|4|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Index creation started
2020-05-31 23:57:03.0683|4|Info|NServiceBus.LicenseManager|Selected active license from C:\ProgramData\ParticularSoftware\license.xml
License Expiration: 202X-XX-XX
2020-05-31 23:57:03.3761|23|Info|ServiceControl.Recoverability.RetryDocumentManager|Found 0 orphaned retry batches from previous sessions.
2020-05-31 23:57:03.4051|12|Info|ServiceControl.Recoverability.RetryProcessor|No batch found to forward.
2020-05-31 23:57:03.4771|23|Info|ServiceControl.Recoverability.RetryProcessor|No batch found to stage.
2020-05-31 23:57:03.7811|13|Info|Particular.ServiceControl.Bootstrapper|Api is now accepting requests on http://localhost:33333/api
2020-05-31 23:57:13.6272|4|Info|NServiceBus.RunningEndpointInstance|Initiating shutdown.
2020-05-31 23:57:13.6672|4|Info|NServiceBus.Raw.RunningRawEndpointInstance|Stopping receiver.
2020-05-31 23:57:13.6712|4|Info|NServiceBus.Raw.RunningRawEndpointInstance|Receiver stopped.
2020-05-31 23:57:13.6712|4|Info|NServiceBus.Raw.StoppableRawEndpoint|Initiating shutdown.
2020-05-31 23:57:13.6712|4|Info|NServiceBus.Raw.StoppableRawEndpoint|Shutdown complete.
2020-05-31 23:57:13.8302|4|Info|NServiceBus.RunningEndpointInstance|Shutdown complete.
2020-05-31 23:57:13.8502|1|Info|ServiceBus.Management.Infrastructure.Settings.Settings|No settings found for error log queue to import, default name will be used
2020-05-31 23:57:13.8502|1|Info|Particular.ServiceControl.Bootstrapper|
-------------------------------------------------------------
ServiceControl Version:             4.9.0+0.Branch.release-4.9.Sha.05662e568bdb5b7f9170dbdd7653480d921596c7
Audit Retention Period (optional):  
Error Retention Period:             15.00:00:00
Ingest Error Messages:              True
Forwarding Error Messages:          False
Database Size:                      1056768 bytes
ServiceControl Logging Level:       Info
RavenDB Logging Level:              Warn
Selected Transport Customization:   ServiceControl.Transports.RabbitMQ.RabbitMQConventionalRoutingTransportCustomization, ServiceControl.Transports.RabbitMQ
-------------------------------------------------------------
2020-05-31 23:57:13.8772|1|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Loading Embedded RavenDB license
2020-05-31 23:57:14.2732|1|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Index creation started
2020-05-31 23:57:14.4033|1|Info|NServiceBus.LicenseManager|Selected active license from C:\ProgramData\ParticularSoftware\license.xml
License Expiration: 202X-XX-XX
2020-05-31 23:57:14.4362|41|Info|ServiceControl.Recoverability.RetryProcessor|No batch found to forward.
2020-05-31 23:57:14.4362|13|Info|ServiceControl.Recoverability.RetryDocumentManager|Found 0 orphaned retry batches from previous sessions.
2020-05-31 23:57:14.4362|13|Info|ServiceControl.Recoverability.RetryProcessor|No batch found to stage.
2020-05-31 23:57:14.4702|28|Info|Particular.ServiceControl.Bootstrapper|Api is now accepting requests on http://localhost:33333/api
2020-05-31 23:57:15.8782|4|Info|ServiceBus.Management.Infrastructure.Settings.Settings|No settings found for error log queue to import, default name will be used
2020-05-31 23:57:16.2472|4|Info|Particular.ServiceControl.Bootstrapper|
-------------------------------------------------------------
ServiceControl Version:             4.9.0+0.Branch.release-4.9.Sha.05662e568bdb5b7f9170dbdd7653480d921596c7
Audit Retention Period (optional):  
Error Retention Period:             15.00:00:00
Ingest Error Messages:              True
Forwarding Error Messages:          False
Database Size:                      1056768 bytes
ServiceControl Logging Level:       Info
RavenDB Logging Level:              Warn
Selected Transport Customization:   ServiceControl.Transports.RabbitMQ.RabbitMQConventionalRoutingTransportCustomization, ServiceControl.Transports.RabbitMQ
-------------------------------------------------------------
2020-05-31 23:57:16.6162|4|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Loading Embedded RavenDB license
2020-05-31 23:57:27.1062|1|Info|ServiceBus.Management.Infrastructure.Settings.Settings|No settings found for error log queue to import, default name will be used
2020-05-31 23:57:27.1102|1|Info|Particular.ServiceControl.Bootstrapper|
-------------------------------------------------------------
ServiceControl Version:             4.9.0+0.Branch.release-4.9.Sha.05662e568bdb5b7f9170dbdd7653480d921596c7
Audit Retention Period (optional):  
Error Retention Period:             15.00:00:00
Ingest Error Messages:              True
Forwarding Error Messages:          False
Database Size:                      1056768 bytes
ServiceControl Logging Level:       Info
RavenDB Logging Level:              Warn
Selected Transport Customization:   ServiceControl.Transports.RabbitMQ.RabbitMQConventionalRoutingTransportCustomization, ServiceControl.Transports.RabbitMQ
-------------------------------------------------------------
2020-05-31 23:57:27.1342|1|Info|ServiceControl.Infrastructure.RavenDB.RavenBootstrapper|Loading Embedded RavenDB license

Looking at the ravendb logs i see the following errors which seem to be related to the issue.

2020-05-31 23:56:55.5406|12|Warn|Raven.Client.Connection.Async.AsyncServerClient|Was unable to fetch topology from primary node http://localhost also there is no cached topology
2020-05-31 23:57:02.3561|13|Warn|Raven.Client.Connection.Async.AsyncServerClient|Was unable to fetch topology from primary node http://localhost also there is no cached topology
2020-05-31 23:57:27.0812|4|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentFileAccessDeniedException: Cannot access file, the file is locked or in use
   at Microsoft.Isam.Esent.Interop.Api.JetInit(JET_INSTANCE& instance)
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-05-31 23:57:27.0812|4|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not write to location: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\. Make sure you have read/write permissions for this path. ---> Microsoft.Isam.Esent.Interop.EsentFileAccessDeniedException: Cannot access file, the file is locked or in use
   at Microsoft.Isam.Esent.Interop.Api.JetInit(JET_INSTANCE& instance)
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-05-31 23:57:37.1582|1|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentFileAccessDeniedException: Cannot access file, the file is locked or in use
   at Microsoft.Isam.Esent.Interop.Api.JetInit(JET_INSTANCE& instance)
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-05-31 23:57:37.1582|1|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not write to location: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\. Make sure you have read/write permissions for this path. ---> Microsoft.Isam.Esent.Interop.EsentFileAccessDeniedException: Cannot access file, the file is locked or in use
   at Microsoft.Isam.Esent.Interop.Api.JetInit(JET_INSTANCE& instance)
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)

It would be awesome if someone can also verify this behavior.

TraGicCode commented 4 years ago

As a side note, our automation scripts seem to have have corrupted the database which is definitely not ideal. Could this be related to the bugs introduced by #2000 ?

2020-06-01 00:18:03.9566|4|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:18:04.0326|4|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:18:04.0416|4|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:18:04.2136|1|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:18:04.2326|1|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:18:04.2326|1|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:19:05.2080|4|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:19:05.2670|4|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:19:05.2790|4|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:19:05.4340|1|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:19:05.4520|1|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:19:05.4520|1|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:21:20.1130|4|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:21:20.1710|4|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:21:20.1819|4|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:21:20.3229|1|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:21:20.3410|1|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:21:20.3459|1|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:23:41.6377|4|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:23:41.6957|4|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:23:41.7067|4|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:23:41.8417|1|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:23:41.8587|1|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:23:41.8587|1|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:26:09.9836|4|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase(JET_SESID sesid, String database, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
2020-06-01 00:26:10.0456|4|Error|Raven.Database.Server.RavenDBOptions|Found errors in the system database while loading it for the first time.
                                    This is recoverable error, since we will simply ingore transactions after the faulted one.
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
2020-06-01 00:26:10.0577|4|Error|Raven.Database.DocumentDatabase|Could not initialize transactional storage, not creating database
System.InvalidOperationException: Could not open transactional storage: C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data ---> Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
   at Microsoft.Isam.Esent.Interop.Api.JetAttachDatabase2(JET_SESID sesid, String database, Int32 maxPages, AttachDatabaseGrbit grbit)
   at Raven.Storage.Esent.TransactionalStorage.EnsureDatabaseIsCreatedAndAttachToDatabase()
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   --- End of inner exception stack trace ---
   at Raven.Storage.Esent.TransactionalStorage.Initialize(IUuidGenerator uuidGenerator, OrderedPartCollection`1 documentCodecs, Action`1 putResourceMarker, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase.DocumentDatabaseInitializer.InitializeTransactionalStorage(IUuidGenerator uuidGenerator, Action`2 onErrorAction)
   at Raven.Database.DocumentDatabase..ctor(InMemoryRavenConfiguration configuration, DocumentDatabase systemDatabase, TransportState recievedTransportState, Action`2 onError)
2020-06-01 00:26:10.1906|1|Warn|Raven.Storage.Esent.TransactionalStorage|Could not recover database C:\ProgramData\Particular\ServiceControl\Particular.ServiceControl\DB\Data, will try opening it one last time. If that doesn't work, try using esentutl
Microsoft.Isam.Esent.Interop.EsentDatabaseDirtyShutdownException: Database was not shutdown cleanly. Recovery must first be run to properly complete database operations for the previous shutdown.
ramonsmits commented 4 years ago

@TraGicCode The files should not be locked if the SC processes exits so I'm wondering which process is then locking the file.

Have you excluded the database folder from virus scanning?

TraGicCode commented 4 years ago

@TraGicCode The files should not be locked if the SC processes exits so I'm wondering which process is then locking the file.

Have you excluded the database folder from virus scanning?

Hey Ramon,

When I downgraded to 4.8.0 the problem went away. Then, upgrading back to 4.9.0 I was able to reproduce the issue. I’m wondering if when u stop the servicecontrol instance on 4.9.0 of its actually stopping the process right away. I can check this in a bit

TraGicCode commented 4 years ago

Hey @ramonsmits ,

that looks to be the issue. When you stop the servicecontrol instance in 4.9.0 the windows service stops, the status shows stopped in the service control management ui, but the process hangs around for a bit.

image

Was this intentional or a bug? With this behavior it will be a PITA to actually attempt to orchestrate starting and stopping servicecontrol with any sort of automation.

TraGicCode commented 4 years ago

I skimmed through the changeset and didn't see anything explicitly related to servicecontrol stopping. I think this is related to the messed up logging that is causing the service to behave differently with the windows service control manager :/

https://github.com/Particular/ServiceControl/compare/4.8.0...4.9.0

ramonsmits commented 4 years ago

@TraGicCode Just be to clear, you also have this issue with 4.10.0 right? So, since 4.9.0?

ramonsmits commented 4 years ago

I tested this locally and I see an almost 30 second delay.

https://youtu.be/sPEb5Vx5ldQ

Scanning the code I think the current version is executing the executable as a regular console app and not as a windows service. I'm going go validate this but I think that is what is happening.

ramonsmits commented 4 years ago

Another thing I noticed is that the application is not properly responding to CTRL+C when running from the commandline.

TraGicCode commented 4 years ago

@TraGicCode Just be to clear, you also have this issue with 4.10.0 right? So, since 4.9.0?

Yes. all newer versions

Another thing I noticed is that the application is not properly responding to CTRL+C when running from the commandline.

okay cool so it should get fixed when the regression of #2017 is resolved.

ramonsmits commented 4 years ago

@TraGicCode I validated my assumption and it was correct. It is run as a console instead as a service. While performing cleanup to get it to run I noticed logging issues too. Both are addressed in this PR:

ramonsmits commented 4 years ago

@TraGicCode We reverted the hosting behavior of 4.9.0 in todays release of 4.10.2. Instances should start/stop as expected again.

TraGicCode commented 4 years ago

Issue resolved. Thanks @ramonsmits !