Redis 4.0.8 Core dump -MISCONF Redis is configured to save RDB snapshots, but it is currently not able to persist on disk.

[PiyushS]

Hi All

I have a simple Redis Master slave configuration.

I do not see any issues when starting Redis with nohup command. Neither do I see any issues with only master running. BGSAVE works fine.

When Redis is started via systemd in master-slave I see the BGSAVE crashes immediately with a core dump. Below errors are seen in logs. On master node I see a temp-##.rdb file with a core dump

Logs from master node

1826:M 22 Mar 13:23:18.474 # Server initialized

1826:M 22 Mar 13:23:18.474 * DB loaded from disk: 0.000 seconds

1826:M 22 Mar 13:23:18.474 * Ready to accept connections

1826:M 22 Mar 13:23:18.491 * Slave 10.207.141.9:6379 asks for synchronization

1826:M 22 Mar 13:23:18.492 * Full resync requested by slave 10.207.141.9:6379

1826:M 22 Mar 13:23:18.492 * Starting BGSAVE for SYNC with target: disk

1826:M 22 Mar 13:23:18.492 * Background saving started by pid 1836

1826:M 22 Mar 13:23:18.574 # Background saving terminated by signal 11

1826:M 22 Mar 13:23:18.574 # Connection with slave 10.207.141.9:6379 lost.

1826:M 22 Mar 13:23:18.574 # SYNC failed. BGSAVE child returned an error

-----------------------

Logs from slave node

9406:S 22 Mar 13:23:26.796 # Server initialized

9406:S 22 Mar 13:23:26.796 * DB loaded from disk: 0.000 seconds

9406:S 22 Mar 13:23:26.796 * Ready to accept connections

9406:S 22 Mar 13:23:26.800 * Connecting to MASTER 10.207.141.11:6379

9406:S 22 Mar 13:23:26.800 * MASTER <-> SLAVE sync started

9406:S 22 Mar 13:23:26.801 * Non blocking connect for SYNC fired the event.

9406:S 22 Mar 13:23:26.802 # Error reply to PING from master: '-MISCONF Redis is configured to save RDB snapshots, but it is currently not able to persist on disk. Commands that may modify the data set are disabled, because this instance is configured to report errors during writes if RDB snapshotting fails (stop-wri'

9406:S 22 Mar 13:23:27.802 * Connecting to MASTER 10.207.141.11:6379

9406:S 22 Mar 13:23:27.802 * MASTER <-> SLAVE sync started

9406:S 22 Mar 13:23:27.802 * Non blocking connect for SYNC fired the event.

9406:S 22 Mar 13:23:27.803 # Error reply to PING from master: '-MISCONF Redis is configured to save RDB snapshots, but it is currently not able to persist on disk. Commands that may modify the data set are disabled, because this instance is configured to report errors during writes if RDB snapshotting fails (stop-wri'

9406:S 22 Mar 13:23:28.804 * Connecting to MASTER 10.207.141.11:6379

9406:S 22 Mar 13:23:28.804 * MASTER <-> SLAVE sync started

9406:S 22 Mar 13:23:28.804 * Non blocking connect for SYNC fired the event.

9406:S 22 Mar 13:23:28.805 # Error reply to PING from master: '-MISCONF Redis is configured to save RDB snapshots, but it is currently not able to persist on disk. Commands that may modify the data set are disabled, because this instance is configured to report errors during writes if RDB snapshotting fails (stop-wri'

From master

 redis-cli -h `hostname -i` info

# Server

redis_version:4.0.8

redis_git_sha1:00000000

redis_git_dirty:0

redis_build_id:14019a439d3e454c

redis_mode:standalone

os:Linux 3.10.0-693.17.1.el7.x86_64 x86_64

arch_bits:64

multiplexing_api:epoll

atomicvar_api:atomic-builtin

gcc_version:4.8.5

process_id:1885

run_id:225405e6768bf382fd6be9c96752ad0c53ca7df4

tcp_port:6379

uptime_in_seconds:1025

uptime_in_days:0

hz:10

lru_clock:11794622

executable:/sbin/redis-server

config_file:/etc/redis/conf/redis.conf

# Clients

connected_clients:1

client_longest_output_list:0

client_biggest_input_buf:0

blocked_clients:0

# Memory

used_memory:827520

used_memory_human:808.12K

used_memory_rss:2707456

used_memory_rss_human:2.58M

used_memory_peak:827520

used_memory_peak_human:808.12K

used_memory_peak_perc:100.00%

used_memory_overhead:815310

used_memory_startup:765680

used_memory_dataset:12210

used_memory_dataset_perc:19.74%

total_system_memory:3710779392

total_system_memory_human:3.46G

used_memory_lua:37888

used_memory_lua_human:37.00K

maxmemory:0

maxmemory_human:0B

maxmemory_policy:noeviction

mem_fragmentation_ratio:3.27

mem_allocator:jemalloc-4.0.3

active_defrag_running:0

lazyfree_pending_objects:0

# Persistence

loading:0

rdb_changes_since_last_save:0

rdb_bgsave_in_progress:0

rdb_last_save_time:1521743055

rdb_last_bgsave_status:ok

rdb_last_bgsave_time_sec:0

rdb_current_bgsave_time_sec:-1

rdb_last_cow_size:131072

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

aof_last_cow_size:0

# Stats

total_connections_received:106

total_commands_processed:106

instantaneous_ops_per_sec:0

total_net_input_bytes:2751

total_net_output_bytes:61144

instantaneous_input_kbps:0.02

instantaneous_output_kbps:0.30

rejected_connections:0

sync_full:0

sync_partial_ok:0

sync_partial_err:0

expired_keys:0

evicted_keys:0

keyspace_hits:0

keyspace_misses:0

pubsub_channels:0

pubsub_patterns:0

latest_fork_usec:226

migrate_cached_sockets:0

slave_expires_tracked_keys:0

active_defrag_hits:0

active_defrag_misses:0

active_defrag_key_hits:0

active_defrag_key_misses:0

# Replication

role:master

connected_slaves:0

master_replid:8179e8483169abeca41a9332bd4d44ea582d4c31

master_replid2:0000000000000000000000000000000000000000

master_repl_offset:0

second_repl_offset:-1

repl_backlog_active:0

repl_backlog_size:1048576

repl_backlog_first_byte_offset:0

repl_backlog_histlen:0

# CPU

used_cpu_sys:0.70

used_cpu_user:0.42

used_cpu_sys_children:0.00

used_cpu_user_children:0.00

# Cluster

cluster_enabled:0

# Keyspace

From Slave

redis-cli -h `hostname -i` info

# Server

redis_version:4.0.8

redis_git_sha1:00000000

redis_git_dirty:0

redis_build_id:14019a439d3e454c

redis_mode:standalone

os:Linux 3.10.0-693.17.1.el7.x86_64 x86_64

arch_bits:64

multiplexing_api:epoll

atomicvar_api:atomic-builtin

gcc_version:4.8.5

process_id:1736

run_id:cc0d4c76fbf5cdb3e40a656295d8d2780c68aa49

tcp_port:6379

uptime_in_seconds:2

uptime_in_days:0

hz:10

lru_clock:11794675

executable:/sbin/redis-server

config_file:/etc/redis/conf/redis.conf

# Clients

connected_clients:1

client_longest_output_list:0

client_biggest_input_buf:0

blocked_clients:0

# Memory

used_memory:828560

used_memory_human:809.14K

used_memory_rss:2662400

used_memory_rss_human:2.54M

used_memory_peak:828560

used_memory_peak_human:809.14K

used_memory_peak_perc:108.21%

used_memory_overhead:815326

used_memory_startup:765696

used_memory_dataset:13234

used_memory_dataset_perc:21.05%

total_system_memory:3710779392

total_system_memory_human:3.46G

used_memory_lua:37888

used_memory_lua_human:37.00K

maxmemory:0

maxmemory_human:0B

maxmemory_policy:noeviction

mem_fragmentation_ratio:3.21

mem_allocator:jemalloc-4.0.3

active_defrag_running:0

lazyfree_pending_objects:0

# Persistence

loading:0

rdb_changes_since_last_save:0

rdb_bgsave_in_progress:0

rdb_last_save_time:1521744113

rdb_last_bgsave_status:ok

rdb_last_bgsave_time_sec:-1

rdb_current_bgsave_time_sec:-1

rdb_last_cow_size:0

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

aof_last_cow_size:0

# Stats

total_connections_received:1

total_commands_processed:0

instantaneous_ops_per_sec:0

total_net_input_bytes:14

total_net_output_bytes:0

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:0

evicted_keys:0

keyspace_hits:0

keyspace_misses:0

pubsub_channels:0

pubsub_patterns:0

latest_fork_usec:0

migrate_cached_sockets:0

slave_expires_tracked_keys:0

active_defrag_hits:0

active_defrag_misses:0

active_defrag_key_hits:0

active_defrag_key_misses:0

# Replication

role:slave

master_host:10.207.141.11

master_port:6379

master_link_status:down

master_last_io_seconds_ago:-1

master_sync_in_progress:0

slave_repl_offset:1

master_link_down_since_seconds:1521744115

slave_priority:100

slave_read_only:1

connected_slaves:0

master_replid:2203cbb53673cbb7844de8b8b2c2aab758608c9b

master_replid2:0000000000000000000000000000000000000000

master_repl_offset:0

second_repl_offset:-1

repl_backlog_active:0

repl_backlog_size:1048576

repl_backlog_first_byte_offset:0

repl_backlog_histlen:0

# CPU

used_cpu_sys:0.00

used_cpu_user:0.00

used_cpu_sys_children:0.00

used_cpu_user_children:0.00

# Cluster

cluster_enabled:0

# Keyspace

------------------

/etc/systemd/system/redis.service

[Unit]

Description=Redis Service

Before=

After=network.target consul-template.service

Wants=consul-template.service

[Service]

User=redis

Group=redis

Type=notify

ExecStart=/sbin/redis-server /etc/redis/conf/redis.conf

ExecStop=/bin/redis-cli -h `hostname -i` -p 6379 shutdown

[Install]

WantedBy=multi-user.target

----------------

/etc/systemd/system/redis.service.d/limits.conf

[Service]

LimitCPU=infinity

LimitFSIZE=infinity

LimitDATA=infinity

LimitSTACK=102400

LimitMEMLOCK=infinity

LimitCORE=infinity

LimitNOFILE=50000

LimitNPROC=infinity

--------------------

Redis.conf has 

daemonize yes

supervised systemd

dbfilename dump.rdb

dir /var/lib/redis

Thank You

[hva...@gmail.com]

What is the output of 'ls -ld /var/lib/redis' ?

[PiyushS]

ls -ld /var/lib/redis
drwxr-xr-x 2 redis redis 4096 Mar 22 13:55 /var/lib/redis

[hva...@gmail.com]

Here are the relevant files from the redis-server 4.0.8 package on Ubuntu 17.10 (artful), which I've used successfully.  Your OS is probably not Ubuntu, but comparing the Systemd and Redis config files may help you narrow down the problem:

/lib/systemd/system/redis-server.service
[Unit]
Description=Advanced key-value store
After=network.target
Documentation=http://redis.io/documentation, man:redis-server(1)

[Service]
Type=forking
ExecStart=/usr/bin/redis-server /etc/redis/redis.conf
PIDFile=/var/run/redis/redis-server.pid
TimeoutStopSec=0
Restart=always
User=redis
Group=redis
RuntimeDirectory=redis
RuntimeDirectoryMode=2755

ExecStartPre=-/bin/run-parts --verbose /etc/redis/redis-server.pre-up.d
ExecStartPost=-/bin/run-parts --verbose /etc/redis/redis-server.post-up.d
ExecStop=-/bin/run-parts --verbose /etc/redis/redis-server.pre-down.d
ExecStop=/bin/kill -s TERM $MAINPID
ExecStopPost=-/bin/run-parts --verbose /etc/redis/redis-server.post-down.d

UMask=007
PrivateTmp=yes
LimitNOFILE=65535
PrivateDevices=yes
ProtectHome=yes
ReadOnlyDirectories=/
ReadWriteDirectories=-/var/lib/redis
ReadWriteDirectories=-/var/log/redis
ReadWriteDirectories=-/var/run/redis

NoNewPrivileges=true
CapabilityBoundingSet=CAP_SETGID CAP_SETUID CAP_SYS_RESOURCE
MemoryDenyWriteExecute=true
ProtectKernelModules=true
ProtectKernelTunables=true
ProtectControlGroups=true
RestrictRealtime=true
RestrictNamespaces=true
RestrictAddressFamilies=AF_INET AF_INET6 AF_UNIX

# redis-server can write to its own config file when in cluster mode so we
# permit writing there by default. If you are not using this feature, it is
# recommended that you replace the following lines with "ProtectSystem=full".
ProtectSystem=true
ReadWriteDirectories=-/etc/redis

[Install]
WantedBy=multi-user.target
Alias=redis.service


/etc/redis/redis.conf (with comments removed)
bind 127.0.0.1
protected-mode yes
port 6379
tcp-backlog 511
timeout 0
tcp-keepalive 300
daemonize yes
supervised no
pidfile /var/run/redis/redis-server.pid
loglevel notice
logfile /var/log/redis/redis-server.log
databases 16
save 900 1
save 300 10
save 60 10000
stop-writes-on-bgsave-error yes
rdbcompression yes
rdbchecksum yes
dbfilename dump.rdb
dir /var/lib/redis
slave-serve-stale-data yes
slave-read-only yes
repl-diskless-sync no
repl-diskless-sync-delay 5
repl-disable-tcp-nodelay no
slave-priority 100
appendonly no
appendfilename "appendonly.aof"
appendfsync everysec
no-appendfsync-on-rewrite no
auto-aof-rewrite-percentage 100
auto-aof-rewrite-min-size 64mb
aof-load-truncated yes
lua-time-limit 5000
slowlog-log-slower-than 10000
slowlog-max-len 128
latency-monitor-threshold 0
notify-keyspace-events ""
hash-max-ziplist-entries 512
hash-max-ziplist-value 64
list-max-ziplist-size -2
list-compress-depth 0
set-max-intset-entries 512
zset-max-ziplist-entries 128
zset-max-ziplist-value 64
hll-sparse-max-bytes 3000
activerehashing yes
client-output-buffer-limit normal 0 0 0
client-output-buffer-limit slave 256mb 64mb 60
client-output-buffer-limit pubsub 32mb 8mb 60
hz 10
aof-rewrite-incremental-fsync yes

[PiyushS]

I did try these configs as well. Unfortunately I still get the same error.
Wierdly this issue is only with systemd. Works fine when I start it via nohup

[hva...@gmail.com]

Well, if comparing those Ubuntu configs to yours doesn't reveal the elements needed to get yours working, the only things I can suggest are to launch Redis under systemd and check the owner of the running process.  Make sure its the same user who owns /var/lib/redis.  Then run strace to trace the process (probably want the '-p pid' and '-f' options to attach to the running Redis process, and to follow child processes, and also the '-o /path/to/output/file' option to save the large output), then trigger the problem.  Near the end of the output file you'll find the system call Redis made that errors out and the error code returned by the OS.  These will usually point to the source of the error.

[Piyush Sandhir]

Master log
9701:C 26 Mar 15:12:08.490 # Redis version=4.0.9, bits=64, commit=00000000, modified=0, pid=9701, just started
9701:C 26 Mar 15:12:08.490 # Configuration loaded
9701:C 26 Mar 15:12:08.490 * supervised by systemd, will signal readiness
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 4.0.9 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
 |    `-._   `._    /     _.-'    |     PID: 9701
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

9701:M 26 Mar 15:12:08.492 # Server initialized
9701:M 26 Mar 15:12:08.492 * DB loaded from disk: 0.000 seconds
9701:M 26 Mar 15:12:08.492 * Ready to accept connections
9701:M 26 Mar 15:12:34.336 * Slave 10.207.141.4:6379 asks for synchronization
9701:M 26 Mar 15:12:34.336 * Full resync requested by slave 10.207.141.4:6379
9701:M 26 Mar 15:12:34.337 * Starting BGSAVE for SYNC with target: disk
9701:M 26 Mar 15:12:34.337 * Background saving started by pid 9787
9701:M 26 Mar 15:12:34.359 # Background saving terminated by signal 11
9701:M 26 Mar 15:12:34.359 # Connection with slave 10.207.141.4:6379 lost.
9701:M 26 Mar 15:12:34.359 # SYNC failed. BGSAVE child returned an error

Below is the strace output when the slave connects. Background saving pid is 9787 killed by SIGSEGV

9701  clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f685ae17a50) = 9787
9701  open("/var/log/redis/redis.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 10
9701  lseek(10, 0, SEEK_END)            = 20715
9701  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3559, ...}) = 0
9701  fstat(10, {st_mode=S_IFREG|0664, st_size=20715, ...}) = 0
9701  mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f685ae23000
9701  write(10, "9701:M 26 Mar 15:12:34.337 * Bac"..., 67) = 67
9701  close(10)                         = 0
9701  munmap(0x7f685ae23000, 4096)      = 0
9701  write(7, "+FULLRESYNC 3a07c70bf94574324561"..., 56) = 56
9701  read(3, 0x7ffd834f060f, 1)        = -1 EAGAIN (Resource temporarily unavailable)
9701  epoll_wait(5,  <unfinished ...>
9787  set_robust_list(0x7f685ae17a60, 24) = 0
9787  close(6)                          = 0
9787  open("temp-9787.rdb", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 6
9787  fstat(6, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
9787  mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f685ae23000
9787  --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0x7ffd834c2734} ---
9787  --- SIGSEGV {si_signo=SIGSEGV, si_code=SI_KERNEL, si_addr=0} ---
9787  +++ killed by SIGSEGV +++
9701  <... epoll_wait resumed> 0x7f685370ecc0, 10128, 21) = -1 EINTR (Interrupted system call)
9701  --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_KILLED, si_pid=9787, si_uid=25337, si_status=SIGSEGV, si_utime=0, si_stime=0} ---
9701  read(3, 0x7ffd834f060f, 1)        = -1 EAGAIN (Resource temporarily unavailable)
9701  epoll_wait(5, [], 10128, 20)      = 0
9701  open("/proc/9701/stat", O_RDONLY) = 10
9701  read(10, "9701 (redis-server) R 1 9701 970"..., 4096) = 327
9701  close(10)                         = 0
9701  wait4(-1, [{WIFSIGNALED(s) && WTERMSIG(s) == SIGSEGV}], WNOHANG, NULL) = 9787
9701  open("/var/log/redis/redis.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = 10
9701  lseek(10, 0, SEEK_END)            = 20782
9701  stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=3559, ...}) = 0
9701  fstat(10, {st_mode=S_IFREG|0664, st_size=20782, ...}) = 0
9701  mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f685ae23000

-Piyush

--
You received this message because you are subscribed to the Google Groups "Redis DB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to redis-db+unsubscribe@googlegroups.com.
To post to this group, send email to redi...@googlegroups.com.
Visit this group at https://groups.google.com/group/redis-db.
For more options, visit https://groups.google.com/d/optout.

[Piyush Sandhir]

FYI, I ried this with 4.0.9 with the same results

-Piyush