MySQL Bugs: #110564: Router tests failing on macOS

Bug #110564	Router tests failing on macOS
Submitted:	30 Mar 2023 9:09	Modified:	30 Mar 2023 10:24
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	Tests	Severity:	S3 (Non-critical)
Version:	8.0.32	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
A high proportion of router tests fail on macOS:

The following tests FAILED:
	220 - routertest_component_async_replicaset (Failed)
	236 - routertest_component_metadata_ttl (Failed)
	247 - routertest_component_routing (Failed)
	250 - routertest_component_routing_strategy (Failed)
	257 - routertest_component_socket_close (Failed)
	260 - routertest_component_routing_splicer (Failed)
	262 - routertest_integration_routing_direct (Failed)
	263 - routertest_integration_routing_reuse (Failed)

Re-runing with verbose output routertest_component_routing:

[ RUN      ] RouterRoutingTest.ConnectTimeoutShutdownEarlyXProtocol
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/component/test_routing.cc:394: Failure
Value of: res.error()
Expected: (is equal to 2006) or (is equal to 2002)
  Actual: 2026 (of type int)
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/component/test_routing.cc:398: Failure
Value of: res.what()
Expected: (has substring "MySQL server has gone away") or (has substring "Connection refused connecting to")
  Actual: 0x600000bfc100 pointing to "connecting to backend failed" (of type char const*)
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/helpers/process_manager.cc:644: Failure
Failed
# Process: (pid=22118)
/Users/laurynas/vilniusdb/mysql-8.0.32/_build-debug/runtime_output_directory/mysqlrouter -c /tmp/conf-nbPGHx/mysqlrouter.conf --core-file

## Log content:

2023-03-30 12:00:48.911 main DEBUG [0x1e61a1b40]   init 'logger' succeeded.
2023-03-30 12:00:48.911 io INFO [0x1e61a1b40] starting 10 io-threads, using backend 'poll'
2023-03-30 12:00:48.912 main DEBUG [0x1e61a1b40]   init 'io' succeeded.
2023-03-30 12:00:48.912 main DEBUG [0x1e61a1b40]   init 'connection_pool' succeeded.
2023-03-30 12:00:48.912 main DEBUG [0x1e61a1b40]   init 'destination_status' succeeded.
2023-03-30 12:00:48.912 main DEBUG [0x1e61a1b40]   init 'router_openssl' succeeded.
2023-03-30 12:00:48.913 main DEBUG [0x1e61a1b40]   init 'routing' succeeded.
2023-03-30 12:00:48.913 main DEBUG [0x1e61a1b40] Starting: io, routing:timeout.
2023-03-30 12:00:48.913 main DEBUG [0x1e61a1b40] Waiting for readiness of: log_reopen, signal_handler, routing:timeout
2023-03-30 12:00:48.913 main DEBUG [0x1e61a1b40]   ready 'log_reopen'
2023-03-30 12:00:48.913 main DEBUG [0x1e61a1b40]   ready 'signal_handler'
2023-03-30 12:00:48.913 main DEBUG [0x1e61a1b40] Using NOTIFY_SOCKET='/tmp/router-SeFwne/kkygerwxdbcb' for the 'STATUS=running' notification
2023-03-30 12:00:48.913 routing INFO [0x16f817000] [routing:timeout] started: routing strategy = first-available
2023-03-30 12:00:48.913 routing INFO [0x16f817000] Start accepting connections for routing routing:timeout listening on 11013
2023-03-30 12:00:48.913 main DEBUG [0x16f817000]   ready 'routing:timeout'
2023-03-30 12:00:48.913 main DEBUG [0x16f817000] Ready, signaling notify socket
2023-03-30 12:00:48.914 main DEBUG [0x16f817000] Using NOTIFY_SOCKET='/tmp/router-SeFwne/kkygerwxdbcb' for the 'READY=1' notification
2023-03-30 12:00:48.916 routing DEBUG [0x16f78b000] [routing:timeout] fd=27 connection accepted at 127.0.0.1:11013
2023-03-30 12:00:48.917 routing WARNING [0x16f213000] 67: resolve() failed: nodename nor servname provided, or not known
2023-03-30 12:00:48.917 routing WARNING [0x16f213000] connecting to backend failed: No such file or directory (generic:2)
2023-03-30 12:00:49.119 main DEBUG [0x1e61a1b40] Shutting down.
2023-03-30 12:00:49.120 main DEBUG [0x1e61a1b40] Using NOTIFY_SOCKET='/tmp/router-SeFwne/kkygerwxdbcb' for the 'STOPPING=1
STATUS=Router shutdown in progress
' notification
2023-03-30 12:00:49.120 main WARNING [0x1e61a1b40] sending 'STOPPING=1
STATUS=Router shutdown in progress
' to NOTIFY_SOCKET='/tmp/router-SeFwne/kkygerwxdbcb' failed: Connection refused
2023-03-30 12:00:49.121  DEBUG [0x16f817000] Clear shared unreachable destinations quarantine list
2023-03-30 12:00:49.121 routing INFO [0x16f817000] Stop accepting connections for routing routing:timeout listening on 11013
2023-03-30 12:00:49.121 routing INFO [0x16f817000] [routing:timeout] stopped
2023-03-30 12:00:49.121 main DEBUG [0x16f817000]   start 'routing:timeout' succeeded.
2023-03-30 12:00:49.123 main DEBUG [0x16f78b000]   start 'io' succeeded.
2023-03-30 12:00:49.123 main DEBUG [0x1e61a1b40] Deinitializing plugins: routing, router_protobuf, router_openssl, connection_pool, io.
2023-03-30 12:00:49.124 main DEBUG [0x1e61a1b40]   deinit 'routing' succeeded.
2023-03-30 12:00:49.124 main DEBUG [0x1e61a1b40]   deinit 'router_protobuf' succeeded.
2023-03-30 12:00:49.124 main DEBUG [0x1e61a1b40]   deinit 'router_openssl' succeeded.
2023-03-30 12:00:49.124 main DEBUG [0x1e61a1b40]   deinit 'connection_pool' succeeded.
2023-03-30 12:00:49.124 main DEBUG [0x1e61a1b40]   deinit 'io' succeeded.
2023-03-30 12:00:49.124 main DEBUG [0x1e61a1b40] Unloading all plugins.

[  FAILED  ] RouterRoutingTest.ConnectTimeoutShutdownEarlyXProtocol (283 ms)
...

Also, if ASan/UBSan are enabled, the test processes balloon up to hundreds of gigabytes of RAM taken, and then crash with core dumps in terabytes (the latter is expected with ASan IIRC, but the former isn't).

How to repeat:
For the regular failure:
-DWITH_DEBUG=ON
make
ctest

For the large sanitized processes:
-DWITH_DEBUG=ON -DWITH_ASAN=ON -DWITH_ASAN_SCOPE=ON -DWITH_UBSAN=ON
make
ctest

[ RUN      ] ConnectTimeout/RouterRoutingConnectTimeoutTest.ConnectTimeout/0
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/component/test_routing.cc:241: Failure
Expected: (end - start) >= (GetParam().expected_connect_timeout), actual: 1ms vs 1000ms
Google Test trace:
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/component/test_routing.cc:220: // connect and trigger a timeout in the router
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/component/test_routing.cc:194: // build router config with connect_timeout=1
/Users/laurynas/vilniusdb/mysql-8.0.32/router/tests/helpers/process_manager.cc:644: Failure
Failed
# Process: (pid=22141)
/Users/laurynas/vilniusdb/mysql-8.0.32/_build-debug/runtime_output_directory/mysqlrouter -c /tmp/router-nuuqH0/mysqlrouter.conf --core-file

## Log content:

2023-03-30 12:00:50.578 main DEBUG [0x1e61a1b40]   init 'logger' succeeded.
2023-03-30 12:00:50.579 io INFO [0x1e61a1b40] starting 10 io-threads, using backend 'poll'
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40]   init 'io' succeeded.
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40]   init 'connection_pool' succeeded.
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40]   init 'destination_status' succeeded.
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40]   init 'router_openssl' succeeded.
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40]   init 'routing' succeeded.
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40] Starting: io, routing:timeout.
2023-03-30 12:00:50.580 main DEBUG [0x1e61a1b40] Waiting for readiness of: log_reopen, signal_handler, routing:timeout
2023-03-30 12:00:50.581 main DEBUG [0x1e61a1b40]   ready 'log_reopen'
2023-03-30 12:00:50.581 main DEBUG [0x1e61a1b40]   ready 'signal_handler'
2023-03-30 12:00:50.581 main DEBUG [0x1e61a1b40] Using NOTIFY_SOCKET='/tmp/router-nuuqH0/gycomaokfqnz' for the 'STATUS=running' notification
2023-03-30 12:00:50.581 routing INFO [0x16ba2f000] [routing:timeout] started: routing strategy = first-available
2023-03-30 12:00:50.581 routing INFO [0x16ba2f000] Start accepting connections for routing routing:timeout listening on 11018
2023-03-30 12:00:50.581 main DEBUG [0x16ba2f000]   ready 'routing:timeout'
2023-03-30 12:00:50.581 main DEBUG [0x16ba2f000] Ready, signaling notify socket
2023-03-30 12:00:50.581 main DEBUG [0x16ba2f000] Using NOTIFY_SOCKET='/tmp/router-nuuqH0/gycomaokfqnz' for the 'READY=1' notification
2023-03-30 12:00:50.582 routing DEBUG [0x16b9a3000] [routing:timeout] fd=27 connection accepted at 127.0.0.1:11018
2023-03-30 12:00:50.583 routing ERROR [0x16b42b000] no backend available to connect to
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40] Shutting down.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40] Using NOTIFY_SOCKET='/tmp/router-nuuqH0/gycomaokfqnz' for the 'STOPPING=1
STATUS=Router shutdown in progress
' notification
2023-03-30 12:00:50.584 main WARNING [0x1e61a1b40] sending 'STOPPING=1
STATUS=Router shutdown in progress
' to NOTIFY_SOCKET='/tmp/router-nuuqH0/gycomaokfqnz' failed: Connection refused
2023-03-30 12:00:50.584  DEBUG [0x16ba2f000] Clear shared unreachable destinations quarantine list
2023-03-30 12:00:50.584 routing INFO [0x16ba2f000] Stop accepting connections for routing routing:timeout listening on 11018
2023-03-30 12:00:50.584 routing INFO [0x16ba2f000] [routing:timeout] stopped
2023-03-30 12:00:50.584 main DEBUG [0x16ba2f000]   start 'routing:timeout' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x16b9a3000]   start 'io' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40] Deinitializing plugins: routing, router_protobuf, router_openssl, connection_pool, io.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40]   deinit 'routing' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40]   deinit 'router_protobuf' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40]   deinit 'router_openssl' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40]   deinit 'connection_pool' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40]   deinit 'io' succeeded.
2023-03-30 12:00:50.584 main DEBUG [0x1e61a1b40] Unloading all plugins.

[  FAILED  ] ConnectTimeout/RouterRoutingConnectTimeoutTest.ConnectTimeout/0, where GetParam() = 56-byte object <01-00 00-00 00-00 00-00 31-00 D3-04 01-00 00-00 B0-2A 72-6D 01-00 00-00 F0-2D 72-6D 01-00 00-01 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00> (51 ms)

The rest of the failures are familiar to the last one

Hello Laurynas,

Thank you for the report and feedback!

regards,
Umesh