nservicebusnservicebus-sagas

Exception in RavenDB.SagaPersister.Save, "Guid should contain 32 digits with 4 dashes". Guid is empty in Raven


NServiceBus 5.1, RavenDB persistence, AutoFac container, log4net, all latest versions in NuGet at time of posting.

EndpointConfig:

            log4net.Config.XmlConfigurator.Configure();
        LogManager.Use<Log4NetFactory>();

        // Raven DataStore for Freight system
        var freightDataStore = new DocumentStore { 
            ConnectionStringName = "RavenDB",
            DefaultDatabase = "ProTeria.Freight"
        };
        freightDataStore.Initialize();
        freightDataStore.Conventions.IdentityPartsSeparator = "-";
        Raven.Client.Indexes.IndexCreation.CreateIndexes(typeof(ProTeria.NET.RavenDB.BringInvoiceIndexes.BringInvoiceIndexBringIdAndStatus).Assembly, freightDataStore);

        // Raven DataStore for NServiceBus
        var nsbDataStore = new DocumentStore
        {
            ConnectionStringName = "NServiceBus.Persistence",
            DefaultDatabase = "Freight.BookingProcessing"
        };
        nsbDataStore.Initialize();

        // Set up and build AutoFac container
        var builder = new ContainerBuilder();
        builder.RegisterInstance<DocumentStore>(freightDataStore).As<IDocumentStore>().SingleInstance();
        builder.Register(c => 
        {
            var reportsService = new ReportsService();
            return reportsService;
        })
            .As<IReportsService>()
            .SingleInstance();
        builder.Register(c =>
        {
            var getCalcShippingTask = new GetCalculatedShippingReportTask(c.Resolve<IReportsService>(), c.Resolve<IBus>(), c.Resolve<IDocumentStore>());
            return getCalcShippingTask;
        });
        var container = builder.Build();

        // Set up NServiceBus
        configuration.UseContainer<AutofacBuilder>(customizations => customizations.ExistingLifetimeScope(container));
        configuration.Conventions()
            .DefiningCommandsAs(t => t.Namespace != null && t.Namespace.EndsWith("Commands"))
            .DefiningEventsAs(t => t.Namespace != null && t.Namespace.EndsWith("Events"))
            .DefiningMessagesAs(t => t.Namespace != null && t.Namespace.EndsWith("Messages"));
        configuration.UsePersistence<RavenDBPersistence>().SetDefaultDocumentStore(nsbDataStore);
    }
  1. An NServiceBus Schedule with Bus.Send()
  2. ACommand starts Saga 2a. ACommand is handled, inside handler a call to RequestTimeout(InvoiceCreationTimeout)
  3. ACommand handler seems to return fine.
  4. At some point after my code in ACommand handler I get a FormatException in the logs.

I checked the database and there are no sagas stored, only TimeoutDatas, f.ex:

  "Destination": {
    "Queue": "Freight.BookingProcessing",
    "Machine": "TRYGVEXISHAN"
  },
  "SagaId": "00000000-0000-0000-0000-000000000000",
  "State": "PD94bWwgdmVyc2lvbj0iMS4wIiA/Pg0KPFNjaGVkdWxlZFRhc2sgeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVtYS1pbnN0YW5jZSIgeG1sbnM6eHNkPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVtYSIgeG1sbnM9Imh0dHA6Ly90ZW1wdXJpLm5ldC9OU2VydmljZUJ1cy5TY2hlZHVsaW5nLk1lc3NhZ2VzIj4KPFRhc2tJZD5kMjk0ZjJlNC0wNDNhLTQ2ZDctYWRlYy0zNGQ5YTRiMzA4N2E8L1Rhc2tJZD4KPE5hbWU+SW52b2ljZVJlcG9ydE9yZGVyU2NoZWR1bGVyPC9OYW1lPgo8RXZlcnk+UFQxSDwvRXZlcnk+CjwvU2NoZWR1bGVkVGFzaz4K",
  "Time": "2014-11-06T20:00:54.7501480Z",
  "OwningTimeoutManager": "Freight.BookingProcessing",
  "Headers": {
    "NServiceBus.MessageId": "04c57504-ef24-4c35-9808-a3db0149d727",
    "NServiceBus.CorrelationId": "04c57504-ef24-4c35-9808-a3db0149d727",
    "NServiceBus.MessageIntent": "Send",
    "NServiceBus.Version": "5.1.0",
    "NServiceBus.TimeSent": "2014-11-06 19:00:54:737148 Z",
    "NServiceBus.ContentType": "text/xml",
    "NServiceBus.EnclosedMessageTypes": "NServiceBus.Scheduling.Messages.ScheduledTask, NServiceBus.Core, Version=5.0.0.0, Culture=neutral, PublicKeyToken=9fc386479f8a226c",
    "CorrId": "04c57504-ef24-4c35-9808-a3db0149d727\\0",
    "NServiceBus.ConversationId": "fb886123-ef8b-49f0-a841-a3db0149d728",
    "WinIdName": "TrygveXishan\\Trygve",
    "NServiceBus.OriginatingMachine": "TRYGVEXISHAN",
    "NServiceBus.OriginatingEndpoint": "Freight.BookingProcessing",
    "$.diagnostics.originating.hostid": "5b9e6ee62b8ad8151326abdad567014e",
    "NServiceBus.IsDeferredMessage": "True",
    "NServiceBus.Timeout.RouteExpiredTimeoutTo": "Freight.BookingProcessing@TRYGVEXISHAN",
    "NServiceBus.Timeout.Expire": "2014-11-06 20:00:54:750148 Z"
  }

EDIT Log output (now with SagaId logged in handler of ACommand (actual name is OrderInvoiceCommand):

    2014-11-07 10:53:49,601 [22] DEBUG Freight.BookingProcessing.InvoiceReporting.InvoiceReportSaga [(null)] <(null)> - Handling OrderInvoiceCommand which starts saga. Saga data: Saga Id: cdd0b4ed-d310-41fa-a8dd-a3dc00b3942f
BringInvoiceId: 702542157
OriginalMessageId: 52a7b74d-5e7c-4e7b-bc03-a3dc00b2cd72
2014-11-07 10:53:49,844 [22] DEBUG Freight.BookingProcessing.InvoiceReporting.InvoiceReportSaga [(null)] <(null)> - Invoice with id 702542157 not found in DB, as Bring to generate and request a timeout for checking generation status
<removed some BehaviorChain entries>
2014-11-07 10:53:50,530 [22] DEBUG NServiceBus.BehaviorChain`1 [(null)] <(null)> - LogOutgoingMessageBehavior
2014-11-07 10:53:50,532 [22] DEBUG LogOutgoingMessage [(null)] <(null)> - Sending message 'Freight.BookingProcessing.InvoiceReporting.InvoiceCreationTimeout, Freight.BookingProcessing, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null' with id '226603e6-8b1e-4dec-ae94-a3dc00b39545' to destination 'Freight.BookingProcessing@TRYGVEXISHAN'.
ToString() of the message yields: Freight.BookingProcessing.InvoiceReporting.InvoiceCreationTimeout
Message headers:
NServiceBus.SagaId:cdd0b4ed-d310-41fa-a8dd-a3dc00b3942f, NServiceBus.IsSagaTimeoutMessage:True, NServiceBus.SagaType:Freight.BookingProcessing.InvoiceReporting.InvoiceReportSaga, Freight.BookingProcessing, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null, NServiceBus.OriginatingSagaId:cdd0b4ed-d310-41fa-a8dd-a3dc00b3942f, NServiceBus.OriginatingSagaType:Freight.BookingProcessing.InvoiceReporting.InvoiceReportSaga, Freight.BookingProcessing, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
2014-11-07 10:53:50,535 [22] DEBUG NServiceBus.BehaviorChain`1 [(null)] <(null)> - DispatchMessageToTransportBehavior
2014-11-07 10:53:50,550 [22] DEBUG NServiceBus.BehaviorChain`1 [(null)] <(null)> - LicenseBehavior
2014-11-07 10:53:51,024 [22] INFO  NServiceBus.Unicast.Transport.TransportReceiver [(null)] <(null)> - Failed to process message
System.FormatException: Guid should contain 32 digits with 4 dashes (xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx).
   at System.Guid.GuidResult.SetFailure(ParseFailureKind failure, String failureMessageID, Object failureMessageFormatArgument, String failureArgumentName, Exception innerException)
   at System.Guid.TryParseGuidWithNoStyle(String guidString, GuidResult& result)
   at System.Guid.TryParseGuid(String g, GuidStyles flags, GuidResult& result)
   at System.Guid..ctor(String g)
   at Raven.Client.Converters.GuidConverter.ConvertTo(String value)
   at Raven.Client.Document.GenerateEntityIdOnTheClient.SetPropertyOrField(Type propertyOrFieldType, Object entity, Action`1 setIdentifier, String id)
   at Raven.Client.Document.GenerateEntityIdOnTheClient.TrySetIdentity(Object entity, String id)
   at Raven.Client.Document.GenerateEntityIdOnTheClient.GenerateDocumentKeyForStorage(Object entity)
   at Raven.Client.Document.InMemoryDocumentSessionOperations.StoreInternal(Object entity, Etag etag, String id, Boolean forceConcurrencyCheck)
   at Raven.Client.Document.InMemoryDocumentSessionOperations.Store(Object entity)
   at NServiceBus.SagaPersisters.RavenDB.SagaPersister.Save(IContainSagaData saga) in c:\BuildAgent\work\9b594c1b0f1d3bab\src\NServiceBus.RavenDB\SagaPersister\SagaPersister.cs:line 22
   at NServiceBus.SagaPersistenceBehavior.Invoke(IncomingContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Sagas\SagaPersistenceBehavior.cs:line 116

Solution

  • I figured it out. It was the

    freightDataStore.Conventions.IdentityPartsSeparator = "-";
    

    that fooled Raven, since the generated id probably would look something like InvoiceSaga-cdd0b4ed-d310-41fa-a8dd-a3dc00b3942f.

    EDIT This can be solved by registering a custom Raven.Client.Converters.ITypeConverter for Guid with the DocumentStore.Conventions.IdentityProviders. See submitted Raven issue and this SO question for more info

    But WHY NSB uses the freightDataStore and not the nsbDataStore for persisting the saga I don't know yet. I might have misunderstood how to configure NSB with two different IDataStores registered in the container? Any guidance on this?

    EDIT I've created a separate question for this: How to configure NServiceBus with two RavenDB IDocumentStores?