Query: GVM 11: Everytime I sync for NVT feeds the gsad service comes down and scanner is not responding anymore for scans

Hello,

Everytime I try to update the NVT feeds I restart the gsad, gvmd & ospd-openvas service, the gsad service breaks and gvmd service takes time as the NVT feeds are getting synced.

But the concern here is I am not able to start the gsad service afterwards anytime and gvmd service starts with an error. Below are the logs

gsad service status:

  • gsad.service - Job that runs the gsa daemon
    Loaded: loaded (/etc/systemd/system/gsad.service; enabled; vendor preset: enabled)
    Active: inactive (dead) since Wed 2020-07-22 02:16:31 CDT; 19min ago
    Docs: man:gsa
    Process: 32526 ExecStart=/opt/gvm/sbin/gsad --drop-privileges=gvm (code=exited, status=0/SUCCESS)
    Main PID: 32528 (code=killed, signal=TERM)
    Tasks: 17 (limit: 4915)
    CGroup: /system.slice/gsad.service
    |-15919 /opt/gvm/sbin/gsad --drop-privileges=gvm
    `-23371 /opt/gvm/sbin/gsad --drop-privileges=gvm

Jul 22 02:16:31 systemd[1]: gsad.service: Scheduled restart job, restart counter is at 8.
Jul 22 02:16:31 systemd[1]: Stopped Job that runs the gsa daemon.
Jul 22 02:16:31 systemd[1]: gsad.service: Found left-over process 15919 (gsad) in control group while starting unit. Ignoring.
Jul 22 02:16:31 systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Jul 22 02:16:31 systemd[1]: gsad.service: Found left-over process 23371 (gsad) in control group while starting unit. Ignoring.
Jul 22 02:16:31 systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Jul 22 02:16:31 systemd[1]: Starting Job that runs the gsa daemon…
Jul 22 02:16:31 systemd[1]: gsad.service: Supervising process 32528 which is not our child. We’ll most likely not notice when it exits.
Jul 22 02:16:31 systemd[1]: Started Job that runs the gsa daemon.

gvmd service status:

  • gvmd.service - Job that runs the gvm daemon
    Loaded: loaded (/etc/systemd/system/gvmd.service; enabled; vendor preset: enabled)
    Active: active (running) since Wed 2020-07-22 02:01:16 CDT; 37min ago
    Docs: man:gvm
    Process: 31198 ExecStart=/opt/gvm/sbin/gvmd --osp-vt-update=/opt/gvm/var/run/ospd.sock (code=exited, status=0/SUCCESS)
    Main PID: 31199 (gvmd)
    Tasks: 5 (limit: 4915)
    CGroup: /system.slice/gvmd.service
    |- 1057 gvmd: Syncing SCAP: Updating CVEs
    |- 1263 gvmd: Reloading NVTs
    |- 1265 gvmd: OSP: Updating NVT cache
    |-15909 gpg-agent --homedir /opt/gvm/var/lib/gvm/gvmd/gnupg --use-standard-socket --daemon
    `-31199 gvmd: Waiting for incoming connections

Jul 22 02:01:06 systemd[1]: Starting Job that runs the gvm daemon…
Jul 22 02:01:06 systemd[1]: gvmd.service: Can’t open PID file /opt/gvm/var/run/gvmd.pid (yet?) after start: No such file or directory
Jul 22 02:01:16 systemd[1]: Started Job that runs the gvm daemon.

Openvas.log:
lib kb: DEBUG:2020-07-20 10h13.36 utc:20306: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/3
sd main:MESSAGE:2020-07-20 10h13.36 utc:20306: Finished testing x.x.x.x. Time : 0.03 secs
sd main: DEBUG:2020-07-20 10h13.36 utc:20305: waitpid() failed. No child processes)
sd main:MESSAGE:2020-07-20 10h13.36 utc:20305: Test complete
sd main:MESSAGE:2020-07-20 10h13.36 utc:20305: Total time to scan all hosts : 1 seconds

gvmd.log:
md manage: INFO:2020-07-22 07h39.42 utc:1298: Updating /opt/gvm/var/lib/gvm/scap-data/nvdcve-2.0-2016.xml
md manage: INFO:2020-07-22 07h39.42 utc:1298: Updating /opt/gvm/var/lib/gvm/scap-data/nvdcve-2.0-2013.xml
md manage: INFO:2020-07-22 07h39.43 utc:1298: Updating /opt/gvm/var/lib/gvm/scap-data/nvdcve-2.0-2017.xml
md manage: INFO:2020-07-22 07h39.43 utc:1298: Updating /opt/gvm/var/lib/gvm/scap-data/nvdcve-2.0-2006.xml
lib osp:WARNING:2020-07-22 07h39.51 utc:1454: osp_get_vts_version: element VTS missing.
md manage:WARNING:2020-07-22 07h39.51 utc:1454: manage_update_nvt_cache_osp: failed to get scanner_version
lib osp:WARNING:2020-07-22 07h40.12 utc:1465: osp_get_vts_version: element VTS missing.
md manage:WARNING:2020-07-22 07h40.12 utc:1465: manage_update_nvt_cache_osp: failed to get scanner_version
lib osp:WARNING:2020-07-22 07h40.22 utc:1472: osp_get_vts_version: element VTS missing.
md manage:WARNING:2020-07-22 07h40.22 utc:1472: manage_update_nvt_cache_osp: failed to get scanner_version
lib osp:WARNING:2020-07-22 07h40.32 utc:1480: osp_get_vts_version: element VTS missing.
md manage:WARNING:2020-07-22 07h40.32 utc:1480: manage_update_nvt_cache_osp: failed to get scanner_version

Would be great if someone could share any insights

GVM versions

gsa: (‘gsad --version’) = Greenbone Security Assistant 9.0.1
gvm: (‘gvmd --version’) = Greenbone Vulnerability Manager 9.0.1
openvas-scanner: (‘openvassd --version’) = OpenVAS 7.0.1
gvm-libs: = gvm-libs 11.0.1

Environment

Operating system: = Unbuntu 18 LTS
Kernel: (‘uname -a’) = 4.15.0-101-generic #102-Ubuntu SMP Mon May 11 10:07:26 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
Installation method / source: = VM Installation

Hi, manage_update_nvt_cache_osp: failed to get scanner_version, you need to have scanner talking with redis. So check redis Hint: Redis setup / configuration for GSE/GVM/OpenVAS and check scanner log after this verify scanner.

I don’t think there is need for checking redis as from the below logs redis is talking with scanner successfully.

sd main:MESSAGE:2020-07-22 08h23.46 utc:4839: openvas 7.0.1 started
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: fetch_max_db_index: maximum DB number: 1025
sd main: DEBUG:2020-07-22 08h23.46 utc:4839: Start loading scan preferences.
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: fetch_max_db_index: maximum DB number: 1025
sd main: DEBUG:2020-07-22 08h23.46 utc:4839: End loading scan preferences.
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: fetch_max_db_index: maximum DB number: 1025
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/3
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: redis_delete_all: deleting all elements from KB #3
sd main:MESSAGE:2020-07-22 08h23.46 utc:4839: Starts a new scan. Target(s) : www.xyz.com, with max_hosts = 20 and max_checks = 4
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: fetch_max_db_index: maximum DB number: 1025
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/3
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: fetch_max_db_index: maximum DB number: 1025
lib kb: DEBUG:2020-07-22 08h23.46 utc:4840: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/3
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/4
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: fetch_max_db_index: maximum DB number: 1025
lib kb: DEBUG:2020-07-22 08h23.46 utc:4841: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/4
lib kb: DEBUG:2020-07-22 08h23.46 utc:4839: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/5
lib kb: DEBUG:2020-07-22 08h23.46 utc:4842: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/5
sd main:MESSAGE:2020-07-22 08h23.46 utc:4841: Testing x.x.x.x (Vhosts: www.xyz.com) [4841]
lib kb: DEBUG:2020-07-22 08h23.46 utc:4841: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/4
sd main:MESSAGE:2020-07-22 08h23.46 utc:4841: Finished testing x.x.x.x. Time : 0.05 secs
sd main:MESSAGE:2020-07-22 08h23.46 utc:4840: Testing x.x.x.x (Vhosts: www.xyz.com) [4840]
lib kb: DEBUG:2020-07-22 08h23.46 utc:4840: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/3
sd main:MESSAGE:2020-07-22 08h23.46 utc:4840: Finished testing x.x.x.x. Time : 0.08 secs
sd main:MESSAGE:2020-07-22 08h23.46 utc:4842: Testing x.x.x.x (Vhosts: www.xyz.com) [4842]
lib kb: DEBUG:2020-07-22 08h23.46 utc:4842: get_redis_ctx: connected to redis:///run/redis-openvas/redis.sock/5
sd main:MESSAGE:2020-07-22 08h23.46 utc:4842: Finished testing x.x.x.x. Time : 0.19 secs
sd main: DEBUG:2020-07-22 08h23.46 utc:4839: waitpid() failed. No child processes)
sd main:MESSAGE:2020-07-22 08h23.47 utc:4839: Test complete
sd main:MESSAGE:2020-07-22 08h23.47 utc:4839: Total time to scan all hosts : 1 seconds

The suspected entry here is below:
sd main: DEBUG:2020-07-22 08h23.46 utc:4839: waitpid() failed. No child processes)

Not sure whats broken but when we try to get the gvmd service status it says
Jul 22 03:26:22 systemd[1]: Starting Job that runs the gvm daemon…
Jul 22 03:26:22 systemd[1]: gvmd.service: Can’t open PID file /opt/gvm/var/run/gvmd.pid (yet?) after start: No such file or directory
Jul 22 03:26:31 systemd[1]: Started Job that runs the gvm daemon.

The file is located at above location which is verified. Also with gvm user this is accessible.

Can you verify scanner from cli?

gsad and ospd-openvas service both are running actively

gvmd --get-scanners, get UUID and gvmd --verify-scanner=UUID if it fails you have scanner issue. I had this error manage_update_nvt_cache_osp: failed to get scanner_version if I remember good, I had a scanner issue.

Able to get UUID successfully and from that scanner version from verify scanner. Not sure where to investigate exactly for this.

Thanks for your inputs anyway :slight_smile:

Good. Now you can start by telling more about installation and giving more logs from gvm, gsa, scanner, but after you restart each service. Read Gvmd stuck at 100% with no CVE's and CPE's same errors in log as yours. md manage:WARNING:2020-03-26 19h50.06 utc:5861: manage_update_nvt_cache_osp: failed to get scanner_version. I would guess something with redis and sync.

1 Like