h2_sockpair_test.exe shutdown_finishes_calls newly flakes on windows

[dgquintas]

From new flakes report:

Test: h2_sockpair_test.exe shutdown_finishes_calls, Polling: None, Timestamp: 2017-10-24 14:38:25 UTC, url: https://kokoro2.corp.google.com/job/grpc/job/windows/job/master/job/grpc_basictests/34

https://sponge.corp.google.com/target?id=8176946b-0c65-41e6-bb71-b9551aa8edcd&target=grpc/windows/master/grpc_basictests&searchFor=&show=FAILED&sortBy=STATUS

2017-10-24 14:20:37,407 D1024 14:20:37.376000000  3944 test_config.c:388] test slowdown factor: sanitizer=1, fixture=1, poller=1, total=1


D1024 14:20:37.376000000  3944 dns_resolver.cc:306] Using native dns resolver


I1024 14:20:37.376000000  3944 shutdown_finishes_calls.c:38] Running test: test_early_server_shutdown_finishes_inflight_calls/chttp2/socketpair


E1024 14:20:37.392000000  3944 shutdown_finishes_calls.c:164] assertion failed: status == GRPC_STATUS_INTERNAL || status == GRPC_STATUS_UNAVAILABLE


Abort handler called.


*** 0: 0000000000DE8BEC  - 0000000000000000


*** 1: 0000000000DE883D  - 0000000000000000


*** 2: 000000006C704672 abort - 000000006C704640


*** 3: 0000000000D8E272 abort - 000000006C704640


*** 4: 0000000000D8DDFE abort - 000000006C704640


*** 5: 0000000000D727FA abort - 000000006C704640


*** 6: 0000000000D7123F abort - 000000006C704640


*** 7: 0000000000E423FB abort - 000000006C704640


*** 8: 0000000074DD336A BaseThreadInitThunk - 0000000074DD3358


*** 9: 00000000770E9902 RtlInitializeExceptionChain - 00000000770E989F


*** 10: 00000000770E98D5 RtlInitializeExceptionChain - 00000000770E989F


Command exited with non-zero status 1

real 0.07

user 0.00

sys 0.01



2017-10-24 14:20:37,407 FAILED: cmake/build/Release/h2_sockpair_test.exe shutdown_finishes_calls [ret=1, pid=6264, time=0.1sec]

[dgquintas]

@jtattermusch , do you think you could take a quick look?

[dgquintas]

Latest instance: https://sponge.corp.google.com/target?id=e6c208dc-de47-401c-907c-4ceb3702cfa1&target=github/grpc/c_windows_dbg_native&searchFor=&show=FAILED&sortBy=STATUS

[jtattermusch]

Last instance is for h2_http_proxy_test.exe shutdown_finishes_calls which I think has been fixed already.

[jtattermusch]

I checked historical data and last occurence of
cmake/build/Release/h2_http_proxy_test.exe shutdown_finishes_calls has been a while ago. Closing.

[muxi]

Seen again in https://sponge.corp.google.com/target?id=98cb06d5-79c7-4bd4-a1e0-13d4cd388677&target=github/grpc/c_windows_dbg_native&searchFor=&show=FAILED&sortBy=STATUS

[jtattermusch]

Similar problem https://sponge.corp.google.com/target?id=efc8fd1e-ddea-4f53-b5cd-350f7e018a60&target=github/grpc/c_windows_dbg_native&searchFor=&show=FAILED&sortBy=STATUS

[jtattermusch]

The most common occurrence is now https://sponge.corp.google.com/target?id=7ac64368-2d47-4c05-b3a2-52aff4374e28&target=github/grpc/c_windows_dbg_native&searchFor=&show=FAILED&sortBy=STATUS

cmake/build/Debug/h2_http_proxy_test.exe shutdown_finishes_calls

Failure
D1213 23:48:48.375000000  2808 test_config.cc:388] test slowdown factor: sanitizer=1, fixture=1, poller=1, total=1
D1213 23:48:48.375000000  2808 dns_resolver.cc:293] Using native dns resolver
I1213 23:48:48.375000000  2808 shutdown_finishes_calls.cc:38] Running test: test_early_server_shutdown_finishes_inflight_calls/chttp2/fullstack
I1213 23:48:50.421000000  2808 http_proxy_fixture.cc:529] Proxy address: localhost:17118
I1213 23:48:50.421000000  2808 http_connect_handshaker.cc:294] Connecting to server localhost:27438 via HTTP proxy ipv6:[::1]:17118
D1213 23:48:50.421000000  2808 http_proxy_fixture.cc:375] on_read_request_done: 00571A90 "No Error"
I1213 23:48:50.421000000  2808 http_proxy_fixture.cc:153] HTTP proxy server read: {"created":"@1513237730.421000000","description":"An established connection was aborted by the software in your host machine.\r\n","file":"T:\src\github\grpc\workspace_c_windows_dbg_native\src\core\lib\iomgr\tcp_windows.cc","file_line":172}
E1213 23:48:50.421000000  2808 shutdown_finishes_calls.cc:165] assertion failed: status == GRPC_STATUS_INTERNAL || status == GRPC_STATUS_UNAVAILABLE
Abort handler called.
*** 0: 0000000000FBA80F print_current_stack - 0000000000FBA770
*** 1: 0000000000FBAD7B abort_handler - 0000000000FBAD50
*** 2: 0000000074BAF0CB raise - 0000000074BAED60
*** 3: 0000000074BB0622 abort - 0000000074BB05F0
*** 4: 0000000000ED8D6A test_early_server_shutdown_finishes_inflight_calls - 0000000000ED86C0
*** 5: 0000000000ED9090 shutdown_finishes_calls - 0000000000ED9060
*** 6: 0000000000E8E9DE grpc_end2end_tests - 0000000000E8D160
*** 7: 0000000000E8CEAA main - 0000000000E8CE30
*** 8: 00000000010F685E invoke_main - 00000000010F6840
*** 9: 00000000010F66C0 __scrt_common_main_seh - 00000000010F6570
*** 10: 00000000010F655D __scrt_common_main - 00000000010F6550
*** 11: 00000000010F6878 mainCRTStartup - 00000000010F6870
*** 12: 000000007510336A BaseThreadInitThunk - 0000000075103358
*** 13: 0000000077829902 RtlInitializeExceptionChain - 000000007782989F
*** 14: 00000000778298D5 RtlInitializeExceptionChain - 000000007782989F
Command exited with non-zero status 1
real 2.10
user 0.00
sys 0.00

[jtattermusch]

Likely same rootcause as #14471 (which is much more common).