search

pyeventsourcing / esdbclient

Python gRPC client for EventStoreDB
BSD 3-Clause "New" or "Revised" License
44 stars 8 forks source link

Trying to use grpc with tlc #26

Closed ikasymov closed 3 months ago

ikasymov commented 3 months ago

I got the error esdbclient.exceptions.InternalError: Request protocol 'HTTP/1.0' is not supported. while trying to connect to ES via the tlc secure mod. Does the python client support http2?

File /consumers.py", line 26, in handle client.create_subscription_to_all( File "python3.11/site-packages/esdbclient/client.py", line 132, in retrygrpc_decorator return f(*args, **kwargs) ^^^^^^^^^^^^^^^^^^ File "python3.11/site-packages/esdbclient/client.py", line 93, in autoreconnect_decorator return f(client, *args, **kwargs) ^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/python3.11/site-packages/esdbclient/client.py", line 940, in create_subscription_to_all self._esdb.persistent_subscriptions.create( File "/python3.11/site-packages/esdbclient/persistent.py", line 1741, in create raise handle_rpc_error(e) from None esdbclient.exceptions.InternalError: Request protocol 'HTTP/1.0' is not supported.

ikasymov commented 3 months ago

The ESDB_ROOT_CERTIFICATES were provided.

johnbywater commented 3 months ago

Hi @ikasymov - good to hear from you!

Thanks for raising the issue.

I don't understand what's going wrong here.

My understanding is that gRPC uses HTTP/2 as its transfer protocol.

If you set these environment variables you might get some debug logging?

GRPC_VERBOSITY="debug
GRPC_TRACE=all

For example, I can see this:

I0606 11:53:06.942204000 123145563418624 chttp2_transport.cc:952]      W:0x7ff14c038400 CLIENT [ipv6:%5B::1%5D:2113] state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
I0606 11:53:06.942214000 123145563418624 chttp2_transport.cc:952]      W:0x7ff14c038400 CLIENT [ipv6:%5B::1%5D:2113] state WRITING -> WRITING+MORE [INITIAL_WRITE]
I0606 11:53:06.942535000 123145563418624 chttp2_transport.cc:952]      W:0x7ff14c038400 CLIENT [ipv6:%5B::1%5D:2113] state WRITING+MORE -> WRITING [begin write in current thread]
I0606 11:53:06.942548000 123145563418624 chttp2_transport.cc:1082]     CLIENT[0x7ff14c038400]: Write 82 bytes
I0606 11:53:06.942553000 123145563418624 tcp_posix.cc:1827]            WRITE 0x7ff150a04080 (peer=ipv6:%5B::1%5D:2113)
D0606 11:53:06.942561000 123145563418624 tcp_posix.cc:1831]            WRITE DATA: 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 'PRI * HTTP/2.0....SM....'
I0606 11:53:06.942565000 123145563418624 tcp_posix.cc:1827]            WRITE 0x7ff150a04080 (peer=ipv6:%5B::1%5D:2113)
D0606 11:53:06.942569000 123145563418624 tcp_posix.cc:1831]            WRITE DATA: 00 00 24 04 00 00 00 00 00 00 02 00 00 00 00 00 03 7f ff ff ff 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 40 00 fe 03 00 00 00 01 '..$...............���...@.....@......@.�.....'
I0606 11:53:06.942572000 123145563418624 tcp_posix.cc:1827]            WRITE 0x7ff150a04080 (peer=ipv6:%5B::1%5D:2113)
D0606 11:53:06.942577000 123145563418624 tcp_posix.cc:1831]            WRITE DATA: 00 00 04 08 00 00 00 00 00 00 3f 00 01 '..........?..'
I0606 11:53:06.942622000 123145563418624 tcp_posix.cc:1875]            write: OK
I0606 11:53:06.942630000 123145563418624 chttp2_transport.cc:1096]     CLIENT[0x7ff14c038400]: Finish write
I0606 11:53:06.942643000 123145563418624 chttp2_transport.cc:952]      W:0x7ff14c038400 CLIENT [ipv6:%5B::1%5D:2113] state WRITING -> IDLE [finish writing]

Which mentions HTTP/2.0.

If you can do the same thing, do you get HTTP/1.0 in the log messages?

ikasymov commented 3 months ago 
I0606 11:09:56.698294000 8544533184 secure_endpoint.cc:242]            READ 0x120808200: 00 00 1e 01 05 00 00 00 03 c4 c3 61 96 df 3d bf 4a 01 c5 32 db 52 82 00 9a 50 21 b8 07 ee 36 da 98 b4 6f c2 c1 c0 bf '.........��a.�=�J.�2�R...P!�.�6�.�o����'
I0606 11:09:56.698306000 8544533184 parsing.cc:338]                    INCOMING[0x11700a600]: HEADERS:END_STREAM:END_HEADERS len:30 id:0x00000003
I0606 11:09:56.698311000 8544533184 parsing.cc:756]                    parsing Trailers-Only
D0606 11:09:56.698316000 8544533184 parsing.cc:897]                    INCOMING[0x11700a600;0x1210651b0]: Parse 30b last frame fragment with header
D0606 11:09:56.698323000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: :status: 426
D0606 11:09:56.698328000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: content-type: application/grpc
D0606 11:09:56.698343000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: date: Thu, 06 Jun 2024 11:09:55 GMT
D0606 11:09:56.698350000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: grpc-message: Request protocol 'HTTP/1.0' is not supported.
D0606 11:09:56.698953000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: grpc-status: 13
D0606 11:09:56.698964000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: server: nginx/1.24.0
D0606 11:09:56.698969000 8544533184 hpack_parser.cc:705]               HTTP:3:TRL:CLI: content-length: 0
D0606 11:09:56.698978000 8544533184 chttp2_transport.cc:2352]          MARK_STREAM_CLOSED: t=0x11700a600 s=0x1210651b0(id=3) read [OK]
D0606 11:09:56.698987000 8544533184 chttp2_transport.cc:2068]          maybe_complete_recv_message 0x1210651b0 final_metadata_requested=1 seen_error=0
D0606 11:09:56.698993000 8544533184 chttp2_transport.cc:2140]          maybe_complete_recv_trailing_metadata cli=1 s=0x1210651b0 closure=0x121065178 read_closed=1 write_closed=1 0
I0606 11:09:56.699003000 8544533184 tcp_posix.cc:1104]                 TCP:0x106fb2d30 got_read: OK
I0606 11:09:56.699006000 8544533184 tcp_posix.cc:894]                  TCP:0x106fb2d30 do_read
I0606 11:09:56.699479000 8544533184 tcp_posix.cc:679]                  TCP:0x106fb2d30 notify_on_read
ikasymov commented 3 months ago

Additional logs:

I0606 11:09:56.585816000 8544533184 chttp2_transport.cc:1377]          --metadata--
I0606 11:09:56.585834000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:user-agent: grpc-python/1.62.1 grpc-c/39.0.0 (osx; chttp2)
I0606 11:09:56.585838000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI::authority: es.n8n.vovalu.ru:443
I0606 11:09:56.585842000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI::path: /event_store.client.persistent_subscriptions.PersistentSubscriptions/Create
I0606 11:09:56.585846000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:GrpcRegisteredMethod: (nil)
I0606 11:09:56.585850000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:WaitForReady: false
I0606 11:09:56.585854000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:grpc-accept-encoding: identity, deflate, gzip
I0606 11:09:56.585858000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:te: trailers
I0606 11:09:56.586215000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:content-type: application/grpc
I0606 11:09:56.586224000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI::scheme: https
I0606 11:09:56.586229000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI::method: POST
I0606 11:09:56.586233000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:connection-name: b7bb6cc8-56ee-42d5-a208-1054db32c388
I0606 11:09:56.586236000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:requires-leader: true
I0606 11:09:56.586241000 8544533184 chttp2_transport.cc:1381]          HTTP:0:HDR:CLI:authorization: Basic YWRtaW46VGVzdDkyODM=
I0606 11:09:56.586245000 8544533184 chttp2_transport.cc:1377]          --metadata--
I0606 11:09:56.586253000 8544533184 stream_lists.cc:127]               0x11700a600[0][cli]: add to waiting_for_concurrency
I0606 11:09:56.586257000 8544533184 stream_lists.cc:73]                0x11700a600[0][cli]: pop from waiting_for_concurrency
I0606 11:09:56.586693000 8544533184 chttp2_transport.cc:1254]          HTTP:CLI: Transport 0x11700a600 allocating new grpc_chttp2_stream 0x1210651b0 to id 3
I0606 11:09:56.586704000 8544533184 stream_lists.cc:127]               0x11700a600[3][cli]: add to writable
I0606 11:09:56.586710000 8544533184 chttp2_transport.cc:952]           W:0x11700a600 CLIENT [ipv4:158.101.222.20:443] state IDLE -> WRITING [START_NEW_STREAM]
I0606 11:09:56.586723000 8544533184 chttp2_transport.cc:952]           W:0x11700a600 CLIENT [ipv4:158.101.222.20:443] state WRITING -> WRITING+MORE [SEND_MESSAGE]
D0606 11:09:56.586730000 8544533184 chttp2_transport.cc:2068]          maybe_complete_recv_message 0x1210651b0 final_metadata_requested=0 seen_error=0
D0606 11:09:56.586737000 8544533184 chttp2_transport.cc:2140]          maybe_complete_recv_trailing_metadata cli=1 s=0x1210651b0 closure=0x0 read_closed=0 write_closed=0 0
D0606 11:09:56.586742000 8544533184 chttp2_transport.cc:2068]          maybe_complete_recv_message 0x1210651b0 final_metadata_requested=1 seen_error=0
D0606 11:09:56.587540000 8544533184 chttp2_transport.cc:2140]          maybe_complete_recv_trailing_metadata cli=1 s=0x1210651b0 closure=0x121065178 read_closed=0 write_closed=0 0
I0606 11:09:56.587553000 8544533184 chttp2_transport.cc:1321]          complete_closure_step: t=0x11700a600 0x121064fb8 refs=3 flags=0x0001 desc=op->on_complete err=OK write_state=WRITING+MORE whence=(null):-1
I0606 11:09:56.587563000 8544533184 stream_lists.cc:73]                0x11700a600[3][cli]: pop from writable
I0606 11:09:56.587565000 8544533184 writing.cc:454]                    W:0x11700a600 CLIENT[3] im-(sent,send)=(0,1)
I0606 11:09:56.587571000 8544533184 chttp2_transport.cc:1321]          complete_closure_step: t=0x11700a600 0x121064fb8 refs=2 flags=0x0001 desc=send_initial_metadata_finished err=OK write_state=WRITING+MORE whence=(null):-1
D0606 11:09:56.587576000 8544533184 chttp2_transport.cc:2352]          MARK_STREAM_CLOSED: t=0x11700a600 s=0x1210651b0(id=3) write [OK]
I0606 11:09:56.588147000 8544533184 chttp2_transport.cc:1321]          complete_closure_step: t=0x11700a600 0x121064fb8 refs=1 flags=0x0001 desc=send_trailing_metadata_finished err=OK write_state=WRITING+MORE whence=(null):-1
I0606 11:09:56.588164000 8544533184 chttp2_transport.cc:1321]          complete_closure_step: t=0x11700a600 0x121064fb8 refs=0 flags=0x0001 desc=on_write_finished_cb err=OK write_state=WRITING+MORE whence=(null):-1
I0606 11:09:56.588169000 8544533184 stream_lists.cc:127]               0x11700a600[3][cli]: add to writing
I0606 11:09:56.588176000 8544533184 chttp2_transport.cc:952]           W:0x11700a600 CLIENT [ipv4:158.101.222.20:443] state WRITING+MORE -> WRITING [begin write in current thread]
I0606 11:09:56.588180000 8544533184 chttp2_transport.cc:1082]          CLIENT[0x11700a600]: Write 276 bytes
johnbywater commented 3 months ago 
HTTP:3:TRL:CLI: server: nginx/1.24.0

Are you somehow (inadvertently or deliberately) trying to get the EventStoreDB client to connect to (or via) nginx?

ikasymov commented 3 months ago

Yes. Nginx worked as a proxy server. My URI looks something like this: esdb://login:password@mydomain.com:443?tls=true

johnbywater commented 3 months ago

Interesting. I would revisit your nginx config? If you had this working before, have you made any recent changes? Are you using a different version of EventStoreDB?

Which version of the client are you using? Which version of EventStoreDB are you using?

johnbywater commented 3 months ago

Maybe your nginx is trying to connect to EventStoreDB with HTTP/1.0 rather than HTTP/2.0? And then propagating the error response back to the Python client. That's my guess.

ikasymov commented 3 months ago

It is my first try to support tlc. Before that, we used to configure on insecure mode with nginx + es and everything worked correctly. But after configuring on secure mode we got this error.

Maybe your nginx is trying to connect to EventStoreDB with HTTP/1.0

I also thought like this but i tried to connect ES via curl:

curl -v https://mydomain.com --http2
*   Trying ip:443...
* Connected to es.n8n.vovalu.ru (ip) port 443 (#0)
* ALPN: offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: /etc/ssl/certs
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: CN=es.n8n.vovalu.ru
*  start date: May 30 06:00:59 2024 GMT
*  expire date: Aug 28 06:00:58 2024 GMT
*  subjectAltName: host "mydomain.com" matched cert's "mydomain.com"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
* using HTTP/2
* h2h3 [:method: GET]
* h2h3 [:path: /]
* h2h3 [:scheme: https]
* h2h3 [:authority: mydomain.com]
* h2h3 [user-agent: curl/7.88.1]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x564a16744e10)
> GET / HTTP/2

Here you can see that nginx can do http2

johnbywater commented 3 months ago

If curl can connect by picking up the certificate from /etc/ssl/certs, maybe let the grpc library pick up the certificate from /etc/ssl/certs to, by not using the root_certificates arg of the Python client? Maybe somehow the certificate text isn't correctly being passed into the client?

johnbywater commented 3 months ago

I'm guessing nginx is somehow falling back onto HTTP/1.0 connecting the backend EventStoreDB server?

Maybe when the grpc library continues with its operations beyond what curl is doing, there's some operation that isn't supported with HTTP/2.0 by nginx and nginx tries to use HTTP/1.0? It does appear that nginx is trying to do HTTP/1.0 with EventStoreDB when you connect using the Python EventStoreDB client.

johnbywater commented 3 months ago

https://nginx.org/en/docs/http/ngx_http_grpc_module.html

To use gRPC over SSL, the “grpcs://” scheme should be used:

grpc_pass grpcs://127.0.0.1:443;

What's your nginx config looking like?

johnbywater commented 3 months ago

Maybe you configured nginx to reverse proxy tls correctly, but not actually configured for grpcs? I never tried this, and I don't know what your nginx config is, so I'm really just guessing here.

johnbywater commented 3 months ago

By the way, you don't need to put tls=true in the connection string URI because that's the default.

esdb://login:password@mydomain.com:443?tls=true

Can be just:

esdb://login:password@mydomain.com:443
ikasymov commented 3 months ago

@johnbywater Thanks so much!! grpc_pass grpcs://127.0.0.1:443 it's fixed my problem. :)

But have a new issue, the consumer crashes with error: esdbclient.exceptions.InternalError: Received RST_STREAM with error code 0

crashes with this error after 30 seconds after connecting

And I see red flag on status while connection is active before crash: Screenshot 2024-06-06 at 19 29 01

In logs i see that error:

D0606 13:50:27.865655000 6158168064 posix_engine.cc:449]               (event_engine) PosixEventEngine:0x600000acc0e0 executing callback:{0000600001de8180,0000000000000004}
Exception ignored in: <function PersistentSubscription.__del__ at 0x1060d25c0>
Traceback (most recent call last):
  File "python3.11/site-packages/esdbclient/persistent.py", line 706, in __del__
  File "python3.11/site-packages/esdbclient/persistent.py", line 679, in stop
  File "python3.11/site-packages/esdbclient/common.py", line 113, in pop
  File "python3.11/weakref.py", line 272, in pop
KeyError: 4399496464
johnbywater commented 3 months ago

it's fixed my problem. :)

Great news!

johnbywater commented 3 months ago

Received RST_STREAM with error code 0 crashes with this error after 30 seconds after connecting

I don't understand why this is happening.

Does it always crash after exactly 30s? If so, that sounds like a timeout, maybe introduced by nginx?

Otherwise, if it's more occasional or intermittent, maybe the EventStoreDB server doesn't have enough memory?

johnbywater commented 3 months ago

D0606 13:50:27.865655000 6158168064 posix_engine.cc:449] (event_engine) PosixEventEngine:0x600000acc0e0 executing callback:{0000600001de8180,0000000000000004} Exception ignored in: <function PersistentSubscription.del at 0x1060d25c0> Traceback (most recent call last): File "python3.11/site-packages/esdbclient/persistent.py", line 706, in del File "python3.11/site-packages/esdbclient/persistent.py", line 679, in stop File "python3.11/site-packages/esdbclient/common.py", line 113, in pop File "python3.11/weakref.py", line 272, in pop KeyError: 4399496464

Somehow you have a race calling stop() on the persistent subscription. Not sure how this is happening without looking at your code. At least we can see that this "Exception ignored" :)

johnbywater commented 3 months ago

PosixEventEngine:0x600000acc0e0 executing callback

What's this callback?

ikasymov commented 3 months ago 
client = get_event_store_client()
        group_name = "scoring-consumer-2"
        try:
            client.create_subscription_to_all(
                group_name=group_name,
                filter_by_stream_name=True,
                filter_include=[r"credit-TXC_.*", r"penalties-TXC_.*"],
            )
        except AlreadyExists:
            pass

        subscription = client.read_subscription_to_all(
            group_name=group_name,
        )

        for event in subscription:
            subscription.ack(event)

it's my all code

ikasymov commented 3 months ago

What is the red flag on status column on my screenshot? this was not the case in other places

johnbywater commented 3 months ago

I don't know what the red dot actually means. I've asked the EventStoreDB team.

ikasymov commented 3 months ago

@johnbywater Thanks. The issue was on nginx timeout. The thread can be closed. But I am really interested in the red dot. Let me know please

johnbywater commented 3 months ago

Well done for getting it working @ikasymov. I haven't heard back yet, but will let you know what they say.

johnbywater commented 3 months ago

Closing, as requested.

johnbywater commented 3 months ago

@ikasymov I'm told the red dot means the subscription consumption is "behind" and "in a high ingress system it'll always be red." In other words, the status is "red" when there are a lot of recorded events that haven't been received and acknowledged (the consumer has "fallen behind") and otherwise "green" (which means the consumer has "caught up").

johnbywater commented 3 months ago

@ikasymov The EventStoreDB team are curious to see your nginx config (reverse proxy for EventStoreDB). Please could you share it with me?