AttributeError in ospd-openvas

Archive Greenbone Community Edition
1

When posting you should provide information about your environment using the following template:

GVM versions

gsad: Greenbone Security Assistant 20.08.0~git
gvmd: Greenbone Vulnerability Manager 20.08.0
openvas-scanner: OpenVAS 20.8.0
gvm-libs: gvm-libs 20.8.0
ospd-openvas:

  • OSP Server for openvas: 20.8.0
  • OSP: 1.2
  • OSPd OpenVAS: 20.8.1

Environment

Operating system: Debian 10.7 (buster)
Kernel: Linux openvas 4.19.0-13-amd64 #1 SMP Debian 4.19.160-2 (2020-11-28) x86_64 GNU/Linux
Installation method / source: Compiled/installed via tarballs referenced at GVM 20.08 (stable, initial release 2020-08-12)

So, I have feeds updating, scanner configs in place, all services running.

I increased the number of redis databases from the default 16 to 128 (I assume that’s excessive), after observing scans hanging, and encountering:
lib kb:CRITICAL:2020-12-31 18h27.52 utc:18006: No redis DB available
when attempting to scan.

Now, when I run a scan of any sort, it fails, indicating that it was interrupted:

==> /var/log/gvm/gvmd.log <==
event task:MESSAGE:2020-12-31 18h41.20 UTC:21665: Status of task Immediate scan of IP 10.100.2.130 (4c0d1dcd-2e29-4d98-bf17-9ecfa2e09bc9) has changed to Requested           
event task:MESSAGE:2020-12-31 18h41.20 UTC:21665: Task Immediate scan of IP 10.100.2.130 (4c0d1dcd-2e29-4d98-bf17-9ecfa2e09bc9) has been requested to start by admin                                              

==> /var/log/gvm/ospd-scanner.log <==
OSPD[16584] 2020-12-31 13:41:58,998: INFO: (ospd.command.command) Scan 9e8754c0-59de-4fcf-82ad-cb7f94470172 added to the queue in position 1.                                                                     

==> /var/log/gvm/gvmd.log <==
event task:MESSAGE:2020-12-31 18h41.59 UTC:21668: Status of task Immediate scan of IP 10.100.2.130 (4c0d1dcd-2e29-4d98-bf17-9ecfa2e09bc9) has changed to Queued                                                   

==> /var/log/gvm/ospd-scanner.log <==
OSPD[16584] 2020-12-31 13:42:03,687: INFO: (ospd.ospd) Currently 1 queued scans.
OSPD[16584] 2020-12-31 13:42:04,632: INFO: (ospd.ospd) Starting scan 9e8754c0-59de-4fcf-82ad-cb7f94470172.                                                                                                        
OSPD[16584] 2020-12-31 13:42:04,689: ERROR: (ospd.ospd) While scanning: 9e8754c0-59de-4fcf-82ad-cb7f94470172                                                                                                      
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/ospd/ospd.py", line 571, in start_scan
    self.exec_scan(scan_id)
  File "/usr/local/lib/python3.7/dist-packages/ospd_openvas/daemon.py", line 1226, in exec_scan
    openvas_scan_id = scan_prefs.prepare_openvas_scan_id_for_openvas()
  File "/usr/local/lib/python3.7/dist-packages/ospd_openvas/preferencehandler.py", line 94, in prepare_openvas_scan_id_for_openvas                                                                                
    self.kbdb.add_scan_id(self.scan_id, self._openvas_scan_id)
AttributeError: 'NoneType' object has no attribute 'add_scan_id'
OSPD[16584] 2020-12-31 13:42:04,714: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan interrupted.                                                                                                    

==> /var/log/gvm/gvmd.log <==
event task:MESSAGE:2020-12-31 18h42.04 UTC:21668: Status of task Immediate scan of IP 10.100.2.130 (4c0d1dcd-2e29-4d98-bf17-9ecfa2e09bc9) has changed to Running                                                  

==> /var/log/gvm/ospd-scanner.log <==
OSPD[16584] 2020-12-31 13:42:09,762: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan stopped with errors.                                                                                            
OSPD[16584] 2020-12-31 13:42:09,765: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan interrupted.                                                                                                    
OSPD[16584] 2020-12-31 13:42:09,779: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan stopped with errors.                                                                                            
OSPD[16584] 2020-12-31 13:42:09,781: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan interrupted.                                                                                                    
OSPD[16584] 2020-12-31 13:42:09,908: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan stopped with errors.                                                                                            
OSPD[16584] 2020-12-31 13:42:09,909: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan interrupted.                                                                                                    
OSPD[16584] 2020-12-31 13:42:09,991: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan stopped with errors.                                                                                            
OSPD[16584] 2020-12-31 13:42:09,992: INFO: (ospd.ospd) 9e8754c0-59de-4fcf-82ad-cb7f94470172: Scan interrupted.                                                                                                    

==> /var/log/gvm/gvmd.log <==
event task:MESSAGE:2020-12-31 18h42.10 UTC:21668: Status of task Immediate scan of IP 10.100.2.130 (4c0d1dcd-2e29-4d98-bf17-9ecfa2e09bc9) has changed to Interrupted

This occurs with any sort of scan I attempt.

2

In this issue (which does not seem to be the same as mine), there is a recommendation against mixing versions of ospd and other GSE components.

The release page I reference in the original post does indicate 20.8.1 specifically, for OSPD, and so I’ve used that version. Is it possible that this is a misunderstanding on my part, and that I should be using 20.8.0? The notes for those .0, and .1 indicate minor bugfixes only, but I’d like to confirmation that isn’t a potential issue.

3

Actually, after looking at the code, it seems more likely that this is still a redis issue of some sort.

In ospd_openvas.db.MainDB:

def get_new_kb_database(self) -> Optional[KbDB]:
    """ Return a new kb db to an empty kb.
    """
    for index in range(1, self.max_database_index):
        if self.try_database(index):
            kbdb = KbDB(index)
            kbdb.flush()
            return kbdb

    return None

So, it’s failing to find an available database. Seems like, if that’s problematic, we aught to be raising an error instead of handing None to the PreferenceHandler and hoping for the best.

Anyway, I don’t know much about redis, or how openvas uses databases in redis…

root@openvas:/etc/systemd/system# for idx in $(seq 1 128); do echo "$idx $(redis-cli -n $idx dbsize)"; done
1 129044
2 5  
3 21 
4 10 
5 10 
6 10 
7 21 
8 10 
9 10 
10 10
11 10
12 21
13 10
14 10
15 10
16 13
17 13
18 13
19 13
20 13
21 13
22 13
23 0                             
24 0
25 0
...snip... (all 0's)
127 0
128
4

SOLVED

It seems like may have been related to my previous redis issue, with insufficient databases.

I restarted ospd-openvas and redis, and eventually scans started to work. I’m not exactly sure what fixed it. I was sure I restarted redis after changing the max dbs…but perhaps I didn’t. Or maybe ospd was holding on to some incorrect state related to that. I don’t know.

1 Like