Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Connecting to localhost or UDS with gRPC client #38

Closed
charithe opened this issue Jul 24, 2023 · 4 comments · Fixed by #39
Closed

Connecting to localhost or UDS with gRPC client #38

charithe opened this issue Jul 24, 2023 · 4 comments · Fixed by #39
Assignees
@Sambigeara

Comments

@charithe
Copy link
Contributor

I didn't investigate this in detail but I am having trouble connecting to localhost (with TLS) using the gRPC client.

UNKNOWN:failed to connect to all addresses; last error: UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed

with GRPC_VERBOSITY=debug and GRPC_TRACE=all

I0724 17:13:11.215147709  142847 handshaker.cc:100]                    handshake_manager 0x55580ce31150: error=OK shutdown=0 index=0, args={endpoint=(nil), args={grpc.client_channel_factory=0x55580ce086f0, grpc.default_authority=localhost:3593, grpc.internal.channel_credentials=0x55580ce09970, grpc.internal.event_engine=0x55580ccd4610, grpc.internal.security_connector=0x55580cc8daf0, grpc.internal.subchannel_pool=0x55580cd7dd50, grpc.internal.tcp_handshaker_bind_endpoint_to_pollset=1, grpc.internal.tcp_handshaker_resolved_address=ipv4:127.0.0.1:3593, grpc.primary_user_agent=grpc-python/1.56.2, grpc.resource_quota=0x55580ccea2a0, grpc.server_uri=dns:///localhost:3593}, read_buffer=0x55580c94ae80 (length=0), exit_early=0}
I0724 17:13:11.215155726  142847 handshaker.cc:146]                    handshake_manager 0x55580ce31150: calling handshaker tcp_connect [0x55580cc098e0] at index 0
I0724 17:13:11.215263179  142847 tcp_client_posix.cc:387]              CLIENT_CONNECT: ipv4:127.0.0.1:3593: asynchronously connecting fd 0x55580cc06f30
D0724 17:13:11.215267479  142847 timer_generic.cc:341]                 TIMER 0x7f8b64001410: SET 21784 now 1784 call 0x7f8b64001448[0x7f8b737cce00]
D0724 17:13:11.215270995  142847 timer_generic.cc:377]                   .. add to shard 11 with queue_deadline_cap=2782 => is_first_timer=false
I0724 17:13:11.215275498  142847 client_channel.cc:614]                chand=0x55580ce7d820: connectivity change for subchannel wrapper 0x55580cdf6aa0 subchannel 0x55580cd71cc0; hopping into work_serializer
I0724 17:13:11.215279227  142847 client_channel.cc:638]                chand=0x55580ce7d820: processing connectivity change in work serializer for subchannel wrapper 0x55580cdf6aa0 subchannel 0x55580cd71cc0 watcher=0x55580cd286b0 state=CONNECTING status=OK
I0724 17:13:11.215284657  142847 subchannel_list.h:259]                [PickFirstSubchannelList 0x55580c8e02f0] subchannel list 0x55580cd2fa70 index 1 of 2 (subchannel 0x55580cdf6aa0): connectivity changed: old_state=IDLE, new_state=CONNECTING, status=OK, shutting_down=0, pending_watcher=0x55580cd286b0
I0724 17:13:11.215289258  142847 client_channel.cc:922]                chand=0x55580ce7d820: update: state=CONNECTING status=(OK) picker=0x55580ce48750
I0724 17:13:11.215293178  142847 client_channel.cc:2555]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: removing from queued picks list
I0724 17:13:11.215298223  142847 tcp_client_posix.cc:182]              CLIENT_CONNECT: ipv4:127.0.0.1:3593: on_writable: error=OK
D0724 17:13:11.215301091  142847 timer_generic.cc:442]                 TIMER 0x7f8b64001410: CANCEL pending=true
I0724 17:13:11.215305789  142847 memory_quota.cc:450]                  Adding allocator 0x7f8b640053d0
I0724 17:13:11.215312588  142847 executor.cc:294]                      EXECUTOR (default-executor) try to schedule 0x55580cc099c0 (short) to thread 0
I0724 17:13:11.215315978  142847 client_channel.cc:2599]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: grabbing LB mutex to get picker
I0724 17:13:11.215319105  142847 client_channel.cc:2609]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: performing pick with picker=0x55580ce48750
I0724 17:13:11.215322189  142847 client_channel.cc:2701]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: LB pick queued
I0724 17:13:11.215325181  142847 client_channel.cc:2569]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: adding to queued picks list
I0724 17:13:11.215329207  142847 tcp_client_posix.cc:143]              CLIENT_CONNECT: ipv4:127.0.0.1:3593: on_alarm: error=CANCELLED
I0724 17:13:11.215333105  142847 client_channel.cc:3105]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: cancelling queued pick: error=OK self=0x55580ce2bc00 calld->pick_canceller=0x7f8b64004a30
I0724 17:13:11.215336457  142847 executor.cc:222]                      EXECUTOR (default-executor) [0]: step (sub_depth=1)
I0724 17:13:11.215338770  142847 executor.cc:243]                      EXECUTOR (default-executor) [0]: execute
I0724 17:13:11.215341203  142847 executor.cc:122]                      EXECUTOR (default-executor) run 0x55580cc099c0
I0724 17:13:11.215349638  142847 handshaker.cc:100]                    handshake_manager 0x55580ce31150: error=OK shutdown=0 index=1, args={endpoint=0x7f8b64004bb0, args={grpc.client_channel_factory=0x55580ce086f0, grpc.default_authority=localhost:3593, grpc.internal.channel_credentials=0x55580ce09970, grpc.internal.event_engine=0x55580ccd4610, grpc.internal.security_connector=0x55580cc8daf0, grpc.internal.subchannel_pool=0x55580cd7dd50, grpc.primary_user_agent=grpc-python/1.56.2, grpc.resource_quota=0x55580ccea2a0, grpc.server_uri=dns:///localhost:3593}, read_buffer=0x55580c94ae80 (length=0), exit_early=0}
I0724 17:13:11.215356050  142847 handshaker.cc:146]                    handshake_manager 0x55580ce31150: calling handshaker http_connect [0x7f8b64002be0] at index 1
I0724 17:13:11.215361480  142847 handshaker.cc:100]                    handshake_manager 0x55580ce31150: error=OK shutdown=0 index=2, args={endpoint=0x7f8b64004bb0, args={grpc.client_channel_factory=0x55580ce086f0, grpc.default_authority=localhost:3593, grpc.internal.channel_credentials=0x55580ce09970, grpc.internal.event_engine=0x55580ccd4610, grpc.internal.security_connector=0x55580cc8daf0, grpc.internal.subchannel_pool=0x55580cd7dd50, grpc.primary_user_agent=grpc-python/1.56.2, grpc.resource_quota=0x55580ccea2a0, grpc.server_uri=dns:///localhost:3593}, read_buffer=0x55580c94ae80 (length=0), exit_early=0}
I0724 17:13:11.215367847  142847 handshaker.cc:146]                    handshake_manager 0x55580ce31150: calling handshaker security [0x55580ce7da60] at index 2
I0724 17:13:11.215372399  142847 security_context.cc:270]              grpc_auth_context_add_cstring_property(ctx=0x7f8b640011f0, name=transport_security_type, value=insecure)
I0724 17:13:11.215376435  142847 security_context.cc:249]              grpc_auth_context_add_property(ctx=0x7f8b640011f0, name=security_level, value=TSI_SECURITY_NONE, value_length=17)
I0724 17:13:11.215379680  142847 security_context.cc:209]              grpc_auth_context_find_properties_by_name(ctx=0x7f8b640011f0, name=security_level)
I0724 17:13:11.215382488  142847 security_context.cc:183]              grpc_auth_property_iterator_next(it=0x7f8b727e9a40)
I0724 17:13:11.215390293  142847 handshaker.cc:100]                    handshake_manager 0x55580ce31150: error=OK shutdown=0 index=3, args={endpoint=0x7f8b64004bb0, args={grpc.auth_context=0x7f8b640011f0, grpc.client_channel_factory=0x55580ce086f0, grpc.default_authority=localhost:3593, grpc.internal.channel_credentials=0x55580ce09970, grpc.internal.event_engine=0x55580ccd4610, grpc.internal.security_connector=0x55580cc8daf0, grpc.internal.subchannel_pool=0x55580cd7dd50, grpc.primary_user_agent=grpc-python/1.56.2, grpc.resource_quota=0x55580ccea2a0, grpc.server_uri=dns:///localhost:3593}, read_buffer=0x55580c94ae80 (length=0), exit_early=0}
I0724 17:13:11.215400773  142847 handshaker.cc:132]                    handshake_manager 0x55580ce31150: handshaking complete -- scheduling on_handshake_done with error=OK
I0724 17:13:11.215410916  142847 init.cc:149]                          grpc_init(void)
I0724 17:13:11.215413891  142847 memory_quota.cc:450]                  Adding allocator 0x7f8b640056d0
I0724 17:13:11.215448971  142847 flow_control.cc:286]                  [flowctl] UPDATE SETTING INITIAL_WINDOW_SIZE from 65535 to 4194304
I0724 17:13:11.215452345  142847 flow_control.cc:286]                  [flowctl] UPDATE SETTING MAX_FRAME_SIZE from 16384 to 4194304
I0724 17:13:11.215456374  142847 chttp2_transport.cc:918]              W:0x7f8b64012b60 CLIENT [ipv4:127.0.0.1:3593] state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
I0724 17:13:11.215459881  142847 chttp2_transport.cc:918]              W:0x7f8b64012b60 CLIENT [ipv4:127.0.0.1:3593] state WRITING -> WRITING+MORE [INITIAL_WRITE]
D0724 17:13:11.215464544  142847 posix_engine.cc:484]                  (event_engine) PosixEventEngine:0x55580cc5c7a0 scheduling callback:{140236654986496,3}
I0724 17:13:11.215470849  142847 chttp2_transport.cc:918]              W:0x7f8b64012b60 CLIENT [ipv4:127.0.0.1:3593] state WRITING+MORE -> WRITING [begin write in current thread]
I0724 17:13:11.215473881  142847 tcp_posix.cc:1804]                    WRITE 0x7f8b64004bb0 (peer=ipv4:127.0.0.1:3593)
D0724 17:13:11.215477299  142847 tcp_posix.cc:1808]                    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....'
I0724 17:13:11.215480205  142847 tcp_posix.cc:1804]                    WRITE 0x7f8b64004bb0 (peer=ipv4:127.0.0.1:3593)
D0724 17:13:11.215483720  142847 tcp_posix.cc:1808]                    WRITE DATA: 00 00 24 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 40 00 fe 03 00 00 00 01 '..$.....................@.....@......@.......'
I0724 17:13:11.215487078  142847 tcp_posix.cc:1804]                    WRITE 0x7f8b64004bb0 (peer=ipv4:127.0.0.1:3593)
D0724 17:13:11.215489533  142847 tcp_posix.cc:1808]                    WRITE DATA: 00 00 04 08 00 00 00 00 00 00 3f 00 01 '..........?..'
I0724 17:13:11.215510782  142847 tcp_posix.cc:1852]                    write: OK
I0724 17:13:11.215514104  142847 chttp2_transport.cc:918]              W:0x7f8b64012b60 CLIENT [ipv4:127.0.0.1:3593] state WRITING -> IDLE [finish writing]
D0724 17:13:11.215518482  142847 posix_engine.cc:484]                  (event_engine) PosixEventEngine:0x55580cc5c7a0 scheduling callback:{140236654987264,4}
I0724 17:13:11.215523117  142847 chttp2_transport.cc:2958]             ipv4:127.0.0.1:3593: Keepalive ping cancelled. Resetting timer.
D0724 17:13:11.215526136  142847 posix_engine.cc:484]                  (event_engine) PosixEventEngine:0x55580cc5c7a0 scheduling callback:{140236654986496,5}
I0724 17:13:11.215529469  142847 tcp_posix.cc:670]                     TCP:0x7f8b64004bb0 notify_on_read
I0724 17:13:11.215532065  142847 executor.cc:222]                      EXECUTOR (default-executor) [0]: step (sub_depth=1)
I0724 17:13:11.215595082  142846 tcp_posix.cc:1086]                    TCP:0x7f8b64004bb0 got_read: OK
I0724 17:13:11.215600686  142846 tcp_posix.cc:876]                     TCP:0x7f8b64004bb0 do_read
I0724 17:13:11.215608438  142846 tcp_posix.cc:811]                     TCP:0x7f8b64004bb0 call_cb 0x7f8b64012cf0 0x7f8b73630030:0x7f8b64012b60
I0724 17:13:11.215614828  142846 tcp_posix.cc:813]                     READ 0x7f8b64004bb0 (peer=ipv4:127.0.0.1:3593) error=INTERNAL:Socket closed {target_address:"ipv4:127.0.0.1:3593", grpc_status:14, fd:5}
I0724 17:13:11.215638815  142846 chttp2_transport.cc:2980]             transport 0x7f8b64012b60 set connectivity_state=4
I0724 17:13:11.215641971  142846 connectivity_state.cc:160]            ConnectivityStateTracker client_transport[0x7f8b64012e50]: READY -> SHUTDOWN (close_transport, OK)
I0724 17:13:11.215695486  142846 subchannel.cc:707]                    subchannel 0x55580cd71cc0 {address=ipv4:127.0.0.1:3593, args={grpc.client_channel_factory=0x55580ce086f0, grpc.default_authority=localhost:3593, grpc.internal.channel_credentials=0x55580ce09970, grpc.internal.event_engine=0x55580ccd4610, grpc.internal.security_connector=0x55580cc8daf0, grpc.internal.subchannel_pool=0x55580cd7dd50, grpc.primary_user_agent=grpc-python/1.56.2, grpc.resource_quota=0x55580ccea2a0, grpc.server_uri=dns:///localhost:3593}}: connect failed (UNKNOWN:Endpoint read failed {occurred_during_write:0, created_time:"2023-07-24T17:13:11.215618718+01:00", children:[INTERNAL:Socket closed {target_address:"ipv4:127.0.0.1:3593", grpc_status:14, fd:5}]}), backing off for 1000 ms
D0724 17:13:11.215711676  142846 posix_engine.cc:484]                  (event_engine) PosixEventEngine:0x55580cc5c7a0 scheduling callback:{140236654987264,6}
I0724 17:13:11.215715096  142846 client_channel.cc:614]                chand=0x55580ce7d820: connectivity change for subchannel wrapper 0x55580cdf6aa0 subchannel 0x55580cd71cc0; hopping into work_serializer
I0724 17:13:11.215718555  142846 client_channel.cc:638]                chand=0x55580ce7d820: processing connectivity change in work serializer for subchannel wrapper 0x55580cdf6aa0 subchannel 0x55580cd71cc0 watcher=0x55580cd286b0 state=TRANSIENT_FAILURE status=UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed
I0724 17:13:11.215722909  142846 subchannel_list.h:259]                [PickFirstSubchannelList 0x55580c8e02f0] subchannel list 0x55580cd2fa70 index 1 of 2 (subchannel 0x55580cdf6aa0): connectivity changed: old_state=CONNECTING, new_state=TRANSIENT_FAILURE, status=UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed, shutting_down=0, pending_watcher=0x55580cd286b0
I0724 17:13:11.215726898  142846 pick_first.cc:412]                    Pick First 0x55580c8e02f0 subchannel list 0x55580cd2fa70 failed to connect to all subchannels
I0724 17:13:11.215729844  142846 child_policy_handler.cc:101]          [child_policy_handler 0x55580cc9bf40] started name re-resolving
I0724 17:13:11.215732563  142846 client_channel.cc:937]                chand=0x55580ce7d820: started name re-resolving
I0724 17:13:11.215735864  142846 polling_resolver.cc:245]              [polling resolver 0x55580cc08b00] in cooldown from last resolution (from 2 ms ago); will resolve again in 29998 ms
D0724 17:13:11.215739284  142846 posix_engine.cc:484]                  (event_engine) PosixEventEngine:0x55580cc5c7a0 scheduling callback:{140236654986496,7}
I0724 17:13:11.215743409  142846 client_channel.cc:922]                chand=0x55580ce7d820: update: state=TRANSIENT_FAILURE status=(UNAVAILABLE: failed to connect to all addresses; last error: UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed) picker=0x55580cca9cf0
I0724 17:13:11.215747544  142846 connectivity_state.cc:160]            ConnectivityStateTracker client_channel[0x55580ce7d918]: CONNECTING -> TRANSIENT_FAILURE (helper, UNAVAILABLE: failed to connect to all addresses; last error: UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed)
I0724 17:13:11.215751690  142846 client_channel.cc:2555]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: removing from queued picks list
I0724 17:13:11.215755605  142846 client_channel.cc:2599]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: grabbing LB mutex to get picker
I0724 17:13:11.215758534  142846 client_channel.cc:2609]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: performing pick with picker=0x55580cca9cf0
I0724 17:13:11.215761947  142846 client_channel.cc:2709]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: LB pick failed: UNAVAILABLE: failed to connect to all addresses; last error: UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed
I0724 17:13:11.215769625  142846 client_channel.cc:2638]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: failed to pick subchannel: error=UNKNOWN:failed to connect to all addresses; last error: UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed {grpc_status:14, created_time:"2023-07-24T17:13:11.215765125+01:00"}
I0724 17:13:11.215777313  142846 client_channel.cc:2829]               chand=0x55580ce7d820 lb_call=0x7f8b4c0026d0: failing 1 pending batches: UNKNOWN:failed to connect to all addresses; last error: UNAVAILABLE: ipv4:127.0.0.1:3593: Socket closed {grpc_status:14, created_time:"2023-07-24T17:13:11.215765125+01:00"}

It might be because we need to use https://grpc.github.io/grpc/python/grpc.html#grpc.local_channel_credentials?
@charithe
Copy link
Contributor Author

Turns out it's because I was using a self-signed certificate and the CN didn't have localhost in it. It looks like that in order to connect with a different authority, we need to set grpc.ssl_target_name_override option when creating the channel.

@charithe
Copy link
Contributor Author

Same for UDS. I think we need a way for the users to set channel options when creating the client.

@Sambigeara
Copy link
Collaborator

Thanks for doing the digging. I'll figure out a way to pass them in 👍

@Sambigeara Sambigeara self-assigned this Jul 25, 2023
@charithe
Copy link
Contributor Author

Thanks! In case you weren't aware, you can run make dev-server on the Cerbos repo to start a server with a self-signed cert.

@Sambigeara Sambigeara mentioned this issue Jul 26, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Sambigeara Sambigeara

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

enhancement: Support optional gRPC channel options cerbos/cerbos-sdk-python
2 participants
@charithe @Sambigeara