Catchup subscription skipping events

I have some integration tests running with an embedded inmemory node. (3.4.0)

Some tests fail with events not appearing, because the OriginalPosition is null.

Output from working test:
2016-02-25 10:28:08.948 +01:00 [Debug] Catch-up Subscription to "<all>": "processed" event ("OID", 0, "EntryEvent.Booking.Domain.Activities.EventsV1+OccasionScheduled" @ "20332/20332”).

Output from failing test:
2016-02-25 10:28:18.041 +01:00 [Debug] Catch-up Subscription to "<all>": event appeared ("OID", 0, "EntryEvent.Booking.Domain.Activities.EventsV1+OccasionScheduled" @ null).
2016-02-25 10:28:18.049 +01:00 [Debug] Catch-up Subscription to "<all>": "skipping" event ("OID", 0, "EntryEvent.Booking.Domain.Activities.EventsV1+OccasionScheduled" @ null).

The difference is that the failing test is calling using an inmemory web api, but I can’t see how this should effect eventstore? What could cause the OriginalPosition to be null?

/Peter

Original Position being null is normally to do with resolved events (linkTos)

Yes, have noticed that, but there are no projections involved (other than $all). The same code is being used to write to es in both cases (and pretty much the exact same data).

Tried setting resolveLinkTos to false, no difference.

/Peter

There are other things that use linkTos including users/projections
itself/competing consumers/etc.

I would take a look at the event that is causing the issue.

Also you should upgrade as there is a fix related to this (I forget
what version might even be 3.4.0)

There are other things that use linkTos including users/projections
itself/competing consumers/etc.

I would take a look at the event that is causing the issue.

It’s pretty much identical to the succeeding one. Only user written event in store.

Also you should upgrade as there is a fix related to this (I forget
what version might even be 3.4.0)

3.4.0 is latest on Nuget.

Tried running embedded on disk btw, same behaviour. But after restarting the event appears in the catchup phase ok.

Do you have code that you can share that reproduces what you are seeing?

My repro turned out to be working, so I’ll have to make a new one.

Forgot to mention this is under asp.net 5/core, but running on standard .net, so don’t think it should be an issue?

It shouldn't be an issue in .net (coreclr isn't ready yet though we
now compile in it).

It being this is from $all I think what you are likely seeing here is
a linkTo etc from something that is not yours.

It shouldn't be an issue in .net (coreclr isn't ready yet though we
now compile in it).

It being this is from $all I think what you are likely seeing here is
a linkTo etc from something that is not yours.

The stream “OID" is mine, and the event never appears in my subscription. I’ll try to make a repro after lunch...

"Catch-up Subscription to "<all>""

Maybe I am confused here?

Also its much more useful to send the verbose client log as opposed to
the logging that you are doing for us to see what is going on

I’m pretty sure the log I sent was from this:

https://github.com/EventStore/EventStore/blob/release-v3.5.0/src/EventStore.ClientAPI/EventStoreCatchUpSubscription.cs#L421-L423

Regarding : Yes, the subscription is on $all, but the event skipped is on stream “OID" (‘my’ stream)

There’s gotta be some really dumb thing I’m doing. Now I’m getting the same behaviour in a simple console application.

Setup:

var node = EmbeddedVNodeBuilder

.AsSingleNode()

.RunInMemory()

.RunProjections(ProjectionsMode.System)

.NoAdminOnPublicInterface()

.NoGossipOnPublicInterface()

.NoStatsOnPublicInterface()

.WithExternalHeartbeatTimeout(TimeSpan.FromMinutes(5))

.WithExternalHttpOn(httpEndpoint)

.WithInternalHttpOn(httpEndpoint)

.WithExternalTcpOn(tcpEndpoint)

.WithInternalTcpOn(tcpEndpoint)

.Build();

Full project:

https://dl.dropboxusercontent.com/u/17053085/EventStoreRepro.zip

Log below. As soon as subscription is caught up it stops forwarding events. (my logging is prefixed with dashes, the rest is verbose client log)

Exiting with exit code: 1.

Exit reason: The requested address is not valid in its context

---- New node status: Unknown

---- New node status: PreMaster

---- New node status: Master

[05,14:02:10.845,DEBUG] Catch-up Subscription to : starting…

[07,14:02:10.848,DEBUG] Catch-up Subscription to : running…

[07,14:02:10.848,DEBUG] Catch-up Subscription to : pulling events…

---- Event rx $$$user-ops 0

[07,14:02:10.894,DEBUG] Catch-up Subscription to : processed event ($$$user-ops, 0, $metadata @ 173/173).

---- Event rx $$$projections-$8507ff484e42407da10cfcb0e5170680 0

[07,14:02:10.894,DEBUG] Catch-up Subscription to : processed event ($$$projections-$8507ff484e42407da10cfcb0e5170680, 0, $metadata @ 335/335).

---- Event rx $$$user-admin 0

[07,14:02:10.894,DEBUG] Catch-up Subscription to : processed event ($$$user-admin, 0, $metadata @ 494/494).

---- Event rx $projections-$master 0

[07,14:02:10.894,DEBUG] Catch-up Subscription to : processed event ($projections-$master, 0, $projection-worker-started @ 658/658).

---- Event rx $$$projections-$control 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($$$projections-$control, 0, $metadata @ 831/831).

---- Event rx $user-ops 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($user-ops, 0, $UserCreated @ 965/965).

---- Event rx $user-admin 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($user-admin, 0, $UserCreated @ 1254/1254).

---- Event rx $$$projections-$master 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($$$projections-$master, 0, $metadata @ 1553/1553).

---- Event rx $users 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($users, 0, $User @ 1686/1686).

---- Event rx $users 1

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($users, 1, $User @ 1786/1786).

---- Event rx $projections-$master 1

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$master, 1, $response-reader-starting @ 1888/1888).

---- Event rx $projections-$control 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$control, 0, $response-reader-started @ 2021/2021).

---- Event rx $projections-$all 0

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$all, 0, $ProjectionsInitialized @ 2154/2154).

---- Event rx $projections-$master 2

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$master, 2, $projection-worker-started @ 2280/2280).

---- Event rx $projections-$all 1

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$all, 1, $ProjectionCreated @ 2453/2453).

---- Event rx $projections-$all 2

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$all, 2, $ProjectionCreated @ 2582/2582).

---- Event rx $projections-$all 3

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$all, 3, $ProjectionCreated @ 2722/2722).

---- Event rx $projections-$all 4

[07,14:02:10.895,DEBUG] Catch-up Subscription to : processed event ($projections-$all, 4, $ProjectionCreated @ 2855/2855).

[07,14:02:10.895,DEBUG] Catch-up Subscription to : finished reading events, nextReadPosition = 2990/2990.

[07,14:02:10.895,DEBUG] Catch-up Subscription to : subscribing…

[07,14:02:10.903,DEBUG] Catch-up Subscription to : pulling events (if left)…

[07,14:02:10.903,DEBUG] Catch-up Subscription to : finished reading events, nextReadPosition = 2990/2990.

[07,14:02:10.903,DEBUG] Catch-up Subscription to : processing live events…

---- Now live processing

[07,14:02:10.903,DEBUG] Catch-up Subscription to {0}: hooking to connection.Connected

[07,14:02:10.918,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 0, $create-and-prepare @ ).

[07,14:02:10.919,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 1, $create-and-prepare @ ).

[07,14:02:10.919,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 2, $create-and-prepare @ ).

[07,14:02:10.919,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 3, $create-and-prepare @ ).

[06,14:02:10.920,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 0, $create-and-prepare @ ).

[06,14:02:10.920,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 1, $create-and-prepare @ ).

[06,14:02:10.920,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 2, $create-and-prepare @ ).

[06,14:02:10.920,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 3, $create-and-prepare @ ).

[07,14:02:10.973,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 3, $statistics-report @ ).

[07,14:02:10.973,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 3, $statistics-report @ ).

[06,14:02:10.992,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 4, $prepared @ ).

[07,14:02:10.992,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 4, $prepared @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 5, $statistics-report @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 6, $prepared @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 7, $statistics-report @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 8, $prepared @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 9, $statistics-report @ ).

[06,14:02:10.997,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 5, $statistics-report @ ).

[06,14:02:10.997,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 6, $prepared @ ).

[06,14:02:10.997,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 7, $statistics-report @ ).

[06,14:02:10.997,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 8, $prepared @ ).

[06,14:02:10.997,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 9, $statistics-report @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 10, $prepared @ ).

[07,14:02:10.997,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 10, $prepared @ ).

[07,14:02:11.015,DEBUG] Catch-up Subscription to : event appeared ($projections-$streams, 0, $ProjectionUpdated @ ).

[07,14:02:11.015,DEBUG] Catch-up Subscription to : skipping event ($projections-$streams, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 4, $load-stopped @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 4, $load-stopped @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : event appeared ($projections-$stream_by_category, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : skipping event ($projections-$stream_by_category, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : event appeared ($projections-$by_category, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : event appeared ($projections-$by_event_type, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 5, $load-stopped @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : skipping event ($projections-$by_category, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : skipping event ($projections-$by_event_type, 0, $ProjectionUpdated @ ).

[07,14:02:11.019,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 5, $load-stopped @ ).

[07,14:02:11.020,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 6, $load-stopped @ ).

[07,14:02:11.020,DEBUG] Catch-up Subscription to : event appeared ($projections-$8507ff484e42407da10cfcb0e5170680, 7, $load-stopped @ ).

[06,14:02:11.020,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 6, $load-stopped @ ).

[06,14:02:11.020,DEBUG] Catch-up Subscription to : skipping event ($projections-$8507ff484e42407da10cfcb0e5170680, 7, $load-stopped @ ).

[06,14:02:11.021,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 11, $statistics-report @ ).

[06,14:02:11.021,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 11, $statistics-report @ ).

[07,14:02:11.039,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 12, $statistics-report @ ).

[07,14:02:11.039,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 12, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 13, $stopped @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 14, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 15, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 16, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 17, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 13, $stopped @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 14, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 15, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 16, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 17, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 18, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 19, $stopped @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 20, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 21, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 18, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 22, $stopped @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 19, $stopped @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 20, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 21, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 23, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 24, $statistics-report @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 25, $stopped @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 22, $stopped @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 23, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 24, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 25, $stopped @ ).

[06,14:02:11.041,DEBUG] Catch-up Subscription to : event appeared ($projections-$master, 26, $statistics-report @ ).

[07,14:02:11.041,DEBUG] Catch-up Subscription to : skipping event ($projections-$master, 26, $statistics-report @ ).

[06,14:02:11.404,DEBUG] Catch-up Subscription to : event appeared ($$$stats-255.255.255.255:0, 0, $metadata @ ).

[06,14:02:11.404,DEBUG] Catch-up Subscription to : skipping event ($$$stats-255.255.255.255:0, 0, $metadata @ ).

----- Writing

[16,14:02:11.846,DEBUG] Catch-up Subscription to : event appeared (MyStream, 0, MyEventType @ ).

[16,14:02:11.846,DEBUG] Catch-up Subscription to : skipping event (MyStream, 0, MyEventType @ ).

----- Writing

[07,14:02:12.842,DEBUG] Catch-up Subscription to : event appeared (MyStream, 1, MyEventType @ ).

[07,14:02:12.842,DEBUG] Catch-up Subscription to : skipping event (MyStream, 1, MyEventType @ ).

----- Writing

[06,14:02:13.843,DEBUG] Catch-up Subscription to : event appeared (MyStream, 2, MyEventType @ ).

[06,14:02:13.843,DEBUG] Catch-up Subscription to : skipping event (MyStream, 2, MyEventType @ ).

----- Writing

[16,14:02:14.843,DEBUG] Catch-up Subscription to : event appeared (MyStream, 3, MyEventType @ ).

[04,14:02:14.843,DEBUG] Catch-up Subscription to : skipping event (MyStream, 3, MyEventType @ ).

----- Writing

[16,14:02:15.843,DEBUG] Catch-up Subscription to : event appeared (MyStream, 4, MyEventType @ ).

[04,14:02:15.843,DEBUG] Catch-up Subscription to : skipping event (MyStream, 4, MyEventType @ ).

----- Writing

[04,14:02:16.843,DEBUG] Catch-up Subscription to : event appeared (MyStream, 5, MyEventType @ ).

[04,14:02:16.843,DEBUG] Catch-up Subscription to : skipping event (MyStream, 5, MyEventType @ ).

----- Writing

[04,14:02:17.844,DEBUG] Catch-up Subscription to : event appeared (MyStream, 6, MyEventType @ ).

[21,14:02:17.844,DEBUG] Catch-up Subscription to : skipping event (MyStream, 6, MyEventType @ ).

----- Writing

[19,14:02:18.845,DEBUG] Catch-up Subscription to : event appeared (MyStream, 7, MyEventType @ ).

[04,14:02:18.845,DEBUG] Catch-up Subscription to : skipping event (MyStream, 7, MyEventType @ ).

I missed the embedded part earlier (got the in memory part) there is
some possibility of an error in the subscription code on embedded.

That said all of the skipped events before (seem to be primarily
projections which I would expect (they are deleted)). To simplify in
debugging what happens when you just use a plain subscribe (not catch
up) catchup susbcription just does this internally.

Two things: SubscribeToAll seems to work fine. But I lost all clientapi logs!

Btw, been meaning to mention (or fix): there are some log statements that throw errors, args doesn’t match up. UseFileLogger throws right away, and I have to catch exceptions in my custom logger. Might be related?

"Btw, been meaning to mention (or fix): there are some log statements
that throw errors, args doesn’t match up. UseFileLogger throws right
away, and I have to catch exceptions in my custom logger. Might be
related?"

This would be useful to identify/fix

Can do a pr later, but this is the first one I found, don’t know if there are others:
https://github.com/EventStore/EventStore/blob/release-v3.5.0/src/EventStore.ClientAPI/EventStoreCatchUpSubscription.cs#L221

Update: Embedded live subscription works in 3.4.0, but OriginalPosition is null, so cannot use in tests.

Can not recreate problems with catchup in 3.5.0 branch. Original position is still null in non-catchup though, is this expected? Have a failing test.

/Peter

-----Ursprungligt meddelande-----

Update 2: Made an issue and a pr on github.

(the problem wasn’t solved in 3.5.0 btw, my test was getting a false positive)