prooph / event-store-client Goto Github PK

View Code? Open in Web Editor NEW

113.0 12.0 31.0 2.22 MB

PHP Event Store Client Implementation

License: BSD 3-Clause "New" or "Revised" License

PHP 100.00%

php async eventstore eventsourcing event-sourcing event-store ddd prooph

event-store-client's Introduction

Prooph Event Store Client

PHP 8.1 Event Store Client Implementation.

Overview

Prooph Event Store Client supports async non-blocking communication via TCP to EventStore.

The EventStoreConnection maintains a full-duplex connection between the client and the Event Store server.

Extensions

The protobuf extension from Google is recommended, however it is not required.

When this extension is missing, the client will fallback to use google/protobuf installable via composer.

The extension allegro/php-protobuf is not compatible.

Additional extensions are only needed if your app necessitates a high numbers of concurrent socket connections.

ev
event
php-uv (experimental fork)

Installation

Client

You can install prooph/event-store-client via composer by adding "prooph/event-store-client": "dev-master" as requirement to your composer.json.

Server

Using docker:

docker run --name eventstore-node -it -p 2113:2113 -p 1113:1113 eventstore/eventstore

Please refer to the documentation of eventstore.org.

See server section.

In the docker-folder you'll find three different docker-compose setups (single node, 3-node-cluster and 3-node-dns-cluster).

Quick Start

For a short overview please see the examples folder.

Unit tests

Plain PHP

Run the server with memory database

Note: This is the start-script of the Event Store database, not something provided by this library!

./run-node.sh --run-projections=all --mem-db

You need to ignore the ignore group

./vendor/bin/phpunit --exclude-group=ignore

Those are tests that only work against an empty database and can only be run manually.

Before next run, restart the server. This way you can always start with a clean server.

Using Docker

See: https://github.com/prooph/event-store-client/tree/master/docker/unittest

Documentation

Documentation is on the prooph website.

Support

Ask questions on Stack Overflow tagged with #prooph.
File issues at https://github.com/prooph/event-store-client/issues.
Say hello in the prooph gitter chat.

Contribute

Please feel free to fork and extend existing or add new plugins and send a pull request with your changes! To establish a consistent code quality, please provide unit tests for all your changes and may adapt the documentation.

License

Released under the New BSD License.

event-store-client's People

Contributors

Stargazers

Watchers

event-store-client's Issues

Support UUID1 / UUID5, ...

Add Sync Projections- / Query- / User-Managers

add PersistentSubscriptionSettings Builder

Rename Method StreamMetadata::build => StreamMetadata::create

Clarify the ports usage in documentation

Streams are managed via client API (port 1113) while projections are managed via HTTP API (port 2113). We need to clarify this when writing docs for this package.

When trying to do an operation with a wrong port I got very confusing error:

In DefaultClient.php line 358:
                                                                      
  [Amp\Artax\SocketException]                                         
  Socket disconnected prior to response completion (Parser state: 0)

Unclear message when trying to communicate through closed connection

The error message indicating that the connection has been closed and thus cannot be used, is not clear.

I'll make a suggestion later (unless this is an expected behaviour?).

Travis failed (ramsey uuid 4)

Optional logging dependencies

Hi @prolic,

While going through the dependencies a bit more it looks like these can be considered more like optional dependencies:

    "amphp/byte-stream": "^1.3.1",
    "amphp/file": "^0.3.1",
    "amphp/log": "^1.0.0",

The only place those three are used is in ConnectionSettingsBuilder in the methods useConsoleLogger() and useFileLogger(), however neither of those functions is ever called except from the example scripts. Is it perhaps an idea to remove those two functions and add some documentation on how to implement those loggers via useCustomLogger()? Then the dependencies are moved to the main project and become optional. If you want to use them you can require them yourself in the root project, if you're not using either useConsoleLogger() or useFileLogger() you're not pulling in unused packages. That reduces potential version conflicts if someone wants to use a newer version of those packages than is required by prooph/event-store-client. For example I'm injecting my own Monolog via useCustomLogger() already, so in the application I'm building there's no point in having those dependencies.

I could do the work on that and make a PR for it.

HTTP API UserCredentials

I don't like passing the UserCredentials object to each method that uses the HTTP API (such as SyncProjectionsManager or SyncPersistentSubscriptionsManager). Maybe we could pass a default UserCredentials to constructor and use it as fallback?

I can prepare a PR for this if you want. If you don't want this feature then just close this issue.

Add psalm

This can also make some interfaces obsolete, like EventAppearedOnSubscription and SubscriptionDropped, because we can have psalm check for correct callables. There's a downside as this is "only" checked with a static analysis tool and not at runtime directly, on the other we can remove quite some code and for end-users it's was more comfortable to just pass a callable, compared to writing a new class and implementing some interface.

see:
https://github.com/prooph/event-store-client/blob/master/src/Internal/EventStoreNodeConnection.php#L642-L643

and:
https://github.com/prooph/event-store-client/blob/master/examples/demo-subscribe-to-stream.php#L49-L72

Note: This has to be done in event-store main repository as well.

Connecting to cluster does not work

Steps to reproduce:

cd docker/local-3-node-dns-cluster
docker-compose up -d

I have to add the following to docker/unittest/docker-compose.yml:

services:
  php:
[...]
#    depends_on:
#      - eventstore

networks:
  clusternetwork:
    external:
      name: local-3-node-dns-cluster_clusternetwork

I have to adjust the example as it gives the following exception right now:

/app/examples # php demo-async-dns-cluster.php 

Fatal error: Uncaught Prooph\EventStoreClient\Exception\InvalidArgumentException: Must specify uri or gossip seeds in /app/src/EventStoreAsyncConnectionFactory.php:138
Stack trace:
#0 /app/src/EventStoreAsyncConnectionFactory.php(163): Prooph\EventStoreClient\EventStoreAsyncConnectionFactory::createFromUri(NULL, Object(Prooph\EventStoreClient\ConnectionSettings), 'dns-cluster-con...')
#1 /app/examples/demo-async-dns-cluster.php(27): Prooph\EventStoreClient\EventStoreAsyncConnectionFactory::createFromSettings(Object(Prooph\EventStoreClient\ConnectionSettings), 'dns-cluster-con...')
#2 [internal function]: Prooph\EventStoreClient\{closure}('a', NULL)
#3 /app/vendor/amphp/amp/lib/Coroutine.php(39): Generator->current()
#4 /app/vendor/amphp/amp/lib/Loop/Driver.php(119): Amp\Coroutine->__construct(Object(Generator))
#5 /app/vendor/amphp/amp/lib/Loop/Driver.php(70): Amp\Loop\Driver->tick()
#6 /app/vendor/amphp/amp/lib/Loop.php(76): Amp\Loop\Driver->run()
#7 /app/examples/demo-async-dns-cluster.php(102): Amp\Loop::run(Object(Clo in /app/src/EventStoreAsyncConnectionFactory.php on line 138

After changing it to this:

    $builder = new ConnectionSettingsBuilder();
    $builder->setClusterDns('escluster.net');
    $builder->setClusterGossipPort(2112); # not 2113 as the example has right now

    $connection = EventStoreAsyncConnectionFactory::createFromConnectionString(
        'ConnectTo=discover://escluster.net:2113',
        $builder->build(),
        'dns-cluster-connection'
    );

the output is this:

/app # php examples/demo-async-dns-cluster.php 
connection closed

Fatal error: Uncaught Prooph\EventStoreClient\Exception\CannotEstablishConnectionException: Cannot resolve target end point in /app/src/Internal/EventStoreConnectionLogicHandler.php:245
Stack trace:
#0 /app/vendor/amphp/amp/lib/Failure.php(26): Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->Prooph\EventStoreClient\Internal\{closure}(Object(Prooph\EventStoreClient\Exception\ClusterException), NULL)
#1 /app/vendor/amphp/amp/lib/Internal/Placeholder.php(122): Amp\Failure->onResolve(Object(Closure))
#2 /app/vendor/amphp/amp/lib/Internal/Placeholder.php(151): Amp\Coroutine->resolve(Object(Amp\Failure))
#3 /app/vendor/amphp/amp/lib/Coroutine.php(93): Amp\Coroutine->fail(Object(Prooph\EventStoreClient\Exception\ClusterException))
#4 /app/vendor/amphp/amp/lib/Internal/Placeholder.php(127): Amp\Coroutine->Amp\{closure}(Object(Prooph\EventStoreClient\Exception\ClusterException), NULL)
#5 /app/vendor/amphp/amp/lib/Delayed.php(20): Amp\Delayed->resolve(NULL)
#6 /app/vendor/amphp/amp/lib/Loop/NativeDriver.php(101): in /app/src/Internal/EventStoreConnectionLogicHandler.php on line 245

Bug in tests using lib-uv

Allow connection settings in connection string

Add new scavenge feature

see EventStore/documentation#276

Should be integrated in the docs.

[Help needed] Trying to understand subsciptions

I am currently writing a PHP project using GYES as the data storage.

I am trying to make a simple read model based on users that register in my application.

In the Event Store I have activated the $by_category projection. I have also created a persistent subscription for the $ce-user stream.

Starting from this example provided by you guys, I created a simple script that connects to the subscription and processes the events.

However I am confused. The $ce-user stream contains all the events that have been triggered for streams of the form "user-id". Events with types like "UserCreate" or "UserEmailChanged". However when I run the script the events that I get in my \Prooph\EventStore\Async\EventAppearedOnPersistentSubscription specific implementation are of the type "$>" and contain data like "0@user-483e374c-2008-3965-b59b-c8c11c9d6183" which is obviously a reference to the user stream that was involved in another type of event.

I assumed that by subscribing to the $ce-user stream I would be receiving the events that were triggered on those specific streams. Can you please help me with what I am doing wrong?

Projection reset issues

Here I'm not really sure what's wrong. When trying reset for the first time I got this error:

In SyncProjectionsManager.php line 308:
                                                                                                                                 
  [Symfony\Component\Debug\Exception\FatalThrowableError]                                                                        
  Return value of Prooph\EventStoreClient\Projections\SyncProjectionsManager::reset() must be of the type string, null returned

But I never saw it since. After that the reset method started failing because of timeouts. However the projection is always reset - much sooner than how long the command is blocking in fact. So it's like the client never receives a response but otherwise everything is ok? What's confusing me even more it that there are two different timeout errors:

With timeout set to 10000 I get this:

In DefaultClient.php line 401:
                                               
  Allowed transfer timeout exceeded: 10000 ms

But with timeout set to 60000 I get this (though it doesn't take 60 seconds for this to appear):

In ProjectionsClient.php line 640:
                                                                                                                                             
  Server returned 408 (Server was unable to handle request in time) for POST on http://127.0.0.1:2113/projection/$by_category/command/reset

If I set the timeout to 1000 and put a try { ... } catch (\Throwable $e) {} to prevent blocking and suppress timeout exceptions then reset seems to work as intended.

Support EventStore v6

support gRPC client as well?

Add ProjectionsManager::reset method

Remove type=JS for projections

... because we will not implement a server in pure PHP.

Possible bug when trying to use the ProjectionsManager

So I have the following code:

$userCredentials = new UserCredentials('admin', 'changeit');
$httpEndpoint = new EndPoint('172.18.0.2', '2133');
$projectionManager = new ProjectionsManager($httpEndpoint, 1000);
yield $projectionManager->enableAsync('$by_category', $userCredentials);

The code above results in Fatal error: Uncaught Amp\Socket\ConnectException: Connection to tcp://172.18.0.2:2133/ refused in /var/www/html/vendor/amphp/artax/lib/DefaultClient.php on line 424

It seems that although I am trying to use the HTTP API, the client is trying to connect via TCP.

Doing a little debugging I found that you get to \Amp\Artax\HttpSocketPool::checkout wkith the correct URI http://172.18.0.2:2133 but it passes through the next blocks of code where the proxy should be set up. Then it reaches line 77, enters the if because no proxy is detected and attempts to connect via TCP (line 78).

Any idea on how to get this working?

RC not compatible with any release of "prooph/event-sourcing"

The proposed RC depends on "dev-master" of "prooph/event-store". However the latest release of "prooph/event-souring" (even dev-master) require "prooph/event-store" as "^7.0". Therefore it is not possible to install both at the same time. I had to resort to installing "1.0.0-beta-8" that does not have an unrestricted dependency.

ConnectionClosed exception

Our command that connects to persistent subscription to project events into a SQL database sometimes fails with Prooph\EventStore\Exception\ConnectionClosed.

Here is the relevant part of the stack trace:

In AbstractSubscriptionOperation.php line 250:
                                                  
  [Prooph\EventStore\Exception\ConnectionClosed]  
  Connection was closed                           
                                                  

Exception trace:
 () at .../vendor/prooph/event-store-client/src/ClientOperations/AbstractSubscriptionOperation.php:250
 Prooph\EventStoreClient\ClientOperations\AbstractSubscriptionOperation->connectionClosed() at .../vendor/prooph/event-store-client/src/Internal/SubscriptionsManager.php:92
 Prooph\EventStoreClient\Internal\SubscriptionsManager->purgeSubscribedAndDroppedSubscriptions() at .../vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:405
 Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->tcpConnectionClosed() at .../vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:170
 Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->Prooph\EventStoreClient\Internal\{closure}() at .../vendor/prooph/event-store-client/src/Internal/MessageHandler.php:38
 Prooph\EventStoreClient\Internal\MessageHandler->handle() at .../vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:190
 Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->enqueueMessage() at .../vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:338
 Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->Prooph\EventStoreClient\Internal\{closure}() at .../vendor/prooph/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:172
 Prooph\EventStoreClient\Transport\Tcp\TcpPackageConnection->Prooph\EventStoreClient\Transport\Tcp\{closure}() at n/a:n/a
 Generator->throw() at .../vendor/amphp/amp/lib/Coroutine.php:73
 Amp\Coroutine->Amp\{closure}() at .../vendor/amphp/amp/lib/Failure.php:29
 Amp\Failure->onResolve() at .../vendor/amphp/amp/lib/Coroutine.php:103
 Amp\Coroutine->__construct() at .../vendor/amphp/amp/lib/Loop/Driver.php:123
 Amp\Loop\Driver->tick() at .../vendor/amphp/amp/lib/Loop/Driver.php:72
 Amp\Loop\Driver->run() at .../vendor/amphp/amp/lib/Loop.php:84
 Amp\Loop::run() at .../src/Module/Core/Console/ConnectToPersistentSubscriptionCommand.php:147

I checked some other similar issues and as far as I can tell it seems I need to implement a reconnecting logic here. Can you give me some advice how to do it? The async code confuses me and I'm not even sure if I can reuse the same EventStoreConnection instance or if I need a new one. Once I understand it I'll gladly send a PR to improve the example.

PersistentSubscriptionSettingsBuilder requires all settings in constructor

It seems not logical to have PersistentSubscriptionSettingsBuilder require the same settings that PersistentSubscriptionSettings does - what's the benefit of using builder with all the setters inside...
I think it should have the same structure as ConnectionSettingsBuilder with defaults set to variables and no constructor args.

If that makes sense I can create a PR for it, thanks.

EventAppearedOnCatchupSubscription uses internal class and non-interface

Hi, another thing I found is in EventAppearedOnCatchupSubscription. The __invoke() method takes an Prooph\EventStoreClient\Internal\EventStoreCatchUpSubscription but that class is marked as @internal in its PHPDoc. That is triggering a warning when the interface is implemented outside the package, since you have to type hint that class to implement the interface. Also the second parameter ResolvedEvent is relying on the Prooph\EventStoreClient\ResolvedEvent implementation rather than the Prooph\EventStoreClient\Internal\ResolvedEvent interface (the interface is also in the Internal namespace though it doesn't have @internal in its PHPDoc).

Should I not be implementing EventAppearedOnCatchupSubscription, though it is required to be able to use EventStoreConnection->subscribeToStreamFromAsync(). Is there another way? Thank you!

Persistent subscription doesn't handle events fast enough

I have the situation where I have a persistent subscription which receives events. I have 5 events created in my stream so they arrive immediately (buffer size of 5) when I connect. The first event enters my code and gets dumped. The other events never arrive and are retried later.

When I change the buffer size to 1 then all works well.

This is my code:

    public function consume(int $timeout = 0, int $maxItems = 0): void
    {
        $this->connection->connectAsync();

        $this->connection->connectToPersistentSubscriptionAsync(
            $this->stream,
            $this->subscriptionName,
            function (
                EventStorePersistentSubscription $subscription,
                ResolvedEvent $event,
                int $retry
            ) use ($timeout, $maxItems): Promise {
                dump((string) $event->event()->eventId());
                return new Success();
            },
            null,
            5,
            true,
            $this->credentials
        );
    }

        $builder = new ConnectionSettingsBuilder();
        $builder->enableVerboseLogging();
        $builder->useConsoleLogger();

        $this->connection = EventStoreConnectionBuilder::createAsyncFromIpEndPoint(
            new IpEndPoint(getenv('EVENT_STORE_HOST'), (int) getenv('EVENT_STORE_TCP_PORT')),
            $builder->build()
        );

This is the console output (heartbeat events removed):

[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message StartConnectionMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': startConnection
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': discoverEndPoint
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message EstablishTcpConnectionMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': EstablishTcpConnection to [component-event-store:1113]
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message StartPersistentSubscriptionMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': StartSubscription enqueue ConnectToPersistentSubscription, StreamId: stream5b62c2b0043946.75821726, ResolveLinkTos: no, GroupName: subscription5b62c2b0043a12.27977132, BufferSize: 5, SubscriptionId: , MaxRetries: 10, Timeout: 7000
[2018-08-02 08:37:04] event-store-client.debug: TcpPackageConnection: connected to [component-event-store:1113, a40e31f36c8e43879a9da81b4672e0bb]
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message TcpConnectionEstablishedMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': TCP connection to [component-event-store:1113, a40e31f36c8e43879a9da81b4672e0bb] established
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package ClientIdentified, cdcd448024ca43df9b6aaf0f4625601d
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': StartSubscription SUBSCRIBING Subscription ConnectToPersistentSubscription (e5ec638d650547fd99cc654a1179a185): StreamId: stream5b62c2b0043946.75821726, ResolveLinkTos: no, GroupName: subscription5b62c2b0043a12.27977132, BufferSize: 5, SubscriptionId: , is subscribed: no, retry count: 0, created: 2018-08-02T08:37:04.055498Z, last updated: 2018-08-02T08:37:04.131925Z
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionConfirmation, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:04] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: subscribed at CommitPosition: 3422620, EventNumber: 4
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION Subscribed (SubscriptionConfirmation), 
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:04] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 0, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:04] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 1, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:04] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 2, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:04] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 3, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:04] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 4, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:04] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
"d9929fe3-228d-a645-9ffd-2fecad6321f4"
[2018-08-02 08:37:04] event-store-client.debug: Persistent Subscription to stream5b62c2b0043946.75821726: processed event (stream5b62c2b0043946.75821726, 0, Tests\Mock\TestDomainEvent @ 0)




[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:35] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 1, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:35] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 2, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:35] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 3, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:37:35] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 4, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:37:35] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
"ce0d29fd-9c71-6944-91b6-b7230bcdf965"
[2018-08-02 08:37:35] event-store-client.debug: Persistent Subscription to stream5b62c2b0043946.75821726: processed event (stream5b62c2b0043946.75821726, 1, Tests\Mock\TestDomainEvent @ 1)
"ba48670b-54eb-da4d-a0f8-4ac6e16b6bb4"
[2018-08-02 08:37:35] event-store-client.debug: Persistent Subscription to stream5b62c2b0043946.75821726: processed event (stream5b62c2b0043946.75821726, 2, Tests\Mock\TestDomainEvent @ 2)




[2018-08-02 08:38:05] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:38:05] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:38:05] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 3, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:38:05] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
[2018-08-02 08:38:05] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': enqueing message HandleTcpPackageMessage
[2018-08-02 08:38:05] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage connId a40e31f36c8e43879a9da81b4672e0bb, package PersistentSubscriptionStreamEventAppeared, e5ec638d650547fd99cc654a1179a185
[2018-08-02 08:38:05] event-store-client.debug: Subscription e5ec638d650547fd99cc654a1179a185 to stream5b62c2b0043946.75821726: event appeared (stream5b62c2b0043946.75821726, 4, Tests\Mock\TestDomainEvent @ <null>)
[2018-08-02 08:38:05] event-store-client.debug: EventStoreNodeConnection '62c98317776b4b4f81b9a19102ff55e9': HandleTcpPackage e5ec638d650547fd99cc654a1179a185 SUBSCRIPTION DECISION DoNothing (StreamEventAppeared), 
"3c463f4d-9f2e-0c48-92bd-df08e935bdd4"
[2018-08-02 08:38:05] event-store-client.debug: Persistent Subscription to stream5b62c2b0043946.75821726: processed event (stream5b62c2b0043946.75821726, 3, Tests\Mock\TestDomainEvent @ 3)
"d8b3d541-c800-1a4b-b82d-775b57614540"
[2018-08-02 08:38:05] event-store-client.debug: Persistent Subscription to stream5b62c2b0043946.75821726: processed event (stream5b62c2b0043946.75821726, 4, Tests\Mock\TestDomainEvent @ 4)

Subscription settings:

Graceful stop on SIGTERM

Hi,

Subscribing to a stream works great, but I'm now trying to implement some logic so the process can stop gracefully if it receives a SIGTERM. Amphp has Loop::onSignal() for that. In my onSignal callback I can do a stop() on all the subscriptions that are running. It looks however like that only stops the listeners for the subscription, but of course in a non-blocking way. Basically when a SIGTERM is received I want to wait until all subscriptions are dropped and all event appeared's are resolved, then close the connection and stop the loop. Is there a way to get all the event appeared promises from a subscription so I can wrap them in a wait(), since I think wait($subscription->drop()) won't wait for the event appeared to resolve, does it? Or should I take a different approach to handle a graceful termination of the process?

Unit test problem

Why is ProophTest\EventStoreClient\PersistentSubscriptionManagement\persistent_subscription_manager::can_replay_parked_messages failing sometimes with Failed asserting that false is true.? Need to investigate.

Add ACL security tests

Imposibility to edit native projections

Currently it's impossible to use SyncProjectionsManager / AsyncProjectionsManager to update the query of a native projection such as $by_category because ProjectionsClient::updateQuery() always adds &type=JS which breaks the native projection.

I would send a PR but I'm unsure how do you want to solve this so let's discuss first.

Issue with simple examples and event store 5

Hello I tried to follow the documentation of eventstore. With the idea in mind of adding PHP aside of .net & jvm examples 💪 .

But event-store-client simple usage seems to have issues:

docker run --name eventstore-node -it -p 2113:2113 -p 1113:1113 eventstore/eventstore

\Amp\Loop::run(function () {
    $connection = EventStoreConnectionFactory::createFromUri(Uri::fromString('tcp://admin:changeit@localhost:1113'));

    // issue 1: onConnected is never fired in this case
    // Same for only connection and closing...
    $connection->onConnected(function (): void {
        echo 'connected' . PHP_EOL;
    });

    $connection->onClosed(function (): void {
        echo 'connection closed' . PHP_EOL;
    });

    yield $connection->connectAsync();

    // Example from official doc, translated to PHP, does not work here.
    $streamName = 'newstream';
    $eventType = 'event-type';
    $data = '{ "a": "1" }';
    $metadata = '{}';
    $eventPayload = new EventData(EventId::generate(), $eventType, true, $data, $metadata);
    yield $connection->appendToStreamAsync($streamName, ExpectedVersion::ANY, [$eventPayload]);

    $connection->close();
});

And the only thing I get is an exeception/failure:

connection closed
PHP Fatal error:  Uncaught Prooph\EventStoreClient\Exception\ConnectionClosedException: Connection 'faadad837aaac842830b6957702454ba' was closed in eventstore/vendor/prooph/event-store-client/src/Exception/ConnectionClosedException.php:20
Stack trace:
#0 eventstore/vendor/prooph/event-store-client/src/Internal/OperationsManager.php(72): Prooph\EventStoreClient\Exception\ConnectionClosedException::withName()
#1 eventstore/vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php(280): Prooph\EventStoreClient\Internal\OperationsManager->cleanUp()
#2 eventstore/vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php(357): Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->closeConnection()
#3 eventstore/vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHan in eventstore/vendor/prooph/event-store-client/src/Exception/ConnectionClosedException.php on line 20

I sorry if I made something wrong. I tried to go on gitter but it seems there's nobody there.

[edit]
After turning on the debug, it seems that I'm missing the \ProtobufMessage class.

[2020-05-01T17:18:47.859751+02:00] event-store-client.debug: TcpPackageConnection: [localhost:1113, 119b2ddd3191394eb010def00cb68ab3]: Error when processing TcpPackage Authenticated: Class 'ProtobufMessage' not found. Connection will be closed

How? Why? o.o I can't understand what should provide this class..

Upgrade to PHP 7.4 (property typehints)

Vote

yes: 👍
no: 👎

v1.0.0-beta-9 requires prooph/event-store dev-master instead of v8.0.0-beta-1

Hi,

Just tried to update to v1.0.0-beta-9 but composer started complaining because it depends on "prooph/event-store": "dev-master" instead of v8.0.0-beta-1. This is more of a FYI. I solved it by adding in the composer.json of my root project:

"prooph/event-store": "v8.0.0-BETA-1 as dev-master",

Protobuf dependency

Thanks for your work.

I saw that Protobuf version has been downgraded from v3 to v2. What is the reason?

Also, do you plan to make protobuf optional so we can use another strategy (for example, a pure PHP userland alternative)?

php-fpm "oops, unknown child exited with 1"

Hi,

I've been playing around with this EventStore client a bit. I've tried various other HTTP and TCP clients (like FriendsOfOuro and Rxnet) but they all had problems that were a no-go for me (HTTP implementations have to do active polling which adds massive overhead and latency and RxPHP silently eats any exceptions thrown in an onError). So far I'm really liking this EventStore TCP, you've done an amazon job on it! :)

One issue I've seen so far is though is that I'm constantly seeing the following in my PHP-FPM logs:

ALERT: oops, unknown child (117) exited with code 1. Please open a bug report (https://bugs.php.net).

I've done some deep-dive debugging with XDebug and it looks like there's nothing actually going wrong. It's just that Amphp spawns a child process and the alert is caused by Amp\Process\Internal\Posix\Runner->kill() that gets called during destruction when the child process isn't needed anymore. This does a proc_terminate(), which causes a ChannelException in the process-runner.php child process which then does an exit(1). At that point the child process isn't actually doing anything any more though, so everything works and nothing is going wrong. It is however not a very nice alert to have scattered in the logs.

I'm not very familiar with Amphp though, is this normal behavior, is prooph/event-store-client missing something so that Amphp can do a graceful shutdown of the child process instead of having to forcefully kill it, or am I implementing the client wrong?

My two test implementations (that both have the same issue) are as follows:

To write to a stream:

Loop::run(function () {
    yield $this->eventStore->connectAsync();
    yield $this->eventStore->appendToStreamAsync(...);
    Loop::stop();
});

Note that I have noticed that if I don't do a $this->eventStore->close() or Loop::stop(), the process will get stuck in the event loop forever doing heartbeats. Is that expected behavior? I don't necessarily want to close the connection because if I need it again later it's a waste to have to re-open it, but I'm also not sure if doing Loop::stop() is the right approach, since everything is done asynchronously I do want to make sure when the loop stops all events have been written to the stream and not risk stopping the loop before that has happened.

And to read from a stream:

Loop::run(function () {
    yield $this->eventStore->connectAsync();
    yield $this->eventStore->subscribeToStreamFromAsync(...);
    Loop::stop();
});

Note that the Loop::stop() here is just for debugging so I could check if in this case the child process would exit with exit(1) as well and it does. The end goal of the subscription is of course to keep it running and not close the connection, so in this case I do want the Loop to continue running and waiting for new events, in this scenario it shouldn't stop.

Hopefully you can shed some light on what's going on here, my guess is that I'm implementing the client wrong :). Thank you!

Reconnecting for subscriptions in a cluster fails

When using service discovery, connecting to a persistent subscription fails. I'll try to explain what happens:

Discovery starts, ES responds with the 'best choice', which is usually a slave node
The ConnectToPersistentSubscription call is made
ES responds with a NotHandled - NotMaster package
The client disconnects
The client tries to remove the active subscription, but since no active subscription was made, that fails.
Client is killed (though I think this is done by Kubernetes in our case)

The entire log is here:
https://gist.github.com/pkruithof/e62baf50f3b1e1334b4929100fdf70e7

Implement PersistentSubscriptions Manager

Methods:

list
describe
replayParkedMessages

Best connection methodology on K8S

I am struggling finding the best way to connect to an ES running on K8S in a cluster formation of 2. I was not able to connect properly in any way apart from using 'discover' which resulted though in 'HEARTBEAT TIMEOUT at pkgNum ...' errors until the max retry attempts are reached.

Default UserCredentials

Since commit 0d4d18d all the *Manager classes support passing default UserCredentials. The main API for async communication (Prooph\EventStoreClient\Internal\EventStoreNodeConnection) however does not.

Your old comment in #55 suggests that this might have been supported before though - I'm not sure...

Anyway I'd like open some discussion and sort this out. I can send a PR but I'm not sure whether the default credentials are wanted and if so then whether they should be added as another argument to EventStoreNodeConnection::__construct() or rather into Prooph\EventStoreClient\ConnectionSettings.

Outdated readme

I wanted to work on a pull request but I need to be able to run the tests. The readme says to use ./run-node.sh --run-projections=all --mem-db but there is no run-node.sh file. Please update the readme accordingly.

Output after the loop is closed

Below is my code that creates several persistent subscriptions. When I have verbose logging enabled and use the console logger on my event store client connection then this gives me this error:

Fatal error: Uncaught Amp\ByteStream\ClosedException: The stream is not writable in /app/vendor/amphp/byte-stream/lib/ResourceOutputStream.php:164
Stack trace:
#0 /app/vendor/amphp/byte-stream/lib/ResourceOutputStream.php(144): Amp\ByteStream\ResourceOutputStream->send('[2018-11-15 13:...', false)
#1 /app/vendor/amphp/log/src/StreamHandler.php(56): Amp\ByteStream\ResourceOutputStream->write('[2018-11-15 13:...')
#2 /app/vendor/monolog/monolog/src/Monolog/Handler/AbstractProcessingHandler.php(39): Amp\Log\StreamHandler->write(Array)
#3 /app/vendor/monolog/monolog/src/Monolog/Logger.php(344): Monolog\Handler\AbstractProcessingHandler->handle(Array)
#4 /app/vendor/monolog/monolog/src/Monolog/Logger.php(623): Monolog\Logger->addRecord(100, 'EventStoreNodeC...', Array)
#5 /app/vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php(926): Monolog\Logger->debug('EventStoreNodeC...')
#6 /app/vendor/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php(184): Prooph\EventStoreClient\ in /app/vendor/amphp/byte-stream/lib/ResourceOutputStream.php on line 164

Which is caused by the __destruct function on the EventStoreAsyncNodeConnection class which closes the connection and then wants to output some debug output. Manually closing the connection inside the loop doesn't help because the __destruct doesn't check if it's already closed.

    public function execute(InputInterface $input, OutputInterface $output): int
    {
        $output->writeln('Create subscriptions');

        Loop::run(function () use ($output): Generator {
            yield $this->connection->connectAsync();

            foreach ($this->subscriptions as $subscription) {
                $name = (string) $subscription;

                try {
                    $result = yield $this->connection->createPersistentSubscriptionAsync(
                        $subscription->getStream(),
                        $subscription->getGroupName(),
                        $subscription->getSettings()
                    );

                    $output->writeln(
                        sprintf('=> <comment>%s</comment>: <comment>%s</comment>', $name, $result->status()->name())
                    );
                } catch (Throwable $error) {
                    $output->writeln(
                        sprintf('=> <comment>%s</comment>: <error>%s</error>', $name, $error->getMessage())
                    );
                }
            }

            Loop::stop();
        });

        $output->writeln('Subscriptions created');

        return 0;
    }

[RFC] Adding PHPdoc to generate API docs

Do you think it's a bad idea?

examples/demo-subscribe-to-all.php throwing exception

When running this script I'm getting the error below. https://github.com/prooph/event-store-client/blob/master/examples/demo-subscribe-to-all.php

This happens with Event Store V4 and V5. I've also tried the suggestion here #86 to change the server config #86

connection closed
PHP Fatal error:  Uncaught Prooph\EventStore\Exception\ConnectionClosed: Connection 'e5bbacd6a74b5e45b71a200d97e6efbe' was closed in C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store\src\Exception\ConnectionClosed.php:20
Stack trace:
#0 C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store-client\src\Internal\SubscriptionsManager.php(54): Prooph\EventStore\Exception\ConnectionClosed::withName('e5bbacd6a74b5e4...')
#1 C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store-client\src\Internal\EventStoreConnectionLogicHandler.php(284): Prooph\EventStoreClient\Internal\SubscriptionsManager->cleanUp()
#2 C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store-client\src\Internal\EventStoreConnectionLogicHandler.php(526): Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->closeConnection('Reconnection li...')
#3 C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store-client\src\Internal\EventStoreConnectionLogicHandler.php(200): Prooph\EventStoreClient\Internal\EventStoreConnectionLogicHandler->timerTick()
#4 C:\xampp in C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store\src\Exception\ConnectionClosed.php on line 20

Fatal error: Uncaught Prooph\EventStore\Exception\ConnectionClosed: Connection 'e5bbacd6a74b5e45b71a200d97e6efbe' was closed in C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store\src\Exception\ConnectionClosed.php on line 20

Prooph\EventStore\Exception\ConnectionClosed: Connection 'e5bbacd6a74b5e45b71a200d97e6efbe' was closed in C:\xampp\htdocs\wa-next-app\vendor\prooph\event-store\src\Exception\ConnectionClosed.php on line 20

Call Stack:
    0.0004     421328   1. {main}() C:\xampp\htdocs\wa-next-app\all_stream.php:0
    0.0168    1720488   2. Amp\Loop::run() C:\xampp\htdocs\wa-next-app\all_stream.php:60
    0.0172    1731304   3. Amp\Loop\NativeDriver->run() C:\xampp\htdocs\wa-next-app\vendor\amphp\amp\lib\Loop.php:84
    2.4435    6141976   4. Amp\Loop\NativeDriver->tick() C:\xampp\htdocs\wa-next-app\vendor\amphp\amp\lib\Loop\Driver.php:72
    2.4436    6138776   5. Amp\Loop\NativeDriver->error() C:\xampp\htdocs\wa-next-app\vendor\amphp\amp\lib\Loop\Driver.php:130

C:\xampp\htdocs\wa-next-app [accounting-domain +0 ~0 -1 | +7 ~7 -0 !]

Here is the log from the event store:

{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.025100Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "\n{description,-25} {version} ({branch}\/{hashtag}, {timestamp})", "EventProperties": { "description": "ES VERSION:", "version": "5.0.2.0", "branch": "oss-v5.0.2", "hashtag": "5b3d4b0680e938e497673146eaafe290f53726a3", "timestamp": "Thu, 18 Jul 2019 09:14:15 +0400" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.055020Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "{description,-25} {osFlavor} ({osVersion})", "EventProperties": { "description": "OS:", "osFlavor": "Windows", "osVersion": "Microsoft Windows NT 6.2.9200.0" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.055020Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "{description,-25} {osRuntimeVersion} ({architecture}-bit)", "EventProperties": { "description": "RUNTIME:", "osRuntimeVersion": ".NET 4.0.30319.42000", "architecture": 64 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.055020Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "{description,-25} {maxGeneration}", "EventProperties": { "description": "GC:", "maxGeneration": "3 GENERATIONS" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.055020Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "{description,-25} {logsDirectory}", "EventProperties": { "description": "LOGS:", "logsDirectory": "C:\\webstack\\event-store-5\\logs" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.089926Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "{@esOptions}", "EventProperties": { "esOptions": {"defaults":{"Help":"False","Version":"False","Log":"C:\\webstack\\event-store-5\\logs","Config":"","Defines":"System.String[]","WhatIf":"False","DisableHTTPCaching":"False","MonoMinThreadpoolSize":"10","IntIp":"127.0.0.1","ExtIp":"127.0.0.1","IntHttpPort":"2112","ExtHttpPort":"2113","IntTcpPort":"1112","IntSecureTcpPort":"0","ExtTcpPort":"1113","ExtSecureTcpPortAdvertiseAs":"0","ExtSecureTcpPort":"0","ExtIpAdvertiseAs":null,"ExtTcpPortAdvertiseAs":"0","ExtHttpPortAdvertiseAs":"0","IntIpAdvertiseAs":null,"IntSecureTcpPortAdvertiseAs":"0","IntTcpPortAdvertiseAs":"0","IntHttpPortAdvertiseAs":"0","IntTcpHeartbeatTimeout":"700","ExtTcpHeartbeatTimeout":"1000","IntTcpHeartbeatInterval":"700","ExtTcpHeartbeatInterval":"2000","GossipOnSingleNode":"False","Force":"False","ClusterSize":"1","NodePriority":"0","MinFlushDelayMs":"2","CommitCount":"-1","PrepareCount":"-1","AdminOnExt":"True","StatsOnExt":"True","GossipOnExt":"True","DisableScavengeMerging":"False","ScavengeHistoryMaxAge":"30","DiscoverViaDns":"True","ClusterDns":"fake.dns","ClusterGossipPort":"30777","GossipSeed":"System.Net.IPEndPoint[]","StatsPeriodSec":"30","CachedChunks":"-1","ReaderThreadsCount":"4","ChunksCacheSize":"536871424","MaxMemTableSize":"1000000","HashCollisionReadLimit":"100","Db":"C:\\webstack\\event-store-5\\data","Index":null,"MemDb":"False","SkipDbVerify":"False","WriteThrough":"False","Unbuffered":"False","ChunkInitialReaderCount":"5","ProjectionThreads":"3","WorkerThreads":"5","ProjectionsQueryExpiry":"5","FaultOutOfOrderProjections":"False","IntHttpPrefixes":"System.String[]","ExtHttpPrefixes":"System.String[]","EnableTrustedAuth":"False","AddInterfacePrefixes":"True","CertificateStoreLocation":"","CertificateStoreName":"","CertificateSubjectName":"","CertificateThumbprint":"","CertificateFile":"","CertificatePassword":"","UseInternalSsl":"False","DisableInsecureTCP":"False","SslTargetHost":"n\/a","SslValidateServer":"True","AuthenticationType":"internal","AuthenticationConfig":"","DisableFirstLevelHttpAuthorization":"False","PrepareTimeoutMs":"2000","CommitTimeoutMs":"2000","UnsafeDisableFlushToDisk":"False","BetterOrdering":"False","UnsafeIgnoreHardDelete":"False","SkipIndexVerify":"False","IndexCacheDepth":"16","OptimizeIndexMerge":"False","GossipIntervalMs":"1000","GossipAllowedDifferenceMs":"60000","GossipTimeoutMs":"500","EnableHistograms":"False","LogHttpRequests":"False","AlwaysKeepScavenged":"False","SkipIndexScanOnReads":"False","ReduceFileCachePressure":"False","InitializationThreads":"1","StructuredLog":"True","MaxAutoMergeIndexLevel":"2147483647"},"modified":{"RunProjections":"all","StartStandardProjections":"true","ConnectionPendingSendBytesThreshold":"50485760"}} } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.099900Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "Quorum size set to {quorum}", "EventProperties": { "quorum": 1 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.099900Z", "Level": "Info", "Logger": "ProgramBase`1", "Message": "Cannot find plugins path: {pluginsDirectory}", "EventProperties": { "pluginsDirectory": "C:\\webstack\\event-store-5\\plugins" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.192652Z", "Level": "Info", "Logger": "VNodeBuilder", "Message": "{description,-25} {instanceId}", "EventProperties": { "description": "INSTANCE ID:", "instanceId": "e12611a3-653e-41c4-8934-acc674b75b90" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.192652Z", "Level": "Info", "Logger": "VNodeBuilder", "Message": "{description,-25} {path}", "EventProperties": { "description": "DATABASE:", "path": "C:\\webstack\\event-store-5\\data" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.192652Z", "Level": "Info", "Logger": "VNodeBuilder", "Message": "{description,-25} {writerCheckpoint} (0x{writerCheckpoint:X})", "EventProperties": { "description": "WRITER CHECKPOINT:", "writerCheckpoint": 138418629 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.192652Z", "Level": "Info", "Logger": "VNodeBuilder", "Message": "{description,-25} {chaserCheckpoint} (0x{chaserCheckpoint:X})", "EventProperties": { "description": "CHASER CHECKPOINT:", "chaserCheckpoint": 138418629 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.192652Z", "Level": "Info", "Logger": "VNodeBuilder", "Message": "{description,-25} {epochCheckpoint} (0x{epochCheckpoint:X})", "EventProperties": { "description": "EPOCH CHECKPOINT:", "epochCheckpoint": 138323389 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.192652Z", "Level": "Info", "Logger": "VNodeBuilder", "Message": "{description,-25} {truncateCheckpoint} (0x{truncateCheckpoint:X})", "EventProperties": { "description": "TRUNCATE CHECKPOINT:", "truncateCheckpoint": -1 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.246508Z", "Level": "Trace", "Logger": "MessageHierarchy", "Message": "MessageHierarchy initialization took {elapsed}.", "EventProperties": { "elapsed": "00:00:00.0264326" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.610907Z", "Level": "Trace", "Logger": "TFChunk", "Message": "Opened ongoing {chunk} as version {version}", "EventProperties": { "chunk": "C:\\webstack\\event-store-5\\data\\chunk-000000.000000", "version": 3 } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.701594Z", "Level": "Trace", "Logger": "TFChunk", "Message": "CACHED TFChunk {chunk} in {elapsed}.", "EventProperties": { "chunk": "#0-0 (chunk-000000.000000)", "elapsed": "00:00:00.0851156" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.921410Z", "Level": "Info", "Logger": "MiniWeb", "Message": "Starting MiniWeb for {localWebRootPath} ==> {fileSystemRoot}", "EventProperties": { "localWebRootPath": "\/web\/es\/js\/projections", "fileSystemRoot": "C:\\webstack\\event-store-5\\projections" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.921410Z", "Level": "Info", "Logger": "MiniWeb", "Message": "Starting MiniWeb for {localWebRootPath} ==> {fileSystemRoot}", "EventProperties": { "localWebRootPath": "\/web\/es\/js\/projections\/v8\/Prelude", "fileSystemRoot": "C:\\webstack\\event-store-5\\Prelude" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.921410Z", "Level": "Trace", "Logger": "MiniWeb", "Message": "Binding MiniWeb to {path}", "EventProperties": { "path": "\/web\/es\/js\/projections\/{*remaining_path}" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.921410Z", "Level": "Trace", "Logger": "MiniWeb", "Message": "Binding MiniWeb to {path}", "EventProperties": { "path": "\/web\/es\/js\/projections\/v8\/Prelude\/{*remaining_path}" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.933379Z", "Level": "Info", "Logger": "MiniWeb", "Message": "Starting MiniWeb for {localWebRootPath} ==> {fileSystemRoot}", "EventProperties": { "localWebRootPath": "\/web", "fileSystemRoot": "C:\\webstack\\event-store-5\\clusternode-web" } }
{ "PID": "23940", "ThreadID": "1", "Date": "2019-09-26T10:58:57.933379Z", "Level": "Trace", "Logger": "MiniWeb", "Message": "Binding MiniWeb to {path}", "EventProperties": { "path": "\/web\/{*remaining_path}" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:57.933379Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] SYSTEM INIT...", "EventProperties": { "internalHttp": "127.0.0.1:2112" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:57.933379Z", "Level": "Info", "Logger": "TcpServerListener", "Message": "Starting {securityType} TCP listening on TCP endpoint: {serverEndPoint}.", "EventProperties": { "securityType": "Normal", "serverEndPoint": "127.0.0.1:1113" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:57.933379Z", "Level": "Info", "Logger": "HttpAsyncServer", "Message": "Starting HTTP server on [{listenPrefixes}]...", "EventProperties": { "listenPrefixes": "http:\/\/127.0.0.1:2113\/,http:\/\/localhost:2113\/" } }
{ "PID": "23940", "ThreadID": "21", "Date": "2019-09-26T10:58:57.942354Z", "Level": "Info", "Logger": "IndexCommitter", "Message": "TableIndex initialization...", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:57.942354Z", "Level": "Info", "Logger": "HttpAsyncServer", "Message": "HTTP server is up and listening on [{listenPrefixes}]", "EventProperties": { "listenPrefixes": "http:\/\/127.0.0.1:2113\/,http:\/\/localhost:2113\/" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:57.942354Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] Service '{service}' initialized.", "EventProperties": { "internalHttp": "127.0.0.1:2112", "service": "StorageReader" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:57.942354Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] Service '{service}' initialized.", "EventProperties": { "internalHttp": "127.0.0.1:2112", "service": "StorageWriter" } }
{ "PID": "23940", "ThreadID": "21", "Date": "2019-09-26T10:58:57.942354Z", "Level": "Info", "Logger": "IndexCommitter", "Message": "ReadIndex building...", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "21", "Date": "2019-09-26T10:58:58.021147Z", "Level": "Debug", "Logger": "IndexCommitter", "Message": "ReadIndex rebuilding done: total processed {processed} records, time elapsed: {elapsed}.", "EventProperties": { "processed": 8209, "elapsed": "00:00:00.0718118" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.021147Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] Service '{service}' initialized.", "EventProperties": { "internalHttp": "127.0.0.1:2112", "service": "StorageChaser" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.021147Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] SYSTEM START...", "EventProperties": { "internalHttp": "127.0.0.1:2112" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.021147Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] IS UNKNOWN...", "EventProperties": { "internalHttp": "127.0.0.1:2112" } }
{ "PID": "23940", "ThreadID": "9", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "PersistentSubscriptionService", "Message": "Persistent subscriptions received state change to {state}. Stopping listening", "EventProperties": { "state": "Unknown" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: STARTING ELECTIONS.", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={view}) SHIFT TO LEADER ELECTION.", "EventProperties": { "view": 0 } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={view}) VIEWCHANGE FROM [{serverInternalHttp}, {serverId:B}].", "EventProperties": { "view": 0, "serverInternalHttp": "127.0.0.1:2112", "serverId": "e12611a3-653e-41c4-8934-acc674b75b90" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={view}) MAJORITY OF VIEWCHANGE.", "EventProperties": { "view": 0 } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={lastAttemptedView}) SHIFT TO PREPARE PHASE.", "EventProperties": { "lastAttemptedView": 0 } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={view}) PREPARE_OK FROM {nodeInfo}.", "EventProperties": { "view": 0, "nodeInfo": "[127.0.0.1:2112,{e12611a3-653e-41c4-8934-acc674b75b90}](L=138400384,W=138418629,C=138418629,E2@138323389:{fe493248-9ce1-458e-a335-a0f583c58a65})" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={lastAttemptedView}) SHIFT TO REG_LEADER.", "EventProperties": { "lastAttemptedView": 0 } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={lastAttemptedView}) SENDING PROPOSAL CANDIDATE: {formatNodeInfo}, ME: {ownInfo}.", "EventProperties": { "lastAttemptedView": 0, "formatNodeInfo": "[127.0.0.1:2112,{e12611a3-653e-41c4-8934-acc674b75b90}](L=138400384,W=138418629,C=138418629,E2@138323389:{fe493248-9ce1-458e-a335-a0f583c58a65})", "ownInfo": "[127.0.0.1:2112,{e12611a3-653e-41c4-8934-acc674b75b90}](L=138400384,W=138418629,C=138418629,E2@138323389:{fe493248-9ce1-458e-a335-a0f583c58a65})" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Debug", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={view}) ACCEPT FROM [{serverInternalHttp},{serverId:B}] M=[{masterInternalHttp},{masterId:B}]).", "EventProperties": { "view": 0, "serverInternalHttp": "127.0.0.1:2112", "serverId": "e12611a3-653e-41c4-8934-acc674b75b90", "masterInternalHttp": "127.0.0.1:2112", "masterId": "e12611a3-653e-41c4-8934-acc674b75b90" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.037105Z", "Level": "Info", "Logger": "ElectionsService", "Message": "ELECTIONS: (V={view}) DONE. ELECTED MASTER = {masterInfo}. ME={ownInfo}.", "EventProperties": { "view": 0, "masterInfo": "[127.0.0.1:2112,{e12611a3-653e-41c4-8934-acc674b75b90}](L=138400384,W=138418629,C=138418629,E2@138323389:{fe493248-9ce1-458e-a335-a0f583c58a65})", "ownInfo": "[127.0.0.1:2112,{e12611a3-653e-41c4-8934-acc674b75b90}](L=138400384,W=138418629,C=138418629,E2@138323389:{fe493248-9ce1-458e-a335-a0f583c58a65})" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.053061Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...", "EventProperties": { "internalHttp": "127.0.0.1:2112" } }
{ "PID": "23940", "ThreadID": "17", "Date": "2019-09-26T10:58:58.053061Z", "Level": "Debug", "Logger": "PersistentSubscriptionService", "Message": "Persistent subscriptions received state change to {state}. Stopping listening", "EventProperties": { "state": "PreMaster" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.053061Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] IS MASTER... SPARTA!", "EventProperties": { "internalHttp": "127.0.0.1:2112" } }
{ "PID": "23940", "ThreadID": "11", "Date": "2019-09-26T10:58:58.053061Z", "Level": "Debug", "Logger": "PersistentSubscriptionService", "Message": "Persistent subscriptions Became Master so now handling subscriptions", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.053061Z", "Level": "Debug", "Logger": "StorageScavenger", "Message": "Searching for incomplete scavenges on node {nodeEndPoint}.", "EventProperties": { "nodeEndPoint": "127.0.0.1:2113" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.080987Z", "Level": "Debug", "Logger": "StorageScavenger", "Message": "No incomplete scavenges found on node {nodeEndPoint}.", "EventProperties": { "nodeEndPoint": "127.0.0.1:2113" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "StorageScavenger", "Message": "Max age and $ops read permission already set for the {stream} stream.", "EventProperties": { "stream": "$scavenges" } }
{ "PID": "23940", "ThreadID": "18", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "EpochManager", "Message": "=== Writing E{epochNumber}@{epochPosition}:{epochId:B} (previous epoch at {lastEpochPosition}).", "EventProperties": { "epochNumber": 3, "epochPosition": 138418629, "epochId": "100cad82-3693-44b6-ae49-9669474167b2", "lastEpochPosition": 138323389 } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: Starting Projections Core Coordinator. (Node State : {state})", "EventProperties": { "state": "Master" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "PROJECTIONS: Starting Projections Manager. (Node State : {state})", "EventProperties": { "state": "Master" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Starting Projection Manager Response Reader (reads from $projections-$master)", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "18", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "EpochManager", "Message": "=== Update Last Epoch E{epochNumber}@{epochPosition}:{epochId:B} (previous epoch at {lastEpochPosition}).", "EventProperties": { "epochNumber": 3, "epochPosition": 138418629, "epochId": "100cad82-3693-44b6-ae49-9669474167b2", "lastEpochPosition": 138323389 } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Starting Projection Core Reader (reads from $projections-${coreServiceId})", "EventProperties": { "coreServiceId": "df59b5a450434bc3910a0d155ebacbae" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Starting Projection Core Reader (reads from $projections-${coreServiceId})", "EventProperties": { "coreServiceId": "87b7b512b05d43c48393fa958330232d" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.082990Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Starting Projection Core Reader (reads from $projections-${coreServiceId})", "EventProperties": { "coreServiceId": "041026d75e9542d09a0b658bbb00817f" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Resetting Worker Writer", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Resetting Master Writer", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Resetting Master Writer", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "EventReaderCoreService" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "EventReaderCoreService" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "EventReaderCoreService" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "ProjectionCoreService" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "ProjectionCoreService" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "ProjectionCoreService" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.101933Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Resetting Master Writer", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-${coreServiceId})", "EventProperties": { "coreServiceId": "041026d75e9542d09a0b658bbb00817f" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-${coreServiceId})", "EventProperties": { "coreServiceId": "87b7b512b05d43c48393fa958330232d" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Finished Starting Projection Core Reader (reads from $projections-${coreServiceId})", "EventProperties": { "coreServiceId": "df59b5a450434bc3910a0d155ebacbae" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "ProjectionCoreServiceCommandReader" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "ProjectionCoreServiceCommandReader" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Finished Starting Projection Manager Response Reader (reads from $projections-$master)", "EventProperties": {  } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreCoordinator", "Message": "PROJECTIONS: SubComponent Started: {subComponent}", "EventProperties": { "subComponent": "ProjectionCoreServiceCommandReader" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Starting read {stream}", "EventProperties": { "stream": "$projections-$control-100cad82-3693-44b6-ae49-9669474167b2" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Starting read {stream}", "EventProperties": { "stream": "$projections-$control-100cad82-3693-44b6-ae49-9669474167b2" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Starting read {stream}", "EventProperties": { "stream": "$projections-$control-100cad82-3693-44b6-ae49-9669474167b2" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 402, "command": "$response-reader-starting" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 403, "command": "$projection-worker-started" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 404, "command": "$projection-worker-started" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 405, "command": "$projection-worker-started" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.147811Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "PROJECTIONS: Reading Existing Projections from {stream}", "EventProperties": { "stream": "$projections-$all" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "PROJECTIONS: Found the following projections in {stream}: {@projections}", "EventProperties": { "stream": "$projections-$all", "projections": ["$streams","$stream_by_category","$by_event_type","$by_category","$by_correlation_id"] } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "Adding projection {projectionCorrelationId}@{projection} to list", "EventProperties": { "projectionCorrelationId": "d7246104-1a38-4436-9546-78925579a8ce", "projection": "$streams" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "Adding projection {projectionCorrelationId}@{projection} to list", "EventProperties": { "projectionCorrelationId": "9892404c-cd41-432f-ad9f-59cbd0138921", "projection": "$stream_by_category" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "Adding projection {projectionCorrelationId}@{projection} to list", "EventProperties": { "projectionCorrelationId": "ea127e9a-341a-4482-9c04-b01cc9b6855d", "projection": "$by_event_type" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "Adding projection {projectionCorrelationId}@{projection} to list", "EventProperties": { "projectionCorrelationId": "5050e99a-58c3-4c86-80d8-f2f62bfd755b", "projection": "$by_category" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Debug", "Logger": "ProjectionManager", "Message": "Adding projection {projectionCorrelationId}@{projection} to list", "EventProperties": { "projectionCorrelationId": "b4289f98-59fc-4c33-bb9e-77de61a1bf0f", "projection": "$by_correlation_id" } }
{ "PID": "23940", "ThreadID": "20", "Date": "2019-09-26T10:58:58.167757Z", "Level": "Info", "Logger": "ClusterVNodeController", "Message": "========== [{internalHttp}] Sub System '{subSystemName}' initialized.", "EventProperties": { "internalHttp": "127.0.0.1:2112", "subSystemName": "Projections" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.204659Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$create-and-prepare", "workerId": "$projections-$df59b5a4-5043-4bc3-910a-0d155ebacbae", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$create-and-prepare", "workerId": "$projections-$87b7b512-b05d-43c4-8393-fa958330232d", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$create-and-prepare", "workerId": "$projections-$041026d7-5e95-42d0-9a0b-658bbb00817f", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$create-and-prepare", "workerId": "$projections-$df59b5a4-5043-4bc3-910a-0d155ebacbae", "isBusy": true } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$create-and-prepare", "workerId": "$projections-$041026d7-5e95-42d0-9a0b-658bbb00817f", "isBusy": true } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$df59b5a450434bc3910a0d155ebacbae", "eventType": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$87b7b512b05d43c48393fa958330232d", "eventType": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$041026d75e9542d09a0b658bbb00817f", "eventType": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$df59b5a450434bc3910a0d155ebacbae", "eventType": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 0, "command": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 0, "command": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 0, "command": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.213635Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$041026d75e9542d09a0b658bbb00817f", "eventType": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$prepared", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$prepared", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$prepared", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 1, "command": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 1, "command": "$create-and-prepare" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$prepared", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$prepared", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 409, "command": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$start", "workerId": "$projections-$87b7b512-b05d-43c4-8393-fa958330232d", "isBusy": false } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$prepared" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$prepared" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$prepared" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.257517Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 410, "command": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 412, "command": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 413, "command": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 415, "command": "$prepared" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$start", "workerId": "$projections-$041026d7-5e95-42d0-9a0b-658bbb00817f", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$start", "workerId": "$projections-$041026d7-5e95-42d0-9a0b-658bbb00817f", "isBusy": true } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$start", "workerId": "$projections-$df59b5a4-5043-4bc3-910a-0d155ebacbae", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {workerId}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$start", "workerId": "$projections-$df59b5a4-5043-4bc3-910a-0d155ebacbae", "isBusy": true } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$87b7b512b05d43c48393fa958330232d", "eventType": "$start" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 1, "command": "$start" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$041026d75e9542d09a0b658bbb00817f", "eventType": "$start" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 2, "command": "$start" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$df59b5a450434bc3910a0d155ebacbae", "eventType": "$start" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 2, "command": "$start" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$041026d75e9542d09a0b658bbb00817f", "eventType": "$start" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.270482Z", "Level": "Debug", "Logger": "MultiStreamMessageWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$df59b5a450434bc3910a0d155ebacbae", "eventType": "$start" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.297410Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 3, "command": "$start" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.297410Z", "Level": "Debug", "Logger": "ProjectionCoreServiceCommandReader", "Message": "PROJECTIONS: Command received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 3, "command": "$start" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.304393Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$started", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.304393Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$started", "stream": "$projections-$master", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.304393Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 422, "command": "$started" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.304393Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 423, "command": "$started" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.323341Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$started", "stream": "$projections-$master", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.323341Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 427, "command": "$started" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.333314Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$started" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.360243Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$started" } }
{ "PID": "23940", "ThreadID": "27", "Date": "2019-09-26T10:58:58.360243Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$started" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.433048Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$started", "stream": "$projections-$master", "isBusy": true } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.454990Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Scheduling the writing of {command} to {stream}. Current status of Writer: Busy: {isBusy}", "EventProperties": { "command": "$started", "stream": "$projections-$master", "isBusy": false } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.482914Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 435, "command": "$started" } }
{ "PID": "23940", "ThreadID": "24", "Date": "2019-09-26T10:58:58.482914Z", "Level": "Debug", "Logger": "ProjectionManagerResponseReader", "Message": "PROJECTIONS: Response received: {eventNumber}@{command}", "EventProperties": { "eventNumber": 438, "command": "$started" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:58.563698Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$started" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:58.563698Z", "Level": "Debug", "Logger": "ResponseWriter", "Message": "PROJECTIONS: Finished writing events to {stream}: {eventType}", "EventProperties": { "stream": "$projections-$master", "eventType": "$started" } }
{ "PID": "23940", "ThreadID": "8", "Date": "2019-09-26T10:58:58.849932Z", "Level": "Trace", "Logger": "QueuedHandlerThreadPool", "Message": "SLOW QUEUE MSG [{queue}]: {message} - {elapsed}ms. Q: {prevQueueCount}\/{curQueueCount}.", "EventProperties": { "queue": "MonitoringQueue", "message": "SystemInit", "elapsed": 911, "prevQueueCount": 0, "curQueueCount": 3 } }
{ "PID": "23940", "ThreadID": "5", "Date": "2019-09-26T10:58:58.867884Z", "Level": "Trace", "Logger": "MonitoringService", "Message": "Created stats stream '{stream}', code = {result}", "EventProperties": { "stream": "$stats-127.0.0.1:2113", "result": "WrongExpectedVersion" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:59.055383Z", "Level": "Trace", "Logger": "InMemoryBus", "Message": "SLOW BUS MSG [{bus}]: {message} - {elapsed}ms. Handler: {handler}.", "EventProperties": { "bus": "bus", "message": "UnwrapEnvelopeMessage", "elapsed": 49, "handler": "UnwrapEnvelopeHandler" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:59.055383Z", "Level": "Trace", "Logger": "QueuedHandlerMRES", "Message": "SLOW QUEUE MSG [{queue}]: {message} - {elapsed}ms. Q: {prevQueueCount}\/{curQueueCount}.", "EventProperties": { "queue": "Projection Core #0", "message": "UnwrapEnvelopeMessage", "elapsed": 49, "prevQueueCount": 322, "curQueueCount": 575 } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:59.374530Z", "Level": "Trace", "Logger": "InMemoryBus", "Message": "SLOW BUS MSG [{bus}]: {message} - {elapsed}ms. Handler: {handler}.", "EventProperties": { "bus": "bus", "message": "UnwrapEnvelopeMessage", "elapsed": 60, "handler": "UnwrapEnvelopeHandler" } }
{ "PID": "23940", "ThreadID": "26", "Date": "2019-09-26T10:58:59.374530Z", "Level": "Trace", "Logger": "QueuedHandlerMRES", "Message": "SLOW QUEUE MSG [{queue}]: {message} - {elapsed}ms. Q: {prevQueueCount}\/{curQueueCount}.", "EventProperties": { "queue": "Projection Core #1", "message": "UnwrapEnvelopeMessage", "elapsed": 60, "prevQueueCount": 481, "curQueueCount": 736 } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:59.387495Z", "Level": "Trace", "Logger": "InMemoryBus", "Message": "SLOW BUS MSG [{bus}]: {message} - {elapsed}ms. Handler: {handler}.", "EventProperties": { "bus": "bus", "message": "UnwrapEnvelopeMessage", "elapsed": 61, "handler": "UnwrapEnvelopeHandler" } }
{ "PID": "23940", "ThreadID": "25", "Date": "2019-09-26T10:58:59.387495Z", "Level": "Trace", "Logger": "QueuedHandlerMRES", "Message": "SLOW QUEUE MSG [{queue}]: {message} - {elapsed}ms. Q: {prevQueueCount}\/{curQueueCount}.", "EventProperties": { "queue": "Projection Core #0", "message": "UnwrapEnvelopeMessage", "elapsed": 62, "prevQueueCount": 386, "curQueueCount": 642 } }

use Promise\rethrow where applicable

Random test failure

1) ProophTest\EventStoreClient\soft_delete::soft_deleted_stream_allows_recreation_when_expver_no_stream
Failed asserting that false is true.

/home/sasa/code/event-store-client/tests/soft_delete.php:206
/home/sasa/code/event-store-client/tests/soft_delete.php:57
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Coroutine.php:74
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Internal/Placeholder.php:127
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Deferred.php:41
/home/sasa/code/event-store-client/src/ClientOperations/AbstractOperation.php:130
/home/sasa/code/event-store-client/src/ClientOperations/ReadStreamEventsForwardOperation.php:100
/home/sasa/code/event-store-client/src/ClientOperations/AbstractOperation.php:105
/home/sasa/code/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:807
/home/sasa/code/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:169
/home/sasa/code/event-store-client/src/Internal/MessageHandler.php:38
/home/sasa/code/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:183
/home/sasa/code/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:321
/home/sasa/code/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:184
/home/sasa/code/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:101
/home/sasa/code/event-store-client/src/Transport/Tcp/LengthPrefixMessageFramer.php:78
/home/sasa/code/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:212
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Coroutine.php:74
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Internal/Placeholder.php:127
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Deferred.php:41
/home/sasa/code/event-store-client/vendor/amphp/byte-stream/lib/ResourceInputStream.php:94
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Loop/NativeDriver.php:172
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Loop/NativeDriver.php:68
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Loop/Driver.php:130
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Loop/Driver.php:70
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/Loop.php:76
/home/sasa/code/event-store-client/vendor/amphp/amp/lib/functions.php:158
/home/sasa/code/event-store-client/tests/soft_delete.php:60
/home/sasa/code/event-store-client/tests/soft_delete.php:240

Reconnect to persistent subscription after a connection drop

I was testing if my client reconnects to a persistent subscription when it looses it's connection. So I see the Subscription dropped callback being called and I also see the onReconnecting and onConnected callbacks being called. But after it reconnects it won't automatically listen to the persistent subscription. Therefore I moved my entire "connect to the subscription" logic into the onConnected callback.

This seems to work for heartbeat lost reconnects. But not when I restart my eventstore. Then it seems to do the reconnect just fine. But it waits indefinitely for the createPersistentSubscriptionAsync promise. If I look into the server communication then i see this:

Client:

15:01:06 INFO      [app] Connected to the eventstore
15:01:06 DEBUG     [app] EventStoreNodeConnection 'listing:appearance:consume:000000005a8c43e80000000023a2feb3': enqueing message StartOperationMessage
15:01:06 DEBUG     [app] EventStoreNodeConnection 'listing:appearance:consume:000000005a8c43e80000000023a2feb3': StartOperation schedule CreatePersistentSubscription, Stream: ListingFeedItemAppearanceMarkerV1, Group Name: Main, 10, 7000
15:01:06 DEBUG     [app] EventStoreNodeConnection 'listing:appearance:consume:000000005a8c43e80000000023a2feb3': ExecuteOperation package CreatePersistentSubscription, e577b257e8f6674785975c89a8919dbc, Operation CreatePersistentSubscription (e577b257e8f6674785975c89a8919dbc): Stream: ListingFeedItemAppearanceMarkerV1, Group Name: Main, retry count: 0, created: 2019-02-05T15:01:06.905455+00:00, last updated: 2019-02-05T15:01:06.905498+00:00

Server:

event-store      | [00001,09,15:01:06.902] Connection 'external-normal' ({4ef3b3bf-c53a-4de1-9242-4d52bf06b934}) identified by client. Client connection name: 'listing:appearance:consume:000000005a8c43e80000000023a2feb3', Client version: V2.

When I add a sleep before creating the subscription then it seems to work. So it feels like the eventstore just ignores the create request because it's not booted completely yet. I would think that the operation timeout would kick in and throw errors or something.

My code:

        Loop::run(function (): Generator {
            $this->logger->info(
                sprintf('Starting consumer for "%s"', $this->subscription)
            );
 
            yield $this->connection->connectAsync();
 
            $this->connection->onReconnecting(function () {
                $this->logger->info('Reconnecting to the eventstore');
            });
            $this->connection->onConnected(function () {
                $this->logger->info('Connected to the eventstore');
 
                // Workaround to connect to the right node in a cluster.
                $promise = $this->connection->createPersistentSubscriptionAsync(
                    $this->subscription->getStream(),
                    $this->subscription->getGroupName(),
                    $this->subscription->getSettings()
                );
 
                $promise->onResolve(function () {
                    $eventAppeared = $this->createEventAppearedHandler();
 
                    $promise = $this->connection->connectToPersistentSubscriptionAsync(
                        $this->subscription->getStream(),
                        $this->subscription->getGroupName(),
                        $eventAppeared,
                        $this->createSubscriptionDroppedHandler(),
                        $this->bufferSize,
                        false
                    );
 
                    $promise->onResolve(function (?Throwable $exception, ?Subscription $subscription) use ($eventAppeared) {
                        if ($exception) {
                            $this->logger->critical($exception->getMessage());
                        }
 
                        if ($subscription) {
                            $eventAppeared->init($subscription);
                        }
                    });
                });
            });
        });

Recheck SubscriptionDrop / LiveProcessing

[Feature request] Throw error when callback doesn't return a promise

    $subscription = $connection->connectToPersistentSubscriptionAsync(
        'foo-bar',
        'test-persistent-subscription',
        function (EventStorePersistentSubscription $subscription, ResolvedEvent $event, int $retry) use ($stopWatch, &$i)/*: Promise*/ {
            echo 'incoming event: ' . $event->originalEventNumber() . '@' . $event->originalStreamName() . PHP_EOL;
            echo 'data: ' . ($event->originalEvent() ? $event->originalEvent()->data() : '<null>') . PHP_EOL;
            echo 'retry: ' . $retry . PHP_EOL;
            echo 'no: ' . ++$i . ', elapsed: ' . $stopWatch->elapsed() . PHP_EOL;

            //return new Success();
        },
        function () {
            echo 'dropped' . PHP_EOL;
        },
        10,
        true,
        new UserCredentials('admin', 'changeit')
    );

Above example doesn't return Success. An error should be thrown in such situation because the callback doesn't return a promise.

What happens now is:

Amp\ByteStream\StreamException: The stream was closed by the peer

/app/vendor/amphp/byte-stream/lib/ResourceOutputStream.php:178
/app/vendor/amphp/byte-stream/lib/ResourceOutputStream.php:141
/app/vendor/amphp/socket/src/Socket.php:69
/app/vendor/prooph/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:171
/app/vendor/amphp/amp/lib/Coroutine.php:39
/app/vendor/amphp/amp/lib/Loop/Driver.php:119
/app/vendor/amphp/amp/lib/Loop/Driver.php:70
/app/vendor/amphp/amp/lib/Loop.php:76
/app/src/Subscription/TcpCompetingConsumer.php:121
/app/tests/Subscription/TcpCompetingConsumerTest.php:224

Because the server will not send the heartbeat response.

Real world example?

I want to try and use this in my application. Basically I need (or rather think I need) some API similar to AggregateRepository::getAggregateRoot() / AggregateRepository::saveAggregateRoot() from old prooph/event-sourcing.

Before I start inventing a wheel, is there some example how to use this with real-world aggregates? I don't quite care if the aggregates are based on prooph/event-sourcing, proophsoftware/event-machine or whatever else.

If there is no such example, can you give me some pseudo-code what is the intended usage? Just something so that I don't have to start completely blind.

Thanks.

Split EventStore*Connection interfaces

Based on the questions in the chat: https://gitter.im/prooph/improoph?at=5b67641a6d45752f989370e8

I'm wondering if we can split the Connection interfaces and define smaller scopes like reading from streams, writing to streams and subscription api.

My idea is that if we have a subset of the methods defined in a smaller interface that is used by the AggregateRepository we could use composition for Snapshotter, Upcaster, Publisher instead of the current plugin system.

Something like this:

$connection = new UpcastingConnection(
  $upcaster,
  new SnapshotConnection(
    $snapshotter,
    new PublishingConnection(
      $publisher,
      new EventStoreConnection($connectionSettings)
    )    
  )
);

$repository = new AggregateRepository($connection);

Random test failure #2

1) ProophTest\EventStoreClient\connect_to_existing_persistent_subscription_with_start_from_x_set_and_events_in_it::the_subscription_gets_the_written_event_as_its_first_event
Failed asserting that 5 is identical to 4.
/home/travis/build/prooph/event-store-client/tests/connect_to_existing_persistent_subscription_with_start_from_x_set_and_events_in_it.php:141
/home/travis/build/prooph/event-store-client/tests/SpecificationWithConnection.php:48
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Coroutine.php:74
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Internal/Placeholder.php:127
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Deferred.php:41
/home/travis/build/prooph/event-store-client/src/ClientOperations/AbstractOperation.php:130
/home/travis/build/prooph/event-store-client/src/ClientOperations/AppendToStreamOperation.php:91
/home/travis/build/prooph/event-store-client/src/ClientOperations/AbstractOperation.php:105
/home/travis/build/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:807
/home/travis/build/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:169
/home/travis/build/prooph/event-store-client/src/Internal/MessageHandler.php:38
/home/travis/build/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:183
/home/travis/build/prooph/event-store-client/src/Internal/EventStoreConnectionLogicHandler.php:321
/home/travis/build/prooph/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:184
/home/travis/build/prooph/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:101
/home/travis/build/prooph/event-store-client/src/Transport/Tcp/LengthPrefixMessageFramer.php:78
/home/travis/build/prooph/event-store-client/src/Transport/Tcp/TcpPackageConnection.php:212
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Coroutine.php:74
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Internal/Placeholder.php:127
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Deferred.php:41
/home/travis/build/prooph/event-store-client/vendor/amphp/byte-stream/lib/ResourceInputStream.php:92
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Loop/NativeDriver.php:172
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Loop/NativeDriver.php:68
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Loop/Driver.php:130
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Loop/Driver.php:70
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/Loop.php:76
/home/travis/build/prooph/event-store-client/vendor/amphp/amp/lib/functions.php:158
/home/travis/build/prooph/event-store-client/tests/SpecificationWithConnection.php:51
/home/travis/build/prooph/event-store-client/tests/connect_to_existing_persistent_subscription_with_start_from_x_set_and_events_in_it.php:143