Issue retrieving max DB number from redis

[Espresso Beanies]

Hi, I wanted to ask if anyone in the community has ever come across the following message in an open-source project using 'redis':

lib  kb_redis-CRITICAL **: fetch_max_db_index: cannot retrieve max DB number: LOADING Redis is loading the dataset in memory

I can post my machine specs if need be, but I'm getting the following from the redis service itself:

root@openvas-01:~# systemctl status redis
● redis-server.service - Advanced key-value store
   Loaded: loaded (/lib/systemd/system/redis-server.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2017-11-06 10:28:41 EST; 23h ago
     Docs: http://redis.io/documentation,
           man:redis-server(1)
  Process: 1062 ExecStartPost=/bin/run-parts --verbose /etc/redis/redis-server.post-up.d (code=exited, status=0/SUCCESS)
  Process: 1047 ExecStart=/usr/bin/redis-server /etc/redis/redis.conf (code=exited, status=0/SUCCESS)
  Process: 1035 ExecStartPre=/bin/run-parts --verbose /etc/redis/redis-server.pre-up.d (code=exited, status=0/SUCCESS)
 Main PID: 1061 (redis-server)
    Tasks: 3
   Memory: 151.5M
      CPU: 34.642s
   CGroup: /system.slice/redis-server.service
           └─1061 /usr/bin/redis-server 127.0.0.1:6379


Nov 06 10:28:40 openvas-01 systemd[1]: Starting Advanced key-value store...
Nov 06 10:28:40 openvas-01 run-parts[1035]: run-parts: executing /etc/redis/redis-server.pre-up.d/00_example
Nov 06 10:28:41 openvas-01 systemd[1]: Started Advanced key-value store.

It looks like the redis service is working fine, but for some reason OpenVAS isn't able to obtain what it needs from redis and I'm not sure where the issue lies.

Redis version: Redis server v=3.0.6 sha=00000000:0 malloc=jemalloc-3.6.0 bits=64 build=687a2a319020fa42

[hva...@gmail.com]

Your systemctl command does not give you any info from the Redis service itself.  That's information from the Linux systemd service, showing what the systemd service knows about the Redis service that it launched.  I.e., it's information from software that started Redis, but not information from within the Redis server process itself.

The error message that OpenVAS received indicates the Redis server process believes it's a slave of another Redis server process (the master), and that it's loading/receiving the data from that master.  While it's in the middle of receiving the data, it responds to most commands with that error "LOADING".

If the condition contimues for longer than a few minutes, you have a situation where the Redis server process is incorrectly configured to think it's a slave; or it's correctly configured to be a slave, but it's getting constant errors as it tries to load the data from the master.  Consult the logfiles for the Redis server process to learn what's happening.

[Espresso Beanies]

Hi hva...,

After checking the logs, it seems that right after I restarted the machine, the log files show the following:

23708:signal-handler (1509375584) Received SIGTERM scheduling shutdown...
23708:M 30 Oct 10:59:45.666 * DB saved on disk
23708:M 30 Oct 10:59:45.666 * Removing the pid file.
23708:M 30 Oct 10:59:45.666 * Removing the unix socket file.
23708:M 30 Oct 10:59:45.666 # Redis is now ready to exit, bye bye...
1083:M 30 Oct 11:16:44.799 # You requested maxclients of 10000 requiring at least 10032 max file descriptors.
1083:M 30 Oct 11:16:44.813 # Redis can't set maximum open files to 10032 because of OS error: Operation not permitted.
1083:M 30 Oct 11:16:44.813 # Current maximum open files is 4096. maxclients has been reduced to 4064 to compensate for low ulimit. If you need higher maxclients increase 'ulimit -n'.
                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 3.0.6 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
 |    `-._   `._    /     _.-'    |     PID: 1083
  `-._    `-._  `-./  _.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'


1083:M 30 Oct 11:16:44.818 # WARNING: The TCP backlog setting of 511 cannot be enforced because /proc/sys/net/core/somaxconn is set to the lower value of 128.
1083:M 30 Oct 11:16:44.818 # Server started, Redis version 3.0.6
1083:M 30 Oct 11:16:44.818 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add 'vm.overcommit_memory = 1' to /etc/sysctl.conf and then reboot or run the command 'sysctl vm.overcommit_memory=1' for this to take effect.
1083:M 30 Oct 11:16:44.818 # WARNING you have Transparent Huge Pages (THP) support enabled in your kernel. This will create latency and memory usage issues with Redis. To fix this issue run the command 'echo never > /sys/kernel/mm/transparent_hugepage/enabled' as root, and add it to your /etc/rc.local in order to retain the setting after a reboot. Redis must be restarted after THP is disabled.
1083:M 30 Oct 11:16:46.457 * DB loaded from disk: 1.639 seconds
1083:M 30 Oct 11:16:46.457 * The server is now ready to accept connections on port 6379
1083:M 30 Oct 11:16:46.457 * The server is now ready to accept connections at /var/run/redis/redis.sock
1083:signal-handler (1509377375) Received SIGTERM scheduling shutdown...
1083:signal-handler (1509377375) Received SIGTERM scheduling shutdown...
1083:M 30 Oct 11:29:35.732 # User requested shutdown...
1083:M 30 Oct 11:29:35.732 * Saving the final RDB snapshot before exiting.
1083:M 30 Oct 11:29:36.645 * DB saved on disk

The kernel tweaks I can resolve, but I'm not sure if they would completely solve the problem. I Googled the maxclients of 10000 and came up with a GitHub bug that was resolved last year. Advice?

[hva...@gmail.com]

Redis is saying that it was configured to expect 10 thousand client connections, but the Linux system software (known as "systemd") that starts/stops Redis did not raise the limit on open file descriptors to match.  Systemd's limit is 4096.

When I entered "max open file descriptors systemd" (without the quote characters) into Google, the first result listed was a serverfault.com q&a that describes a method that would work.  However, farther down the search terms is a stackoverflow.com q&a that I feel has a better approach:

https://stackoverflow.com/questions/27849331/how-to-set-nginx-max-open-files

It advises creating a systemd override file, which will not be replaced if/when Redis is upgraded by installing a newer package.  I.e., a version upgrade won't revert the file descriptor limits and change Redis's behavior.

I'm a bit concerned by something I see in the Redis logfile you posted.  Redis was shut down, then 15 minutes later it was started, and 15 minutes after that, it was shut down again.  Were you just testing, or is it being stopped and started like that all the time?

[Espresso Beanies]

Yea, I pretty much resolved those startup warning messages by changing settings in sysctl.conf and rc.local. But the OpenVAS error still persists. 

The shutdown and startup again 15 minutes later was me performing some troubleshooting. Definitely not an ongoing issue. From my last reboot, I now see the following:

1043:signal-handler (1510154489) Received SIGTERM scheduling shutdown...
1043:M 08 Nov 10:21:29.068 # User requested shutdown...
1043:M 08 Nov 10:21:29.069 * Saving the final RDB snapshot before exiting.
1043:M 08 Nov 10:21:29.910 * DB saved on disk
1043:M 08 Nov 10:21:29.910 * Removing the pid file.
1043:M 08 Nov 10:21:29.910 * Removing the unix socket file.
1043:M 08 Nov 10:21:29.910 # Redis is now ready to exit, bye bye...

                _._
           _.-``__ ''-._
      _.-``    `.  `_.  ''-._           Redis 3.0.6 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._
 (    

'      ,       .-`  | `,    )     Running in standalone mode

 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379

 |    `-._   `._    /     _.-'    |     PID: 1068
  `-._    `-._  `-./  _.-'    _.-'

 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |           http://redis.io
  `-._    `-._`-.__.-'_.-'    _.-'
 |`-._`-._    `-.__.-'    _.-'_.-'|
 |    `-._`-._        _.-'_.-'    |
  `-._    `-._`-.__.-'_.-'    _.-'
      `-._    `-.__.-'    _.-'
          `-._        _.-'
              `-.__.-'

1068:M 08 Nov 10:21:42.444 # Server started, Redis version 3.0.6
1068:M 08 Nov 10:21:44.247 * DB loaded from disk: 1.802 seconds
1068:M 08 Nov 10:21:44.247 * The server is now ready to accept connections on port 6379
1068:M 08 Nov 10:21:44.247 * The server is now ready to accept connections at /var/run/redis/redis.sock

[hva...@gmail.com]

The Redis start-up logfile entry says "Running in standalone mode", which shouldn't return the "LOADING" error that OpenVAS reported.  Has the OpenVAS error message changed?

If it hasn't changed, then I would verify that OpenVAS really is testing the same Redis process.  Perhaps it's testing a different Redis that is configured as a slave rather than a standalone process.

I would also check to see if there are Sentinel processes monitoring this Redis process and re-configuring it to be a slave of another Redis.  However, if such a reconfigure is taking place, I would expect later logfile messages to say so.

[Espresso Beanies]

It has changed in a way that the 'lib  kb_redis-CRITICAL...' message no longer appears during a restart of the OpenVAS service. However, the message does appear at startup. One other thing to note is that a restart of the OpenVAS service now takes considerably longer before the service times out.

I'll take a look at the Sentinel processes as suggested.