Skip to content

[grpcio>=1.68.0] Windows connection aborted after one minute #39631

Closed as duplicate of#38290
Closed as duplicate of#38290
[grpcio>=1.68.0] Windows connection aborted after one minute#39631
Assignees
sergiitksreenithiasheshvidyut
Labels
kind/buglang/Pythonpriority/P2
@TomaszNo

Description

@TomaszNo
TomaszNo
opened on May 22, 2025

What version of gRPC and what language are you using?

grpcio >= 1.68.01, Python

What operating system (Linux, Windows,...) and version?

Windows 11

What runtime / compiler are you using (e.g. python version or version of gcc)

Python 3.13

What did you do?

  1. I'm using route_guide example. In https://github.com/grpc/grpc/blob/master/examples/python/route_guide/route_guide_client.py after first 2 RPCs2 I'm adding a sleep of 61 seconds (at least 1 minute is needed).
    with grpc.insecure_channel("localhost:50051", options=options) as channel:
        stub = route_guide_pb2_grpc.RouteGuideStub(channel)
        print("-------------- GetFeature --------------")
        guide_get_feature(stub)

        # Additional line with sleep
        time.sleep(61)

        print("-------------- ListFeatures --------------")
        guide_list_features(stub)
        print("-------------- RecordRoute --------------")
        guide_record_route(stub)
        print("-------------- RouteChat --------------")
        guide_route_chat(stub)
  1. I'm running server and client. First 2 RPC calls work fine, then after the sleep I'm getting an error on client side:
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "IOCP/Socket: Connection aborted (An established connection was aborted by the software in your host machine.
 -- 10053)"
        debug_error_string = "UNKNOWN:Error received from peer  {created_time:"2025-05-21T15:47:41.4091295+00:00", grpc_status:14, grpc_message:"IOCP/Socket: Connection aborted (An established connection was aborted by the software in your host machine.\r\n -- 10053)"}"
  1. I increased the sleep on client side to few minutes and then re-run the server with gRPC tracing (with GRPC_TRACE = "all" and GRPC_VERBOSITY = "DEBUG"), after 1 minute I see in the logs3:
I0000 00:00:1747899282.463871   10356 iocp.cc:80] IOCP::0000025B869DB870 deadline exceeded
I0000 00:00:1747899282.463885   24064 windows_engine.cc:191] WindowsEventEngine:0000025B869DB7E0 executing callback:{0000025b889f7e80,000000000000000d}
I0000 00:00:1747899282.464058   24064 chttp2_transport.cc:1867] ipv6:%5B::1%5D:58725: Ping timeout. Closing transport.
I0000 00:00:1747899282.463997   10356 iocp.cc:74] IOCP::0000025B869DB870 doing work
I0000 00:00:1747899282.464132   24064 chttp2_transport.cc:970] W:Success(1) SERVER [ipv6:%5B::1%5D:58725] state IDLE -> WRITING [GOAWAY_SENT]    
I0000 00:00:1747899282.464225   24064 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNKNOWN:ping timeout {grpc_status:14, created_time:"2025-05-22T07:34:42.4642202+00:00"}
I0000 00:00:1747899282.471942   24064 chttp2_transport.cc:2928] ipv6:%5B::1%5D:58725: Complete BDP ping err=CANCELLED
I0000 00:00:1747899282.472094   24064 chttp2_transport.cc:970] W:Success(1) SERVER [ipv6:%5B::1%5D:58725] state WRITING -> WRITING [begin write in current thread]
I0000 00:00:1747899282.472333   24064 chttp2_transport.cc:1100] SERVER[Success(1)]: Write 29 bytes
I0000 00:00:1747899282.472481   24064 endpoint.cc:150] TCP: 0000025B86BF90E0 WRITE (peer=ipv6:%5B::1%5D:58725)
I0000 00:00:1747899282.472604   24064 windows_endpoint.cc:151] WindowsEndpoint::0000025B88984160 writing
I0000 00:00:1747899282.472657   24064 windows_endpoint.cc:163] WindowsEndpoint::0000025B88984160 WRITE (peer=ipv6:%5B::1%5D:58725): 
ping_t
I0000 00:00:1747899282.472707   24064 windows_endpoint.cc:163] WindowsEndpoint::0000025B88984160 WRITE (peer=ipv6:%5B::1%5D:58725): imeout       
I0000 00:00:1747899282.472811   24064 endpoint.cc:174] TCP: 0000025B86BF90E0 WRITE (peer=ipv6:%5B::1%5D:58725) error=OK
I0000 00:00:1747899282.472837   24064 chttp2_transport.cc:1113] SERVER[Success(1)]: Finish write
I0000 00:00:1747899282.472889   24064 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNKNOWN:goaway sent {created_time:"2025-05-22T07:34:42.4728856+00:00"}
I0000 00:00:1747899282.484469   24064 chttp2_transport.cc:970] W:Success(1) SERVER [ipv6:%5B::1%5D:58725] state WRITING -> IDLE [finish writing] 
I0000 00:00:1747899282.495655   20600 completion_queue.cc:1041] RETURN_EVENT[0000025B86CA89D0]: QUEUE_TIMEOUT
I0000 00:00:1747899282.495779   20600 completion_queue.cc:932] grpc_completion_queue_next(cq=0000025B86CA89D0, deadline=gpr_timespec { tv_sec: 1747899282, tv_nsec: 695000000, clock_type: 1 }, reserved=0000000000000000)
I0000 00:00:1747899282.484553   24064 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNKNOWN:Delayed close due to in-progress write {created_time:"2025-05-22T07:34:42.4719217+00:00", children:[UNKNOWN:ping timeout {grpc_status:14, created_time:"2025-05-22T07:34:42.4642202+00:00"}, UNKNOWN:goaway sent {created_time:"2025-05-22T07:34:42.4728856+00:00", grpc_status:14}]}
I0000 00:00:1747899282.510036   24064 chttp2_transport.cc:3138] transport Success(1) set connectivity_state=4; status=OK; reason=close_transport 
I0000 00:00:1747899282.510285   24064 connectivity_state.cc:150] ConnectivityStateTracker server_transport[0000025B8891D810]: READY -> SHUTDOWN (close_transport, OK)
I0000 00:00:1747899282.510469   24064 connectivity_state.cc:158] ConnectivityStateTracker server_transport[0000025B8891D810]: notifying watcher 0000025B88981D30: READY -> SHUTDOWN
I0000 00:00:1747899282.510606   24064 windows_engine.cc:252] WindowsEventEngine::0000025B869DB7E0 cancelling {0000025b889f84b0,000000000000000e} 
I0000 00:00:1747899282.510725   24064 endpoint.cc:348] EventEngine::Endpoint::0000025B86BF90E0 EndpointDestroy
I0000 00:00:1747899282.510880   24064 win_socket.cc:93] WinSocket::0000025B8695B630 Shut down from (null):-1. Reason: ~WindowsEndpoint
I0000 00:00:1747899282.511070   24064 win_socket.cc:87] WinSocket::0000025B8695B630 socket closed
I0000 00:00:1747899282.511184   24064 windows_endpoint.cc:76] ~WindowsEndpoint::0000025B88984160
I0000 00:00:1747899282.511076   10356 iocp.cc:95] IOCP::0000025B869DB870 got event on OVERLAPPED::0000025B8695B648
I0000 00:00:1747899282.511291   24064 memory_quota.cc:573] Removing allocator 0000025B8695AEC0
I0000 00:00:1747899282.511395   10356 win_socket.cc:174] WinSocket::0000025B8695B630 looking for matching OVERLAPPED::0000025B8695B648. read(0000025B8695B648) write(0000025B8695B688)
I0000 00:00:1747899282.511484   24064 connectivity_state.cc:73] watcher 0000025B88981D30: delivering async notification for SHUTDOWN (OK)        
I0000 00:00:1747899282.511595   10356 iocp.cc:74] IOCP::0000025B869DB870 doing work
I0000 00:00:1747899282.511603   17988 windows_endpoint.cc:283] WindowsEndpoint::0000025B88984160 Handling Read Event
I0000 00:00:1747899282.511659   24064 server.cc:1779] Disconnected client
I0000 00:00:1747899282.511882   17988 endpoint.cc:121] TCP: 0000025B86BF90E0 READ error=UNAVAILABLE: GetOverlappedResult: WSA Error (The I/O operation has been aborted because of either a thread exit or an application request.
 -- 995) [type.googleapis.com/grpc.status.time.created_time='2025-05-22T07:34:42.511585+00:00'] [type.googleapis.com/grpc.status.int.grpc_status='14']
I0000 00:00:1747899282.511955   24064 chttp2_transport.cc:2094] perform_transport_op[t=Success(1)]:
I0000 00:00:1747899282.512149   24064 memory_quota.cc:366] [0000025B8695B8C0] Early return 4096 bytes
I0000 00:00:1747899282.512082   17988 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNAVAILABLE:GetOverlappedResult: WSA Error (The I/O operation has been aborted because of either a thread exit or an application request.
 -- 995) {created_time:"2025-05-22T07:34:42.511585+00:00", grpc_status:14}
I0000 00:00:1747899282.522091   17988 win_socket.cc:93] WinSocket::0000025B8695B630 Shut down from (null):-1. Reason: ~AsyncIOState
I0000 00:00:1747899282.522456   17988 win_socket.cc:58] WinSocket::0000025B8695B630 already shutting down
I0000 00:00:1747899282.522670   17988 win_socket.cc:49] WinSocket::0000025B8695B630 destroyed
I0000 00:00:1747899282.522101   24024 chttp2_transport.cc:2094] perform_transport_op[t=Success(1)]:  DISCONNECT:UNKNOWN:Channel Destroyed {created_time:"2025-05-22T07:34:42.5220978+00:00"}
I0000 00:00:1747899282.528104   24024 memory_quota.cc:573] Removing allocator 0000025B8695B460
I0000 00:00:1747899282.528277   24024 init.cc:176] grpc_shutdown(void)
I0000 00:00:1747899282.528388   24024 chttp2_transport.cc:970] W:Success(1) SERVER [ipv6:%5B::1%5D:58725] state IDLE -> WRITING [GOAWAY_SENT]    
I0000 00:00:1747899282.528514   24024 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNKNOWN:Channel Destroyed {created_time:"2025-05-22T07:34:42.5220978+00:00"}
I0000 00:00:1747899282.534699   24024 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNKNOWN:Transport destroyed {occurred_during_write:1, created_time:"2025-05-22T07:34:42.5346943+00:00"}
I0000 00:00:1747899282.540326   24024 memory_quota.cc:573] Removing allocator 0000025B8695B6E0
I0000 00:00:1747899282.540506   24024 chttp2_transport.cc:970] W:Success(1) SERVER [ipv6:%5B::1%5D:58725] state WRITING -> IDLE [begin writing nothing]
I0000 00:00:1747899282.540817   24024 chttp2_transport.cc:1749] Success(1) CANCEL PINGS: UNKNOWN:Transport destroyed {created_time:"2025-05-22T07:34:42.5408145+00:00"}
I0000 00:00:1747899282.546544   24024 init.cc:176] grpc_shutdown(void)

What did you expect to see?

I expected the channel to be active. When using aio channel it works correctly. The same for gprcio <= 1.67.1.

What did you see instead?

The gRPC channel/connection is aborted.

Footnotes

  1. I tested all stable, non-yanked grpcio versions from PyPi: 1.68.0, 1.68.1, 1.69, 1.70.0 and 1.71.0 ↩

  2. One RPC call is not enough to reproduce the issue. ↩

  3. The log for grpcio==1.71.0 ↩

Metadata

Metadata

Assignees

Labels

kind/buglang/Pythonpriority/P2

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions