Catchup subscription skipping events

Peter_Hageus · February 25, 2016, 9:42am

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

Greg_Young1 · February 25, 2016, 9:46am

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

Peter_Hageus · February 25, 2016, 10:06am

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

Greg_Young1 · February 25, 2016, 10:08am

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)

Peter_Hageus · February 25, 2016, 10:45am

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.

pieter.germishuys · February 25, 2016, 10:52am

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

Peter_Hageus · February 25, 2016, 11:17am

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?

Greg_Young1 · February 25, 2016, 11:19am

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.

Peter_Hageus · February 25, 2016, 11:25am

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...

Greg_Young1 · February 25, 2016, 11:28am

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

Maybe I am confused here?

Greg_Young1 · February 25, 2016, 11:34am

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

Peter_Hageus · February 25, 2016, 12:46pm

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)

Peter_Hageus · February 25, 2016, 2:03pm

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 @ ).

Greg_Young1 · February 25, 2016, 2:31pm

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.

Peter_Hageus · February 25, 2016, 2:38pm

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?

Greg_Young1 · February 25, 2016, 2:39pm

"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

Peter_Hageus · February 25, 2016, 2:55pm

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

Peter_Hageus · February 26, 2016, 9:16am

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-----

Peter_Hageus · March 1, 2016, 7:57am

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)