read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated. #701

mettatu · 2019-08-15T11:35:56Z

I am receiving "read_from_client_tls: failed to read from client" from a remote scanner in the middle of the scan when performing longer scans (~800 seconds) resulting that the task ends up as "Interrupted" on the master. Shorter scans (<180 seconds) end up correctly as "Done".

I debugged the tcp session timeouts with netcat to rule out kernel level timeouts.

I presume it is related to the function "read_from_client_tls" in src/gmpd.c but I cannot debug further.

Expected behavior

Keep the TLS-session open until the task has been finished on a remote scanner

Current behavior

TLS-session is terminated after ~180 seconds.

Steps to reproduce

Schedule a task that runs for a long time
Look for "read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated." in gvmd.log

GVM versions

gsa: Greenbone Security Assistant 8.0.1
gvm: Greenbone Vulnerability Manager 8.0.1
openvas-scanner: OpenVAS Scanner 6.0.1
gvm-libs: gvm-libs-10.0.1

Environment

Operating system: Debian 9 (Stretch)
Kernel: Linux scanner 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1+deb9u4 (2019-07-19) x86_64 GNU/Linux
Compiled from source

Slave

GVM versions

gvm: Greenbone Vulnerability Manager 8.0.1
openvas-scanner: OpenVAS Scanner 6.0.1
gvm-libs: gvm-libs-10.0.1

Environment

Debian 9 (Stretch)
Linux scanner-01 4.9.0-9-amd64 #1 SMP Debian 4.9.168-1+deb9u4 (2019-07-19) x86_64 GNU/Linux
Compiled from source

Logfiles

Slave gvmd.log:
event task:MESSAGE:2019-08-15 10h25.51 UTC:2000: Status of task  (259c6cdc-15dc-4d8e-bdd3-7fff127b2ffb) has changed to New
event task:MESSAGE:2019-08-15 10h25.51 UTC:2000: Task 8a671037-2843-403e-8fa3-214c5050ce12 for scanner-test slow (259c6cdc-15dc-4d8e-bdd3-7fff127b2ffb) has been created by scanner-02
event task:MESSAGE:2019-08-15 10h25.52 UTC:2000: Status of task 8a671037-2843-403e-8fa3-214c5050ce12 for scanner-test slow (259c6cdc-15dc-4d8e-bdd3-7fff127b2ffb) has changed to Requested
event task:MESSAGE:2019-08-15 10h25.52 UTC:2000: Task 8a671037-2843-403e-8fa3-214c5050ce12 for scanner-test slow (259c6cdc-15dc-4d8e-bdd3-7fff127b2ffb) has been requested to start by scanner-02
event task:MESSAGE:2019-08-15 10h26.02 UTC:2003: Status of task 8a671037-2843-403e-8fa3-214c5050ce12 for scanner-test slow (259c6cdc-15dc-4d8e-bdd3-7fff127b2ffb) has changed to Running
md   main:WARNING:2019-08-15 10h29.16 UTC:2000: read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated.
event task:MESSAGE:2019-08-15 10h38.54 UTC:2003: Status of task 8a671037-2843-403e-8fa3-214c5050ce12 for scanner-test slow (259c6cdc-15dc-4d8e-bdd3-7fff127b2ffb) has changed to Done

Master gvmd.log:
event task:MESSAGE:2019-08-15 10h25.51 UTC:88410: Status of task scanner-test slow (cca48b94-55b6-4be3-a969-346ab4892fc7) has changed to Requested
event task:MESSAGE:2019-08-15 10h25.51 UTC:88410: Task scanner-test slow (cca48b94-55b6-4be3-a969-346ab4892fc7) has been requested to start by test_user
event task:MESSAGE:2019-08-15 10h26.17 UTC:88422: Status of task scanner-test slow (cca48b94-55b6-4be3-a969-346ab4892fc7) has changed to Running
md manage:WARNING:2019-08-15 10h29.16 UTC:88422: manage_cleanup_process_error: Error exit, setting running task to Interrupted
event task:MESSAGE:2019-08-15 10h29.16 UTC:88422: Status of task scanner-test slow (cca48b94-55b6-4be3-a969-346ab4892fc7) has changed to Interrupted
test_user

The text was updated successfully, but these errors were encountered:

mettatu · 2019-08-20T12:55:14Z

When replicating the issue, it seems the error happens constantly after 194 seconds on the remote scanner logs if there has not been any output.

Workaround is to have multiple scans at the same time that generate traffic to the TLS session avoiding the channel to be silent.

falkowich · 2019-09-24T13:25:38Z

@mettatu I have the same issue here.
I thought it was a PEBKAC on my part when building the docker images that made this..

But I made an src install on two new vm's and the same problem showed up.
I have the same versions as @mettatu other then:

Environment

Ubuntu 18.04.3 LTS
Linux server 4.15.0-64-generic #73-Ubuntu SMP Thu Sep 12 13:16:13 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Moar debugging on master.

md manage:  DEBUG:2019-09-24 13h19.45 UTC:8820:    sql: INSERT into result_nvts (nvt) SELECT '1.3.6.1.4.1.25623.1.0.10330' WHERE NOT EXISTS (SELECT * FROM result_nvts                               WHERE nvt = '1.3.6.1.4.1.25623.1.0.10330');
md manage:  DEBUG:2019-09-24 13h19.45 UTC:8820:    sql: INSERT into results (owner, date, task, host, hostname, port,  nvt, nvt_version, severity, type,  description, uuid, qod, qod_type, result_nvt  report) VALUES (1, m_now (), 1, '10.8.10.15', '', '22/tcp',  '1.3.6.1.4.1.25623.1.0.10330', 'SELECT iso_time (modification_time) FROM nvts WHERE uuid = '1.3.6.1.4.1.25623.1.0.10330';', '0.0', 'Log Message',  'An ssh server is running on this port', make_uuid (), 80, 'remote_banner',  (SELECT id FROM result_nvts WHERE
 nvt = '1.3.6.1.4.1.25623.1.0.10330'),  6) RETURNING id;
md manage:WARNING:2019-09-24 13h19.45 UTC:8820: sql_prepare_internal: sqlite3_prepare failed: near "report": syntax error
md manage:WARNING:2019-09-24 13h19.45 UTC:8820: init_iterator: sql_prepare failed
md manage:  DEBUG:2019-09-24 13h19.45 UTC:8820: Received Aborted signal
md manage:WARNING:2019-09-24 13h19.45 UTC:8820: manage_cleanup_process_error: Error exit, setting running task to Interrupted

cfi-gb · 2019-09-24T13:41:31Z

@falkowich Those SQL messages where discussed in #657 and should be already fixed with #658, #659, #665 and #666.

As you're getting the following:

qod_type, result_nvt  report

which should be:

qod_type, result_nvt, report

it seems you're using an older version not containing this fixes yet.

mettatu · 2019-09-24T13:50:43Z

Yes, the SQL messages were fixed but the TLS termination still exists with the remote scanners.

falkowich · 2019-09-24T14:07:30Z

@falkowich Those SQL messages where discussed in #657 and should be already fixed with #658, #659, #665 and #666.
it seems you're using an older version not containing this fixes yet.

@cfi-gb
Ah, I used the 8.0.1 release tar.

@mettatu,
So these are not related?
The client stops with read_from_client_tls: failed to read from client

--
Regards Falk

mettatu · 2019-09-24T14:12:13Z

@falkowich
"read_from_client_tls: failed to read from client" is related to this bug (#701). If the scan takes long, the TLS session is terminated before the scan ends. When the scan is finished, the results are not updated from the remote scanner to the master because the TLS session was previously terminated. The job completion stays at a specific percentage on the master.

SQL errors were a different issue and not related.

falkowich · 2019-09-25T06:38:26Z

@mettatu,
Ah, sorry to hijack the bug :)
I thought they were related.

But we have the problem with TLS too.

falkowich · 2019-09-28T14:30:10Z

Hi,
just a heads up, I don't get this error anymore with latest gvmd-8.0-git
I have tested with master/scanner and a /24 ciddr, with no TLS problems.

--
Regards Falk

mettatu · 2019-09-30T10:54:13Z

Thanks Falk, I have not tested this in a while.

I can confirm that this problem does not exist anymore with the recent build of Greenbone Vulnerability Manager 8.0.2.

ghost · 2019-11-20T07:39:30Z

Thanks Falk, I have not tested this in a while.

I can confirm that this problem does not exist anymore with the recent build of Greenbone Vulnerability Manager 8.0.2.

I a currently running GVM-10 latest stable release having the same issue. Greenbone Vulnerability Manager 8.0.2 seems not to be released yet, do you know if that will happen anytime soon?

falkowich mentioned this issue Sep 24, 2019

master/scanner seems broken in latest build. falkowich/gvm10-docker#16

Closed

mettatu closed this as completed Sep 30, 2019

SergioBinfo mentioned this issue Oct 30, 2019

post/gmv10dockermasterslave/ falkowich/comments-sadsloth#7

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated. #701

read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated. #701

mettatu commented Aug 15, 2019 •

edited

Loading

mettatu commented Aug 20, 2019 •

edited

Loading

falkowich commented Sep 24, 2019

cfi-gb commented Sep 24, 2019

mettatu commented Sep 24, 2019

falkowich commented Sep 24, 2019 •

edited

Loading

mettatu commented Sep 24, 2019 •

edited

Loading

falkowich commented Sep 25, 2019

falkowich commented Sep 28, 2019

mettatu commented Sep 30, 2019

ghost commented Nov 20, 2019

read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated. #701

read_from_client_tls: failed to read from client: The TLS connection was non-properly terminated. #701

Comments

mettatu commented Aug 15, 2019 • edited Loading

Expected behavior

Current behavior

Steps to reproduce

GVM versions

Environment

GVM versions

Environment

Logfiles

mettatu commented Aug 20, 2019 • edited Loading

falkowich commented Sep 24, 2019

cfi-gb commented Sep 24, 2019

mettatu commented Sep 24, 2019

falkowich commented Sep 24, 2019 • edited Loading

mettatu commented Sep 24, 2019 • edited Loading

falkowich commented Sep 25, 2019

falkowich commented Sep 28, 2019

mettatu commented Sep 30, 2019

ghost commented Nov 20, 2019

mettatu commented Aug 15, 2019 •

edited

Loading

mettatu commented Aug 20, 2019 •

edited

Loading

falkowich commented Sep 24, 2019 •

edited

Loading

mettatu commented Sep 24, 2019 •

edited

Loading