Data Subscription not starting

84 views
Skip to first unread message

Steven Devooght

unread,
Oct 25, 2016, 9:06:28 AM10/25/16
to RavenDB - 2nd generation document database
Hi,

We are having issues getting data subscriptions to work. We have created a data subscription with ETag.Empty, so we excpect it to process all next documents configured in the 'BelongsToAnyCollection'. Unfortunately OnNext is never hit in our observer even though there are 70000+ documents waiting to be processed.

What I have tried:
  • Create a data subscription without a StartEtag
  • Create a data subscription with StartEtag set to Etag.Empty
I tried this both on RavenDB version 3.0.30157-Hotfix & 3.5.0-rc-35173 without success. Our database has 500000+ documents in total.

This is what our data subscription looks like:
{
   
"SubscriptionId": 37,
   
"AckEtag": "00000000-0000-0000-0000-000000000000",
   
"TimeOfLastClientActivity": "2016-10-25T12:59:28.7893865Z",
   
"TimeOfSendingLastBatch": "2016-10-25T12:59:19.0867674Z",
   
"Criteria": {
     
"KeyStartsWith": null,
     
"BelongsToAnyCollection": [
       
"Imports"
     
],
     
"PropertiesMatch": [],
     
"PropertiesNotMatch": [],
     
"StartEtag": null
   
},
   
"IsOpen": true,
   
"ConnectionOptions": {
     
"ConnectionId": "1051/6kNm2wsD0qH/4zJ7WOlakty",
     
"BatchOptions": {
       
"MaxSize": null,
       
"MaxDocCount": 4096,
       
"AcknowledgmentTimeout": "00:01:00"
     
},
     
"TimeToWaitBeforeConnectionRetry": "00:00:15",
     
"ClientAliveNotificationInterval": "00:02:00",
     
"PullingRequestTimeout": "00:05:00",
     
"IgnoreSubscribersErrors": true,
     
"Strategy": "OpenIfFree"
   
}
 
}

Any idea what might be causing this issue?

Idan Haim

unread,
Oct 25, 2016, 10:31:25 AM10/25/16
to RavenDB - 2nd generation document database
Can you show me the code you using and the index ?

Steven Devooght

unread,
Oct 25, 2016, 10:43:12 AM10/25/16
to RavenDB - 2nd generation document database
// Create subscription
Session.Advanced.DocumentStore.Subscriptions.Create(
new SubscriptionCriteria<Import>
{
    PropertiesMatch = new Dictionary<Expression<Func<Import, object>>, RavenJToken>
  {
     {x => x.IsImported, false}
  }
}, Session.Advanced.GetDatabaseName());

// Above used GetDatabaseName extension method
public static string GetDatabaseName(this IAdvancedDocumentSessionOperations session)
{
    return ((DocumentSession)session).DatabaseName;
}

Steven Devooght

unread,
Oct 25, 2016, 10:43:37 AM10/25/16
to RavenDB - 2nd generation document database
We don't use a specific index for our datasubscription?

Oren Eini (Ayende Rahien)

unread,
Oct 25, 2016, 11:47:10 PM10/25/16
to ravendb
This doesn't match the previously mentioned document. 
What do the logs say?

Hibernating Rhinos Ltd  

Oren Eini l CEO 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.

Steven Devooght

unread,
Oct 26, 2016, 3:46:01 AM10/26/16
to RavenDB - 2nd generation document database
This is what the logs says:
2016-10-26 09:39:47.2017;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;Andes;127;Document with key 'Settings/DataSubscriptions/ImportCareProvider' was found, etag: 01000000-0000-0004-0000-00000009037A;
2016-10-26 09:39:47.2017;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,024: GET     -     0 ms - Andes      - 304 - http://localhost:8080/databases/Andes/docs?id=Settings%2FDataSubscriptions%2FImportCareProvider;
2016-10-26 09:39:47.2017;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;76;Request #28,025: POST    -     3 ms - Andes      - 200 - http://localhost:8080/databases/Andes/subscriptions/open?id=1&connection=3/6ffbDh3bSMB/-;
2016-10-26 09:39:47.2173;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,026: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=watch-docs;
2016-10-26 09:39:47.2329;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,027: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=watch-bulk-operation;
2016-10-26 09:39:47.2329;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,028: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/subscriptions/pull?id=1&connection=3/6ffbDh3bSMB/-;
2016-10-26 09:39:52.3525;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,029: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=unwatch-docs;
2016-10-26 09:39:52.3681;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,030: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=unwatch-bulk-operation;
2016-10-26 09:39:58.3985;Raven.Database.Impl.DocumentRetriever;Debug;;127;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore CareProviders/520941/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:39:58.3985;Raven.Database.Impl.DocumentRetriever;Debug;;127;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore UniqueConstraints/CareProviders/RizivNumber/52094146/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:09.0038;Raven.Database.Impl.DTC.InFlightTransactionalState;Info;Andes;170;Performing Transactions Cleanup Sequence for db Andes;
2016-10-26 09:40:09.0038;Raven.Database.Impl.DTC.InFlightTransactionalState;Info;America;74;Performing Transactions Cleanup Sequence for db America;
2016-10-26 09:40:10.2694;Raven.Database.Impl.DTC.InFlightTransactionalState;Info;<system>;59;Performing Transactions Cleanup Sequence for db <system>;
2016-10-26 09:40:15.7322;Raven.Database.Impl.DocumentRetriever;Debug;;127;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore CareProviders/N36440/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:15.7322;Raven.Database.Impl.DocumentRetriever;Debug;;127;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore UniqueConstraints/CareProviders/RizivNumber/93644095/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:17.3103;Raven.Database.Server.Controllers.SubscriptionsController;Warn;;127;Subscription filtered out all possible documents for 30 seconds in a row, stopping operation;
2016-10-26 09:40:17.3103;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,031: POST    -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/subscriptions/close?id=1&connection=3/6ffbDh3bSMB/-;
2016-10-26 09:40:28.6556;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;Andes;149;Document with key 'Settings/DataSubscriptions/ImportCareProvider' was found, etag: 01000000-0000-0004-0000-00000009037A;
2016-10-26 09:40:28.6556;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,032: GET     -     0 ms - Andes      - 304 - http://localhost:8080/databases/Andes/docs?id=Settings%2FDataSubscriptions%2FImportCareProvider;
2016-10-26 09:40:28.6556;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;142;Request #28,033: POST    -     1 ms - Andes      - 200 - http://localhost:8080/databases/Andes/subscriptions/open?id=1&connection=4/5sl7cNstuQq/614Jwqvdu7z;
2016-10-26 09:40:28.6712;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,034: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=watch-docs;
2016-10-26 09:40:28.6869;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,035: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=watch-bulk-operation;
2016-10-26 09:40:28.7025;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,036: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/subscriptions/pull?id=1&connection=4/5sl7cNstuQq/614Jwqvdu7z;
2016-10-26 09:40:28.7181;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,037: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=unwatch-docs;
2016-10-26 09:40:28.7337;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;127;Request #28,038: GET     -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/changes/config?id=1/6OuwhXvZejy/2R2dB6gJ7rA&command=unwatch-bulk-operation;
2016-10-26 09:40:39.0049;Raven.Database.Impl.DTC.InFlightTransactionalState;Info;Andes;147;Performing Transactions Cleanup Sequence for db Andes;
2016-10-26 09:40:39.0049;Raven.Database.Impl.DTC.InFlightTransactionalState;Info;America;142;Performing Transactions Cleanup Sequence for db America;
2016-10-26 09:40:39.5683;Raven.Database.Impl.DocumentRetriever;Debug;;149;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore CareProviders/520941/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:39.5683;Raven.Database.Impl.DocumentRetriever;Debug;;149;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore UniqueConstraints/CareProviders/RizivNumber/52094146/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:40.2714;Raven.Database.Impl.DTC.InFlightTransactionalState;Info;<system>;155;Performing Transactions Cleanup Sequence for db <system>;
2016-10-26 09:40:54.8533;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;;147;Document with key 'Raven/Replication/Destinations' was not found;
2016-10-26 09:40:54.8533;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;;72;Document with key 'Raven/Replication/Destinations' was not found;
2016-10-26 09:40:54.9314;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;;174;Document with key 'Raven/Replication/Destinations' was not found;
2016-10-26 09:40:56.2696;Raven.Database.Impl.DocumentRetriever;Debug;;149;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore CareProviders/N36440/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:56.2696;Raven.Database.Impl.DocumentRetriever;Debug;;149;Trigger Raven.Bundles.Replication.Triggers.HideVirtuallyDeletedDocumentsReadTrigger asked us to ignore UniqueConstraints/CareProviders/RizivNumber/93644095/conflicts/c024e3df-cc14-4b14-9f61-092244fec6fd;
2016-10-26 09:40:56.6603;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;;142;Document with key 'Raven/Replication/Destinations' was found, etag: 01000000-0000-0014-0000-000000000005;
2016-10-26 09:40:56.6603;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;;72;Document with key 'Raven/Replication/Destinations' was found, etag: 01000000-0000-0014-0000-000000000005;
2016-10-26 09:40:56.7071;Raven.Database.Storage.Esent.StorageActions.DocumentStorageActions;Debug;;74;Document with key 'Raven/Replication/Destinations' was found, etag: 01000000-0000-0014-0000-000000000005;
2016-10-26 09:40:58.8366;Raven.Database.Server.Controllers.SubscriptionsController;Warn;;149;Subscription filtered out all possible documents for 30 seconds in a row, stopping operation;
2016-10-26 09:40:58.8366;Raven.Database.Server.WebApi.RequestManager;Debug;Andes;149;Request #28,039: POST    -     0 ms - Andes      - 200 - http://localhost:8080/databases/Andes/subscriptions/close?id=1&connection=4/5sl7cNstuQq/614Jwqvdu7z;

The id of the subscription is 1.

Note that the documents were already inserted in the database prior to starting the subscription.


Steven Devooght

unread,
Oct 26, 2016, 4:21:44 AM10/26/16
to RavenDB - 2nd generation document database
I think the subscription does not start because we close the subscription to soon.

using (var subscription = _importRepository.OpenDataSubscriptionForEntity(subscriptionId, true))
            {
                using (subscription.Subscribe(_processCareProviderImportObserver))
                {
                    // Continue processing until a timeout period (> WaitTimeInSeconds) expires or until the job is interrupted
                    while (!_processCareProviderImportObserver.IsIdle() && !IsInterrupted)
                    {
                        Thread.Sleep(500);
                    }
                }
            }

If we don't get a next document within 5 seconds we close the subscription. I upped the WaitTimeInSeconds to to 15 minutes and after a few minutes my OnNext method was hit.

I think the way we use data subscriptions is not what is was designed for.

Oren Eini (Ayende Rahien)

unread,
Oct 26, 2016, 6:40:47 AM10/26/16
to ravendb
You need to keep the subscription opened for it to get the data, yes.

The idea is that a subscription is pretty much always opened.

what is it that you are trying to do?

Hibernating Rhinos Ltd  

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

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

 


--

Steven Devooght

unread,
Oct 26, 2016, 7:13:06 AM10/26/16
to RavenDB - 2nd generation document database
We have an application with 10 tenants. For each tenant we have 3 jobs that have to do some batch processing. All jobs use data subscriptions internally to fetch new or changed documents. These jobs are hosted in a windows service using Quartz.NET. So in total we have 30 jobs that have to be ran from time to time. Quartz internally uses a queue and won't startup all 30 jobs at the same time, but will schedule this for us, which is what we want performance wise...

Maxim Buryak

unread,
Oct 26, 2016, 7:48:24 AM10/26/16
to rav...@googlegroups.com
Hi,
The 15 minutes delay that you are experiencing is due to the time it takes to get to the first document from the collection(s) you are listening to.
If your collection naming conventions are [collection name]/[number or another string] and you are tracking a single collection, you could use the KeyStartsWith criteria to help the mechanism to skip that initial gap.




Best Regards,

Hibernating Rhinos Ltd  cid:image001.png@01CF95E2.8ED1B7D0

Maxim Buryak l Core Team Developer Mobile:+972-54-217-7751

RavenDB paving the way to "Data Made Simplehttp://ravendb.net/  


Steven Devooght

unread,
Oct 26, 2016, 8:04:03 AM10/26/16
to RavenDB - 2nd generation document database
Hi Maxim,

We can indeed use the KeyStartsWith in our case. I will give that a test.


I have an additional question about the 'IgnoreSubscribersErrors' flag when opening a data subscription. We have that set to true for our data subscription. If we stop and start the data subscription again we receive the errored documents again. I think this is not the expected behavior?

Maxim Buryak

unread,
Oct 26, 2016, 8:57:56 AM10/26/16
to rav...@googlegroups.com
I think that you stop the subscription before it manages to report to server, see test:

 [Fact]
        public void ShouldIncrementFailingTests()
        {
            using (var store = NewRemoteDocumentStore())
            {

                var lastId = string.Empty;
                var docsAmount = 50;
                using (var biPeople = store.BulkInsert())
                {
                    
                    for (int i = 0; i < docsAmount; i++)
                    {
                        lastId = biPeople.Store(new Raven.Tests.Common.Dto.Company()
                        {
                            Name = "Something Inc. #" + i
                        });
                    }
                }

                var lastDoc = store.DatabaseCommands.Get(lastId);


                var id = store.Subscriptions.Create(new SubscriptionCriteria<Company>());

                var subscription = store.Subscriptions.Open<Company>(id, new SubscriptionConnectionOptions()
                {
                    BatchOptions = new SubscriptionBatchOptions()
                    {
                        MaxDocCount = 1
                    },
                    IgnoreSubscribersErrors = true
                });


                var cde = new CountdownEvent(docsAmount);

                subscription.Subscribe(x =>
                {
                    throw new Exception();
                });

                subscription.AfterBatch += processed => cde.Signal(processed);
                cde.Wait(10000);

                var subscriptionStatus = store.Subscriptions.GetSubscriptions(0, 1024).First();

                Assert.Equal(subscriptionStatus.AckEtag, lastDoc.Etag);
            }
        }



Best Regards,

Hibernating Rhinos Ltd  cid:image001.png@01CF95E2.8ED1B7D0

Maxim Buryak l Core Team Developer Mobile:+972-54-217-7751

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

RavenDB paving the way to "Data Made Simplehttp://ravendb.net/  



--

Steven Devooght

unread,
Oct 26, 2016, 9:28:39 AM10/26/16
to RavenDB - 2nd generation document database
If we properly dispose our subscriber & our data subscription this should not be an issue?

Maxim Buryak

unread,
Oct 26, 2016, 1:04:44 PM10/26/16
to rav...@googlegroups.com
It depends if you've finished proccessing all the documents received in the last batch, then yes. Else, all progress of recent batch will be discarded. You can control max batch size through SubscriptionOptions.



Best Regards,

Hibernating Rhinos Ltd  cid:image001.png@01CF95E2.8ED1B7D0

Maxim Buryak l Core Team Developer Mobile:+972-54-217-7751

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

RavenDB paving the way to "Data Made Simplehttp://ravendb.net/  



Reply all
Reply to author
Forward
0 new messages