Newtonsoft.Json.JsonReaderException thrown using GetContinuousChangesAsync

[ulja-dd]

Hi,

I'm using CouchCB.NET 3.1.0 via nuget.org

The exception occurs sometimes when there is high workload. In cases where the exception is thrown the changes feed response line has two concatenated change documents.
I guess the reason is that FlurlClient is mixing data of different requests.

Following is a more detailed explanation:

I'm using a BackgroundService to process changes from particular databases using the following code (Some logging and exception handling is droped here to shorten the code):

protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
	var scope = _services.CreateScope();

	var documentsContext = scope.ServiceProvider.GetRequiredService<Data.Documents.Context>();

	var options = new ChangesFeedOptions
	{
		Heartbeat = 1000,
		Since = "now",
		IncludeDocs = true,
	};

	await foreach (var change in documentsContext.Documents.GetContinuousChangesAsync(options, null, stoppingToken))
	{
		if (change == null)
			continue;

		if (change.Id.StartsWith('_'))
			continue;

		var innerScope = _services.CreateScope();

		var innerDocumentsContext = innerScope.ServiceProvider.GetRequiredService<Data.Documents.Context>();
		var reportContext = innerScope.ServiceProvider.GetRequiredService<Data.Context>();

		if (change.Deleted)
		{
			await HandleDelete(change, reportContext);
		}
		else
		{
			await HandleUpsert(change, reportContext, innerDocumentsContext);
		}

		await ((IAsyncDisposable)innerScope).DisposeAsync();

	}

	await ((IAsyncDisposable)scope).DisposeAsync();
}

I'm using different scopes for the context because I assumed the issue is related to this issue. In fact, the frequence of the exceptions was reduced by using dedicated scopes and creating a context for each change. However, the same exception is thrown less frequent.

With little workload (1 change per second) the BackgroundService works fine. But with high workload (~1000 changes per second) somtimes a Newtonsoft.Json.JsonReaderException is thrown by the GetContinuousChangesAsync method. Heres an example stacktrace:

[2021-08-27 14:59:14] fail: LogipadDocumentReportServer.Services.DocumentChangesService[0]
      Unexpected exit of DocumentChangesService. Reason Newtonsoft.Json.JsonReaderException: Additional text encountered after finished reading JSON content: {. Path '', line 1, position 910.
         at Newtonsoft.Json.JsonTextReader.Read()
         at Newtonsoft.Json.Serialization.JsonSerializerInternalReader.Deserialize(JsonReader reader, Type objectType, Boolean checkAdditionalContent)
         at Newtonsoft.Json.JsonSerializer.DeserializeInternal(JsonReader reader, Type objectType)
         at Newtonsoft.Json.JsonConvert.DeserializeObject(String value, Type type, JsonSerializerSettings settings)
         at Newtonsoft.Json.JsonConvert.DeserializeObject[T](String value, JsonSerializerSettings settings)
         at CouchDB.Driver.CouchDatabase`1.GetContinuousChangesAsync(ChangesFeedOptions options, ChangesFeedFilter filter, CancellationToken cancellationToken)+MoveNext() in /home/devopsmaster/buildlinux01-agent01/_work/121/s/src/CouchDB.Driver/CouchDatabase.cs:line 415
         at CouchDB.Driver.CouchDatabase`1.GetContinuousChangesAsync(ChangesFeedOptions options, ChangesFeedFilter filter, CancellationToken cancellationToken)+MoveNext() in /home/devopsmaster/buildlinux01-agent01/_work/121/s/src/CouchDB.Driver/CouchDatabase.cs:line 408
         at CouchDB.Driver.CouchDatabase`1.GetContinuousChangesAsync(ChangesFeedOptions options, ChangesFeedFilter filter, CancellationToken cancellationToken)+MoveNext() in /home/devopsmaster/buildlinux01-agent01/_work/121/s/src/CouchDB.Driver/CouchDatabase.cs:line 408
         at CouchDB.Driver.CouchDatabase`1.GetContinuousChangesAsync(ChangesFeedOptions options, ChangesFeedFilter filter, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
         at LogipadDocumentReportServer.Services.DocumentChangesService.ExecuteAsync(CancellationToken stoppingToken) in /home/devopsmaster/buildlinux01-agent01/_work/121/s/src/LogipadDocumentReportServer/Services/DocumentChangesService.cs:line 46
         at LogipadDocumentReportServer.Services.DocumentChangesService.ExecuteAsync(CancellationToken stoppingToken) in /home/devopsmaster/buildlinux01-agent01/_work/121/s/src/LogipadDocumentReportServer/Services/DocumentChangesService.cs:line 46

The change document causing the exception as well as the position of the additional text differs from test to test. (Sometimes even no exception is thrown at all). Of cause the changes feed is the exact same for every test.

I did some more debuging by adding a custom output in method CouchDB.Driver.CouchDatabase.GetContinuousChangesAsync :

        public async IAsyncEnumerable<ChangesFeedResponseResult<TSource>> GetContinuousChangesAsync(ChangesFeedOptions? options, ChangesFeedFilter? filter,
            [EnumeratorCancellation] CancellationToken cancellationToken)
        {
            var infiniteTimeout = TimeSpan.FromMilliseconds(Timeout.Infinite);
            IFlurlRequest request = NewRequest()
                .WithTimeout(infiniteTimeout)
                .AppendPathSegment("_changes")
                .SetQueryParam("feed", "continuous");

            if (options != null)
            {
                request = request.ApplyQueryParametersOptions(options);
            }

            await using Stream stream = filter == null
                ? await request.GetStreamAsync(cancellationToken, HttpCompletionOption.ResponseHeadersRead)
                    .ConfigureAwait(false)
                : await request.QueryContinuousWithFilterAsync<TSource>(_queryProvider, filter, cancellationToken)
                    .ConfigureAwait(false);

            await foreach (var line in stream.ReadLinesAsync(cancellationToken))
            {
                if (string.IsNullOrEmpty(line))
                {
                    continue;
                }
                Console.WriteLine($"--\n{line}\n--");
                ChangesFeedResponseResult<TSource> result = JsonConvert.DeserializeObject<ChangesFeedResponseResult<TSource>>(line);
                yield return result;
            }
        }

A normal line looks like:

{"seq":"1257-g1AAAACReJzLYWBgYMpgTmHgzcvPy09JdcjLz8gvLskBCScyJNX___8_K4M5CcjzzQWKsZsmJacaGVmiq8dhQh4LkGRoAFL_EQbNgRiUmGpubGqKri0LABCdK3Q","id":"62a856af-29fc-420d-ada2-ac44df1703bc","changes":[{"rev":"7-21a5f4f6a30431f543f34e92ee2f6c81"}],"doc":{"_id":"62a856af-29fc-420d-ada2-ac44df1703bc","_rev":"7-21a5f4f6a30431f543f34e92ee2f6c81","displayName":"1465_document_2021-08-13T14:42:45.7676475Z","folderId":"33fcd8f2-9891-4727-890b-c60069b1e15c","typeId":"4bd83ef2-92da-43f5-988d-963d6a9c76bd","priority":0,"isConfirmable":true,"isExportable":true,"isIndexable":true,"openExternal":true,"versionIds":["ddab772a-10b8-4561-8f81-085db2789b33"],"roleIds":["6c5f588a-1000-4e02-ab78-cfb7b9693adb","7310e618-dbd5-41a7-8fb0-c2ba1211ac81","fbd6658b-c100-4767-bffc-4c87e8a99838","434cebd9-c3d7-4cf5-9554-f66197e23d52","29e0e863-7b5f-4a8a-80dd-5019edb97594"],"createdAt":"2021-08-13T14:42:46.0680065Z","createdBy":"_root"}}

A line causing the exception has json of two changes. It looks like:

{"seq":"1261-g1AAAACReJzLYWBgYMpgTmHgzcvPy09JdcjLz8gvLskBCScyJNX___8_K4M5CcgLyAWKsZsmJacaGVmiq8dhQh4LkGRoAFL_EQbNhRiUmGpubGqKri0LABHwK3g","id":"646a4368-f3f4-4f22-a1c2-9914e8eb2d41","changes":[{"rev":"7-4e7827c00b95b17aae6e9ed3c294964c"}],"doc":{"_id":"646a4368-f3f4-4f22-a1c2-9914e8eb2d41","_rev":"7-4e7827c00b95b17aae6e9ed3c294964c","displayName":"1303_document_2021-08-13T14:41:47.7472154Z","folderId":"aa80bac2-3fd1-4bf3-8644-f5ea5ad8d158","typeId":"71b273e8-e8a5-4397-b006-4f8ce97dcb9f","priority":0,"isConfirmable":true,"isExportable":true,"isIndexable":true,"openExternal":true,"versionIds":["a4cbd232-e083-4fce-aefe-ccb61e1b1a0f"],"roleIds":["63a1d717-6a3c-4d99-a893-8ac551c6c0cb","f260bc05-7db0-4256-9373-b67c37480ceb","59a34798-d72b-4595-b871-0430985a560d","a01cc30e-d679-410e-8a9e-3af558be9276","723f7db8-8ad2-4895-8fec-3f8ed5e6ae31"],"createdAt":"2021-08-13T14:41:48.1187505Z","createdBy":"_root"}}{"seq":"1262-g1AAAACReJzLYWBgYMpgTmHgzcvPy09JdcjLz8gvLskBCScyJNX___8_K4M5CcgLzAWKsZsmJacaGVmiq8dhQh4LkGRoAFL_EQbNhRiUmGpubGqKri0LABJXK3k","id":"64c0d2b4-decc-46e4-9045-e3f653be6c5a","changes":[{"rev":"7-2d66ebc57aa8d5da47a95bf4d1e8bb91"}],"doc":{"_id":"64c0d2b4-decc-46e4-9045-e3f653be6c5a","_rev":"7-2d66ebc57aa8d5da47a95bf4d1e8bb91","displayName":"1196_document_2021-08-13T14:41:10.0064201Z","folderId":"14043628-6097-4c9c-b305-7fa8cf2b9e8b","typeId":"55a1221a-993d-4a1b-a1f6-54b6dcdec83c","priority":0,"isConfirmable":true,"isExportable":true,"isIndexable":true,"openExternal":true,"versionIds":["5d3d3d38-73b5-475f-9be1-acbb087cc201"],"roleIds":["96ae4689-274d-49b1-af3f-072f30e26ae1","59a34798-d72b-4595-b871-0430985a560d","ad84173e-3915-4c7a-a5c4-b3cffb9f3155","1404626f-0dd7-4cd6-9b01-4c0064ea58f3","29e0e863-7b5f-4a8a-80dd-5019edb97594"],"createdAt":"2021-08-13T14:41:10.3588087Z","createdBy":"_root"}}

[matteobortolazzo]

Hi, I think it's not related to #133 as that is about the string builder for queries not being thread-safe.

This one is about what CouchDB returns. And I thought I handled that, but I'll give a look

[matteobortolazzo]

@ulja-dd I added some code to check for multiple "lines" in 1 line, I suppose it will be slower but it should not break. Can you test the dev branch and let me know please?

[ulja-dd]

Thank you for having a look at this issue! And sorry for my late reply.

I've done two tests:

1. Only replacing the couchdb-net projects by the code from dev branch
2. Removing the "inner" scope and instanciating the CouchDB contexts outside of the GetContinuousChangesAsync foreach loop. This way the context used reading the changes feed is also used to handle the change.

In both cases the exception hasn't been thrown anymore. About 400k changes were processed so far.

At the moment I can't say much about a potential performance drag caused by the fix, since I didn't do any dedicated benchmarking before and after. At the moment changes are handled in about 10ms. Where stop creating a new context for every change was a hugh performance improvment (obviously).

So I think the issue is fixed in dev branch. Thank you :)

[matteobortolazzo]

@ulja-dd I am glad to hear that! I'll work on more bugs then I'll release everything