iOS Unit Test Flake - CallAPIv2Tests testTimeoutBackoff2]

[dennycd]

As seen from

• sample https://source.cloud.google.com/results/invocations/30f0a4ea-5a82-4440-8326-05a282694ede/log

Test Case '-[CallAPIv2Tests testTimeoutBackoff2]' started.
I0516 11:16:41.539143000 123145378361344 subchannel.cc:955]            subchannel 0x7fe390030600 {address=ipv4:127.0.0.1:10000, args={grpc.client_channel_factory=0x6000036dfad0, grpc.default_authority=127.0.0.1:10000, grpc.http2_scheme=https, grpc.initial_reconnect_backoff_ms=400, grpc.internal.channel_credentials=0x6000017ecfa0, grpc.internal.security_connector=0x600001acb600, grpc.internal.subchannel_pool=0x600001fc5340, grpc.min_reconnect_backoff_ms=700, grpc.primary_user_agent=grpc-objc-cfstream/1.47.0-dev, grpc.resource_quota=0x600003ae25e0, grpc.server_uri=dns:///127.0.0.1:10000}}: connect failed ({"created":"@1652725001.538968000","description":"tcp handshaker shutdown","file":"src/core/lib/transport/tcp_connect_handshaker.cc","file_line":116}), backing off for -52 ms
I0516 11:16:41.539405000 123145378361344 subchannel.cc:901]            subchannel 0x7fe390030600 {address=ipv4:127.0.0.1:10000, args={grpc.client_channel_factory=0x6000036dfad0, grpc.default_authority=127.0.0.1:10000, grpc.http2_scheme=https, grpc.initial_reconnect_backoff_ms=400, grpc.internal.channel_credentials=0x6000017ecfa0, grpc.internal.security_connector=0x600001acb600, grpc.internal.subchannel_pool=0x600001fc5340, grpc.min_reconnect_backoff_ms=700, grpc.primary_user_agent=grpc-objc-cfstream/1.47.0-dev, grpc.resource_quota=0x600003ae25e0, grpc.server_uri=dns:///127.0.0.1:10000}}: connection attempt requested while backoff timer was pending, retrying now
I0516 11:16:41.643632000 123145381580800 subchannel.cc:955]            subchannel 0x7fe38f04ac00 {address=ipv4:127.0.0.1:10000, args={grpc.client_channel_factory=0x6000036dfad0, grpc.default_authority=127.0.0.1:10000, grpc.http2_scheme=https, grpc.initial_reconnect_backoff_ms=800, grpc.internal.channel_credentials=0x6000017de490, grpc.internal.security_connector=0x600001ace300, grpc.internal.subchannel_pool=0x600001fc5340, grpc.min_reconnect_backoff_ms=300, grpc.primary_user_agent=grpc-objc-cfstream/1.47.0-dev, grpc.resource_quota=0x600003ae25e0, grpc.server_uri=dns:///127.0.0.1:10000}}: connect failed ({"created":"@1652725001.643459000","description":"tcp handshaker shutdown","file":"src/core/lib/transport/tcp_connect_handshaker.cc","file_line":116}), backing off for -3 ms
I0516 11:16:42.420716000 123145378361344 subchannel.cc:955]            subchannel 0x7fe390030600 {address=ipv4:127.0.0.1:10000, args={grpc.client_channel_factory=0x6000036dfad0, grpc.default_authority=127.0.0.1:10000, grpc.http2_scheme=https, grpc.initial_reconnect_backoff_ms=400, grpc.internal.channel_credentials=0x6000017ecfa0, grpc.internal.security_connector=0x600001acb600, grpc.internal.subchannel_pool=0x600001fc5340, grpc.min_reconnect_backoff_ms=700, grpc.primary_user_agent=grpc-objc-cfstream/1.47.0-dev, grpc.resource_quota=0x600003ae25e0, grpc.server_uri=dns:///127.0.0.1:10000}}: connect failed ({"created":"@1652725002.420552000","description":"tcp handshaker shutdown","file":"src/core/lib/transport/tcp_connect_handshaker.cc","file_line":116}), backing off for -10 ms
I0516 11:16:48.667141000 123145381580800 subchannel.cc:901]            subchannel 0x7fe38f04ac00 {address=ipv4:127.0.0.1:10000, args={grpc.client_channel_factory=0x6000036dfad0, grpc.default_authority=127.0.0.1:10000, grpc.http2_scheme=https, grpc.initial_reconnect_backoff_ms=800, grpc.internal.channel_credentials=0x6000017de490, grpc.internal.security_connector=0x600001ace300, grpc.internal.subchannel_pool=0x600001fc5340, grpc.min_reconnect_backoff_ms=300, grpc.primary_user_agent=grpc-objc-cfstream/1.47.0-dev, grpc.resource_quota=0x600003ae25e0, grpc.server_uri=dns:///127.0.0.1:10000}}: connection attempt requested while backoff timer was pending, retrying now
I0516 11:16:48.711681000 123145378361344 subchannel.cc:901]            subchannel 0x7fe390030600 {address=ipv4:127.0.0.1:10000, args={grpc.client_channel_factory=0x6000036dfad0, grpc.default_authority=127.0.0.1:10000, grpc.http2_scheme=https, grpc.initial_reconnect_backoff_ms=400, grpc.internal.channel_credentials=0x6000017ecfa0, grpc.internal.security_connector=0x600001acb600, grpc.internal.subchannel_pool=0x600001fc5340, grpc.min_reconnect_backoff_ms=700, grpc.primary_user_agent=grpc-objc-cfstream/1.47.0-dev, grpc.resource_quota=0x600003ae25e0, grpc.server_uri=dns:///127.0.0.1:10000}}: connection attempt requested while backoff timer was pending, retrying now
src/objective-c/tests/UnitTests/APIv2Tests.m:409: error: -[CallAPIv2Tests testTimeoutBackoff2] : (([[NSDate date] timeIntervalSinceDate:startTime]) less than (maxConnectTime + kMargin)) failed: ("7.87385702133") is not less than ("0.9")
Test Case '-[CallAPIv2Tests testTimeoutBackoff2]' failed (7.875 seconds). 

It appears that iOS/ObjC has not set min_reconnect_backoff_ms in the event of a reconnection (700ms in the sample) which result in the overall timeout time well exceeding the test expectation (0.91 secs)

--

@HannahShiSFB