Issue with subscription when using secured connection

EventStoreDB
1

Greetings,

Finally be able to use encrypted connection with my Haskell Client. However, I’m experiencing a weird behavior that only

occurs when using an encrypted connection.

During the test, I subscribe to a stream which doesn’t exist yet. Then I write 3 events to it. Finally, I make sure the subscription serves those events.

On non secured connection, that test passes. On secured connection though, while the write succeeded, my subscription received nothing.

Obviously, I don’t exclude a bug coming from my lib but considering that SSL support doesn’t change the client logic itself, I rather ask for

your feedback first.

OS: Archlinux on Kernel 4.5.4 (64 bits)
EventStore: 3.3.0 (Mono linked) In memory mode

``

Here the log output:

ES VERSION: 3.3.0.0 (release-v3.3.0/4923f4c0f427a85a275f362402e62645bca38c07, Wed, 7 Oct 2015 07:37:39 +0200)

OS: Linux (Unix 4.5.4.1)

RUNTIME: 3.12.1 (tarball) (64-bit)

GC: 2 GENERATIONS

LOGS: /home/yoeight.bak/Downloads.bak/EventStore-OSS-Ubuntu-v3.3.0/toto.log

MODIFIED OPTIONS:

LOG: toto.log (Command Line)

MEM DB: true (Command Line)

EXT SECURE TCP PORT: 1119 (Command Line)

CERTIFICATE FILE: /home/yoeight/code/haskell/eventstore/domain.p12 (Command Line)

CERTIFICATE PASSWORD: ****** (Command Line)

DEFAULT OPTIONS:

HELP: False ()

VERSION: False ()

CONFIG: ()

DEFINES: ()

WHAT IF: False ()

START STANDARD PROJECTIONS: False ()

DISABLE HTTP CACHING: False ()

MONO MIN THREADPOOL SIZE: 10 ()

INT IP: 127.0.0.1 ()

EXT IP: 127.0.0.1 ()

INT HTTP PORT: 2112 ()

EXT HTTP PORT: 2113 ()

INT TCP PORT: 1112 ()

INT SECURE TCP PORT: 0 ()

EXT TCP PORT: 1113 ()

EXT SECURE TCP PORT ADVERTISE AS: 0 ()

EXT IP ADVERTISE AS: ()

EXT TCP PORT ADVERTISE AS: 0 ()

EXT HTTP PORT ADVERTISE AS: 0 ()

INT IP ADVERTISE AS: ()

INT SECURE TCP PORT ADVERTISE AS: 0 ()

INT TCP PORT ADVERTISE AS: 0 ()

INT HTTP PORT ADVERTISE AS: 0 ()

INT TCP HEARTBEAT TIMEOUT: 700 ()

EXT TCP HEARTBEAT TIMEOUT: 1000 ()

INT TCP HEARTBEAT INTERVAL: 700 ()

EXT TCP HEARTBEAT INTERVAL: 2000 ()

FORCE: False ()

CLUSTER SIZE: 1 ()

NODE PRIORITY: 0 ()

MIN FLUSH DELAY MS: 2 ()

COMMIT COUNT: -1 ()

PREPARE COUNT: -1 ()

ADMIN ON EXT: True ()

STATS ON EXT: True ()

GOSSIP ON EXT: True ()

DISABLE SCAVENGE MERGING: False ()

DISCOVER VIA DNS: True ()

CLUSTER DNS: fake.dns ()

CLUSTER GOSSIP PORT: 30777 ()

GOSSIP SEED: ()

STATS PERIOD SEC: 30 ()

CACHED CHUNKS: -1 ()

CHUNKS CACHE SIZE: 536871424 ()

MAX MEM TABLE SIZE: 1000000 ()

DB: /var/lib/eventstore ()

SKIP DB VERIFY: False ()

RUN PROJECTIONS: None ()

PROJECTION THREADS: 3 ()

WORKER THREADS: 5 ()

INT HTTP PREFIXES: ()

EXT HTTP PREFIXES: ()

ENABLE TRUSTED AUTH: False ()

ADD INTERFACE PREFIXES: True ()

CERTIFICATE STORE LOCATION: ()

CERTIFICATE STORE NAME: ()

CERTIFICATE SUBJECT NAME: ()

CERTIFICATE THUMBPRINT: ()

USE INTERNAL SSL: False ()

SSL TARGET HOST: n/a ()

SSL VALIDATE SERVER: True ()

AUTHENTICATION TYPE: internal ()

PREPARE TIMEOUT MS: 2000 ()

COMMIT TIMEOUT MS: 2000 ()

UNSAFE DISABLE FLUSH TO DISK: False ()

INDEX CACHE DEPTH: 16 ()

GOSSIP INTERVAL MS: 1000 ()

GOSSIP ALLOWED DIFFERENCE MS: 60000 ()

GOSSIP TIMEOUT MS: 500 ()

ENABLE HISTOGRAMS: False ()

[03444,01,21:27:31.468] Quorum size set to 1

[03444,01,21:27:31.473] Cannot find plugins path: plugins

[03444,01,21:27:31.488] INSTANCE ID: 3abc7bff-f2f3-4ce1-8526-67187942303a

[03444,01,21:27:31.488] DATABASE: /var/lib/eventstore

[03444,01,21:27:31.491] WRITER CHECKPOINT: 0 (0x0)

[03444,01,21:27:31.491] CHASER CHECKPOINT: 0 (0x0)

[03444,01,21:27:31.491] EPOCH CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)

[03444,01,21:27:31.491] TRUNCATE CHECKPOINT: -1 (0xFFFFFFFFFFFFFFFF)

[03444,01,21:27:31.573] MessageHierarchy initialization took 00:00:00.0613144.

[03444,01,21:27:31.660] Starting MiniWeb for /web/es/js/projections ==> projections

[03444,01,21:27:31.660] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> Prelude

[03444,01,21:27:31.660] Binding MiniWeb to /web/es/js/projections/{*remaining_path}

[03444,01,21:27:31.660] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}

[03444,01,21:27:31.666] Starting MiniWeb for /web ==> clusternode-web

[03444,01,21:27:31.666] Binding MiniWeb to /web/{*remaining_path}

[03444,20,21:27:31.679] ========== [127.0.0.1:2112] SYSTEM INIT…

[03444,20,21:27:31.693] Starting Normal TCP listening on TCP endpoint: 127.0.0.1:1113.

[03444,20,21:27:31.696] Starting Secure TCP listening on TCP endpoint: 127.0.0.1:1119.

[03444,23,21:27:31.706] TableIndex initialization…

[03444,23,21:27:31.709] ReadIndex building…

[03444,23,21:27:31.709] ReadIndex rebuilding done: total processed 0 records, time elapsed: 00:00:00.0007620.

[03444,20,21:27:31.720] Starting HTTP server on [http://127.0.0.1:2113/,http://localhost:2113/]…

[03444,20,21:27:31.723] HTTP server is up and listening on [http://127.0.0.1:2113/,http://localhost:2113/]

[03444,20,21:27:31.734] SLOW QUEUE MSG [MainQueue]: SystemInit - 54ms. Q: 0/6.

[03444,20,21:27:31.734] ========== [127.0.0.1:2112] Service ‘StorageReader’ initialized.

[03444,20,21:27:31.734] ========== [127.0.0.1:2112] Service ‘StorageWriter’ initialized.

[03444,20,21:27:31.734] ========== [127.0.0.1:2112] Service ‘StorageChaser’ initialized.

[03444,20,21:27:31.735] ========== [127.0.0.1:2112] SYSTEM START…

[03444,20,21:27:31.737] ========== [127.0.0.1:2112] IS UNKNOWN…

[03444,09,21:27:31.748] Subscriptions received state change to Unknown stopping listening.

[03444,20,21:27:31.760] ELECTIONS: STARTING ELECTIONS.

[03444,20,21:27:31.760] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.

[03444,20,21:27:31.760] ELECTIONS: (V=0) VIEWCHANGE FROM [127.0.0.1:2112, {3abc7bff-f2f3-4ce1-8526-67187942303a}].

[03444,20,21:27:31.760] ELECTIONS: (V=0) MAJORITY OF VIEWCHANGE.

[03444,20,21:27:31.761] ELECTIONS: (V=0) SHIFT TO PREPARE PHASE.

[03444,20,21:27:31.761] ELECTIONS: (V=0) PREPARE_OK FROM 127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}.

[03444,20,21:27:31.762] ELECTIONS: (V=0) SHIFT TO REG_LEADER.

[03444,20,21:27:31.765] ELECTIONS: (V=0) SENDING PROPOSAL CANDIDATE: 127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}, ME: 127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}.

[03444,20,21:27:31.765] ELECTIONS: (V=0) ACCEPT FROM [127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}] M=[127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}]).

[03444,20,21:27:31.766] ELECTIONS: (V=0) DONE. ELECTED MASTER = 127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}. ME=127.0.0.1:2112,{3abc7bff-f2f3-4ce1-8526-67187942303a}.

[03444,20,21:27:31.767] ========== [127.0.0.1:2112] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP…

[03444,13,21:27:31.767] Subscriptions received state change to PreMaster stopping listening.

[03444,20,21:27:31.768] ========== [127.0.0.1:2112] IS MASTER… SPARTA!

[03444,09,21:27:31.768] Subscriptions Became Master so now handling subscriptions

[03444,16,21:27:31.831] === Writing E0@0:{43279d88-98f6-4f77-8e7a-6ad9cd796129} (previous epoch at -1).

[03444,16,21:27:31.832] === Update Last Epoch E0@0:{43279d88-98f6-4f77-8e7a-6ad9cd796129} (previous epoch at -1).

[03444,04,21:27:31.868] Created stats stream ‘$stats-127.0.0.1:2113’, code = Success

[03444,20,21:27:31.879] ‘admin’ user account has been created.

[03444,20,21:27:31.880] ‘admin’ user added to $users.

Segments count: 1, buffers count: 512, should be when full: 512

TcpConnectionSsl::InitClientSocket(127.0.0.1:53454, L127.0.0.1:1119)

[03444,13,21:27:39.332] External TCP connection accepted: [Secure, 127.0.0.1:53454, L127.0.0.1:1119, {1879ce32-74e6-4cea-90b9-b2a12502c93d}].

[03444,12,21:27:39.389] [S127.0.0.1:53454, L127.0.0.1:1119]

[03444,12,21:27:39.389] Cipher: Aes128 strength 128

[03444,12,21:27:39.389] Hash: Sha1 strength 160

[03444,12,21:27:39.389] Key exchange: RsaKeyX strength 2048

[03444,12,21:27:39.390] Protocol: Tls

[03444,12,21:27:39.390] Is authenticated: True as server? True

[03444,12,21:27:39.391] IsSigned: True

[03444,12,21:27:39.391] Is Encrypted: True

[03444,12,21:27:39.391] Can read: True, write True

[03444,12,21:27:39.391] Can timeout: True

[03444,12,21:27:39.391] Certificate revocation list checked: True

[03444,12,21:27:39.393] Local certificate was issued to CN=test.com and is valid from 5/29/2016 1:34:21 PM until 5/29/2017 1:34:21 PM.

[03444,12,21:27:39.393] Remote certificate is null.

``

Here’s the command I used

./run-node.sh --log toto.log --mem-db --ext-secure-tcp-port 1119 --certificate-file /home/yoeight/code/haskell/eventstore/domain.p12 --certificate-password {password}

``

Thanks for your time.

Yorick

2

As far as I know there is no difference except for the transport for ssl.

Will try to write up a test tomorrow.

3

More info, if I keep the server up, close the client connection and reconnect, the test passes. It’s a regular subscription, so it isn’t the previous events I was receiving.

Cheers

4

Could your subscription be cancelled or back pressure hit etc in your tests?

5

I should have been more specific. What I meant is I kill the test program and relaunch it right away. So the client restart with a clean state.
I didn’t check if the subscription was cancelled at the first run. Will look this tonight.

6

So I checked, the subscription isn’t dropped. Is there more information I can provide ?

7

packet flow would help especially with just the single test being run
if that can reproduce it. there isn't anything in the ssl transport vs
the tcp transport that should cause such things. more likely we are
looking at some usage pattern etc.

8

So I followed you advice and looked at the package flow.

It was an asynchronous issue. In the first run, I received subscription confirmation after sending events to the server. So, it’s totally normal I didn’t receive anything. The second run (when I restart the program but let the server untouched), I received subscription confirmation before writing events.

After the fact, it seems obvious but anyway I learnt my lesson :slight_smile:

I don’t use the lib in such way that this kind of issue occurs. That’s why I implemented and exposed a new function named waitConfirmation that blocks until the subscription has been confirmed.

As always, thanks Greg for your time. Now I’m happy to say my Haskell client supports 100% EventStore features !

Cheers.