[MXS-3936] Expected status message in the context of queued command, but received a ARRAY Created: 2022-01-06  Updated: 2023-10-27  Resolved: 2022-03-29

Status: Closed
Project: MariaDB MaxScale
Component/s: cache
Affects Version/s: 6.2.0
Fix Version/s: 6.2.4

Type: Bug Priority: Major
Reporter: acsfer Assignee: Johan Wikman
Resolution: Fixed Votes: 1
Labels: None
Environment:

Ubuntu Focal


Sprint: MXS-SPRINT-152, MXS-SPRINT-153, MXS-SPRINT-154

 Description   

I've activated the cache with Redis, but each time Maxscale starts, this is logged:

error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.

I don't know if this is expected (it shouldn't as it is flagged as 'error') but trafic flow between Maxscale and Redis, and queries seems to be cached and Hit.

1641486142.092844 [0 10.1.0.3:34884] "GET" "user127.0.0.1@!-\xf3\x14\xfc\xaf\xf5\x85\xfd\xf6P4\xcb\xccx"
1641486142.095463 [0 10.1.0.3:34904] "GET" "user127.0.0.1L]6\x02\xe4U\xe1\x91\xc5\x02\x89\xd1\xce\xed\\l"
1641486142.096087 [0 10.1.0.3:34884] "GET" "user127.0.0.1\x0bhbI \a\xca\x96%?H\xb6\xd5)C\x9c"
1641486142.099103 [0 10.1.0.3:34904] "GET" "user127.0.0.1\xf0\x85h\x00\xed\x19\xc7\xb1\x02\xb5\n-\xdd\x0e\xf4|"
1641486142.099418 [0 10.1.0.3:34884] "GET" "user127.0.0.1\xbdh\x19]\xde2_L\x03\xca\x83\xef\xe0\x05\xea\xa6"
1641486142.102874 [0 10.1.0.3:34904] "GET" "user127.0.0.115mG\xf5\xeeqp5\x82\x01(\xad\x97\xf0\xdf"
1641486142.103658 [0 10.1.0.3:34884] "GET" "user127.0.0.1&\xf9\xc7\xd1\x1c\x97Z\x0bRF\xf0\xe0H.V\xef"

  • Maxscale 6.2.0 on 10.1.0.3
  • Redis 6.2.6 on 10.1.0.4


 Comments   
Comment by markus makela [ 2022-01-07 ]

Doesn't seem like it's expected, I'm pretty sure this is a bug of some sorts.

Comment by acsfer [ 2022-01-07 ]

Here a full log between start and stop of maxscale:

MariaDB MaxScale  /var/log/maxscale/maxscale.log  Thu Jan  6 22:51:39 2022
----------------------------------------------------------------------------
2022-01-06 22:51:39   notice : The systemd watchdog is Enabled. Internal timeout = 30s
2022-01-06 22:51:39   notice : Worker message queue size: 1MiB
2022-01-06 22:51:39   notice : Using up to 1.14GiB of memory for query classifier cache
2022-01-06 22:51:39   notice : syslog logging is enabled.
2022-01-06 22:51:39   notice : maxlog logging is enabled.
2022-01-06 22:51:39   notice : Host: 'fsn1-php2' OS: Linux@5.4.0-91-generic, #102-Ubuntu SMP Fri Nov 5 16:31:28 UTC 2021, x86_64 with 4 processor cores.
2022-01-06 22:51:39   notice : Total usable main memory: 7.59GiB.
2022-01-06 22:51:39   notice : MariaDB MaxScale 6.2.0 started (Commit: c7921a4e99b023e4c3ac8a1d197250c848ab9508)
2022-01-06 22:51:39   notice : MaxScale is running in process 2117888
2022-01-06 22:51:39   notice : Configuration file: /etc/maxscale.cnf
2022-01-06 22:51:39   notice : Log directory: /var/log/maxscale
2022-01-06 22:51:39   notice : Data directory: /var/lib/maxscale
2022-01-06 22:51:39   notice : Module directory: /usr/lib/x86_64-linux-gnu/maxscale
2022-01-06 22:51:39   notice : Service cache: /var/cache/maxscale
2022-01-06 22:51:39   notice : Working directory: /var/log/maxscale
2022-01-06 22:51:39   notice : Module 'qc_sqlite' loaded from '/usr/lib/x86_64-linux-gnu/maxscale/libqc_sqlite.so'.
2022-01-06 22:51:39   notice : Query classification results are cached and reused. Memory used per thread: 291.44MiB
2022-01-06 22:51:39   notice : Using encrypted passwords. Encryption key read from '/var/lib/maxscale/.secrets'.
2022-01-06 22:51:39   notice : MaxScale started with 4 worker threads.
2022-01-06 22:51:39   notice : Loading /etc/maxscale.cnf.
2022-01-06 22:51:39   notice : /etc/maxscale.cnf.d does not exist, not reading.
2022-01-06 22:51:39   notice : Module 'cache' loaded from '/usr/lib/x86_64-linux-gnu/maxscale/libcache.so'.
2022-01-06 22:51:39   notice : Module 'readwritesplit' loaded from '/usr/lib/x86_64-linux-gnu/maxscale/libreadwritesplit.so'.
2022-01-06 22:51:39   notice : Module 'galeramon' loaded from '/usr/lib/x86_64-linux-gnu/maxscale/libgaleramon.so'.
2022-01-06 22:51:39   notice : [cache] Creating shared cache.
2022-01-06 22:51:39   notice : [cache] Created multi threaded cache.
2022-01-06 22:51:39   warning: [cache] The used cache storage limits the maximum size of a value to 536870912 bytes, but either no value has been specified for max_resultset_size or the value is larger. Setting max_resultset_size to the maximum size.
2022-01-06 22:51:39   notice : Started REST API on [127.0.0.1]:8989
2022-01-06 22:51:39   notice : 'nbg1' sent version string '10.4.22-MariaDB-1:10.4.22+maria~focal'. Detected type: 'MariaDB', version: 10.4.22.
2022-01-06 22:51:39   notice : Server 'nbg1' charset: utf8mb4
2022-01-06 22:51:39   notice : 'nbg2' sent version string '10.4.22-MariaDB-1:10.4.22+maria~focal'. Detected type: 'MariaDB', version: 10.4.22.
2022-01-06 22:51:39   notice : Server 'nbg2' charset: utf8mb4
2022-01-06 22:51:39   notice : 'fsn1' sent version string '10.4.22-MariaDB-1:10.4.22+maria~focal'. Detected type: 'MariaDB', version: 10.4.22.
2022-01-06 22:51:39   notice : Server 'fsn1' charset: utf8mb4
2022-01-06 22:51:39   notice : Starting a total of 1 services...
2022-01-06 22:51:39   notice : (listener); Listening for connections at [127.0.0.1]:3306
2022-01-06 22:51:39   notice : Service 'readwritesplit' started (1/1)
2022-01-06 22:51:39   notice : Read 39 user@host entries from 'nbg1' for service 'readwritesplit'.
2022-01-06 22:55:01   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-01-06 23:12:56   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-01-06 23:25:06   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-01-06 23:39:59   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-01-06 23:57:06   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-01-07 00:03:10   notice : Stopped MaxScale REST API
2022-01-07 00:03:11   notice : MaxScale is shutting down.
2022-01-07 00:03:11   notice : All workers have shut down.
2022-01-07 00:03:11   notice : MaxScale shutdown completed.
2022-01-07 00:03:11   notice : MaxScale received signal SIGTERM. Exiting.
2022-01-07 00:03:11   MariaDB MaxScale is shut down.
----------------------------------------------------

Comment by Pramod Mahto [ 2022-02-22 ]

Similar issue reported for Maxscale 6.2.1 *and MariaDB 10.4.22-14*

 
2022-02-16 19:19:21   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-02-16 20:29:40   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-02-16 20:36:48   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-02-16 20:45:18   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-02-16 20:46:23   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
2022-02-16 20:57:15   error  : [storage_redis] Expected status message in the context of queued command, but received a ARRAY.
 

Comment by Johan Wikman [ 2022-03-03 ]

acs-ferreira Could you please provide your MaxScale and Redis configuration. Be sure to remove passwords and other sensitive information.
Johan

Comment by acsfer [ 2022-03-03 ]

Sorry but we've abandonned Redis as cache in the meanwhile.
Maybe Pramod can help you investigate this.

Comment by Johan Wikman [ 2022-03-29 ]

I could not repeat the error, but based upon code inspection I am fairly certain I was able to find and fix the problem. Further, the error handling and logging has been improved, so should the fix not cure the problem, the cache should nonetheless recover from this situation and continue to function normally. If this is not the case, please reopen this bug-report.

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