MySQL Bugs: #109118: mysql router connect error

Bug #109118	mysql router connect error
Submitted:	17 Nov 2022 2:00	Modified:	18 Dec 2022 15:20
Reporter:	WANG FENG	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Router	Severity:	S2 (Serious)
Version:	8.0.29	OS:	CentOS (7.7.1908)
Assigned to:	MySQL Verification Team	CPU Architecture:	x86 (x86_64)

Description:
Mysql router log file gets a lot of error like this:
"2022-11-17 09:40:33 routing INFO [7f14ea4a3700] [routing:bootstrap_rw] 10.86.132.231:7744 closed connection before finishing handshake"

Pelease tell me how can i fix this. thank you!

[root@MYSQL-SIT-FARM03 router]# cat mysqlrouter.conf
# File automatically generated during MySQL Router bootstrap
[DEFAULT]
user=mysql
logging_folder=/xxx/my4000/router/log
runtime_folder=/xxx/my4000/router/run
data_folder=/xxx/my4000/router/data
keyring_path=/xxx/my4000/router/data/keyring
master_key_path=/xxx/my4000/router/mysqlrouter.key
connect_timeout=5
read_timeout=30
dynamic_state=/xxx/my4000/router/data/state.json
client_ssl_cert=/xxx/my4000/router/data/router-cert.pem
client_ssl_key=/xxx/my4000/router/data/router-key.pem
client_ssl_mode=PREFERRED
server_ssl_mode=AS_CLIENT
server_ssl_verify=DISABLED
unknown_config_option=error

[logger]
level=INFO

[metadata_cache:bootstrap]
cluster_type=gr
router_id=5
user=routeruser
metadata_cluster=xxx
ttl=0.5
auth_cache_ttl=-1
auth_cache_refresh_interval=2
use_gr_notifications=0

[routing:bootstrap_rw]
bind_address=0.0.0.0
bind_port=4001
destinations=metadata-cache://xxx/?role=PRIMARY
routing_strategy=first-available
protocol=classic
connect_timeout=20
client_connect_timeout=9

#[routing:bootstrap_ro]
#bind_address=0.0.0.0
#bind_port=4002
#destinations=metadata-cache://xxx/?role=SECONDARY
#routing_strategy=round-robin-with-fallback
#protocol=classic

#[routing:bootstrap_x_rw]
#bind_address=0.0.0.0
#bind_port=4003
#destinations=metadata-cache://xxx/?role=PRIMARY
#routing_strategy=first-available
#protocol=x

#[routing:bootstrap_x_ro]
#bind_address=0.0.0.0
#bind_port=4004
#destinations=metadata-cache://xxx/?role=SECONDARY
#routing_strategy=round-robin-with-fallback
#protocol=x

[http_server]
port=8443
ssl=1
ssl_cert=/xxx/my4000/router/data/router-cert.pem
ssl_key=/xxx/my4000/router/data/router-key.pem

[http_auth_realm:default_auth_realm]
backend=default_auth_backend
method=basic
name=default_realm

[rest_router]
require_realm=default_auth_realm

[rest_api]

[http_auth_backend:default_auth_backend]
backend=metadata_cache

[rest_routing]
require_realm=default_auth_realm

[rest_metadata_cache]
require_realm=default_auth_realm

How to repeat:
Always happend in my application.

Mysql router version 8.0.29 
Mysql version 8.0.26 Centos 7.7.1908 x86_64
client use Connector/NET

tcpdump data analized by wireshark

Attachment: tcpdump.PNG (image/png, text), 67.86 KiB.

Hi,

I cannot reproduce this.

Do you have any actual issues with your application other then errors in the log?

Please try to reproduce this using 
MySQL Server 8.0.31
MySQL Router 8.0.31
and .net connector 8.0.31

Thanks

Do you have any actual issues with your application other then errors in the log?
The answer is: yes, application has connection error occasionally.

I got the tcp packet using tcpdump, and i found that  after tcp connection handshake finish between client and router as well as router and mysql server, the client nevel send any packets to router ,which difference than normal, at the end, mysql server will send a 'Got timeout reading communication packets' message to router.

the error messages like this 

"longdate": "2022-11-18 11:34:21.3175", 
"level": "ERROR", 
"logger": "Grpc.AspNetCore.Server.ServerCallHandler", 
"message": "Error when executing service method 'ClearTimeout'.", 
"exception": "System.Exception: Unable to connect to any of the specified MySQL hosts.
 ---> MySql.Data.MySqlClient.MySqlException (0x80004005): Unable to connect to any of the specified MySQL hosts.
   at MySql.Data.Failover.FailoverManager.AttemptConnection(MySqlConnection connection, String originalConnectionString, String& connectionString, Boolean mySqlPoolManager)
   at MySql.Data.MySqlClient.MySqlConnection.Open()
   at System.Data.Common.DbConnection.OpenAsync(CancellationToken cancellationToken)
--- End of stack trace from previous location ---
   at FreeSql.MySql.MySqlConnectionPoolPolicy.OnGetAsync(Object`1 obj)
   at FreeSql.Internal.ObjectPool.ObjectPool`1.GetAsync()
   at FreeSql.Internal.CommonProvider.AdoProvider.ExecuteNonQueryAsync(DbConnection connection, DbTransaction transaction, CommandType cmdType, String cmdText, Int32 cmdTimeout, DbParameter[] cmdParms, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at FreeSql.Internal.CommonProvider.AdoProvider.LoggerException(IObjectPool`1 pool, PrepareCommandResult pc, Exception ex, DateTime dt, StringBuilder logtxt, Boolean isThrowException)
   at FreeSql.Internal.CommonProvider.AdoProvider.ExecuteNonQueryAsync(DbConnection connection, DbTransaction transaction, CommandType cmdType, String cmdText, Int32 cmdTimeout, DbParameter[] cmdParms, CancellationToken cancellationToken)
   at FreeSql.Internal.CommonProvider.UpdateProvider`1.<>c__DisplayClass60_0.<<RawExecuteAffrowsAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at FreeSql.Internal.CommonProvider.UpdateProvider`1.ToSqlFetchAsync(Func`2 fetchAsync)
   at FreeSql.Internal.CommonProvider.UpdateProvider`1.RawExecuteAffrowsAsync(CancellationToken cancellationToken)
   at FreeSql.Internal.CommonProvider.UpdateProvider`1.SplitExecuteAffrowsAsync(Int32 valuesLimit, Int32 parameterLimit, CancellationToken cancellationToken)
   at Laiye.EntCmd.Service.CoreModule.Repositories.WorkerRepository.ClearTimeout(Int64 databaseId) in \/src\/Laiye.EntCmd.Service.CoreModule\/Repositories\/WorkerRepository.cs:line 1173
   at Laiye.EntCmd.Service.CoreModule.Services.WorkerService.ClearTimeout(ClearTimeoutRequest request, ServerCallContext context) in \/src\/Laiye.EntCmd.Service.CoreModule\/Services\/WorkerService.cs:line 830
   at Grpc.Shared.Server.UnaryServerMethodInvoker`3.ResolvedInterceptorInvoker(TRequest resolvedRequest, ServerCallContext resolvedContext)
   at Grpc.Shared.Server.UnaryServerMethodInvoker`3.ResolvedInterceptorInvoker(TRequest resolvedRequest, ServerCallContext resolvedContext)
   at Laiye.EntUC.Core.Common.LaiyeExceptionInterceptor.UnaryServerHandler[TRequest,TResponse](TRequest request, ServerCallContext context, UnaryServerMethod`2 continuation)
   at Grpc.Shared.Server.InterceptorPipelineBuilder`2.<>c__DisplayClass5_0.<<UnaryPipeline>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Grpc.Shared.Server.InterceptorPipelineBuilder`2.<>c__DisplayClass5_0.<<UnaryPipeline>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Grpc.AspNetCore.Server.Internal.CallHandlers.UnaryServerCallHandler`3.HandleCallAsyncCore(HttpContext httpContext, HttpContextServerCallContext serverCallContext)
   at Grpc.AspNetCore.Server.Internal.CallHandlers.ServerCallHandlerBase`3.<HandleCallAsync>g__AwaitHandleCall|8_0(HttpContextServerCallContext serverCallContext, Method`2 method, Task handleCall)"

I'm testing using 
MySQL Server 8.0.31
MySQL Router 8.0.31
and .net connector 8.0.31

The answer will soon;

Hi,
I'm testing using 8.0.31 (MySQL Server, Connect/NET,Mysql Router) and the problem still there.

Hi,

I cannot reproduce this. Please supply a minimal project I can compile to try to reproduce this.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".