System.ArgumentNullException when trying to process enqueued jobs

[m18h]

Hello,

I am using Hangfire 1.6.8, with Redis DB. I have about 120,000 jobs enqueued, but the worker is not picking any of them up to process. The logs are however filled with:

Error occurred during execution of 'Worker #1bfac2d9' process. Execution will be retried (attempt 58 of 2147483647) in 00:05:00 seconds.
System.ArgumentNullException: String reference not set to an instance of a String. Parameter name: s at System.DateTime.Parse(String s, IFormatProvider provider, DateTimeStyles styles) at Hangfire.Pro.Redis.RedisConnection.GetJobData(String jobId) at Hangfire.States.BackgroundJobStateChanger.GetJobData(StateChangeContext context) at Hangfire.States.BackgroundJobStateChanger.ChangeState(StateChangeContext context) at Hangfire.Server.Worker.Execute(BackgroundProcessContext context) at Hangfire.Server.AutomaticRetryProcess.Execute(BackgroundProcessContext context)

Any help with this would be appreciated.

[odinserj]

Hi @BlitzinBuffalo. Something bad happened with your background jobs. This exception tells us that the CreatedAt field is null, but it can't be null under normal circumstances. Since this field is null, other fields may be malformed as well. What the dashboard tells about those background jobs? Could you send me result of the following Redis command against next background job ids in your queue?

lrange hangfire:queue:default -10 -1 // Getting job ids
hgetall hangfire:job:{job-id} 

[m18h]

@odinserj, on the dashboard, it just says the jobs have been enqueued

Here are the results of the commands:

192.168.1.100:6379> lrange hangfire:queue:statements -10 -1
 1) "dc6490f1-3b50-412f-875d-3db4d937230a"
 2) "fe9d0949-bf91-43cf-8808-43cd91dfe4a3"
 3) "9abd2f6c-1458-4df2-8511-b458cd1339f3"
 4) "b8ad7ec0-bee7-4189-a9be-6531fd12bb06"
 5) "44a58255-5c97-4991-a08c-354f6ff6e183"
 6) "8688dd8d-72a8-4ec7-b4c3-0c4239afa39b"
 7) "3f5ac95f-e418-4308-802d-dfa2eef736db"
 8) "302c3f6f-7349-47e4-8420-e747c74be936"
 9) "a4176818-d12c-404c-853e-a612582d74f3"
10) "d041437e-16ec-43b1-b2db-bc499b8d24ac"

192.168.1.100:6379> hgetall hangfire:job:dc6490f1-3b50-412f-875d-3db4d937230a
1) "State"
2) "Enqueued"

[odinserj]

There also should be Type, Method, ParameterTypes, Arguments and CreatedAt fields. Looks like the key is evicted just before the state change. This may happen due to the small JobExpirationTimeout is set in job filters, or when maxmemory-policy is set to other than noeviction value (please see recommended settings for Redis).

Are you setting JobExpirationTimeout? What is the output of the Redis' info command?

[m18h]

Our Redis db has all the recommended values set, and I have not set the JobExpirationTimeout setting.

Here is the output of the Redis info command:

Server
redis_version:3.2.100
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:dd26f1f93c5130ee
redis_mode:standalone
os:Windows
arch_bits:64
multiplexing_api:WinSock_IOCP
process_id:2188
run_id:2b264556397ca248eb0f9464039a6d36cd2887e6
tcp_port:6379
uptime_in_seconds:430469
uptime_in_days:4
hz:10
lru_clock:8162370
executable:C:\Program Files\Redis"C:\Program Files\Redis\redis-server.exe"
config_file:C:\Program Files\Redis\redis.windows-service.conf

Clients
connected_clients:15
client_longest_output_list:0
client_biggest_input_buf:0
blocked_clients:0

Memory
used_memory:1043752
used_memory_human:1019.29K
used_memory_rss:1005840
used_memory_rss_human:982.27K
used_memory_peak:1051639032
used_memory_peak_human:1002.92M
total_system_memory:0
total_system_memory_human:0B
used_memory_lua:34816
used_memory_lua_human:34.00K
maxmemory:0
maxmemory_human:0B
maxmemory_policy:noeviction
mem_fragmentation_ratio:0.96
mem_allocator:jemalloc-3.6.0

Persistence
loading:0
rdb_changes_since_last_save:586
rdb_bgsave_in_progress:0
rdb_last_save_time:1484557187
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
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:209
total_commands_processed:40041416
instantaneous_ops_per_sec:9
total_net_input_bytes:4125357671
total_net_output_bytes:2639945438
instantaneous_input_kbps:0.52
instantaneous_output_kbps:0.06
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
expired_keys:245884
evicted_keys:0
keyspace_hits:7275054
keyspace_misses:1402377
pubsub_channels:4
pubsub_patterns:0
latest_fork_usec:25205
migrate_cached_sockets: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:661.84
used_cpu_user:892.69
used_cpu_sys_children:0.00
used_cpu_user_children:0.00

Cluster
cluster_enabled:0

Keyspace
db0:keys=9,expires=0,avg_ttl=0

[m18h]

Any update to this issue?

[odinserj]

Sorry for the delay. I'm seeing this problem for the first time, and don't understand what's going on. As I stated earlier, looks like the hangfire:job:{job_id} key is evicted during the creation phase, just before the state change. This shouldn't be happening, because expiration time is set to 1 hour for that case (and all dates are in UTC).

The only explanation for this is your system clock (not time zone) was moved forward more than 1 hour. But that's very strange too. Another explanation is there's a bug in Redis for Windows, but I didn't see such reports on MSOpenTech/redis repository. However, there are some general bugs (for example). Does your Redis' error log contains any interesting records?

I could teach Hangfire to ignore such exceptions and proceed with background processing, but something terribly wrong is happening, and I don't like to fix it by ignoring symptoms.