EXCEPTION OCCURED (unexpected state?)

Hi

I am running ES docker container (ES v5.0.8) on linux server. The container has been running fine for a couple of weeks but last night it kept crashing (and was being restarted) about 8 times. Always the same log entries, see below. Btw., I filtered out a bunch of EnvelopeMessage and GetFreshStats log entries.

I feel like line 16 and the following ones might be interesting. Mayebe line 16 is the cause of the exception? Idk…

I can’t do much with those logs and would be grateful if anybody could shed some light as to what might be happening here!

Cheers!

  0 [00001,25,15:46:37.765] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
  1 [00001,24,15:46:37.769] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
  2 [00001,24,15:46:37.769] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
  3 [00001,23,15:46:37.817] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
  4 [00001,23,15:46:37.817] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
  5 [00001,25,15:46:37.825] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
  6 [00001,25,15:46:37.825] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
  7 [00001,24,15:46:37.892] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
  8 [00001,24,15:46:37.907] Writing checkpoint for "DataTransformation" at $ce-some-subscription: 144 with expected version number -1
  9 [00001,22,15:46:37.961] PROJECTIONS: Response received: 253139@"$started"
 10 [00001,24,15:46:38.004] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 11 [00001,23,15:46:38.100] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 12 [00001,23,15:46:38.100] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 13 [00001,22,15:46:38.129] PROJECTIONS: Response received: 253142@"$started"
 14 [00001,22,15:46:38.129] PROJECTIONS: Response received: 253145@"$started"
 15 [00001,22,15:46:38.198] PROJECTIONS: Response received: 253148@"$started"
 16 [00001,24,15:46:38.206] Failed to write projection checkpoint to stream "$projections-DataTransformation-checkpoint". Error: "WrongExpectedVersion"
 17 [00001,24,15:46:38.208] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 18 [00001,24,15:46:38.211] Projection '"DataTransformation"'(0cbba36a-9eb8-4f2b-88f7-8899a685d310) restart has been requested due to: '"Checkpoint stream has been written to from the outside"'
 19 [00001,24,15:46:38.258] Error while processing message CoreProjectionProcessingMessage+PrerecordedEventsLoaded in queued handler '"Projection Core #1"'.
 20 EXCEPTION OCCURRED
 21 Current state is Running. Expected states are: StateLoaded
 22 [00001,24,15:46:38.314] PROJECTIONS: Scheduling the writing of "$started" to "$projections-$master". Current status of Writer: Busy: true
 23 [00001,25,15:46:38.374] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 24 [00001,25,15:46:38.374] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 25 [00001,22,15:46:38.387] PROJECTIONS: Response received: 253151@"$started"
 26 [00001,22,15:46:38.387] PROJECTIONS: Response received: 253154@"$started"
 27 [00001,22,15:46:38.523] PROJECTIONS: Response received: 253169@"$started"
 28 [00001,24,15:46:38.579] PROJECTIONS: Finished writing events to "$projections-$master": "$started"
 29 [00001,23,15:46:40.842] SLOW BUS MSG ["bus"]: "CoreTick" - 131ms. Handler: "ProjectionCoreService".
 30 [00001,23,15:46:40.846] SLOW QUEUE MSG ["Projection Core #0"]: "CoreTick" - 132ms. Q: 92/101.
 31 [00001,26,15:46:44.160] New connection to persistent subscription "$ce-some-subscription1" by <some-id>
 32 [... a bunch of those]
 33 [00001,26,15:46:44.167] New connection to persistent subscription "$ce-some-subscription2" by <some-id>
 34 [00001,01,16:20:21.599]
 35 "ES VERSION:"             "5.0.8.0" ("HEAD"/"6b871e5659ed38775372456fb21be6a99392fddb", "Thu, 26 Mar 2020 11:42:43 +0100")
 36 [00001,01,16:20:21.643] "OS:"                     Linux (Unix 4.9.0.15)

If you are sure that no one is writing to that stream directly (maybe by mistake), I’d suggest trying 5.0.10 as some issues were fixed in two latest v5 releases.

Thanks for replying.

I was assuming the $projections-DataTransformation-checkpoint is some kind of internal stream for metadata that is not supposed to be written to directly. Is there any documentation for this?

I’m fairly certain that we’re not directly writing to this stream. The eventstore was running months if not years without this occuring.