3.0.500.7_1 Access Violation Exception - Windows Server 2012 R2 Standard

[BoasE]

We have potentially the same issue as here #376. But as I'm not quite sure i open a new post.

As this one impacts on our production site this is quite urgent for us
We use Redis 3.0.500.7_1

We have one redis master, 2 Slaves and 3 Sentinels.

We also use SignalR which uses redis, and we use redis for some custom cache implementations
We Connect with ServiceSTack Redis and on the .net side we get this exception

System.InvalidOperationException: ERR Error running script (call to f_5b8e3b60e050400311bc8b6ef2cbba37bc0b9cb3): @user_script:1: @user_script: 1: -MISCONF Redis is configured to save RDB snapshots, but is currently not able to persist on disk. Commands that may modify the data set are disabled. Please check Redis logs for details about the error.
at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.Send(Func`2 send, Object state)
at Microsoft.AspNet.SignalR.Infrastructure.Connection.Send(ConnectionMessage message)
at Microsoft.AspNet.SignalR.Transports.TransportConnectionExtensions.SendCommand(ITransportConnection connection, String connectionId, CommandType commandType)
at Microsoft.AspNet.SignalR.Transports.ForeverTransport.ProcessRequestCore(ITransportConnection connection)

Before 2 Weeks we upgraded to the current version of Redis windows. not it ran without problems. but not it seems like its crashin every two hors with this

[8616] 27 Dec 18:11:45.687 * Background saving started by pid 7780
[8616] 27 Dec 18:12:08.991 # fork operation complete
[8616] 27 Dec 18:12:09.644 * Background saving terminated with success
[8616] 27 Dec 18:12:54.314 # Client id=14001 addr=79.133.49.6:13428 fd=450 name=GREEN-PARROT03 age=343 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16384 oll=1 omem=18446744073709551551 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:12:54.314 # Client id=14002 addr=79.133.49.4:17766 fd=445 name=GREEN-PARROT02 age=343 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16384 oll=1 omem=18446744073709551551 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:13:35.035 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:13:35.137 * Background saving started by pid 14780
[8616] 27 Dec 18:13:58.141 # fork operation complete
[8616] 27 Dec 18:13:58.856 * Background saving terminated with success
[8616] 27 Dec 18:15:22.234 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:15:22.336 * Background saving started by pid 18040
[8616] 27 Dec 18:15:44.840 # fork operation complete
[8616] 27 Dec 18:15:45.500 * Background saving terminated with success
[8616] 27 Dec 18:17:06.299 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:17:06.415 * Background saving started by pid 14056
[8616] 27 Dec 18:17:29.725 # fork operation complete
[8616] 27 Dec 18:17:30.439 * Background saving terminated with success
[8616] 27 Dec 18:17:38.214 # Client id=14004 addr=79.133.49.6:19461 fd=446 name=GREEN-PARROT03 age=284 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=1 omem=18446744073709551581 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:17:38.214 # Client id=14003 addr=79.133.49.4:4294 fd=447 name=GREEN-PARROT02 age=284 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=1 omem=18446744073709551581 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:19:02.937 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:19:03.044 * Background saving started by pid 6864
[8616] 27 Dec 18:19:26.250 # fork operation complete
[8616] 27 Dec 18:19:26.936 * Background saving terminated with success
[8616] 27 Dec 18:20:44.857 # Client id=14005 addr=79.133.49.6:5810 fd=453 name=GREEN-PARROT03 age=186 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16384 oll=1 omem=18446744073709551601 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:20:44.857 # Client id=14006 addr=79.133.49.4:8991 fd=452 name=GREEN-PARROT02 age=186 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16384 oll=1 omem=18446744073709551601 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:20:49.822 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:20:49.926 * Background saving started by pid 8828
[8616] 27 Dec 18:21:13.132 # fork operation complete
[8616] 27 Dec 18:21:13.903 * Background saving terminated with success
[8616] 27 Dec 18:22:15.941 # Client id=14007 addr=79.133.49.4:11774 fd=455 name=GREEN-PARROT02 age=91 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16379 oll=1 omem=18446744073709551610 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:22:15.941 # Client id=14008 addr=79.133.49.6:8810 fd=456 name=GREEN-PARROT03 age=91 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16379 oll=1 omem=18446744073709551610 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 27 Dec 18:22:47.087 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:22:47.192 * Background saving started by pid 6656
[6656] 27 Dec 18:22:47.891 #

=== REDIS BUG REPORT START: Cut & paste starting from here ===
[6656] 27 Dec 18:22:47.891 # Redis version: 3.0.500
[6656] 27 Dec 18:22:47.891 # --- EXCEPTION_ACCESS_VIOLATION
[6656] 27 Dec 18:22:47.891 # --- STACK TRACE
redis-server.exe!((null):0)(0x000BE600, 0x0013FF90, 0x00000001, 0x40123730)
redis-server.exe!((null):0)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
KERNELBASE.dll!UnhandledExceptionFilter((null):0)(0x00000000, 0xB8B01AA0, 0x00000000, 0x0013FF20)
ntdll.dll!memset((null):0)(0x000BF230, 0x00000000, 0x40129C28, 0x00000000)
ntdll.dll!_C_specific_handler((null):0)(0x00000000, 0x000BE770, 0x000BF230, 0x000BF230)
ntdll.dll!_chkstk((null):0)(0x00000001, 0xBB750000, 0x00000000, 0xBB88309C)
ntdll.dll!RtlRaiseException((null):0)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!KiUserExceptionDispatcher((null):0)(0x31AF2F2B, 0x02800000, 0xB33FFF8E, 0xB314A2BC)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0xBA547880, 0xBA547880, 0x00000001, 0x00000034)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0xBA547880, 0x400A00B3, 0x0013F6E0, 0x00000034)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x2CB86EE6, 0x00000001, 0x02407040, 0xE4E49D10)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x0013F6E0, 0x00000001, 0xBA547880, 0xBA547880)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x4014F210, 0x008C0000, 0x00000005, 0x00CC2754)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x008C0000, 0x567D4016, 0x008C0000, 0x00000005)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x00000005, 0x00000000, 0x00347340, 0x00000005)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x00000006, 0x00000000, 0xFFFFE000, 0x003486D0)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x00000000, 0x00000000, 0x00000000, 0xFFFFE000)
redis-server.exe!KiUserExceptionDispatcher((null):0)(0x00000000, 0x4004382C, 0x00000000, 0x00000000)
KERNEL32.DLL!BaseThreadInitThunk((null):0)(0xBB0113B0, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!RtlUserThreadStart((null):0)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
ntdll.dll!RtlUserThreadStart((null):0)(0x00000000, 0x00000000, 0x00000000, 0x00000000)
[6656] 27 Dec 18:22:47.894 # --- INFO OUTPUT
[8616] 27 Dec 18:22:48.692 # fork operation failed
[8616] 27 Dec 18:22:48.872 # Background saving terminated by signal 1
[8616] 27 Dec 18:22:53.078 * 10000 changes in 60 seconds. Saving...
[8616] 27 Dec 18:22:53.160 * Background saving started by pid 7196
[8616] 27 Dec 18:23:16.064 # fork operation complete
[8616] 27 Dec 18:23:16.638 * Background saving terminated with success
[8616] 27 Dec 18:28:17.076 * 10 changes in 300 seconds. Saving...
[8616] 27 Dec 18:28:17.190 * Background saving started by pid 19344

Any suggestions ?

[enricogior]

Hi @Gentlehag
from the stack trace it seems a different problem from the #376.
Can you please post the log lines before the crash? (20 lines should be enough)
Can you please post the server configuration file?
What Windows server are you running?
Thank you.

[SebastianStehle]

Hi Enrico,
I am his colleague, so I am just going to answer his questions:

We had a mongocluster with one primary, 2 slaves and 3 sentinels running on Windows Server 2012 R2 with a SSD Raid and enough RAM. The config file of the master is:

include redis.windows.conf
logfile "D:\\Redis\\host\\redis.master.log"
port 6379
maxmemory 8gb
dir D:\Redis\host

The log file:

[8616] 26 Dec 19:06:43.569 # Client id=6003 addr=79.133.49.6:18192 fd=106 name=GREEN-PARROT03 age=641 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=1 omem=18446744073709551583 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 26 Dec 19:06:43.570 # Client id=6004 addr=79.133.49.4:15452 fd=61 name=GREEN-PARROT02 age=641 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=0 oll=1 omem=18446744073709551583 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 26 Dec 19:06:55.235 # fork operation complete
[8616] 26 Dec 19:06:55.893 * Background saving terminated with success
[8616] 26 Dec 19:08:26.175 * 10000 changes in 60 seconds. Saving...
[8616] 26 Dec 19:08:26.279 * Background saving started by pid 11088
[8616] 26 Dec 19:08:48.089 # fork operation complete
[8616] 26 Dec 19:08:48.794 * Background saving terminated with success
[8616] 26 Dec 19:10:23.909 * 10000 changes in 60 seconds. Saving...
[8616] 26 Dec 19:10:24.017 * Background saving started by pid 14076
[8616] 26 Dec 19:10:46.128 # fork operation complete
[8616] 26 Dec 19:10:46.839 * Background saving terminated with success
[8616] 26 Dec 19:12:24.427 * 10000 changes in 60 seconds. Saving...
[8616] 26 Dec 19:12:24.530 * Background saving started by pid 5028
[8616] 26 Dec 19:12:46.441 # fork operation complete
[8616] 26 Dec 19:12:47.150 * Background saving terminated with success
[8616] 26 Dec 19:14:04.120 # Client id=6005 addr=79.133.49.6:8777 fd=11 name=GREEN-PARROT03 age=441 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16380 oll=1 omem=18446744073709551597 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 26 Dec 19:14:04.120 # Client id=6006 addr=79.133.49.4:6951 fd=62 name=GREEN-PARROT02 age=441 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16380 oll=1 omem=18446744073709551597 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.
[8616] 26 Dec 19:14:13.645 * 10000 changes in 60 seconds. Saving...
[8616] 26 Dec 19:14:13.756 * Background saving started by pid 7764
[8616] 26 Dec 19:14:36.318 # fork operation complete
[8616] 26 Dec 19:14:37.074 * Background saving terminated with success
[8616] 26 Dec 19:16:04.389 * 10000 changes in 60 seconds. Saving...
[8616] 26 Dec 19:16:04.494 * Background saving started by pid 13440
[8616] 26 Dec 19:16:26.500 # fork operation complete
[8616] 26 Dec 19:16:27.144 * Background saving terminated with success
[8616] 26 Dec 19:18:01.342 * 10000 changes in 60 seconds. Saving...
[8616] 26 Dec 19:18:01.448 * Background saving started by pid 1132
[1132] 26 Dec 19:18:14.175 # 

We are not sure yet, why we reached the buffer limit, probably there was a network issues. We see a drop in our network activity at this time.

[enricogior]

Hi @SebastianStehle
thanks for the additional infos.
The crash occurs in the child process and the server handles it so that the next save can complete without errors. Unfortunately the stack trace isn't useful to determine the cause of the crash.
I can prepare a private build to try to improve the crash report, let me know if it would be ok for you to use the private build.
Thank you.

[SebastianStehle]

Hi Enrico, at the moment we cannot afford it to work with an unstable version. Sorry.

[enricogior]

@SebastianStehle
sure, no problem.

[enricogior]

@Gentlehag, @SebastianStehle
today we released 3.0.501 with a critical fix for a different issue, you should stop using 3.0.500 and upgrade to 3.0.501.
I'm going to close this issue since 3.0.500 is not supported anymore, if you run into the same issue with 3.0.501 please reopen it specifying that it reproduced with the new version.
Thank you.

[SebastianStehle]

Do you know that it is fixed? We cannot reproduce it in the testing environment and it is too critical to use in our production system. Therefore working with a version that might be stable is not option for us.

[enricogior]

@SebastianStehle
the fix released with 3.0.501 is for a different bug.
During the stress test for 3.0.501 we haven't seen the issue you reported, so it may be fixed as well but I can't guarantee it.

[BoasE]

could this issue be related to the clustering / sentinels or is this less likely ? So if we would use it without clustering could it be better? we have currently a quite urgent issue #414 which seems to be better after upgrade to a Redis versiojn 3

[enricogior]

Hi @Gentlehag
currently we don't have any indication that this bug was related to the clustering/sentinels.
Thank you.

[Misterhex]

[8616] 26 Dec 19:14:04.120 # Client id=6005 addr=79.133.49.6:8777 fd=11 name=GREEN-PARROT03 age=441 idle=0 flags=N db=0 sub=2 psub=0 multi=-1 qbuf=0 qbuf-free=0 obl=16380 oll=1 omem=18446744073709551597 events=rw cmd=unsubscribe scheduled to be closed ASAP for overcoming of output buffer limits.

the omem=18446744073709551597 value seems ridiculously large, is this related to #517 and #546 ???