Multiple projections emitting to the same stream detected error caused by a single projection

Adrian_Weidermann · March 27, 2015, 9:19am

Hi,

maybe anyone can help me with this issue… or has at least an idea how it can happen

We have an instance of the EventStore v3.0 running with about 100 events of us stored in it and one projection. Since it is an internal testing system we undersized it a little bit, causing the projection to go into a faulted state from time to time since the server was just too slow, but a simple restart of the projection normally solved it for us.

The last time we tried to restart the projection it went into another fault state:

Multiple projections emitting to the same stream detected. Stream: ‘EventStream’. Last event projection: ‘6’. Emitting projection: ‘7’

Normally you get this kind of error if you have multiple projections trying to write to the same stream, in our case it sounds a bit weird because we only got this one custom projection. We also didn’t add and delete another one.

Any ideas how to solve it, or what went wrong?

Our projection:

options({

//reorderEvents: true, // enables event reordering in a multi-stream projection

// event reordering attempts to feed the projection with events in a

// their natural order

//processingLag: 50, // processing lag in ms allowing event reordering to happen

});

fromAll()

.when({

$any: function(s,e) {

if (e.metadata !== null) {

if (e.metadata.MessageStreamType === “Event”) {

linkTo(“EventStream”, e);

}

});

Greg_Young1 · March 27, 2015, 11:41am

Likely its a bug thats on the board with taking over a projection (off
by one error on the checkpoint that we need to track down).

Can you reset the projection?

Adrian_Weidermann · March 27, 2015, 2:55pm

Hi Greg,

resetting the projection didn’t solve the issue If i modify the StreamName the events get linked to for example, everything works fine but that’s more a workaround than a fix.

Julio_Araujo · June 4, 2015, 11:40am

Hi Greg,

Any update on this bug? I am having the same issue.

RS,

Julio Araujo

jen20 · June 4, 2015, 2:25pm

Can you post the source of the projection you’re seeing this with? Is it reliably reproducible? If so can we get a copy of your database for further debugging?

Julio_Araujo · June 4, 2015, 6:11pm

James,

I was able to start from a new instance of the EventStore
and reproduce this bug. Below are the steps that I used to reproduce it.
Note that I am running version 3.0.3 of the Eventstore under a Ubuntu docker
container.

Started the Eventstore with this command: ./run-node.sh --http-prefixes=http://*:2113/ --ext-ip=0.0.0.0 --db /data/db --log /data/logs --run-projections=All
Loaded these two streams using Postman (chrome ext.):

a. [{“eventId”: “ab2fd86f-8171-4463-a1bd-e6f71abec5aa”,“eventType”: “tagRead”,“data”: { “tagId”: “12345”, “reader”: “reader-one” }}]

b. [{“eventId”: “6fb825cf-5c20-4c68-aede-30ac5e325d6d”,“eventType”: “itemTagAssociated”,“data”: { “itemId”: “123”, “tagId”: “12345”, “name”: “Notebook” }}]

I Enabled All Projections in the web UI.
The I created the first Projection which I called batch_to_tag_stream:

fromCategory(‘batch’)

.when({

tagRead: function(s,e) {

linkTo(‘tag-’ + e.body.tagId,e);

}

})

The I created the second Projection called item_to_tag_association; this is the one that gives me the error:

fromCategory(‘item’)

.when({

itemTagAssociated: function(s,e) {

linkTo(‘tag-’ + e.body.tagId, e);

}

})

I hope this helps.

Thank You,

Julio Araujo

Greg_Young1 · June 5, 2015, 12:41pm

This looks like two projections writing to the same stream which is
exactly the error you are given. I am confused?

Julio_Araujo · June 5, 2015, 1:11pm

Greg,

Maybe I don’t know what I’m doing but shouldn’t that be allowed. The two projections are writing to that stream from different events.

Julio

Greg_Young1 · June 5, 2015, 1:12pm

Yes but projections are not allowed to write to the same stream by
default. It screws up them being able to be started/stopped etc. Also
it screws up the ability to delete everything a projection has done!

Julio_Araujo · June 5, 2015, 1:24pm

Oh OK, I understand. Thanks. I will approach this from another angle.

Greg_Young1 · June 5, 2015, 1:25pm

This is one of the conceptual things about projections that really
needs documentation around it. I have made a note to get a detailed
explantation of this in the docs as we are working on them.

Julio_Araujo · June 5, 2015, 2:40pm

Awesome, Thanks Greg.

Darien_Narvaez · September 13, 2016, 7:15pm

Is this still a bug? I am having the same Issue, and I´m not trying to write to a stream owned by a projection. I think I have the same issue as Adrian. Is there an update on this topic?

pieter.germishuys · September 13, 2016, 7:31pm

What are you seeing in your logs Darien?
If you are seeing something like the following: Multiple projections emitting to the same stream detected. Stream: ‘EventStream’. Last event projection: ‘6’. Emitting projection: ‘7’

This likely means that you have had a projection that emitted to a stream, deleted the projection and created a new projection that is now emitting to the same stream the previous projection was. This has been resolved by allowing users to track/delete streams that were created by projections. If you didn’t have the ability to track the streams option when creating the projection, you are more than welcome to delete those streams manually and the projection should be able to run just fine.

Darien_Narvaez · September 13, 2016, 7:44pm

I did not deleted any stream/projection. The error is hapening on my dev machine which was recently updated to Windows 10 Anniversary wich is making the ssd to frezze from time to time (2+ minutes of freezing). This is the log: (im sorry if it is too long…)

ES VERSION: 0.0.0.0 (Unknown/Unknown, Unknown)

OS: Windows (Microsoft Windows NT 6.2.9200.0)

RUNTIME: .NET 4.0.30319.42000 (64-bit)

GC: 3 GENERATIONS

LOGS: C:\EventStore\logs

MODIFIED OPTIONS:

RUN PROJECTIONS: all (Command Line)

DEFAULT OPTIONS:

HELP: False ()

VERSION: False ()

LOG: C:\EventStore\logs ()

CONFIG: ()

DEFINES: ()

WHAT IF: False ()

START STANDARD PROJECTIONS: False ()

DISABLE HTTP CACHING: False ()

MONO MIN THREADPOOL SIZE: 10 ()

INT IP: 127.0.0.1 ()

EXT IP: 127.0.0.1 ()

INT HTTP PORT: 2112 ()

EXT HTTP PORT: 2113 ()

INT TCP PORT: 1112 ()

INT SECURE TCP PORT: 0 ()

EXT TCP PORT: 1113 ()

EXT SECURE TCP PORT ADVERTISE AS: 0 ()

EXT SECURE TCP PORT: 0 ()

EXT IP ADVERTISE AS: ()

EXT TCP PORT ADVERTISE AS: 0 ()

EXT HTTP PORT ADVERTISE AS: 0 ()

INT IP ADVERTISE AS: ()

INT SECURE TCP PORT ADVERTISE AS: 0 ()

INT TCP PORT ADVERTISE AS: 0 ()

INT HTTP PORT ADVERTISE AS: 0 ()

INT TCP HEARTBEAT TIMEOUT: 700 ()

EXT TCP HEARTBEAT TIMEOUT: 1000 ()

INT TCP HEARTBEAT INTERVAL: 700 ()

EXT TCP HEARTBEAT INTERVAL: 2000 ()

FORCE: False ()

CLUSTER SIZE: 1 ()

NODE PRIORITY: 0 ()

MIN FLUSH DELAY MS: 2 ()

COMMIT COUNT: -1 ()

PREPARE COUNT: -1 ()

ADMIN ON EXT: True ()

STATS ON EXT: True ()

GOSSIP ON EXT: True ()

DISABLE SCAVENGE MERGING: False ()

SCAVENGE HISTORY MAX AGE: 30 ()

DISCOVER VIA DNS: True ()

CLUSTER DNS: fake.dns ()

CLUSTER GOSSIP PORT: 30777 ()

GOSSIP SEED: ()

STATS PERIOD SEC: 30 ()

CACHED CHUNKS: -1 ()

CHUNKS CACHE SIZE: 536871424 ()

MAX MEM TABLE SIZE: 1000000 ()

DB: C:\EventStore\data ()

INDEX: ()

MEM DB: False ()

SKIP DB VERIFY: False ()

PROJECTION THREADS: 3 ()

WORKER THREADS: 5 ()

INT HTTP PREFIXES: ()

EXT HTTP PREFIXES: ()

ENABLE TRUSTED AUTH: False ()

ADD INTERFACE PREFIXES: True ()

CERTIFICATE STORE LOCATION: ()

CERTIFICATE STORE NAME: ()

CERTIFICATE SUBJECT NAME: ()

CERTIFICATE THUMBPRINT: ()

CERTIFICATE FILE: ()

CERTIFICATE PASSWORD: ()

USE INTERNAL SSL: False ()

SSL TARGET HOST: n/a ()

SSL VALIDATE SERVER: True ()

AUTHENTICATION TYPE: internal ()

AUTHENTICATION CONFIG: ()

PREPARE TIMEOUT MS: 2000 ()

COMMIT TIMEOUT MS: 2000 ()

UNSAFE DISABLE FLUSH TO DISK: False ()

BETTER ORDERING: False ()

UNSAFE IGNORE HARD DELETE: False ()

INDEX CACHE DEPTH: 16 ()

GOSSIP INTERVAL MS: 1000 ()

GOSSIP ALLOWED DIFFERENCE MS: 60000 ()

GOSSIP TIMEOUT MS: 500 ()

ENABLE HISTOGRAMS: False ()

LOG HTTP REQUESTS: False ()

[PID:05340:001 2016.09.13 17:31:05.907 INFO ProgramBase`1 ] Quorum size set to 1

[PID:05340:001 2016.09.13 17:31:05.907 INFO ProgramBase`1 ] Cannot find plugins path: C:\EventStore\plugins

[PID:05340:001 2016.09.13 17:31:06.052 INFO VNodeBuilder ] INSTANCE ID: f784fa4e-cfef-4c6a-a9b7-65f23943ec56

[PID:05340:001 2016.09.13 17:31:06.052 INFO VNodeBuilder ] DATABASE: C:\EventStore\data

[PID:05340:001 2016.09.13 17:31:06.052 INFO VNodeBuilder ] WRITER CHECKPOINT: 1449164292 (0x56607E04)

[PID:05340:001 2016.09.13 17:31:06.052 INFO VNodeBuilder ] CHASER CHECKPOINT: 1449164292 (0x56607E04)

[PID:05340:001 2016.09.13 17:31:06.052 INFO VNodeBuilder ] EPOCH CHECKPOINT: 1407711847 (0x53E7FA67)

[PID:05340:001 2016.09.13 17:31:06.052 INFO VNodeBuilder ] TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)

[PID:05340:001 2016.09.13 17:31:06.416 TRACE MessageHierarchy ] MessageHierarchy initialization took 00:00:00.2399295.

[PID:05340:006 2016.09.13 17:31:08.430 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\EventStore\data\chunk-000003.000000’…

[PID:05340:001 2016.09.13 17:31:08.587 TRACE TFChunk ] CACHED TFChunk #5-5 (chunk-000005.000000) in 00:00:00.2313765.

[PID:05340:001 2016.09.13 17:31:13.011 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections ==> C:\EventStore\projections

[PID:05340:001 2016.09.13 17:31:13.011 INFO MiniWeb ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> C:\EventStore\Prelude

[PID:05340:001 2016.09.13 17:31:13.025 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}

[PID:05340:001 2016.09.13 17:31:13.025 TRACE MiniWeb ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}

[PID:05340:001 2016.09.13 17:31:13.072 INFO MiniWeb ] Starting MiniWeb for /web ==> C:\EventStore\clusternode-web

[PID:05340:001 2016.09.13 17:31:13.073 TRACE MiniWeb ] Binding MiniWeb to /web/{*remaining_path}

[PID:05340:014 2016.09.13 17:31:13.132 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] SYSTEM INIT…

[PID:05340:014 2016.09.13 17:31:13.233 INFO TcpServerListener ] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.

[PID:05340:015 2016.09.13 17:31:13.278 INFO IndexCommitter ] TableIndex initialization…

[PID:05340:014 2016.09.13 17:31:13.333 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: SystemInit - 101ms. Handler: TcpService.

[PID:05340:015 2016.09.13 17:31:13.384 TRACE PTable ] Loading PTable ‘1fa058fe-a3bf-4b0b-851e-f95c234e2d95’ started…

[PID:05340:014 2016.09.13 17:31:13.451 INFO HttpAsyncServer ] Starting HTTP server on [http://127.0.0.1:2113/,http://localhost:2113/]…

[PID:05340:014 2016.09.13 17:31:13.451 INFO HttpAsyncServer ] HTTP server is up and listening on [http://127.0.0.1:2113/,http://localhost:2113/]

[PID:05340:014 2016.09.13 17:31:13.451 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: SystemInit - 127ms. Handler: HttpService.

[PID:05340:014 2016.09.13 17:31:13.534 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: SystemInit - 387ms. Q: 0/4.

[PID:05340:014 2016.09.13 17:31:13.534 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service ‘StorageReader’ initialized.

[PID:05340:014 2016.09.13 17:31:13.534 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service ‘StorageWriter’ initialized.

[PID:05340:010 2016.09.13 17:31:13.685 TRACE TFChunk ] CACHED TFChunk #4-4 (chunk-000004.000000) in 00:00:05.0970283.

[PID:05340:011 2016.09.13 17:31:14.621 TRACE InMemoryBus ] SLOW BUS MSG [Worker #5 Bus]: AuthenticatedHttpRequestMessage - 487ms. Handler: AuthenticatedHttpRequestProcessor.

[PID:05340:011 2016.09.13 17:31:14.654 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #5]: AuthenticatedHttpRequestMessage - 487ms. Q: 0/1.

[PID:05340:015 2016.09.13 17:31:15.529 TRACE PTable ] Loading PTable ‘1fa058fe-a3bf-4b0b-851e-f95c234e2d95’ (1000427 entries, cache depth 16) done in 00:00:02.1447583.

[PID:05340:015 2016.09.13 17:31:15.529 TRACE PTable ] Verifying file hash of PTable ‘1fa058fe-a3bf-4b0b-851e-f95c234e2d95’ started…

[PID:05340:015 2016.09.13 17:31:16.050 TRACE PTable ] Verifying file hash of PTable ‘1fa058fe-a3bf-4b0b-851e-f95c234e2d95’ (1000427 entries) done in 00:00:00.5170903.

[PID:05340:015 2016.09.13 17:31:16.050 TRACE PTable ] Loading PTable ‘6ca901fd-2648-44ea-9d98-0b7764863b04’ started…

[PID:05340:005 2016.09.13 17:31:16.123 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [MonitoringQueue]: SystemInit - 2980ms. Q: 0/0.

[PID:05340:015 2016.09.13 17:31:17.307 TRACE PTable ] Loading PTable ‘6ca901fd-2648-44ea-9d98-0b7764863b04’ (2000182 entries, cache depth 16) done in 00:00:01.2542598.

[PID:05340:015 2016.09.13 17:31:17.307 TRACE PTable ] Verifying file hash of PTable ‘6ca901fd-2648-44ea-9d98-0b7764863b04’ started…

[PID:05340:015 2016.09.13 17:31:18.133 TRACE PTable ] Verifying file hash of PTable ‘6ca901fd-2648-44ea-9d98-0b7764863b04’ (2000182 entries) done in 00:00:00.8255720.

[PID:05340:015 2016.09.13 17:31:18.141 INFO IndexCommitter ] ReadIndex building…

[PID:05340:006 2016.09.13 17:31:18.908 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\EventStore\data\chunk-000002.000000’…

[PID:05340:015 2016.09.13 17:31:19.175 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 100000 records (16,0%).

[PID:05340:015 2016.09.13 17:31:20.034 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 200000 records (32,0%).

[PID:05340:015 2016.09.13 17:31:20.935 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 300000 records (48,0%).

[PID:05340:015 2016.09.13 17:31:21.826 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 400000 records (63,9%).

[PID:05340:015 2016.09.13 17:31:22.785 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 500000 records (80,6%).

[PID:05340:006 2016.09.13 17:31:22.918 TRACE TFChunk ] Verifying hash for TFChunk ‘C:\EventStore\data\chunk-000001.000000’…

[PID:05340:015 2016.09.13 17:31:23.718 DEBUG IndexCommitter ] ReadIndex Rebuilding: processed 600000 records (96,5%).

[PID:05340:015 2016.09.13 17:31:23.911 DEBUG IndexCommitter ] ReadIndex rebuilding done: total processed 621627 records, time elapsed: 00:00:05.7703467.

[PID:05340:014 2016.09.13 17:31:23.943 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Service ‘StorageChaser’ initialized.

[PID:05340:014 2016.09.13 17:31:23.943 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] SYSTEM START…

[PID:05340:014 2016.09.13 17:31:23.943 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] IS UNKNOWN…

[PID:05340:014 2016.09.13 17:31:24.037 DEBUG ElectionsService ] ELECTIONS: STARTING ELECTIONS.

[PID:05340:014 2016.09.13 17:31:24.037 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.

[PID:05340:014 2016.09.13 17:31:24.041 DEBUG ElectionsService ] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {f784fa4e-cfef-4c6a-a9b7-65f23943ec56}].

[PID:05340:014 2016.09.13 17:31:24.041 DEBUG ElectionsService ] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.

[PID:05340:014 2016.09.13 17:31:24.041 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.

[PID:05340:014 2016.09.13 17:31:24.041 DEBUG ElectionsService ] ELECTIONS: (V=0) PREPARE_OK FROM 127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}.

[PID:05340:014 2016.09.13 17:31:24.041 DEBUG ElectionsService ] ELECTIONS: (V=0) SHIFT TO REG_LEADER.

[PID:05340:014 2016.09.13 17:31:24.075 DEBUG ElectionsService ] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: 127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}, ME: 127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}.

[PID:05340:014 2016.09.13 17:31:24.075 DEBUG ElectionsService ] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}] M=[127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}]).

[PID:05340:014 2016.09.13 17:31:24.075 INFO ElectionsService ] ELECTIONS: (V=0) DONE. ELECTED MASTER = 127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}. ME=127.0.0.1:2112,{f784fa4e-cfef-4c6a-a9b7-65f23943ec56}.

[PID:05340:014 2016.09.13 17:31:24.075 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: StartElections - 136ms. Handler: ElectionsService.

[PID:05340:014 2016.09.13 17:31:24.075 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: StartElections - 136ms. Q: 0/4.

[PID:05340:014 2016.09.13 17:31:24.089 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP…

[PID:05340:014 2016.09.13 17:31:24.089 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] IS MASTER… SPARTA!

[PID:05340:008 2016.09.13 17:31:24.089 DEBUG PersistentSubscripti] Subscriptions received state change to Unknown stopping listening.

[PID:05340:008 2016.09.13 17:31:24.110 TRACE InMemoryBus ] SLOW BUS MSG [PersistentSubscriptionsBus]: BecomeUnknown - 161ms. Handler: PersistentSubscriptionService.

[PID:05340:008 2016.09.13 17:31:24.110 DEBUG PersistentSubscripti] Subscriptions received state change to PreMaster stopping listening.

[PID:05340:008 2016.09.13 17:31:24.110 DEBUG PersistentSubscripti] Subscriptions Became Master so now handling subscriptions

[PID:05340:012 2016.09.13 17:31:24.322 DEBUG EpochManager ] === Writing E159@1449164292:{8c8f9105-3a08-496d-a9af-c70c79c54689} (previous epoch at 1407711847).

[PID:05340:014 2016.09.13 17:31:24.322 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: UserManagementServiceInitialized - 139ms. Q: 0/2.

[PID:05340:012 2016.09.13 17:31:24.353 DEBUG EpochManager ] === Update Last Epoch E159@1449164292:{8c8f9105-3a08-496d-a9af-c70c79c54689} (previous epoch at 1407711847).

[PID:05340:019 2016.09.13 17:31:24.374 DEBUG ProjectionCoreCoordi] PROJECTIONS: Starting Projections Core Coordinator. (Node State : Master)

[PID:05340:019 2016.09.13 17:31:24.374 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: SystemCoreReady - 56ms. Handler: ProjectionCoreCoordinator.

[PID:05340:008 2016.09.13 17:31:24.436 TRACE MonitoringService ] Created stats stream ‘$stats-127.0.0.1:2113’, code = WrongExpectedVersion

[PID:05340:021 2016.09.13 17:31:24.500 DEBUG ProjectionCoreServic] PROJECTIONS: Starting Projection Core Reader (reads from $projections-$a16ff381cd0a422ab03ca1ca3dfac53f)

[PID:05340:021 2016.09.13 17:31:24.537 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 125ms. Handler: ProjectionCoreServiceCommandReader.

[PID:05340:019 2016.09.13 17:31:24.556 DEBUG ProjectionManager ] PROJECTIONS: Starting Projections Manager. (Node State : Master)

[PID:05340:019 2016.09.13 17:31:24.556 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: SystemCoreReady - 172ms. Handler: ProjectionManager.

[PID:05340:019 2016.09.13 17:31:24.556 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: SystemCoreReady - 228ms. Q: 0/3.

[PID:05340:020 2016.09.13 17:31:24.556 DEBUG ProjectionCoreServic] PROJECTIONS: Starting Projection Core Reader (reads from $projections-$de1f9f20d742406fa1756cf3212f48c1)

[PID:05340:022 2016.09.13 17:31:24.556 DEBUG ProjectionCoreServic] PROJECTIONS: Starting Projection Core Reader (reads from $projections-$d8eece94299240839d6ec243c28ed722)

[PID:05340:020 2016.09.13 17:31:24.557 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 163ms. Handler: ProjectionCoreServiceCommandReader.

[PID:05340:022 2016.09.13 17:31:24.557 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 143ms. Handler: ProjectionCoreServiceCommandReader.

[PID:05340:014 2016.09.13 17:31:24.616 ERROR StorageScavenger ] Failed to write the $scavengeIndexInitialized event to the $scavenges stream. Reason: WrongExpectedVersion

[PID:05340:014 2016.09.13 17:31:24.616 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: WriteEventsCompleted - 182ms. Handler: RequestResponseDispatcher`2.

[PID:05340:014 2016.09.13 17:31:24.616 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: WriteEventsCompleted - 185ms. Q: 0/8.

[PID:05340:021 2016.09.13 17:31:24.663 DEBUG ResponseWriter ] PROJECTIONS: Resetting Master Writer

[PID:05340:022 2016.09.13 17:31:24.663 DEBUG ResponseWriter ] PROJECTIONS: Resetting Master Writer

[PID:05340:020 2016.09.13 17:31:24.663 DEBUG ResponseWriter ] PROJECTIONS: Resetting Master Writer

[PID:05340:022 2016.09.13 17:31:24.663 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 107ms. Handler: ProjectionCoreResponseWriter.

[PID:05340:020 2016.09.13 17:31:24.663 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 107ms. Handler: ProjectionCoreResponseWriter.

[PID:05340:021 2016.09.13 17:31:24.666 TRACE InMemoryBus ] SLOW BUS MSG [bus]: StartCore - 128ms. Handler: ProjectionCoreResponseWriter.

[PID:05340:022 2016.09.13 17:31:24.666 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #2]: StartCore - 253ms. Q: 1/6.

[PID:05340:020 2016.09.13 17:31:24.666 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #0]: StartCore - 273ms. Q: 1/6.

[PID:05340:021 2016.09.13 17:31:24.666 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projection Core #1]: StartCore - 254ms. Q: 1/6.

[PID:05340:020 2016.09.13 17:31:24.689 DEBUG ProjectionCoreServic] PROJECTIONS: Starting read control from 159

[PID:05340:021 2016.09.13 17:31:24.689 DEBUG ProjectionCoreServic] PROJECTIONS: Starting read control from 159

[PID:05340:022 2016.09.13 17:31:24.689 DEBUG ProjectionCoreServic] PROJECTIONS: Starting read control from 159

[PID:05340:021 2016.09.13 17:31:24.698 DEBUG ProjectionCoreServic] PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-$a16ff381cd0a422ab03ca1ca3dfac53f)

[PID:05340:020 2016.09.13 17:31:24.698 DEBUG ProjectionCoreServic] PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-$de1f9f20d742406fa1756cf3212f48c1)

[PID:05340:022 2016.09.13 17:31:24.698 DEBUG ProjectionCoreServic] PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-$d8eece94299240839d6ec243c28ed722)

[PID:05340:019 2016.09.13 17:31:24.745 DEBUG ProjectionManagerRes] PROJECTIONS: Starting Projection Manager Response Reader (reads from $projections-$master)

[PID:05340:019 2016.09.13 17:31:24.745 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: Starting - 196ms. Handler: ProjectionManagerResponseReader.

[PID:05340:019 2016.09.13 17:31:24.805 DEBUG MultiStreamMessageWr] PROJECTIONS: Resetting Worker Writer

[PID:05340:019 2016.09.13 17:31:24.805 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: Starting - 50ms. Handler: ProjectionManagerCommandWriter.

[PID:05340:019 2016.09.13 17:31:24.805 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: Starting - 247ms. Q: 1/3.

[PID:05340:014 2016.09.13 17:31:25.571 TRACE InMemoryBus ] SLOW BUS MSG [MainBus]: RequestForwardingTimerTick - 618ms. Handler: RequestForwardingService.

[PID:05340:014 2016.09.13 17:31:25.573 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [MainQueue]: RequestForwardingTimerTick - 620ms. Q: 0/5.

[PID:05340:012 2016.09.13 17:31:25.573 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [StorageWriterQueue]: WritePrepares - 823ms. Q: 0/0.

[PID:05340:019 2016.09.13 17:31:25.613 DEBUG ProjectionManagerRes] PROJECTIONS: Finished Starting Projection Manager Response Reader (reads from $projections-$master)

[PID:05340:019 2016.09.13 17:31:25.635 DEBUG ProjectionManagerRes] PROJECTIONS: Response received: 49965@$response-reader-starting

[PID:05340:019 2016.09.13 17:31:25.635 DEBUG ProjectionManagerRes] PROJECTIONS: Response received: 49966@$projection-worker-started

[PID:05340:019 2016.09.13 17:31:25.654 DEBUG ProjectionManagerRes] PROJECTIONS: Response received: 49967@$projection-worker-started

[PID:05340:019 2016.09.13 17:31:25.654 DEBUG ProjectionManagerRes] PROJECTIONS: Response received: 49968@$projection-worker-started

[PID:05340:019 2016.09.13 17:31:25.654 DEBUG ProjectionManager ] PROJECTIONS: Reading/Starting Existing Projections from $projections-$all

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] PROJECTIONS: Found the following projections in $projections-$all. TestEvents2,Test4_labcoleV_siscole_informesControlLechero,TestEventsProjection,Test3_labcoleV_siscole_informesControlLechero,Test2_labcoleV_siscole_informesControlLechero,Test1_labcoleV_siscole_informesControlLechero,siscole_comandosDeInformeControlLechero,labcoleV_siscole_informesControlLechero,labcoleV_solicitudDeAnalisisSub,labcoleV_siscoleAdapterSub,labcoleV_insumoSub,labcoleV_indiceCodigosDeBarraSub,labcoleV_cuentaDeUsuarioSub,labcoleV_globalViewStream,labcoleV_solicitudDeAnalisisStream,labcoleV_siscoleAdapterStream,labcoleV_insumoStream,labcoleV_indiceCodigosDeBarraStream,labcoleV_cuentaDeUsuarioStream,$by_event_type,$by_category,$stream_by_category,$streams

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection c6717696-63f5-47bf-a532-90ca486668d5@TestEvents2 to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 1137d46e-aab2-4970-98ce-637f09348c6b@Test4_labcoleV_siscole_informesControlLechero to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 686566bf-aaa3-4c81-91e3-e3eb8134c4b8@TestEventsProjection to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 1d67cfd3-db81-4f53-bfc6-6816cc7af646@Test3_labcoleV_siscole_informesControlLechero to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 395bbac0-e0cb-4ef9-aca6-44e03d57094a@Test2_labcoleV_siscole_informesControlLechero to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection c29506bb-98c0-44ff-a353-5fcdb07861cc@Test1_labcoleV_siscole_informesControlLechero to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 0d80bc8b-d375-46b2-80f7-790a134c3e79@siscole_comandosDeInformeControlLechero to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 2287f303-813a-4ded-8522-cf8f1f822fb1@labcoleV_siscole_informesControlLechero to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 6d729e38-cafa-4fc7-b5a3-313f1d985127@labcoleV_solicitudDeAnalisisSub to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 831a2e3b-8632-4a80-a243-d34d7783c511@labcoleV_siscoleAdapterSub to list

[PID:05340:019 2016.09.13 17:31:25.718 DEBUG ProjectionManager ] Adding projection 64ac89d5-bc4f-414c-beca-977d51775050@labcoleV_insumoSub to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection e7347862-7699-48ed-971c-5352c5a673a2@labcoleV_indiceCodigosDeBarraSub to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection 79249301-c73a-4e21-88e6-53c4c9a37afb@labcoleV_cuentaDeUsuarioSub to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection b3738400-1264-4675-a0c2-23188b249c81@labcoleV_globalViewStream to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection b8b1bfb9-8588-4912-9132-17fdd8315c4e@labcoleV_solicitudDeAnalisisStream to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection 08bde92f-4705-4398-829b-3431c9ee595d@labcoleV_siscoleAdapterStream to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection bd78d3be-b57e-48e3-b531-0f78552875e3@labcoleV_insumoStream to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection e5d08e73-16c1-4e14-a779-2e9aad2958ea@labcoleV_indiceCodigosDeBarraStream to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection c8446aaa-d1df-4fc6-bc25-05c86cdfd3db@labcoleV_cuentaDeUsuarioStream to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection d6202ade-79eb-4282-b3fd-887371d1b489@$by_event_type to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection 68c28c28-6b44-4804-8f2f-3f4810574422@$by_category to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection f71cbb9e-b52c-4af0-ae93-28989f57e348@$stream_by_category to list

[PID:05340:019 2016.09.13 17:31:25.729 DEBUG ProjectionManager ] Adding projection 270ae598-f0fe-4a5d-944d-5b7402b96918@$streams to list

[PID:05340:014 2016.09.13 17:31:25.729 INFO ClusterVNodeControll] ========== [127.0.0.1:2112] Sub System ‘Projections’ initialized.

[PID:05340:019 2016.09.13 17:31:25.729 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: ReadStreamEventsBackwardCompleted - 70ms. Handler: ProjectionManager.

[PID:05340:019 2016.09.13 17:31:25.729 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: ReadStreamEventsBackwardCompleted - 70ms. Q: 0/49.

[PID:05340:019 2016.09.13 17:31:25.871 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: ReadStreamEventsBackwardCompleted - 137ms. Handler: ProjectionManager.

[PID:05340:019 2016.09.13 17:31:25.871 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: ReadStreamEventsBackwardCompleted - 137ms. Q: 22/24.

[PID:05340:019 2016.09.13 17:31:25.893 DEBUG MultiStreamMessageWr] PROJECTIONS: Scheduling the writing of $create-and-prepare to $projections-$de1f9f20-d742-406f-a175-6cf3212f48c1. Current status of Writer: Busy: False

[PID:05340:019 2016.09.13 17:31:25.935 TRACE InMemoryBus ] SLOW BUS MSG [manager input bus]: CreateAndPrepare - 53ms. Handler: ProjectionManagerCommandWriter.

[PID:05340:019 2016.09.13 17:31:25.935 TRACE QueuedHandlerMRES ] SLOW QUEUE MSG [Projections Master]: CreateAndPrepare - 53ms. Q: 23/24.

[PID:05340:019 2016.09.13 17:31:25.935 DEBUG MultiStreamMessageWr] PROJECTIONS: Scheduling the writing of $create-and-prepare to $projections-$a16ff381-cd0a-422a-b03c-a1ca3dfac53f. Current status of Writer: Busy: False

[PID:05340:019 2016.09.13 17:31:25.935 DEBUG MultiStreamMessageWr] PROJECTIONS: Scheduling the writing of $create-and-prepare to $projections-$d8eece94-2992-4083-9d6e-c243c28ed722. Current status of Writer: Busy: False