Scans of multiple hosts interrupting at 99%

felixN · January 4, 2022, 5:04am

Hello,

I have a problem running scans on multiple hosts. The scan interrupts at 99%. This occured when doing a host discovery scan and also when doing a “Full and Fast” scan.

This is the ospd-openvas.log:

OSPD[19530] 2022-01-03 17:48:53,871: INFO: (ospd.command.command) Scan 59725179-f036-49af-a7bd-c7e523fac7e3 added to the queue in position 1.
OSPD[19530] 2022-01-03 17:48:55,707: INFO: (ospd.ospd) Currently 1 queued scans.
OSPD[19530] 2022-01-03 17:48:55,814: INFO: (ospd.ospd) Starting scan 59725179-f036-49af-a7bd-c7e523fac7e3.
OSPD[19530] 2022-01-03 18:30:00,534: ERROR: (ospd.server) Error sending data to the client. [Errno 32] Broken pipe
OSPD[19530] 2022-01-04 00:12:17,890: ERROR: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Exception Error 111 connecting to unix socket: /run/redis-openvas/redis.sock. Connection refused. while scanning
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 182, in _read_from_socket
    data = recv(self._sock, socket_read_size)
  File "/usr/lib/python3/dist-packages/redis/_compat.py", line 58, in recv
    return sock.recv(*args, **kwargs)
ConnectionResetError: [Errno 104] Connection reset by peer

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/redis/client.py", line 3520, in execute
    return execute(conn, stack, raise_on_error)
  File "/usr/lib/python3/dist-packages/redis/client.py", line 3395, in _execute_transaction
    self.parse_response(connection, '_')
  File "/usr/lib/python3/dist-packages/redis/client.py", line 3479, in parse_response
    self, connection, command_name, **options)
  File "/usr/lib/python3/dist-packages/redis/client.py", line 789, in parse_response
    response = connection.read_response()
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 637, in read_response
    response = self._parser.read_response()
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 290, in read_response
    response = self._buffer.readline()
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 224, in readline
    self._read_from_socket()
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 199, in _read_from_socket
    (e.args,))
redis.exceptions.ConnectionError: Error while reading from socket: (104, 'Connection reset by peer')

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 492, in connect
    sock = self._connect()
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 785, in _connect
    sock.connect(self.path)
ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/gvm/.local/lib/python3.7/site-packages/ospd/ospd.py", line 516, in start_scan
    self.exec_scan(scan_id)
  File "/home/gvm/.local/lib/python3.7/site-packages/ospd_openvas/daemon.py", line 1320, in exec_scan
    got_results = self.report_openvas_results(kbdb, scan_id)
  File "/home/gvm/.local/lib/python3.7/site-packages/ospd_openvas/daemon.py", line 1022, in report_openvas_results
    all_results = db.get_result()
  File "/home/gvm/.local/lib/python3.7/site-packages/ospd_openvas/db.py", line 470, in get_result
    return self._pop_list_items("internal/results")
  File "/home/gvm/.local/lib/python3.7/site-packages/ospd_openvas/db.py", line 454, in _pop_list_items
    return OpenvasDB.pop_list_items(self.ctx, name)
  File "/home/gvm/.local/lib/python3.7/site-packages/ospd_openvas/db.py", line 194, in pop_list_items
    results, redis_return_code = pipe.execute()
  File "/usr/lib/python3/dist-packages/redis/client.py", line 3535, in execute
    return execute(conn, stack, raise_on_error)
  File "/usr/lib/python3/dist-packages/redis/client.py", line 3387, in _execute_transaction
    connection.send_packed_command(all_cmds)
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 595, in send_packed_command
    self.connect()
  File "/usr/lib/python3/dist-packages/redis/connection.py", line 497, in connect
    raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error 111 connecting to unix socket: /run/redis-openvas/redis.sock. Connection refused.
OSPD[19530] 2022-01-04 00:12:17,919: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Host scan got interrupted. Progress: 98, Status: RUNNING
OSPD[19530] 2022-01-04 00:12:17,920: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan interrupted.
OSPD[19530] 2022-01-04 00:12:19,645: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan process is dead and its progress is 98
OSPD[19530] 2022-01-04 00:12:19,648: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan interrupted.
OSPD[19530] 2022-01-04 00:12:19,652: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan process is dead and its progress is 98
OSPD[19530] 2022-01-04 00:12:19,653: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan interrupted.
OSPD[19530] 2022-01-04 00:12:19,695: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan process is dead and its progress is 98
OSPD[19530] 2022-01-04 00:12:19,695: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan interrupted.
OSPD[19530] 2022-01-04 00:12:19,713: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan process is dead and its progress is 98
OSPD[19530] 2022-01-04 00:12:19,713: INFO: (ospd.ospd) 59725179-f036-49af-a7bd-c7e523fac7e3: Scan interrupted.

gvmd.log:

event task:MESSAGE:2022-01-03 16h48.32 UTC:24995: Status of task  (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has changed to New
event task:MESSAGE:2022-01-03 16h48.33 UTC:24995: Task Full and Fast - All (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has been created by admin
event task:MESSAGE:2022-01-03 16h48.39 UTC:25026: Status of task Full and Fast - All (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has changed to Requested
event task:MESSAGE:2022-01-03 16h48.39 UTC:25026: Task Full and Fast - All (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has been requested to start by admin
event task:MESSAGE:2022-01-03 16h48.53 UTC:25032: Status of task Full and Fast - All (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has changed to Queued
event task:MESSAGE:2022-01-03 16h48.58 UTC:25032: Status of task Full and Fast - All (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has changed to Running
md    gmp:WARNING:2022-01-03 17h06.43 utc:13697: Authentication failure for 'admin' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.43 utc:13702: Authentication failure for 'sadmin' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.43 utc:13709: Authentication failure for 'admin' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.43 utc:13718: Authentication failure for 'admin' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.43 utc:13724: Authentication failure for 'gmp' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.43 utc:13728: Authentication failure for 'gvmadmin' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.44 utc:13733: Authentication failure for 'omp' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.44 utc:13737: Authentication failure for 'observer' from unix_socket
md    gmp:WARNING:2022-01-03 17h06.44 utc:13743: Authentication failure for 'webadmin' from unix_socket
event task:MESSAGE:2022-01-03 23h12.19 UTC:25032: Status of task Full and Fast - All (ce6668a1-1f2d-4aee-9871-b54e0690b31d) has changed to Interrupted

The machine has GVM installed as documented (by copy/pasting the commands on the docs page).
GVM-Version is 21.4.3.
I haven’t found any solution yet, i hope you can help me

Thanks and happy new year.

bricks · January 4, 2022, 6:53am

Hi, could you check the permissions on /run/redis-openvas/redis.sock and if the gvm user is in the redis group?

felixN · January 4, 2022, 11:39am

Hi, thanks for the reply.

Permissions of the redis socket:
srwxrwx--- 1 redis redis 0 Jan 4 00:12 /run/redis-openvas/redis.sock

From /etc/group:
redis:x:114:gvm

Edit: I’ve set up gvm on another machine with a script I wrote and ran a scan against the same networks. Here too the scan is interrupted at 99%.

cat /etc/log/gvm/ospd-openvas.log:

OSPD[429] 2022-01-04 06:30:06,192: INFO: (ospd.command.command) Scan 15624901-038a-4d54-b70b-60ed3b891cea added to the queue in position 1.
OSPD[429] 2022-01-04 06:30:07,370: INFO: (ospd.ospd) Currently 1 queued scans.
OSPD[429] 2022-01-04 06:30:07,546: INFO: (ospd.ospd) Starting scan 15624901-038a-4d54-b70b-60ed3b891cea.
OSPD[429] 2022-01-04 08:34:31,583: ERROR: (ospd.server) Error sending data to the client. [Errno 32] Broken pipe
OSPD[429] 2022-01-04 09:35:42,484: ERROR: (ospd.server) Error sending data to the client. [Errno 32] Broken pipe
OSPD[429] 2022-01-04 11:36:23,889: ERROR: (ospd.server) Error sending data to the client. [Errno 32] Broken pipe
OSPD[429] 2022-01-04 12:48:33,423: ERROR: (ospd_openvas.db) 15624901-038a-4d54-b70b-60ed3b891cea: Target set as finished because redis returned None as scanner status.
OSPD[429] 2022-01-04 12:48:33,436: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Host scan finished.
OSPD[429] 2022-01-04 12:48:33,437: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Host scan got interrupted. Progress: 99, Status: RUNNING
OSPD[429] 2022-01-04 12:48:33,438: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan interrupted.
OSPD[429] 2022-01-04 12:48:33,682: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan process is dead and its progress is 99
OSPD[429] 2022-01-04 12:48:33,684: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan interrupted.
OSPD[429] 2022-01-04 12:48:33,693: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan process is dead and its progress is 99
OSPD[429] 2022-01-04 12:48:33,693: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan interrupted.
OSPD[429] 2022-01-04 12:48:33,724: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan process is dead and its progress is 99
OSPD[429] 2022-01-04 12:48:33,724: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan interrupted.
OSPD[429] 2022-01-04 12:48:33,737: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan process is dead and its progress is 99
OSPD[429] 2022-01-04 12:48:33,738: INFO: (ospd.ospd) 15624901-038a-4d54-b70b-60ed3b891cea: Scan interrupted.

cat /var/log/gvm/gvmd.log:

event target:MESSAGE:2022-01-04 05h29.50 UTC:32319: Target Target for Test Task - 2022-01-04 05:29:50 (3329c002-39b8-465c-b93c-752f26099b96) has been created by admin
event task:MESSAGE:2022-01-04 05h29.50 UTC:32319: Status of task  (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has changed to New
event task:MESSAGE:2022-01-04 05h29.50 UTC:32319: Task Test Task (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has been created by admin
event task:MESSAGE:2022-01-04 05h29.50 UTC:32319: Status of task Test Task (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has changed to Requested
event task:MESSAGE:2022-01-04 05h29.50 UTC:32319: Task Test Task (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has been requested to start by admin
event wizard:MESSAGE:2022-01-04 05h29.50 UTC:32319: Wizard quick_task has been run by admin
event task:MESSAGE:2022-01-04 05h30.06 UTC:32327: Status of task Test Task (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has changed to Queued
event task:MESSAGE:2022-01-04 05h30.11 UTC:32327: Status of task Test Task (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has changed to Running
event task:MESSAGE:2022-01-04 11h48.33 UTC:32327: Status of task Test Task (bba1a68e-cf79-4c6c-b106-fb1ea9e3b596) has changed to Interrupted

/run/redis-openvas/redis.sock (on second machine):
srwxrwx--- 1 redis redis 0 Jan 4 12:48 /run/redis-openvas/redis.sock

/etc/group (second machine):
redis:x:114:gvm

felixN · January 5, 2022, 3:44pm

Could this be an issue with the amount of machines i’m trying to scan? I started the tasks on multiple subnets containing 136 hosts. Scans on single machines seem to work fine.

cfi · January 7, 2022, 3:39pm

This could be indeed an insufficient redis configuration related to the maximum amount of clients and/or databases when scanning a larger amount of hosts.

Some hints on configuring redis are available here:

github.com

greenbone/openvas-scanner/blob/v21.4.3/doc/redis_config.md

# Redis KB server <!-- omit in toc -->

- [Presentation](#presentation)
- [Connection](#connection)
- [Database number](#database-number)
- [Clients numbers](#clients-numbers)
- [Debugging and monitoring a scan via redis](#debugging-and-monitoring-a-scan-via-redis)

## Presentation

[Redis](http://redis.io) is used to store and access the KB (Knowledge Base).
Scans won't run if they cannot access the server and might be significantly
slowed down if redis is not properly configured.

The feature has been developed with neither cluster mode nor replication
enabled. Redis 3.2 and higher are supported.

## Connection

OpenVAS can currently only access redis via a unix socket. This choice has been

This file has been truncated. show original