Docker-compose / Scan interrupted

nschmitz · September 28, 2022, 8:07am

Hello,
I’m trying to use greenbone following Greenbone Community Containers 22.4 - Greenbone Community Documentation

When I start a scan, it’s almost immediatly terminated with “gvm2204-ospd-openvas-1 | OSPD[6] 2022-09-28 07:46:02,062: INFO: (ospd.ospd) a7dbafc9-3d98-44ec-a8b6-f237af028d0f: Scan interrupted.”

In the log, at startup, I see :

gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h49.30 UTC:183: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 07:49:37,857: INFO: (ospd_openvas.daemon) Loading VTs. Scans will be [requested|queued] until VTs are loaded. This may take a few minutes, please wait...
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h49.45 UTC:192: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h50.00 UTC:201: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h50.16 UTC:210: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h50.31 UTC:219: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h50.46 UTC:228: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-redis-server-1         | 7:M 28 Sep 2022 07:50:57.066 * DB saved on disk
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 07:50:57,072: INFO: (ospd_openvas.daemon) VTs were up to date. Feed version is 202209271013.
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h51.01 UTC:237: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h51.16 UTC:246: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 07h51.31 UTC:255: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting

Following the workflow described in documentation, I should get something like “OSP service has different VT status (version X) from database (version (Y), Z VTs). Starting update …” from gvmd, but it never happens.

Any help would be appreciated

bricks · September 28, 2022, 8:37am

As you can read from the logs the VTs are not loaded yet. The scanner ospd-openvas is currently loading the meta information from the files on the disk. If that is finished gvmd needs to request the VT meta information from ospd-openvas. As you can read from osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting this can’t happen until ospd-openvas has finished loading the VTs. And because you don’t have any VTs you can’t scan and therefore will get Scan interrupted. messages.

Just be patient and wait until the feed is loaded completely by both daemons. As mentioned in the docs this may take a while.

nschmitz · September 28, 2022, 11:17am

Thank you for your quick answer. I was thinking the message “OSPD[6] INFO: (ospd_openvas.daemon) VTs were up to date. Feed version is 202209271013.” was an indication that ospd-openvas had finished and that gvmd could start his next job.

I waited more than 2 hours now, and no new line of log, and no CPU/disk activity. Is there a way to check if something is really happening ?

bricks · September 28, 2022, 11:53am

Sorry of course you are right. The log VTs were up to date. Feed version is 202209271013. means ospd-openvas is finished with loading the VT information. Without clear text formatting the logs are very difficult to read. I’ve adjusted your message.

You are also completely right that gvmd should raise the OSP service has different VT status (version X) from database (version (Y), Z VTs). Starting update message some minutes later.

If that doesn’t happen you can try to restart the gvmd container.

nschmitz · September 28, 2022, 12:13pm

Thanks ! My bad for formatting, I will be more careful now.
I restarted my gvmd container this is what I got (the first two lines are 2 hours old):


gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 08h52.19 UTC:79: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 08h52.29 UTC:80: osp_scanner_feed_version: No feed version available yet. OSPd OpenVAS is still starting
gvm2204-gvmd-1                 |  connection 
gvm2204-gvmd-1                 | ------------
gvm2204-gvmd-1                 |  connected
gvm2204-gvmd-1                 | (1 row)
gvm2204-gvmd-1                 | 
gvm2204-gvmd-1                 | User exists already.
gvm2204-gvmd-1                 | starting gvmd
gvm2204-gvmd-1                 | md   main:MESSAGE:2022-09-28 12h03.05 utc:19:    Greenbone Vulnerability Manager version 22.4.0~dev1 (DB revision 250)
gvm2204-gvmd-1                 | md   main:   INFO:2022-09-28 12h03.05 utc:19:    Migrating database.
gvm2204-gvmd-1                 | md   main:   INFO:2022-09-28 12h03.05 utc:19: gvmd: databases are already at the supported version
gvm2204-gvmd-1                 | md   main:MESSAGE:2022-09-28 12h03.05 utc:20:    Greenbone Vulnerability Manager version 22.4.0~dev1 (DB revision 250)
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 12h03.05 utc:20:    Creating user.
gvm2204-gvmd-1                 | md   main:MESSAGE:2022-09-28 12h03.05 utc:22:    Greenbone Vulnerability Manager version 22.4.0~dev1 (DB revision 250)
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 12h03.05 utc:22:    Getting users.
gvm2204-gvmd-1                 | md   main:MESSAGE:2022-09-28 12h03.06 utc:25:    Greenbone Vulnerability Manager version 22.4.0~dev1 (DB revision 250)
gvm2204-gvmd-1                 | md manage:   INFO:2022-09-28 12h03.06 utc:25:    Modifying setting.
gvm2204-gvmd-1                 | md   main:MESSAGE:2022-09-28 12h03.06 utc:26:    Greenbone Vulnerability Manager version 22.4.0~dev1 (DB revision 250)
gvm2204-gsa-1                  | gsad  gmp:MESSAGE:2022-09-28 12h07.26 GMT:12: Authentication success for 'admin' from XXXX

And this is what I get when I start a scan :


gvm2204-gvmd-1                 | event task:MESSAGE:2022-09-28 14h10.12 CEST:194: Status of task Immediate scan of IP XXXX(7627de08-7b8c-404e-8383-cafb907fb964) has changed to Requested
gvm2204-gvmd-1                 | event task:MESSAGE:2022-09-28 14h10.12 CEST:194: Task Immediate scan of IP XXXXX(7627de08-7b8c-404e-8383-cafb907fb964) has been requested to start by admin
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:17,452: INFO: (ospd.command.command) Scan fffe2e93-ba72-428b-8c28-6373a675f050 added to the queue in position 1.
gvm2204-gvmd-1                 | event task:MESSAGE:2022-09-28 14h10.17 CEST:196: Status of task Immediate scan of IP XXXXX (7627de08-7b8c-404e-8383-cafb907fb964) has changed to Queued
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:25,403: INFO: (ospd.ospd) Currently 1 queued scans.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:25,438: INFO: (ospd.ospd) Starting scan fffe2e93-ba72-428b-8c28-6373a675f050.
gvm2204-gvmd-1                 | event task:MESSAGE:2022-09-28 14h10.27 CEST:196: Status of task Immediate scan of IP XXXXXX (7627de08-7b8c-404e-8383-cafb907fb964) has changed to Running
gvm2204-mqtt-broker-1          | 1664367028: New connection from 192.168.80.6:47330 on port 1883.
gvm2204-mqtt-broker-1          | 1664367028: New client connected from 192.168.80.6:47330 as 339e2dd3-b295-4ce9-b876-50a44921ee21 (p5, c1, k0).
gvm2204-mqtt-broker-1          | 1664367029: New connection from 192.168.80.6:47332 on port 1883.
gvm2204-mqtt-broker-1          | 1664367029: New client connected from 192.168.80.6:47332 as 0ceecc73-9389-40e3-83e5-8d1f801e954b (p5, c1, k0).
gvm2204-mqtt-broker-1          | 1664367029: Client 0ceecc73-9389-40e3-83e5-8d1f801e954b closed its connection.
gvm2204-mqtt-broker-1          | 1664367030: Client 339e2dd3-b295-4ce9-b876-50a44921ee21 closed its connection.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,235: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Host scan finished.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,237: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Host scan got interrupted. Progress: 0, Status: RUNNING
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,237: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan interrupted.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,583: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan process is dead and its progress is 0
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,583: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan interrupted.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,587: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan process is dead and its progress is 0
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,587: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan interrupted.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,647: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan process is dead and its progress is 0
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,648: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan interrupted.
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,683: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan process is dead and its progress is 0
gvm2204-ospd-openvas-1         | OSPD[6] 2022-09-28 12:10:32,684: INFO: (ospd.ospd) fffe2e93-ba72-428b-8c28-6373a675f050: Scan interrupted.
gvm2204-gvmd-1                 | event task:MESSAGE:2022-09-28 12h10.32 UTC:196: Status of task Immediate scan of IP XXXXX (7627de08-7b8c-404e-8383-cafb907fb964) has changed to Interrupted

If you have any idea Thx again.

bricks · September 28, 2022, 12:31pm

At least the general setup is fine. Do you get some error in the corresponding tab of the report of this scan in the web interface? Do you have NVTs in web ui?

nschmitz · September 28, 2022, 12:44pm

This is what I get in Error Messages :

I do have 23988 loaded and visible in my SecInfo/NVTs menu (last one of Sep 27).

Thank you again !

bricks · September 28, 2022, 1:08pm

That number is really low. It should be around 100.000. Did you try to restart from scratch already? If you want to keep your current data you can delete the containers and volumes excluding the psql_data_vol volume.

nschmitz · September 28, 2022, 2:52pm

I started from scratch and it worked ! No idea what changed but still, thank you very much and sorry, I should have tried this first.
Thx again.

nschmitz · September 28, 2022, 2:58pm

Arf, I was too quick to answer
It got stuck at 98% with these logs :

greenbone-community-edition-pg-gvm-1               | 2022-09-28 14:49:44.757 UTC [1460] gvmd@gvmd ERROR:  duplicate key value violates unique constraint "settings_uuid_owner_key"
greenbone-community-edition-pg-gvm-1               | 2022-09-28 14:49:44.757 UTC [1460] gvmd@gvmd DETAIL:  Key (uuid, owner)=(3d5db3c7-5208-4b47-8c28-48efc621b1e0, 1) already exists.
greenbone-community-edition-pg-gvm-1               | 2022-09-28 14:49:44.757 UTC [1460] gvmd@gvmd STATEMENT:  INSERT INTO settings (uuid, owner, name, comment, value) VALUES ('3d5db3c7-5208-4b47-8c28-48efc621b1e0',  (SELECT id FROM users WHERE uuid = '08d16cf8-6f35-4301-84cc-3c60f1c24bb8'),  'Tasks Top Dashboard Configuration',  (SELECT comment FROM settings   WHERE uuid = '3d5db3c7-5208-4b47-8c28-48efc621b1e0' AND owner IS NULL),  '{"rows":[{"id":"fd81e390-be1b-4920-b7c7-92d6cc7651b9","height":253,"items":[{"id":"7d503c72-ea25-46d1-a101-cd327effed61","displayId":"task-by-severity-class"},{"id":"4003776d-a85e-4bbe-a9d2-fa530cb75e36","displayId":"task-by-most-high-results"},{"id":"4b29d88f-ece1-440f-ad40-44daaad59140","displayId":"task-by-status"}]}]}');
greenbone-community-edition-gvmd-1                 | md manage:WARNING:2022-09-28 16h49.44 CEST:2144: sql_exec_internal: constraint violation: ERROR:  duplicate key value violates unique constraint "settings_uuid_owner_key"
greenbone-community-edition-gvmd-1                 | DETAIL:  Key (uuid, owner)=(3d5db3c7-5208-4b47-8c28-48efc621b1e0, 1) already exists.
greenbone-community-edition-gvmd-1                 | md manage:WARNING:2022-09-28 16h49.44 CEST:2144: sql_exec_internal: SQL: INSERT INTO settings (uuid, owner, name, comment, value) VALUES ('3d5db3c7-5208-4b47-8c28-48efc621b1e0',  (SELECT id FROM users WHERE uuid = '08d16cf8-6f35-4301-84cc-3c60f1c24bb8'),  'Tasks Top Dashboard Configuration',  (SELECT comment FROM settings   WHERE uuid = '3d5db3c7-5208-4b47-8c28-48efc621b1e0' AND owner IS NULL),  '{"rows":[{"id":"fd81e390-be1b-4920-b7c7-92d6cc7651b9","height":253,"items":[{"id":"7d503c72-ea25-46d1-a101-cd327effed61","displayId":"task-by-severity-class"},{"id":"4003776d-a85e-4bbe-a9d2-fa530cb75e36","displayId":"task-by-most-high-results"},{"id":"4b29d88f-ece1-440f-ad40-44daaad59140","displayId":"task-by-status"}]}]}');

It’s weird because it’s a simple single scan, I did nothing special. I do now have 100 000 NVT loaded.

nschmitz · September 28, 2022, 3:20pm

Ok, I found Scan Interrupted at 98% - #4 by investguy and used the proposed workaround : use greenbone/ospd-openvas:22.4.1 instead of stable for ospd-openvas. All seems fine now !

I can add that I also came accros the problem with Redis (unable to dump the .rdb file due to permission issue) but I already solved it by patching the redis.conf file to redirect the .rdb file to a writable folder.