[MXS-3578] Unexpected result state when using connection_keepalive Created: 2021-05-30  Updated: 2021-09-02  Resolved: 2021-06-18

Status: Closed
Project: MariaDB MaxScale
Component/s: Core
Affects Version/s: 2.5.11
Fix Version/s: 2.5.14

Type: Bug Priority: Major
Reporter: Alex Assignee: markus makela
Resolution: Fixed Votes: 0
Labels: None
Environment:

Debian Buster, Backend Mariadb 10.4.19


Issue Links:
Duplicate
is duplicated by MXS-3651 Xpandmon: Unexpected result state. cm... Closed
Sprint: MXS-SPRINT-133

 Description   

See this in log file:

2021-05-30 04:43:06   error  : (1509449) Unexpected result state. cmd: 0x00, len: 18 server: odonata
2021-05-30 04:43:06   error  : (1509450) Unexpected result state. cmd: 0xfe, len: 44 server: flea
2021-05-30 04:43:06   error  : (1509450) Unexpected result state. cmd: 0x00, len: 18 server: flea
2021-05-30 04:43:09   error  : (1433484) Unexpected result state. cmd: 0xfe, len: 44 server: flea
2021-05-30 04:43:09   error  : (1433485) Unexpected result state. cmd: 0xfe, len: 44 server: flea
2021-05-30 04:43:09   error  : (1433484) Unexpected result state. cmd: 0xfe, len: 44 server: odonata
2021-05-30 04:43:09   error  : (1433485) Unexpected result state. cmd: 0xfe, len: 44 server: odonata
2021-05-30 04:43:09   error  : (1433484) Unexpected result state. cmd: 0x00, len: 18 server: flea
2021-05-30 04:43:09   error  : (1433485) Unexpected result state. cmd: 0x00, len: 18 server: flea
2021-05-30 04:43:09   error  : (1433484) Unexpected result state. cmd: 0x00, len: 18 server: odonata
2021-05-30 04:43:09   error  : (1433485) Unexpected result state. cmd: 0x00, len: 18 server: odonata
2021-05-30 04:43:09   error  : (1503070) Unexpected result state. cmd: 0xfe, len: 44 server: flea
2021-05-30 04:43:09   error  : (1503070) Unexpected result state. cmd: 0xfe, len: 44 server: odonata
2021-05-30 04:43:09   error  : (1503070) Unexpected result state. cmd: 0x00, len: 18 server: flea
2021-05-30 04:43:09   error  : (1503070) Unexpected result state. cmd: 0x00, len: 18 server: odonata
2021-05-30 04:43:10   error  : (1503072) Unexpected result state. cmd: 0xfe, len: 44 server: flea
2021-05-30 04:43:10   error  : (1503072) Unexpected result state. cmd: 0xfe, len: 44 server: odonata
2021-05-30 04:43:10   error  : (1503072) Unexpected result state. cmd: 0x00, len: 18 server: flea



 Comments   
Comment by markus makela [ 2021-05-30 ]

Can you attach the configuration that generates this output? Please remove any sensitive information from it before uploading.

If you know which actions cause this to happen or it happens relatively often, you can enable log_info to get verbose log output that would help explain why it does this.

Comment by Alex [ 2021-05-31 ]

cat /var/lib/maxscale/maxscale.cnf.d/*

[flea]
address=10.0.0.1
extra_port=0
persistmaxtime=60000ms
persistpoolmax=500
port=3306
priority=0
protocol=MariaDBBackend
proxy_protocol=false
rank=primary
ssl=false
ssl_cert_verify_depth=9
ssl_verify_peer_certificate=false
ssl_verify_peer_host=false
ssl_version=MAX
type=server
 
[maxscale]
admin_auth=true
admin_enabled=true
admin_gui=true
admin_host=127.0.0.1
admin_log_auth_failures=true
admin_port=8989
admin_secure_gui=true
auth_connect_timeout=10000ms
auth_read_timeout=10000ms
auth_write_timeout=10000ms
dump_last_statements=never
load_persisted_configs=true
log_debug=false
log_info=false
log_notice=true
log_throttling=0,0ms,0ms
log_warn_super_user=true
log_warning=true
max_auth_errors_until_block=10
maxlog=true
ms_timestamp=false
passive=false
query_classifier=qc_sqlite
query_classifier_cache_size=0
query_retries=1
query_retry_timeout=5000ms
rebalance_period=0ms
rebalance_threshold=20
rebalance_window=10
retain_last_statements=0
session_trace=0
skip_permission_checks=false
sql_mode=default
syslog=false
threads=2
users_refresh_interval=0ms
users_refresh_time=30000ms
writeq_high_water=16777216
writeq_low_water=8192
 
[odonata]
address=10.0.0.2
extra_port=0
persistmaxtime=60000ms
persistpoolmax=500
port=3306
priority=0
protocol=MariaDBBackend
proxy_protocol=false
rank=primary
ssl=false
ssl_cert_verify_depth=9
ssl_verify_peer_certificate=false
ssl_verify_peer_host=false
ssl_version=MAX
type=server
 
[Read-Write-Service]
type=service
router=readwritesplit
user=maxscale
password=Jg7Vjf$bd0B
enable_root_user=false
max_connections=0
connection_timeout=0
net_write_timeout=0
auth_all_servers=true
strip_db_esc=true
log_auth_warnings=true
session_track_trx_state=false
retain_last_statements=-1
session_trace=false
rank=primary
connection_keepalive=300s
causal_reads=local
causal_reads_timeout=3s
delayed_retry=true
delayed_retry_timeout=30s
disable_sescmd_history=false
lazy_connect=false
master_accept_reads=true
master_failure_mode=fail_on_write
master_reconnection=true
max_sescmd_history=1500
max_slave_connections=255
max_slave_replication_lag=1s
optimistic_trx=false
prune_sescmd_history=true
retry_failed_reads=true
slave_connections=255
slave_selection_criteria=ADAPTIVE_ROUTING
strict_multi_stmt=true
strict_sp_calls=true
transaction_replay=true
transaction_replay_attempts=20
transaction_replay_max_size=1073741824
transaction_replay_retry_on_deadlock=false
use_sql_variables_in=master
cluster=TheMonitor
 
[TheMonitor]
type=monitor
module=mariadbmon
user=maxscale
password=Jg7Vjf$bd0B
servers=flea,ladybug,odonata
monitor_interval=1000ms
backend_connect_timeout=3s
backend_read_timeout=3s
backend_write_timeout=3s
backend_connect_attempts=1
journal_max_age=28800s
disk_space_check_interval=0ms
script_timeout=90s
events=all
failcount=5
ignore_external_masters=false
auto_failover=false
failover_timeout=90s
switchover_timeout=90s
replication_master_ssl=false
verify_master_failure=true
master_failure_timeout=10s
auto_rejoin=false
enforce_read_only_slaves=true
switchover_on_low_disk_space=false
maintenance_on_low_disk_space=true
handle_events=true
assume_unique_hostnames=true
enforce_simple_topology=false
cooperative_monitoring_locks=none
master_conditions=primary_monitor_master
slave_conditions=none
 
[ladybug]
address=10.0.0.3
extra_port=0
persistmaxtime=0ms
persistpoolmax=0
port=3306
priority=0
protocol=mariadbbackend
proxy_protocol=false
rank=primary
ssl=false
ssl_cert_verify_depth=9
ssl_verify_peer_certificate=false
ssl_verify_peer_host=false
ssl_version=MAX
type=server

2021-05-31 04:21:13   info   : (1751899) [mariadbclient] Client 'mmm'@'::ffff:10.0.1.1' is attempting a COM_CHANGE_USER to 'mmm'.
2021-05-31 04:21:13   info   : (1751899) Found matching user 'mmm'@'%' for client 'meshok7'@'::ffff:10.0.1.1' with sufficient privileges.
2021-05-31 04:21:13   info   : (1751899) [mariadbclient] COM_CHANGE_USER from 'mmm'@'::ffff:10.0.1.1' to 'mmm' in service 'Read-Write-Service' succeeded.
2021-05-31 04:21:13   info   : (1751899) [readwritesplit] (Read-Write-Service) Storing query (len: 112 cmd: 11), expecting -64 replies to current command: 
2021-05-31 04:23:42   error  : (1751899) Unexpected result state. cmd: 0xfe, len: 44 server: odonata
2021-05-31 04:23:42   error  : (1751899) Unexpected result state. cmd: 0xfe, len: 44 server: ladybug
2021-05-31 04:23:42   error  : (1751899) Unexpected result state. cmd: 0x00, len: 18 server: odonata
2021-05-31 04:23:42   info   : (1751899) [readwritesplit] (Read-Write-Service) Reply complete, last reply from odonata
2021-05-31 04:23:42   error  : (1751899) Unexpected result state. cmd: 0x00, len: 18 server: ladybug
2021-05-31 04:23:42   info   : (1751899) [readwritesplit] (Read-Write-Service) Reply complete, last reply from ladybug

Comment by Alex [ 2021-05-31 ]

Another observation.

We are using PHP 7.4 with mysqli.

Somtimes we get unexpected results for queries like this:

mysqli_query($db,"select GET_LOCK('test', 600)");

This query should return a result set with one row, but sometimes we got TRUE which should happend only with queries like INSERT/UPDATE.

It does not happend when we connect directly to MariaDB.

Comment by markus makela [ 2021-05-31 ]

One thing to test would be if setting persistpoolmax to 0 has any effect. If it does, it means the problem is in the persistent connection pool.

Comment by Alex [ 2021-05-31 ]

Changed for one of the servers - did not help
Changed for all servers - did not help

Comment by markus makela [ 2021-05-31 ]

Another thing to test would be to set causal_reads=none for the service but I think this might change the functional behavior of MaxScale and your application might execute stale reads. If you can test it, it would help identify which part the problem is in.

Comment by Alex [ 2021-05-31 ]

Can not do that. Stale reads are not acceptable in our workload.

Comment by Alex [ 2021-06-01 ]

I turned persistent connections in PHP off. ( mysqli_connect() )

It fixed the problem.

PHP 7.4.16 debian buster.

It seems that if connection stays innactive for some time this problem happends.

Comment by markus makela [ 2021-06-01 ]

Hmm, that would suggest that it could be caused by the connection_keepalive feature. To check whether this is the case, you can disable it with connection_keepalive=0s.

Comment by Alex [ 2021-06-01 ]

To clarify.

The problem has gone when I disabled persistent connections between application and maxscale. Not between maxscale and backend servers.

Do you still think I should try to disable the connection_keepalive feature?

Comment by markus makela [ 2021-06-01 ]

If possible, please test with connection_keepalive=0s and enable the persistent connections between your application and MaxScale. This would help us identify where the problem is in MaxScale and you'd be able to use persistent connections.

Comment by Alex [ 2021-06-01 ]

made this:

maxctrl alter service Read-Write-Service connection_keepalive 0

observing

Comment by Alex [ 2021-06-01 ]

With persistent connections from app to maxscale and connection_keepalive=0

30 minutes, everything is OK

Comment by markus makela [ 2021-06-01 ]

OK, that seems to suggest the problem is with that feature. I'll update the title of this issue.

Comment by markus makela [ 2021-06-16 ]

I think I've managed to reproduce this using connection_keepalive=1s and sending COM_CHANGE_USER commands slower than the keepalive ping is sent.

Generated at Thu Feb 08 04:22:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.