Projection progress halts

Hi,
I have this user defined projection in the status Running, see the two pictures below.

I would like to conclude in the backend that this projection is done.
When I use ProjectionsManager GetStatusAsync and parse it for progress, most of the times it
returns > 100 very fast :ok_hand:.

Some times it halts on a high progress number of 99.x. Why is this? The status value is Running.

This test is always on a clean 5.0.8.0 eventstore using .net clientApi 5.0.5.0 and with the same events as input for the projection.

Kind regards,
Walter

[00001,23,13:02:22.113] PROJECTIONS: Starting Projections Core Coordinator. (Node State : Master)
[00001,23,13:02:22.114] PROJECTIONS: Starting Projections Manager. (Node State : Master)
[00001,23,13:02:22.116] PROJECTIONS: Starting Projection Manager Response Reader (reads from $projections-$master)
[00001,25,13:02:22.127] PROJECTIONS: Starting Projection Core Reader (reads from $projections-$"2b238abd13a249f8b1adc94ea0a5f212")
[00001,24,13:02:22.129] PROJECTIONS: Starting Projection Core Reader (reads from $projections-$"1f138e6af2224c3f8749d05d1c78306c")
[00001,26,13:02:22.129] PROJECTIONS: Starting Projection Core Reader (reads from $projections-$"9f4f84f3ef474e10b235ccdc0febe37e")
[00001,23,13:02:22.129] PROJECTIONS: Resetting Worker Writer
[00001,23,13:02:22.131] PROJECTIONS: SubComponent Started: "EventReaderCoreService"
[00001,23,13:02:22.131] PROJECTIONS: SubComponent Started: "EventReaderCoreService"
[00001,23,13:02:22.132] PROJECTIONS: SubComponent Started: "ProjectionCoreService"
[00001,23,13:02:22.132] PROJECTIONS: SubComponent Started: "ProjectionCoreService"
[00001,23,13:02:22.132] PROJECTIONS: SubComponent Started: "EventReaderCoreService"
[00001,23,13:02:22.134] PROJECTIONS: SubComponent Started: "ProjectionCoreService"
[00001,25,13:02:22.140] PROJECTIONS: Resetting Master Writer
[00001,24,13:02:22.141] PROJECTIONS: Resetting Master Writer
[00001,26,13:02:22.142] PROJECTIONS: Resetting Master Writer
[00001,23,13:02:22.156] PROJECTIONS: Finished Starting Projection Manager Response Reader (reads from $projections-$master)
[00001,25,13:02:22.165] PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-$"2b238abd13a249f8b1adc94ea0a5f212")
[00001,24,13:02:22.166] PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-$"1f138e6af2224c3f8749d05d1c78306c")
[00001,26,13:02:22.166] PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-$"9f4f84f3ef474e10b235ccdc0febe37e")
[00001,24,13:02:22.168] PROJECTIONS: Starting read "$projections-$control-6563996c-42fa-42d5-90eb-90e09fa8827c"
[00001,25,13:02:22.168] PROJECTIONS: Starting read "$projections-$control-6563996c-42fa-42d5-90eb-90e09fa8827c"
[00001,26,13:02:22.171] PROJECTIONS: Starting read "$projections-$control-6563996c-42fa-42d5-90eb-90e09fa8827c"
[00001,23,13:02:22.174] PROJECTIONS: Response received: 0@"$response-reader-starting"
[00001,23,13:02:22.206] PROJECTIONS: SubComponent Started: "ProjectionCoreServiceCommandReader"
[00001,23,13:02:22.208] PROJECTIONS: SubComponent Started: "ProjectionCoreServiceCommandReader"
[00001,23,13:02:22.209] PROJECTIONS: SubComponent Started: "ProjectionCoreServiceCommandReader"
[00001,23,13:02:22.212] PROJECTIONS: Response received: 1@"$projection-worker-started"
[00001,23,13:02:22.220] PROJECTIONS: Response received: 2@"$projection-worker-started"
[00001,23,13:02:22.221] PROJECTIONS: Response received: 3@"$projection-worker-started"
[00001,23,13:02:22.228] PROJECTIONS: Reading Existing Projections from "$projections-$all"
[00001,23,13:02:22.235] PROJECTIONS: No projections were found in "$projections-$all", starting from empty stream
[00001,14,13:02:22.243] ========== [0.0.0.0:2112] Sub System '"Projections"' initialized.
[00001,23,13:02:22.272] Adding projection cfd70de4-4bd4-4343-a996-d9c8d325eb0c@"$stream_by_category" to list
[00001,23,13:02:22.284] Adding projection b97bb6db-450f-474a-9909-4a77aaf87df3@"$by_category" to list
[00001,23,13:02:22.298] PROJECTIONS: Scheduling the writing of "$create-and-prepare" to "$projections-$1f138e6a-f222-4c3f-8749-d05d1c78306c". Current status of Writer: Busy: false
[00001,23,13:02:22.324] PROJECTIONS: Scheduling the writing of "$create-and-prepare" to "$projections-$2b238abd-13a2-49f8-b1ad-c94ea0a5f212". Current status of Writer: Busy: false
[00001,23,13:02:22.324] Adding projection 4a5a5553-81f2-4689-b2bb-fdbc13ed49b8@"$streams" to list
[00001,23,13:02:22.327] Adding projection 6b5c9768-5a6a-4ddb-b419-2d5bfda66023@"$by_event_type" to list
[00001,23,13:02:22.327] Adding projection 2ec6ae2f-c57c-4b51-876a-10e43863919e@"$by_correlation_id" to list
[00001,24,13:02:22.342] PROJECTIONS: Command received: 0@"$create-and-prepare"
[00001,25,13:02:22.345] PROJECTIONS: Command received: 0@"$create-and-prepare"
[00001,23,13:02:22.381] SLOW BUS MSG ["manager input bus"]: "GetStatistics" - 52ms. Handler: "ProjectionManager".
[00001,23,13:02:22.381] SLOW QUEUE MSG ["Projections Master"]: "GetStatistics" - 52ms. Q: 6/8.
[00001,23,13:02:22.381] PROJECTIONS: Scheduling the writing of "$create-and-prepare" to "$projections-$9f4f84f3-ef47-4e10-b235-ccdc0febe37e". Current status of Writer: Busy: false
[00001,23,13:02:22.382] PROJECTIONS: Scheduling the writing of "$create-and-prepare" to "$projections-$1f138e6a-f222-4c3f-8749-d05d1c78306c". Current status of Writer: Busy: true
[00001,23,13:02:22.382] PROJECTIONS: Scheduling the writing of "$create-and-prepare" to "$projections-$2b238abd-13a2-49f8-b1ad-c94ea0a5f212". Current status of Writer: Busy: true
[00001,26,13:02:22.383] PROJECTIONS: Command received: 0@"$create-and-prepare"
[00001,23,13:02:22.385] PROJECTIONS: Finished writing events to "$projections-$2b238abd13a249f8b1adc94ea0a5f212": "$create-and-prepare"
[00001,23,13:02:22.386] PROJECTIONS: Finished writing events to "$projections-$1f138e6af2224c3f8749d05d1c78306c": "$create-and-prepare"
[00001,23,13:02:22.387] PROJECTIONS: Finished writing events to "$projections-$9f4f84f3ef474e10b235ccdc0febe37e": "$create-and-prepare"
[00001,23,13:02:22.389] PROJECTIONS: Finished writing events to "$projections-$2b238abd13a249f8b1adc94ea0a5f212": "$create-and-prepare"
[00001,23,13:02:22.389] PROJECTIONS: Finished writing events to "$projections-$1f138e6af2224c3f8749d05d1c78306c": "$create-and-prepare"
[00001,25,13:02:22.426] SLOW BUS MSG ["bus"]: "CreateAndPrepare" - 69ms. Handler: "ProjectionCoreService".
[00001,24,13:02:22.426] SLOW BUS MSG ["bus"]: "CreateAndPrepare" - 69ms. Handler: "ProjectionCoreService".
[00001,25,13:02:22.426] SLOW QUEUE MSG ["Projection Core #1"]: "CreateAndPrepare" - 69ms. Q: 5/10.
[00001,24,13:02:22.427] SLOW QUEUE MSG ["Projection Core #0"]: "CreateAndPrepare" - 70ms. Q: 1/9.
[00001,26,13:02:22.447] PROJECTIONS: Scheduling the writing of "$prepared" to "$projections-$master". Current status of Writer: Busy: true
[00001,25,13:02:22.449] PROJECTIONS: Scheduling the writing of "$prepared" to "$projections-$master". Current status of Writer: Busy: true
[00001,25,13:02:22.449] PROJECTIONS: Command received: 1@"$create-and-prepare"
[00001,24,13:02:22.461] PROJECTIONS: Scheduling the writing of "$prepared" to "$projections-$master". Current status of Writer: Busy: true
[00001,24,13:02:22.465] PROJECTIONS: Command received: 1@"$create-and-prepare"
[00001,25,13:02:22.487] PROJECTIONS: Scheduling the writing of "$prepared" to "$projections-$master". Current status of Writer: Busy: true
[00001,23,13:02:22.507] PROJECTIONS: Response received: 7@"$prepared"
[00001,25,13:02:22.510] PROJECTIONS: Finished writing events to "$projections-$master": "$prepared"
[00001,25,13:02:22.511] PROJECTIONS: Finished writing events to "$projections-$master": "$prepared"
[00001,24,13:02:22.512] PROJECTIONS: Scheduling the writing of "$prepared" to "$projections-$master". Current status of Writer: Busy: true
[00001,24,13:02:22.512] PROJECTIONS: Finished writing events to "$projections-$master": "$prepared"
[00001,24,13:02:22.516] PROJECTIONS: Finished writing events to "$projections-$master": "$prepared"
[00001,26,13:02:22.518] PROJECTIONS: Finished writing events to "$projections-$master": "$prepared"
[00001,23,13:02:22.534] PROJECTIONS: Response received: 8@"$prepared"
[00001,23,13:02:22.544] PROJECTIONS: Response received: 9@"$prepared"
[00001,23,13:02:22.544] PROJECTIONS: Response received: 11@"$prepared"
[00001,23,13:02:22.545] PROJECTIONS: Response received: 13@"$prepared"
[00001,23,13:02:22.550] '"$streams"' projection source has been written
[00001,23,13:02:22.552] PROJECTIONS: Scheduling the writing of "$load-stopped" to "$projections-$9f4f84f3-ef47-4e10-b235-ccdc0febe37e". Current status of Writer: Busy: false
[00001,23,13:02:22.555] '"$stream_by_category"' projection source has been written
[00001,23,13:02:22.556] '"$by_category"' projection source has been written
[00001,23,13:02:22.556] '"$by_correlation_id"' projection source has been written
[00001,23,13:02:22.556] '"$by_event_type"' projection source has been written
[00001,23,13:02:22.556] PROJECTIONS: Scheduling the writing of "$load-stopped" to "$projections-$1f138e6a-f222-4c3f-8749-d05d1c78306c". Current status of Writer: Busy: false
[00001,23,13:02:22.558] PROJECTIONS: Scheduling the writing of "$load-stopped" to "$projections-$2b238abd-13a2-49f8-b1ad-c94ea0a5f212". Current status of Writer: Busy: false
[00001,23,13:02:22.558] PROJECTIONS: Scheduling the writing of "$load-stopped" to "$projections-$2b238abd-13a2-49f8-b1ad-c94ea0a5f212". Current status of Writer: Busy: true
[00001,23,13:02:22.558] PROJECTIONS: Scheduling the writing of "$load-stopped" to "$projections-$1f138e6a-f222-4c3f-8749-d05d1c78306c". Current status of Writer: Busy: true
[00001,24,13:02:22.559] PROJECTIONS: Command received: 2@"$load-stopped"
[00001,26,13:02:22.562] PROJECTIONS: Command received: 1@"$load-stopped"
[00001,25,13:02:22.565] PROJECTIONS: Command received: 2@"$load-stopped"
[00001,23,13:02:22.564] PROJECTIONS: Finished writing events to "$projections-$9f4f84f3ef474e10b235ccdc0febe37e": "$load-stopped"
[00001,23,13:02:22.568] PROJECTIONS: Finished writing events to "$projections-$1f138e6af2224c3f8749d05d1c78306c": "$load-stopped"
[00001,23,13:02:22.569] PROJECTIONS: Finished writing events to "$projections-$2b238abd13a249f8b1adc94ea0a5f212": "$load-stopped"
[00001,23,13:02:22.570] PROJECTIONS: Finished writing events to "$projections-$1f138e6af2224c3f8749d05d1c78306c": "$load-stopped"
[00001,23,13:02:22.571] PROJECTIONS: Finished writing events to "$projections-$2b238abd13a249f8b1adc94ea0a5f212": "$load-stopped"
[00001,26,13:02:22.590] PROJECTIONS: Scheduling the writing of "$stopped" to "$projections-$master". Current status of Writer: Busy: true
[00001,24,13:02:22.590] PROJECTIONS: Scheduling the writing of "$stopped" to "$projections-$master". Current status of Writer: Busy: true
[00001,25,13:02:22.590] PROJECTIONS: Scheduling the writing of "$stopped" to "$projections-$master". Current status of Writer: Busy: true
[00001,24,13:02:22.590] PROJECTIONS: Command received: 3@"$load-stopped"
[00001,25,13:02:22.592] PROJECTIONS: Command received: 3@"$load-stopped"
[00001,23,13:02:22.595] PROJECTIONS: Response received: 20@"$stopped"
[00001,26,13:02:22.595] PROJECTIONS: Finished writing events to "$projections-$master": "$stopped"
[00001,23,13:02:22.596] PROJECTIONS: Response received: 22@"$stopped"
[00001,25,13:02:22.598] PROJECTIONS: Finished writing events to "$projections-$master": "$stopped"
[00001,24,13:02:22.596] PROJECTIONS: Finished writing events to "$projections-$master": "$stopped"
[00001,23,13:02:22.598] PROJECTIONS: Response received: 24@"$stopped"
[00001,25,13:02:22.600] PROJECTIONS: Scheduling the writing of "$stopped" to "$projections-$master". Current status of Writer: Busy: true
[00001,24,13:02:22.600] PROJECTIONS: Scheduling the writing of "$stopped" to "$projections-$master". Current status of Writer: Busy: true
[00001,24,13:02:22.604] PROJECTIONS: Finished writing events to "$projections-$master": "$stopped"
[00001,25,13:02:22.603] PROJECTIONS: Finished writing events to "$projections-$master": "$stopped"
[00001,23,13:02:22.605] PROJECTIONS: Response received: 29@"$stopped"
[00001,23,13:02:22.606] PROJECTIONS: Response received: 32@"$stopped"
[00001,11,13:02:22.709] Segments count: 1, buffers count: 512, should be when full: 512
[00001,11,13:02:22.724] External TCP connection accepted: [Normal, 192.168.176.1:41484, L192.168.176.2:1113, {0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}].
[00001,07,13:02:22.953] Connection '"external-normal"' ({0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}) identified by client. Client connection name: '"EventStoreProjectionManagerTestsWriteSide_EventStoreProjectionManagerTests"', Client version: V2.
[00001,23,13:02:23.823] Adding projection 79dd9676-dfbc-4753-adec-d6736eb7f7b9@"tenantAllByCode" to list
[00001,23,13:02:23.823] PROJECTIONS: Scheduling the writing of "$create-and-prepare" to "$projections-$9f4f84f3-ef47-4e10-b235-ccdc0febe37e". Current status of Writer: Busy: false
[00001,23,13:02:23.824] PROJECTIONS: Finished writing events to "$projections-$9f4f84f3ef474e10b235ccdc0febe37e": "$create-and-prepare"
[00001,26,13:02:23.824] PROJECTIONS: Command received: 2@"$create-and-prepare"
[00001,26,13:02:23.874] SLOW BUS MSG ["bus"]: "CreateAndPrepare" - 49ms. Handler: "ProjectionCoreService".
[00001,26,13:02:23.874] SLOW QUEUE MSG ["Projection Core #2"]: "CreateAndPrepare" - 49ms. Q: 4/8.
[00001,26,13:02:23.874] PROJECTIONS: Scheduling the writing of "$prepared" to "$projections-$master". Current status of Writer: Busy: true
[00001,26,13:02:23.877] PROJECTIONS: Finished writing events to "$projections-$master": "$prepared"
[00001,23,13:02:23.877] PROJECTIONS: Response received: 35@"$prepared"
[00001,23,13:02:23.878] '"tenantAllByCode"' projection source has been written
[00001,23,13:02:23.878] PROJECTIONS: Scheduling the writing of "$start" to "$projections-$9f4f84f3-ef47-4e10-b235-ccdc0febe37e". Current status of Writer: Busy: false
[00001,23,13:02:23.881] PROJECTIONS: Finished writing events to "$projections-$9f4f84f3ef474e10b235ccdc0febe37e": "$start"
[00001,26,13:02:23.882] PROJECTIONS: Command received: 3@"$start"
[00001,26,13:02:23.902] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: false
[00001,23,13:02:23.904] PROJECTIONS: Response received: 38@"$started"
[00001,26,13:02:23.927] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
[00001,30,13:03:24.329] ES "TcpConnection" closed [13:03:24.329: N192.168.176.1:41484, L192.168.176.2:1113, {0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}]:Received bytes: 3273, Sent bytes: 348
[00001,30,13:03:24.334] ES "TcpConnection" closed [13:03:24.334: N192.168.176.1:41484, L192.168.176.2:1113, {0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}]:Send calls: 10, callbacks: 10
[00001,30,13:03:24.334] ES "TcpConnection" closed [13:03:24.334: N192.168.176.1:41484, L192.168.176.2:1113, {0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}]:Receive calls: 11, callbacks: 11
[00001,30,13:03:24.335] ES "TcpConnection" closed [13:03:24.335: N192.168.176.1:41484, L192.168.176.2:1113, {0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}]:Close reason: [Success] "Socket closed"
[00001,30,13:03:24.338] Connection '"external-normal"":EventStoreProjectionManagerTestsWriteSide_EventStoreProjectionManagerTests"' [192.168.176.1:41484, {0a375ee5-c62a-4ae5-9e8e-2c303b02cc4a}] closed: Success.
[00001,18,13:03:24.341] Persistent subscription lost connection from 192.168.176.1:41484

Have you checked that it’s not simply a case of “Events for this projection are coming in as they are being projected”?
The information “is it up-to-date yet?” is always going to be potentially stale once you recieve it.
Maybe you should consider different acceptance-criteria, like “ready enough to be used” (f.x. “Running and at least 99%?”

Cheers

Hi Julian,

Thanks for the quick reply.

The events were added synchronously. Than I was giving it a whole minute to wait for the 100 progress, using GetStatusAsync. 9 out of 10 times it succeeded. I probably wasn’t clear enough about that.

Anyway I updated the EventStore.ClientAPI to Version=5.0.8.0. and now I get a repeatable/consisten result.

1 Like

Is that a repeatable consisent “good” result?

Hi,
Yes, fortunately it is.
Thanks