Redis error in the logs: Expected 'OK' got '1'

question
1

I noticed following Redis-related error in the Hangfire-related logs (we use HangfirePro with Redis backend). It does not seem to affect functionality (all jobs run through fine) and dashboard does not show any errors.

Should I be concerned? Can we make our logs cleaner without disabling this logger?

An exception occurred while processing a job. It will be re-queued.
ServiceStack.Redis.RedisResponseException: Unknown reply on integer response: 4216, sPort: 14152, LastCommand:
at ServiceStack.Redis.RedisNativeClient.CreateResponseError(String error) in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisNativeClient.ReadLong() in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisNativeClient.SendExpectLong(Byte[][] cmdWithBinaryArgs) in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisNativeClient.Del(String key) in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisLock.Dispose() in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at Hangfire.Redis.RedisConnection.DistributedLockWrapper.Dispose() in c:\projects\hangfire-pro\src\Hangfire.Redis\RedisConnection.cs:line 483
at Hangfire.States.BackgroundJobStateChanger.ChangeState(StateChangeContext context) in C:\develop\AAAA\Current\WebApplications\AAAAWeb\Tools\Hangfire\src\Hangfire.Core\States\BackgroundJobStateChanger.cs:line 96
at Hangfire.Server.Worker.Execute(BackgroundProcessContext context) in C:\develop\AAAA\Current\WebApplications\AAAAWeb\Tools\Hangfire\src\Hangfire.Core\Server\Worker.cs:line 127

Error occurred during execution of ‘Worker #d6b6b78c’ process. Execution will be retried (attempt 1 of 2147483647) in 00:00:00 seconds.
ServiceStack.Redis.RedisResponseException: Expected ‘OK’ got ‘1’, sPort: 14152, LastCommand:
at ServiceStack.Redis.RedisNativeClient.CreateResponseError(String error) in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisNativeClient.ExpectWord(String word) in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisNativeClient.ExpectOk() in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.Pipeline.QueuedRedisOperation.ProcessResult() in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at ServiceStack.Redis.RedisTransaction.Commit() in c:\projects\hangfire-pro\src\Hangfire.Redis\Properties\Annotations.cs:line 0
at Hangfire.Redis.RedisFetchedJob.Requeue() in c:\projects\hangfire-pro\src\Hangfire.Redis\RedisFetchedJob.cs:line 71
at Hangfire.Redis.RedisFetchedJob.Dispose() in c:\projects\hangfire-pro\src\Hangfire.Redis\RedisFetchedJob.cs:line 83
at Hangfire.Server.Worker.Execute(BackgroundProcessContext context) in C:\develop\AAAA\Current\WebApplications\AAAAWeb\Tools\Hangfire\src\Hangfire.Core\Server\Worker.cs:line 159
at Hangfire.Server.ServerProcessExtensions.Execute(IServerProcess process, BackgroundProcessContext context) in C:\develop\AAAA\Current\WebApplications\AAAAWeb\Tools\Hangfire\src\Hangfire.Core\Server\ServerProcessExtensions.cs:line 39
at Hangfire.Server.AutomaticRetryProcess.Execute(BackgroundProcessContext context) in C:\develop\XXX\Current\XXX\XXX\Tools\Hangfire\src\Hangfire.Core\Server\AutomaticRetryProcess.cs:line 57

2

This exception sometimes appear due to non-synchronized access to the RedisConnection object from multiple threads. This may happen directly when using custom job or state filters and sharing the object for different threads, or indirectly, when passing IJobCancellationToken to other threads. Are you using custom filters or IJobCancellationToken? If yes, can you show me how do you use them?

Sometimes this may happen due to firewall issues, it may cause killing idle connections. Redis itself may kill connections, please ensure that you have client timeout disabled (response for the CONFIG GET timeout Redis command should be zero). Any thoughts?

3

Thank you for looking into this. We do not use IJobCancellationToken and we do not access RedisConnection object from multiple threads.

It appears that the error is related to Redis configuration. We have 2 Redis servers (both running the same version 2.8.24) and if we point Hangfire server to one of them - everything is running clean, and if we point to another then we get high rate of errors “Expected ‘OK’ got ‘1’”.

Sometimes the first error happens right away after server start (1-2 sec after hangfire worker started) when processing the very first job.

BOTH servers return “0” for “CONFIG GET timeout” command

C:…\Tools\Redis\Redis-x64-2.8.2104>redis-cli.exe -h 192.168.2.37 -p 6379 CONFIG GET timeout

  1. “timeout”
  2. “0”

C:…\Tools\Redis\Redis-x64-2.8.2104>redis-cli.exe -h 192.168.2.20 -p 6379 CONFIG GET timeout

  1. “timeout”
  2. “0”

What other Redis configuration parameters may cause this ?

Redis INFO output for both servers below if it helps.

================
WORKS

Server

redis_version:2.8.24

redis_git_sha1:00000000

redis_git_dirty:0

redis_build_id:65111979569a38e8

redis_mode:standalone

os:Linux 3.5.0-17-generic x86_64

arch_bits:64

multiplexing_api:epoll

gcc_version:4.7.2

process_id:1106

run_id:7063f1b4ba47a171b1b4b0b09f99a1e19ff078b5

tcp_port:6379

uptime_in_seconds:595263

uptime_in_days:6

hz:10

lru_clock:3448924

config_file:/etc/redis.conf

Clients

connected_clients:1

client_longest_output_list:0

client_biggest_input_buf:0

blocked_clients:0

Memory

used_memory:867424

used_memory_human:847.09K

used_memory_rss:2867200

used_memory_peak:16085592

used_memory_peak_human:15.34M

used_memory_lua:36864

mem_fragmentation_ratio:3.31

mem_allocator:jemalloc-3.6.0

Persistence

loading:0

rdb_changes_since_last_save:124092

rdb_bgsave_in_progress:0

rdb_last_save_time:1479248669

rdb_last_bgsave_status:ok

rdb_last_bgsave_time_sec:-1

rdb_current_bgsave_time_sec:-1

aof_enabled:0

aof_rewrite_in_progress:0

aof_rewrite_scheduled:0

aof_last_rewrite_time_sec:-1

aof_current_rewrite_time_sec:-1

aof_last_bgrewrite_status:ok

aof_last_write_status:ok

Stats

total_connections_received:528

total_commands_processed:288460

instantaneous_ops_per_sec:0

total_net_input_bytes:226216857

total_net_output_bytes:81383146

instantaneous_input_kbps:0.00

instantaneous_output_kbps:0.00

rejected_connections:0

sync_full:0

sync_partial_ok:0

sync_partial_err:0

expired_keys:12956

evicted_keys:0

keyspace_hits:39264

keyspace_misses:71545

pubsub_channels:0

pubsub_patterns:0

latest_fork_usec:0

Replication

role:master

connected_slaves:0

master_repl_offset:0

repl_backlog_active:0

repl_backlog_size:1048576

repl_backlog_first_byte_offset:0

repl_backlog_histlen:0

CPU

used_cpu_sys:465.63

used_cpu_user:304.38

used_cpu_sys_children:0.00

used_cpu_user_children:0.00

Keyspace

db0:keys=193,expires=54,avg_ttl=2110818705

=================================
HIGH RATE OF ERRORS: Expected ‘OK’ got ‘1’

Server

redis_version:2.8.24

redis_git_sha1:00000000

redis_git_dirty:0

redis_build_id:4df63a5f7093a212

redis_mode:standalone

os:Linux 2.6.32-642.6.2.el6.x86_64 x86_64

arch_bits:64

multiplexing_api:epoll

gcc_version:4.4.7

process_id:2220

run_id:e125bd479fe5fb9e198ceced23184f5248a8b89f

tcp_port:6379

uptime_in_seconds:241

uptime_in_days:0

hz:10

lru_clock:3448808

config_file:/etc/redis/redis.conf

Clients

connected_clients:147

client_longest_output_list:0

client_biggest_input_buf:0

blocked_clients:39

Memory

used_memory:49075464

used_memory_human:46.80M

used_memory_rss:59322368

used_memory_peak:51602656

used_memory_peak_human:49.21M

used_memory_lua:36864

mem_fragmentation_ratio:1.21

mem_allocator:jemalloc-3.6.0

Persistence

loading:0

rdb_changes_since_last_save:7454

rdb_bgsave_in_progress:0

rdb_last_save_time:1479843575

rdb_last_bgsave_status:ok

rdb_last_bgsave_time_sec:-1

rdb_current_bgsave_time_sec:-1

aof_enabled:0

aof_rewrite_in_progress:0

aof_rewrite_scheduled:0

aof_last_rewrite_time_sec:-1

aof_current_rewrite_time_sec:-1

aof_last_bgrewrite_status:ok

aof_last_write_status:ok

Stats

total_connections_received:451

total_commands_processed:22782

instantaneous_ops_per_sec:61

total_net_input_bytes:41744971

total_net_output_bytes:49595021

instantaneous_input_kbps:68.84

instantaneous_output_kbps:179.22

rejected_connections:0

sync_full:0

sync_partial_ok:0

sync_partial_err:0

expired_keys:982

evicted_keys:0

keyspace_hits:4046

keyspace_misses:2627

pubsub_channels:1

pubsub_patterns:0

latest_fork_usec:0

Replication

role:master

connected_slaves:0

master_repl_offset:0

repl_backlog_active:0

repl_backlog_size:1048576

repl_backlog_first_byte_offset:0

repl_backlog_histlen:0

CPU

used_cpu_sys:1.63

used_cpu_user:1.24

used_cpu_sys_children:0.00

used_cpu_user_children:0.00

Keyspace

db0:keys=24102,expires=22787,avg_ttl=33449415

db1:keys=1468,expires=1468,avg_ttl=595410707

4

Thanks for the detailed output. I don’t see any difference other than high number of active clients on a problem server. How many workers do you have? The Expected ‘OK’ got ‘1’ error appears in your case after another problem, when Hangfire tries to requeue a background job whose processing was failed due to an exception.

Looks like something strange happen either with ServiceStack.Redis, or with Redis instance itself. Problems like this were caused only by multi-threaded access, or by a firewall.

Have you tried to use Hangfire.Pro.Redis 2.X?
Did you run make test before performing make install for Redis?

5

Btw, what versions of Hangfire.Core and Hangfire.Pro.Redis are you using? Do you use any extension packages?

6

Upgrading to Hangire Pro 1.4.7 and Redis Storage 2.0.4 helped on my local machine. We will deploy this code to production and see if this issue is fully fixed.

Thank you for your help!

7

Good to know, StackExchange.Redis package that is used by Hangfire.Pro 2.X, is more stable. Please let me know if you have any issues with the new version!