search

greenbone / ospd-openvas

ospd-openvas is an OSP server implementation to allow GVM to remotely control an OpenVAS Scanner
GNU Affero General Public License v3.0
67 stars 58 forks source link

[20.8.0] Unexpected interrupted return code #335

Closed tuxmaster5000 closed 3 years ago

tuxmaster5000 commented 4 years ago

The scanner self will exits fine, but ospd-openvas will interpret it as an error. ospd-openvas log:

(ospd.ospd) aae6b036-7a1c-47d4-8866-0e07c8799b48: Host scan finished. (ospd.ospd) aae6b036-7a1c-47d4-8866-0e07c8799b48: Scan interrupted. (ospd.ospd) aae6b036-7a1c-47d4-8866-0e07c8799b48: Scan stopped with errors. (ospd.ospd) aae6b036-7a1c-47d4-8866-0e07c8799b48: Scan interrupted.

openvas log:

Vulnerability scan d667271d-11ef-4e68-bc0c-39fa0659e778 finished for host XXXXX in 993.56 seconds Vulnerability scan d667271d-11ef-4e68-bc0c-39fa0659e778 finished in 1000 seconds: 1 hosts

No error was logged by openvas.

openvas --version

OpenVAS 20.8.0 gvm-libs 20.8.0

ospd version:

20.8.1

Most new code since 2005: (C) 2020 Greenbone Networks GmbH Nessus origin: (C) 2004 Renaud Deraison deraison@nessus.org License GPLv2: GNU GPL version 2 This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law.

wisukind commented 3 years ago

This is weird. The problem has gone on this particular task ! So far it happened systematically but the last scan done with the patched version worked without problem and was super fast.

The only thing I did was update the OS to latest patches and reboot.

I'm thinking it's perhaps a problem which occurs only with certain targets & probes.

Nevertheless, I will roll out this version to all my slaves. We are running dozens of scans per week, so one time or another the same problem will arise again and I'll be able to report more debug informations.

bjoernricks commented 3 years ago

Yes this issue is really really weird. We still are not able to reproduce it reliably. Therefore we are very thankful for every feedback

wisukind commented 3 years ago

OK, I was able to reproduce the problem with your patched version. See below the latest logs just before task was set to Interrupted. Hope that helps.

ospd Logs:

OSPD[241864] 2021-06-19 21:07:49,048: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,049: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,050: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,124: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 17 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,126: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,127: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,128: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,129: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,197: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 16 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,199: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,200: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,201: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,201: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,281: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 17 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,283: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,284: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,285: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,286: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,367: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 20 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,369: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,370: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,371: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,372: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,460: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 20 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,463: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,464: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,465: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,466: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,573: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 21 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,574: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Host 10.234.37.104 has progress: 100 OSPD[241864] 2021-06-19 21:07:49,576: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,579: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,583: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,583: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: ['10.234.37.104'] OSPD[241864] 2021-06-19 21:07:49,584: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Remove the following hosts from the target list, as they are already finished or are dead: ['10.234.37.104'] OSPD[241864] 2021-06-19 21:07:49,609: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:49,609: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,609: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Check scan process: OSPD[241864] 2021-06-19 21:07:49,609: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:49,610: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,610: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:49,611: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Results sent successfully to the client. Cleaning temporary result list. OSPD[241864] 2021-06-19 21:07:49,661: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:49,661: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,661: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Check scan process: OSPD[241864] 2021-06-19 21:07:49,661: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Inserting 11 results into scan collection table OSPD[241864] 2021-06-19 21:07:49,663: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:49,663: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,666: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:49,666: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,670: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,672: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,672: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:49,715: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Results sent successfully to the client. Cleaning temporary result list. OSPD[241864] 2021-06-19 21:07:49,726: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:49,727: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:49,728: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:49,729: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:50,733: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:50,734: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:50,734: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as dead: [] OSPD[241864] 2021-06-19 21:07:50,735: DEBUG: (ospd.scan) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Setting the following hosts as finished: [] OSPD[241864] 2021-06-19 21:07:50,735: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Target is finished OSPD[241864] 2021-06-19 21:07:50,735: DEBUG: (ospd_openvas.daemon) cf376b64-9aee-4f2e-81d3-a67a086d95a4: End Target. Release main database OSPD[241864] 2021-06-19 21:07:50,736: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Host scan finished. OSPD[241864] 2021-06-19 21:07:50,736: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: RUNNING, OSPD[241864] 2021-06-19 21:07:50,736: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:50,737: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:50,738: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:50,738: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Host scan finished. Progress: 21, Status: RUNNING OSPD[241864] 2021-06-19 21:07:50,738: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Set scan status INTERRUPTED, OSPD[241864] 2021-06-19 21:07:50,738: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Scan interrupted. OSPD[241864] 2021-06-19 21:07:50,738: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:50,739: DEBUG: (root) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current progress: OSPD[241864] 2021-06-19 21:07:50,781: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: INTERRUPTED, OSPD[241864] 2021-06-19 21:07:50,782: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:50,782: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Scan process is dead and its progress is 21 OSPD[241864] 2021-06-19 21:07:50,782: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Set scan status INTERRUPTED, OSPD[241864] 2021-06-19 21:07:50,783: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Scan interrupted. OSPD[241864] 2021-06-19 21:07:50,783: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Check scan process: OSPD[241864] 2021-06-19 21:07:50,783: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: INTERRUPTED, OSPD[241864] 2021-06-19 21:07:50,783: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:50,783: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: INTERRUPTED, OSPD[241864] 2021-06-19 21:07:50,784: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Results sent successfully to the client. Cleaning temporary result list. OSPD[241864] 2021-06-19 21:07:51,533: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: INTERRUPTED, OSPD[241864] 2021-06-19 21:07:51,533: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan progress: 21, OSPD[241864] 2021-06-19 21:07:51,534: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Scan process is dead and its progress is 21 OSPD[241864] 2021-06-19 21:07:51,534: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Set scan status INTERRUPTED, OSPD[241864] 2021-06-19 21:07:51,535: INFO: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Scan interrupted. OSPD[241864] 2021-06-19 21:07:51,535: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Check scan process: OSPD[241864] 2021-06-19 21:07:51,536: DEBUG: (ospd.ospd) cf376b64-9aee-4f2e-81d3-a67a086d95a4: Current scan status: INTERRUPTED,

openvas.log

sd main:MESSAGE:2021-06-19 10h26.30 utc:156222: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.39.68 in 1886.43 seconds sd main:MESSAGE:2021-06-19 10h30.38 utc:37166: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.42.144 in 1247.39 seconds sd main:MESSAGE:2021-06-19 10h36.47 utc:139012: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.39.25 in 2717.57 seconds sd main:MESSAGE:2021-06-19 10h37.12 utc:3117: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.42.131 in 1834.90 seconds sd main:MESSAGE:2021-06-19 10h37.14 utc:95393: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.39.2 in 1234.85 seconds sd main:MESSAGE:2021-06-19 10h39.18 utc:34893: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.36.117 in 1780.30 seconds sd main:MESSAGE:2021-06-19 10h39.29 utc:12480: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.37.1 in 1894.58 seconds sd main:MESSAGE:2021-06-19 10h40.42 utc:8236: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.42.135 in 2004.86 seconds sd main:MESSAGE:2021-06-19 10h42.40 utc:108227: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.38.217 in 3447.68 seconds sd main:MESSAGE:2021-06-19 10h48.16 utc:116816: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.39.1 in 1721.25 seconds sd main:MESSAGE:2021-06-19 10h49.08 utc:103345: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.37.94 in 3987.17 seconds sd main:MESSAGE:2021-06-19 10h49.25 utc:105167: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.42.166 in 1894.44 seconds sd main:MESSAGE:2021-06-19 10h52.02 utc:121885: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.36.40 in 1891.72 seconds sd main:MESSAGE:2021-06-19 10h53.58 utc:43319: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.36.15 in 2605.61 seconds sd main:MESSAGE:2021-06-19 11h02.00 utc:37180: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.43.111 in 5491.19 seconds sd main:MESSAGE:2021-06-19 19h07.49 utc:60285: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished for host 10.234.37.104 in 34385.34 seconds sd main:MESSAGE:2021-06-19 19h07.50 utc:242198: Vulnerability scan cf376b64-9aee-4f2e-81d3-a67a086d95a4 finished in 38595 seconds: 82 alive hosts of 1710

This is weird, as both ospd and openvas confirm the scan task is finished, but instead of putting a 100% score and settings the task as finished, it immediately put it as Interrupted without further details. I don't know what the patch was suppose to do, but it seems to me it failed since I see no difference in the logs vs previous unpatched version.

tuxmaster5000 commented 3 years ago

I have an idea for it. I have seen this messages last week, when no redis connection was available any more. Because to much parallel jobs was running. After allowing redis more parallel databases it was gone. I have set databases to 512 in the redis.conf

wisukind commented 3 years ago

@tuxmaster5000 not my case here unfortunately. My redis databases number here is set to 65535...

Virsacer commented 3 years ago

I have one job sheduled every day and 4 jobs spread over the weekends.

With 20.8.0 and 21.4.0 the daily job did complete about every ten days or so. Two of the weekend-jobs did work most of the time and the other two did not complete most of the time.

On thursday I updated to the latest from 21.04-branch and all jobs have completed successfully since then :)

wisukind commented 3 years ago

@Virsacer that's the problem. This issue is completely erratic. Sometimes it happens all the times, sometimes everything runs without issues. Right now I have two tasks which constantly ends up in interrupted state; while using the latest 21.04 version. But I don't see anything in the logs explaining why a running task, right after being set as "finished" by ospd is put in Interrupted state. That's completely weird.

Kraemii commented 3 years ago

To give you a short update: I put quite some work into restructuring the code and eliminating some possible race conditions. These changes are contained in the master and 21.04 branch. Thanks again for the many feedback we get regarding this topic!

wisukind commented 3 years ago

Thanks Kraemii. Will give it a try and let you know. Regards

jjnicola commented 3 years ago

HI everyone! I was able to reproduce the issue for a few scans, even with the patch from @Kraemii, since the problem was in openvas-scanner. This got me some hints. The issue should be fixed with greenbone/openvas-scanner#832 . Please let me know if you still can reproduce the issue after applying the patch. Regards, Juan

wisukind commented 3 years ago

Thanks guys for the update and trying to fix this problem. I've applied the patch from Kraemii a couple of weeks ago, and ran dozens of scans after that on targets usually prone to this problem, and so far I wasn't able to reproduce the issue anymore. So even if it doesn't fix totally the problem, it seems to help. I'll continue to report any new findings here.

wisukind commented 3 years ago

All,

I had the problem again, but now the situation is a bit different. Basically what happens now is:

1) Ospd / Openvas finishs the scan at 100% 2) For whatever reason, gvmd is stuck at various percentage levels, and isn't progressing anymore 3) Situation rest like this, until the admin stop the task. Stopping the task would yeld the following error message on gvmd:

`event task:MESSAGE:2021-08-11 08h11.21 UTC:1788: Status of task Cedar Rapids, VOIP (c54c7ddb-a119-4417-8bbd-7952f6f2faab) has changed to Stop Requested event task:MESSAGE:2021-08-11 08h11.22 UTC:1788: Status of task Cedar Rapids, VOIP (c54c7ddb-a119-4417-8bbd-7952f6f2faab) has changed to Stopped event task:MESSAGE:2021-08-11 08h12.15 UTC:1918: Status of task Cedar Rapids, VOIP (c54c7ddb-a119-4417-8bbd-7952f6f2faab) has changed to Requested md manage:WARNING:2021-08-11 08h12.15 UTC:2083: OSP start_scan c54c7ddb-a119-4417-8bbd-7952f6f2faab: Couldn't send stop_scan command to scanner event task:MESSAGE:2021-08-11 08h12.15 UTC:1918: Task Cedar Rapids, VOIP (c54c7ddb-a119-4417-8bbd-7952f6f2faab) has been resumed by tatooin event task:MESSAGE:2021-08-11 08h12.17 UTC:1937: Status of task Cedar Rapids, VOIP (c54c7ddb-a119-4417-8bbd-7952f6f2faab) has changed to Done event task:MESSAGE:2021-08-11 08h12.34 UTC:1937: Status of task Cedar Rapids, VOIP (c54c7ddb-a119-4417-8bbd-7952f6f2faab) has changed to Interrupted

`

While on ospd side, you have:

OSPD[31890] 2021-08-11 03:06:17,001: DEBUG: (ospd.ospd) 353e53cf-550d-458e-aee5-a2da966c2fe4: Current scan progress: 100,
OSPD[31890] 2021-08-11 03:06:17,001: DEBUG: (ospd.ospd) 353e53cf-550d-458e-aee5-a2da966c2fe4: Current scan status: FINISHED,
OSPD[31890] 2021-08-11 03:06:17,002: DEBUG: (ospd.ospd) 353e53cf-550d-458e-aee5-a2da966c2fe4: Results sent successfully to the client. Cleaning temporary result list.

4) Tasks is set to Stopped; then to Done, and almost immediately switch from Done to Interrupted.

Step 2) should ring some bells to old timers. We exactly had this very problem with GVM 11, and this bug was closed as too old. But seems it hasn't been resolved either...

There is really something broken in the communication protocol between ospd and gvmd. How comes gvmd has so many issues tracking scan progress & status, while everything seems to work quite fine on ospd side ?

On my end it seems I can narrow down the problem to one scanner on some tasks in particular. I'llupdate ospd/openvas with #882 and see if it happens again. Regards

wisukind commented 3 years ago

Same problem with patch #832.

Scans are continuing to run on ospd side; while frozen then stopped on gvmd side. Trying to resume the task will actually:

1) Start a new scan on the scanner side (note it's a NEW scan, so it will run concurrently with the initial one, still running !!) 2) After a few seconds on gvmd side; scan status will change to Interrupted state 3) Both scans continue to run on ospd side

jjnicola commented 3 years ago

Hi @wisukind , Thanks for reporting. But as far as I understand, everything is working as expected on the scanner side, since openvas and ospd-openvas are finishing the scan without issues now. But the problem is now on the gvmd client side, which for some reason is setting the scan as interrupted. IIRC, you have a master-sensor setup via TLS sockets. Do you see some communication problem here? In those cases you can see some messages about a broken pipe. Is this happening only on tasks which run in a sensor?

wisukind commented 3 years ago

Yes, it's indeed a different issue. Here ospd / openvas are working fine. On gvmd side I had several connection lost logs lines when the issue occured; so that's fine. But my question is mostly on the resuming part; why gvmd start a new scan when the connection is back, instead of resuming the already finished one (and putting the state as Done) ? And why gvmd puts immediately the resumed task as Interrupted ?

Overrall that's always the same story; gvmd is not reliably maintaining the communication with ospd and loose tracks of scans tasks too easily. It should be able to resume tasks where it left, and also to get up to date scan status from the scanner directly, even after the connection has dropped for some time.

Should I open a new bug report for this ?

jjnicola commented 3 years ago

Yes, what you are experimenting now is a complete different issue. Feel free to open a new issue for gvmd.

Regarding the current issue, despite I think the main issue here (ospd putting the scanner as interrupted) is already addressed, I will keep it open some more time, waiting for more feedback about openvas/ospd-openvas behaviour.

jjnicola commented 3 years ago

@wisukind And as always, thank you very much for your feedback! ;)

wisukind commented 3 years ago

Yes, please leave that bug open for now. I am running dozens of scans per month, so this is usually happening very frequently. If it doesn't happen again by, let's say, mid september, then you should be fine to close it.

Also I've created bug #1668 on gvmd side.

wisukind commented 3 years ago

Hello,

After a few weeks of testing on targets prone to this bug, I confirm the bug has just moved to issue #1668. Basically, tasks are no longer put in Interrupted state, but in Stopped state now for no reasons. On some of my tasks, it's systemic. It turns out, however, that the bug is now on gvmd side, as on ospd the task appears as finished.

jjnicola commented 3 years ago

I am glad to read that last comment and can closed this issue. Thanks a lot to those who have tested the the different patches and given feedback. So, closing here.

wisukind commented 2 years ago

Hello. This bug should unfortunately be re-opened. I am witnessing that problem again on some tasks. Highly less frequent, but still happens in 21.4.3 final release. :-(

jjnicola commented 2 years ago

Hello @wisukind, I think it is not the same issue, but the same results, since this issue was fixed with https://github.com/greenbone/openvas-scanner/pull/832. I would suggest to open a new issue, and add more information:

Please also set the log level to debug for OSPD and OpenVAS and add some logs if possible. Please. Open a new issue.

Thanks in advanced.