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
[email protected] | [email protected]
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:[email protected]]
Namens Thijs Stuurman
Verzonden: woensdag 24 mei 2017 13:39
Aan: Hani Benhabiles <[email protected]>
CC: [email protected]
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
[email protected] | [email protected]
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' <[email protected]>
CC: [email protected]
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] S
to 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
[email protected] | [email protected]
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:[email protected]]
Verzonden: woensdag 24 mei 2017 12:10
Aan: Thijs Stuurman <[email protected]>
CC: [email protected]
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
[email protected]
https://lists.wald.intevation.org/cgi-bin/mailman/listinfo/openvas-discuss
_______________________________________________
Openvas-discuss mailing list
[email protected]
https://lists.wald.intevation.org/cgi-bin/mailman/listinfo/openvas-discuss
