[Openvas-discuss] OpenVAS9 hanging nasl tasks

Thijs Stuurman Thijs.Stuurman at internedservices.nl
Wed May 24 14:23:22 CEST 2017


Hani,

The task should have long finished by now.
It ended up with all 4 again:

"""
root     18222  0.1  0.1 143332 14024 ?        Ss   11:31   0:12 openvassd: Waiting for incoming connections
root     23807  0.4  0.3 158932 25056 ?        Ss   13:08   0:17  \_ openvassd: Serving /opt/openvas9/var/run/openvassd.sock
root     23878 47.0  0.2 158932 21416 ?        t    13:08  30:57      \_ openvassd: testing xxx
root     24812  0.0  0.2 158932 21484 ?        S    13:15   0:00          \_ openvassd: testing xxx  (/opt/openvas9/var/lib/openvas/plugins/ssh_authorization.nasl)
root     24813  0.0  0.2 158932 21488 ?        S    13:15   0:00          \_ openvassd: testing xxx  (/opt/openvas9/var/lib/openvas/plugins/netbios_name_get.nasl)
root     26277  0.0  0.2 158932 21484 ?        S    13:25   0:00          \_ openvassd: testing xxx  (/opt/openvas9/var/lib/openvas/plugins/2012/secpod_database_open_access_vuln.nasl)
root     29234  0.3  0.2 158932 22320 ?        S    13:47   0:05          \_ openvassd: testing xxx  (/opt/openvas9/var/lib/openvas/plugins/pre2008/tcp_port_zero.nasl)
root     18290  0.0  1.0 267816 87920 pts/2    SL   11:32   0:02 openvasmd
root     23802  0.6  1.1 279308 95524 pts/2    S    13:08   0:25  \_ openvasmd
root     23812  0.1  1.1 274480 98048 pts/2    S    13:08   0:04      \_ openvasmd: OTP: Handling scan c9ac6ded-8474-4d76-bfa6-dd5f6faabaf6
"""

The Nasl's are hanging in "recvfrom(xx,"
The "openvassd: testing" process is very busy with read and writes:

""" 
...
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$41\r\noid:1"..., 70) = 70
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$40\r\noid:1"..., 69) = 69
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$40\r\noid:1"..., 69) = 69
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$41\r\noid:1"..., 70) = 70
...
"""

A 120 second strace dump while grepping away all those read and writes delivers the following:

"""
...
getppid()                               = 23807
wait4(23807, NULL, WNOHANG, NULL)       = -1 ECHILD (No child processes)
kill(23807, SIG_0)                      = 0
...
"""

Always the same pid, the 120 second dump results in 18 of those.
The pid is the following process:

root     23807  0.4  0.3 158932 25056 ?        Ss   13:08   0:18  \_ openvassd: Serving /opt/openvas9/var/run/openvassd.sock

It is not clear to me what it is hanging on, but it hangs while looping something for sure.
Strace of 23807 shows it looping on:

"""
kill(23878, SIG_0)                      = 0
select(9, [8], NULL, NULL, {0, 10000})  = 0 (Timeout)
select(8, [7], NULL, NULL, {0, 1000})   = 0 (Timeout)
wait4(-1, NULL, WNOHANG, NULL)          = 0
"""

23778 is the testing process:

root     23878 47.1  0.2 158932 21416 ?        R    13:08  34:57      \_ openvassd: testing xxx

Thijs Stuurman
Security Operations Center | KPN Internedservices
thijs.stuurman at internedservices.nl | thijs.stuurman at kpn.com
T: +31(0)299476185 | M: +31(0)624366778
PGP Key-ID: 0x16ADC048 (https://pgp.surfnet.nl/)
Fingerprint: 2EDB 9B42 D6E8 7D4B 6E02 8BE5 6D46 8007 16AD C048

W: https://www.internedservices.nl | L: http://nl.linkedin.com/in/thijsstuurman




-----Oorspronkelijk bericht-----
Van: Openvas-discuss [mailto:openvas-discuss-bounces at wald.intevation.org] Namens Thijs Stuurman
Verzonden: woensdag 24 mei 2017 13:39
Aan: Hani Benhabiles <hani.benhabiles at greenbone.net>
CC: openvas-discuss at wald.intevation.org
Onderwerp: Re: [Openvas-discuss] OpenVAS9 hanging nasl tasks

Hani,

I restarted the task that stops a few times with the same result every time.
Ran one other scan on the same scanner which completed just fine.

Yesterday I saw 4 tasks hanging, now only 2 after about 5 minutes of running:

ssh_authorization.nasl and netbios_name_get.nasl

I did update the nvt database this morning.
The target host in this scan is 'dead' and I do not expect to see any open ports.
The ssh_authorization.nasl strace hangs at:

recvfrom(10, 

Just now I saw secpod_database_open_Access_vuln.nasl getting started. So now I expect it to end up hanging with the same 4 tasks as yesterday.
Redis is busy as ever but it seems 'normal' behavior.

Right now I think it has to do with systems not responding but these particular scans are not being killed while I do have the default timeouts set.
Plugins_timeout is set to 320, about 5 minutes but these are running for over 30 minutes while I'm typing this email.
Checks_read_timeout = 5
scanner_plugins_timeout = 36000 ... is this the relevant one? It's set to 10 hours by default ?! hmm

Perhaps I ran in to the issue from 5.0.7 as I went from OpenVAS8 to OpenVAS9 with my scan config? The  Full and fast scan (never used it) uses the same values.

Main changes compared to 5.0.7:
   15 * An issue which caused the 'scanner_plugins_timeout' preference to contain a
   16   wrong value under certain circumstances has been addressed.



Thijs Stuurman
Security Operations Center | KPN Internedservices thijs.stuurman at internedservices.nl | thijs.stuurman at kpn.com
T: +31(0)299476185 | M: +31(0)624366778
PGP Key-ID: 0x16ADC048 (https://pgp.surfnet.nl/)
Fingerprint: 2EDB 9B42 D6E8 7D4B 6E02 8BE5 6D46 8007 16AD C048

W: https://www.internedservices.nl | L: http://nl.linkedin.com/in/thijsstuurman




-----Oorspronkelijk bericht-----
Van: Thijs Stuurman
Verzonden: woensdag 24 mei 2017 12:56
Aan: 'Hani Benhabiles' <hani.benhabiles at greenbone.net>
CC: openvas-discuss at wald.intevation.org
Onderwerp: RE: [Openvas-discuss] OpenVAS9 hanging nasl tasks

Hani,

- Can you get a backtrace for the stuck processes ? The 4 nvts ones + the "testing xxxx" parent.
- Could it be related to your Redis setup ? You can monitor it with: 
redis-cli -s /tmp/redis.sock MONITOR

Strange, it floods with:

"""
...
1495622782.133505 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.94181:category"
1495622782.133559 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.869756:category"
1495622782.133601 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.870215:category"
1495622782.133667 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.902298:category"
1495622782.133728 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.869970:category"
1495622782.133813 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.865412:category"
1495622782.133859 [1 unix:/var/run/redis/redis.sock] "SRANDMEMBER" "oid:1.3.6.1.4.1.25623.1.0.801558:category"
...
"""

Strace on openvassd show's:

"""
...
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$40\r\noid:1"..., 69) = 69
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$41\r\noid:1"..., 70) = 70
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$41\r\noid:1"..., 70) = 70
read(5, "$1\r\n3\r\n", 16384)           = 7
write(5, "*2\r\n$11\r\nSRANDMEMBER\r\n$40\r\noid:1"..., 69) = 69 ...
"""

Both redis and openvassd are consuming all CPU resources together.

- If you're able to build from source, do you see this issue with current openvas-9 branch, and with trunk branch too ?

I build from source, currently running from http://www.openvas.org/install-source.html on Ubuntu 16.04 LTS:

openvas-libraries-9.0.1.tar.gz
openvas-manager-7.0.1.tar.gz
openvas-scanner-5.1.1.tar.gz

Before I get in to more debugging (bit short on time today to dive in to this), perhaps this information explains the problem?
It gets stuck on just 2 now (ssh_authorization.nasl and netbios_name_get.nasl) so it seems to not be the actual nasl scan being the issue but something with my openvassd and redis part of the scanner.
I run 4 scanners with the same setup/version's and there are some jobs that completed without any issue.

When I stop this scan, my openvassd.messages log says:

"""
[Wed May 24 10:53:23 2017][19411] Stopping the whole test (requested by client) [Wed May 24 10:53:23 2017][19411] Stopping host XXX scan [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2014/gb_windows_services_stop.nasl (1.3.6.1.4.1.25623.1.0.804787) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching unknown_services.nasl (1.3.6.1.4.1.25623.1.0.11154) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching find_service_nmap.nasl (1.3.6.1.4.1.25623.1.0.66286) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching gb_nist_win_oval_sys_char_generator.nasl (1.3.6.1.4.1.25623.1.0.802042) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching host_scan_end.nasl (1.3.6.1.4.1.25623.1.0.103739) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching gb_tls_version.nasl (1.3.6.1.4.1.25623.1.0.103823) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/GSHB_M4_007.nasl (1.3.6.1.4.1.25623.1.0.94
 177) [We
 d May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL13/GSHB_M4_007.nasl (1.3.6.1.4.1.25623.1.0.94108) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching Policy/gb_policy_tls_passed.nasl (1.3.6.1.4.1.25623.1.0.105781) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL11/GSHB_M4_007.nasl (1.3.6.1.4.1.25623.1.0.894007) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching kb_2_sc.nasl (1.3.6.1.4.1.25623.1.0.103998) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2011/system_characteristics.nasl (1.3.6.1.4.1.25623.1.0.103999) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2016/nvt_debugging.nasl (1.3.6.1.4.1.25623.1.0.111091) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL10/GSHB_M4_007.nasl (1.3.6.1.4.1.25623.1.0.94007) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL12/GSHB_M4_007.nasl (1.3.6.1.4.1.25623.1.0.94013) [Wed May
  24 10:5
 3:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL12/GSHB-12.nasl (1.3.6.1.4.1.25623.1.0.94000) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL10/GSHB-10.nasl (1.3.6.1.4.1.25623.1.0.95000) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL11/GSHB-11.nasl (1.3.6.1.4.1.25623.1.0.895000) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching cpe_inventory.nasl (1.3.6.1.4.1.25623.1.0.810002) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching pre2008/scan_info.nasl (1.3.6.1.4.1.25623.1.0.19506) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/GSHB.nasl (1.3.6.1.4.1.25623.1.0.94171) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2013/gb_os_eol.nasl (1.3.6.1.4.1.25623.1.0.103674) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching GSHB/EL13/GSHB-13.nasl (1.3.6.1.4.1.25623.1.0.94999) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching
  Policy/
 gb_policy_tls_violation.nasl (1.3.6.1.4.1.25623.1.0.105780) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching pre2008/check_ports.nasl (1.3.6.1.4.1.25623.1.0.10919) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2016/gb_default_ssh_credentials_report.nasl (1.3.6.1.4.1.25623.1.0.103239) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2017/gb_default_http_credentials_report.nasl (1.3.6.1.4.1.25623.1.0.103240) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2011/host_details.nasl (1.3.6.1.4.1.25623.1.0.103997) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2013/gb_host_scanned_ssh.nasl (1.3.6.1.4.1.25623.1.0.103625) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching 2013/gb_host_scanned_wmi.nasl (1.3.6.1.4.1.25623.1.0.96171) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching Policy/gb_policy_cpe.nasl (1.3.6.1.4.1.25623.1.0.103962) [Wed May 24 10:53:31 2017][19  500] Sto  pped scan wrap-up: Launching 2009/cpe_policy.nasl (1.3.6.1.4.1.25623.1.0.100353) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching Policy/gb_policy_cpe_violation.nasl (1.3.6.1.4.1.25623.1.0.103964) [Wed May 24 10:53:31 2017][19500] Stopped scan wrap-up: Launching Policy/gb_policy_cpe_ok.nasl (1.3.6.1.4.1.25623.1.0.103963) [Wed May 24 10:53:31 2017][19411] Test complete [Wed May 24 10:53:31 2017][19411] Total time to scan all hosts : 702 seconds """

Seems like it wanted to start more but never could.
Perhaps I have to rebuild the redis DB; any and all tips are welcome of course.


Thijs Stuurman
Security Operations Center | KPN Internedservices thijs.stuurman at internedservices.nl | thijs.stuurman at kpn.com
T: +31(0)299476185 | M: +31(0)624366778
PGP Key-ID: 0x16ADC048 (https://pgp.surfnet.nl/)
Fingerprint: 2EDB 9B42 D6E8 7D4B 6E02 8BE5 6D46 8007 16AD C048

W: https://www.internedservices.nl | L: http://nl.linkedin.com/in/thijsstuurman




-----Oorspronkelijk bericht-----
Van: Hani Benhabiles [mailto:hani.benhabiles at greenbone.net]
Verzonden: woensdag 24 mei 2017 12:10
Aan: Thijs Stuurman <Thijs.Stuurman at internedservices.nl>
CC: openvas-discuss at wald.intevation.org
Onderwerp: Re: [Openvas-discuss] OpenVAS9 hanging nasl tasks

On 2017-05-23 12:05, Thijs Stuurman wrote:
> OpenVAS discuss list,
> 
> I ran a few scans with my new OpenVAS9 setup and all worked well.
> Now I am starting a lot of scans and noticing most of 'm are hanging 
> on  the exact same 4 tests:
> 
> |   \_ openvassd: testing xxx
> (/opt/openvas9/var/lib/openvas/plugins/ssh_authorization.nasl)
> |   \_ openvassd: testing xxx
> (/opt/openvas9/var/lib/openvas/plugins/netbios_name_get.nasl)
> |   \_ openvassd: testing xxx
> (/opt/openvas9/var/lib/openvas/plugins/pre2008/tcp_port_zero.nasl)
> |   \_ openvassd: testing xxx
> (/opt/openvas9/var/lib/openvas/plugins/2012/secpod_database_open_acces
> s_vuln.nasl)
> 
> Is anyone else experiencing this? Is this a known issue? I updated the 
> NVT's etc' yesterday.
> The processes run for an hour+.
> Killing defuncts the process. I am unable to continue in any way 
> except kill and abort the whole scan.
> 
> 

Hi Thijs,

- Can you get a backtrace for the stuck processes ? The 4 nvts ones + the "testing xxxx" parent.
- Could it be related to your Redis setup ? You can monitor it with: 
redis-cli -s /tmp/redis.sock MONITOR
- If you're able to build from source, do you see this issue with current openvas-9 branch, and with trunk branch too ?

Best regards,

Hani.
_______________________________________________
Openvas-discuss mailing list
Openvas-discuss at wald.intevation.org
https://lists.wald.intevation.org/cgi-bin/mailman/listinfo/openvas-discuss


More information about the Openvas-discuss mailing list