Stuck in infinite handshake loop when performing a non https connection with correct SSLConfig provided.

[mkoonen]

Short description issue Stuck in infinite handshake loop when performing a non-https connection such as by netcat or http request to HTTP.listen() with correct SSLConfig.

Environment

Ubuntu 18.04 x64
Julia v1.0.0
julia> Pkg.status() 
    Status `~/.julia/environments/v1.0/Project.toml`
  [cd3eb016] HTTP v0.6.14
  [739be429] MbedTLS v0.6.0

Code Given is server.jl with HTTP.listen() with correct SSLConfig. HTTPS request are handled, so there are no problems with certificate and key.

using HTTP
using MbedTLS

# SSL configuration via files (cert and key)
const CERT_FILE = "server_cert.pem"
const PK_FILE = "server_key.pem"

println("Create the SSLConfig")
tlsconfig = invoke(
  HTTP.Servers.SSLConfig, Tuple{Any,Any}, CERT_FILE, PK_FILE
)

function show_debug(level, filename, number, msg)
  println("[DBG] $filename $number $msg")  
end

MbedTLS.dbg!(tlsconfig,show_debug)
MbedTLS.set_dbg_level(MbedTLS.INFO)

println(tlsconfig)
println(tlsconfig.cert)

HTTP.listen("0.0.0.0", 8000, ssl=true, sslconfig = tlsconfig) do request::HTTP.Request
   @show request
   @show request.method
   @show HTTP.header(request, "Content-Type")
   try
      return HTTP.Response("Hello Julia World!")
   catch e
      return HTTP.Response(404, "Error: $e")
   end
end

Creation of error situation If I run server.jl and execute the the following command in a console (where dev.xxxxxxxx.com maps to 127.0.0.1):

$ nc dev.xxxxxxxx.com 8000
^C

this action, CTRL-C, results in the following output in the Julia terminal:

[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 6754 => handshake
[DBG] /workspace/srcdir/mbedtls/library/ssl_srv.c 4219 server state: 1
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2471 => flush output
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2483 <= flush output
[DBG] /workspace/srcdir/mbedtls/library/ssl_srv.c 1192 => parse client hello
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2252 => fetch input
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2413 in_left: 0, nb_want: 5
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2437 in_left: 0, nb_want: 5
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 6764 <= handshake
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 6754 => handshake
[DBG] /workspace/srcdir/mbedtls/library/ssl_srv.c 4219 server state: 1
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2471 => flush output
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2483 <= flush output
[DBG] /workspace/srcdir/mbedtls/library/ssl_srv.c 1192 => parse client hello
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2252 => fetch input
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2413 in_left: 0, nb_want: 5
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 2437 in_left: 0, nb_want: 5
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 6764 <= handshake
[DBG] /workspace/srcdir/mbedtls/library/ssl_tls.c 6754 => handshake
[DBG] /workspace/srcdir/mbedtls/library/ssl_srv.c 4219 server state:
... infinitely.

and I cannot perform any other request, e.g. curl https://dev.xxxxxxxx.com:8000. When I press CTRL-C listen() is interrupted:

^C┌ Warning: Interrupted: listen(Sockets.InetAddr{Sockets.IPv4}(ip"0.0.0.0", 0x1f40))
└ @ HTTP.Servers ~/.julia/packages/HTTP/nUK4f/src/Servers.jl:379 

Analysis I have performed some analysis and I think the problem is caused by the fact that in MbedTLS.jl in file ssl.jl function frecv() does not terminate in case the underlying connection is closed:

function f_recv(c_ctx, c_msg, sz)
    jl_ctx = unsafe_pointer_to_objref(c_ctx)
    n = bytesavailable(jl_ctx)
    if n == 0
        return Cint(MBEDTLS_ERR_SSL_WANT_READ)
    end
    n = min(sz, n)
    unsafe_read(jl_ctx, c_msg, n)
    return Cint(n)
end

When I look at the function int mbedtls_net_recv( void ctx, unsigned char buf, size_t len ) as used by example ssl_server.c code for MbedTLS 2.11.0 I see the following code:

        if( errno == EPIPE || errno == ECONNRESET )
            return( MBEDTLS_ERR_NET_CONN_RESET );

I would expect to see something like this in MbedTLS.jl/ssl.jl as well to exit the handshake flow but but I cannot find it, perhaps because I am relatively new to Julia and the underlying frameworks.

[quinnj]

Thanks for the detailed report! I agree w/ your analysis that it seems like we should be doing some kind of check if the underlying connection is closed in the f_recv function. I'm reviewing the code now.

[samoconnor]

Can you try this patch?

diff --git a/src/ssl.jl b/src/ssl.jl
index e8e5ac8..58c986c 100644
--- a/src/ssl.jl
+++ b/src/ssl.jl
@@ -118,7 +118,8 @@ function f_recv(c_ctx, c_msg, sz)
     jl_ctx = unsafe_pointer_to_objref(c_ctx)
     n = bytesavailable(jl_ctx)
     if n == 0
-        return Cint(MBEDTLS_ERR_SSL_WANT_READ)
+        return isopen(jl_ctx) ? Cint(MBEDTLS_ERR_SSL_WANT_READ) :
+                                Cint(MBEDTLS_ERR_NET_CONN_RESET)
     end
     n = min(sz, n)
     unsafe_read(jl_ctx, c_msg, n)

[quinnj]

I can confirm that the fix in #166 fixes the endless loop behavior in the original example.

[GearsAD]

@samoconnor - thanks, I'll confirm it fixes it tonight

[mkoonen]

Thank you so much for the quick response and your fix!

I applied the fix forssl.jl in MbedTLS.jl version v0.6.0

julia> Pkg.status()
    Status `~/.julia/environments/v1.0/Project.toml`
  [cd3eb016] HTTP v0.6.14
  [739be429] MbedTLS v0.6.0

and this solution fixed the code that lead to an infinite handshake loop. When I executed:

$ nc dev.xxxxxxxx.com 8000
^C

the connection is terminated.

I performed another test, and unfortunately another problem popped up, which I believe is connected to this fix. Therefore I post my findings here.

Creation of the problem situation Given the execution of the same server.jl code mentioned in my start post with fix for ssl.jl applied I run, in 3 seperate Julia consoles, the following code client.jl. I do this to generate some reproducible continuous HTTPS traffic:

using HTTP
ENDPOINT = "https://dev.xxxxxxxx.com:8000"
println("HTTPS client request loop for $ENDPOINT")
function performrequest(requestnumber::Int64)
    r = HTTP.request("GET", ENDPOINT, headers = [ "reqnum" => "$requestnumber"])
    s = String(r.body)
    println("<r#: $requestnumber> result: $s")
end

function main()
    reqnum = 0
    while true
        performrequest(reqnum)
        reqnum = reqnum + 1
    end
end

main()

When I run

$ nc dev.xxxxxxxx.com 8000
^C
$ curl https://dev.xxxxxxxx.com:8000
curl: (7) Failed to connect to dev.xxxxxxxx.com port 8000: Connection refused

the three processes that each execute client.jl keep on running, but when I'm am trying to reconnect, e.g. using curl I get Connection refused.

I think this implies the "book keeping" of the closure of connections is not entirely correct, but I do not have the knowledge yet to say for sure.

[samoconnor]

Can you try with version 0.6.1 (which incorporates an improved fix) ?

[samoconnor]

@quinnj The release notes for 0.6.1 just says "Remove non-existent use of warn function and check that bio is open in f_send".

Can you add something about fixing #164 as well?

[mkoonen]

Thanks again!

With

julia> Pkg.status()
    Status `~/.julia/environments/v1.0/Project.toml`
  [cd3eb016] HTTP v0.6.14
  [739be429] MbedTLS v0.6.1

I followed the steps with server.jl and 3 times client.jl as described before and unfortunately I still get:

$ nc dev.xxxxxxxx.com 8000
^C
$ curl https://dev.xxxxxxxx.com:8000
curl: (7) Failed to connect to dev.xxxxxxxx.com port 8000: Connection refused

[GearsAD]

@quinnj is correct and the patch does stop the infinite loop issue. I reran the mutual authentication test and it seems to fail later in the code. The equivalent Javascript code works, which I'm using to validate the certificates and the test case.

I'll look deeper into the failure over the weekend, but adding the error here in case it helps with @mkoonen's issue:

WARNING: DBG: => fetch input
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:2252
WARNING: DBG: in_left: 0, nb_want: 5
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:2413
WARNING: DBG: in_left: 0, nb_want: 5
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:2437
WARNING: DBG: ssl->f_recv(_timeout)() returned 0 (-0x0000)
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:2438
WARNING: DBG: mbedtls_ssl_fetch_input() returned -29312 (-0x7280)
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:3956
WARNING: DBG: mbedtls_ssl_read_record_layer() returned -29312 (-0x7280)
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:3820
WARNING: DBG: mbedtls_ssl_read_record() returned -29312 (-0x7280)
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:4416
WARNING: DBG: <= handshake
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:6764
ERROR: LoadError: MbedTLS error code -29312: SSL - The connection indicated an EOF
Stacktrace:
 [1] mbed_err(::Int32) at /home/gearsad/.julia/packages/MbedTLS/hTU1b/src/error.jl:17
 [2] handshake(::MbedTLS.SSLContext) at /home/gearsad/.julia/packages/MbedTLS/hTU1b/src/ssl.jl:180
 [3] handshake! at /home/gearsad/.julia/packages/MbedTLS/hTU1b/src/MbedTLS.jl:101 [inlined]
 [4] getsslcontext(::Sockets.TCPSocket, ::SSLConfig) at /home/gearsad/.julia/packages/HTTP/nUK4f/src/Servers.jl:235
 [5] macro expansion at ./logging.jl:307 [inlined]
 [6] macro expansion at ./logging.jl:317 [inlined]
 [7] #listen#39(::Bool, ::Bool, ::SSLConfig, ::Int64, ::getfield(HTTP.Servers, Symbol("##43#49")), ::Base.RefValue{Base.IOServer}, ::Bool, ::Base.Iterators.Pairs{Symbol,Bool,Tuple{Symbol},NamedTuple{(:verbose,),Tuple{Bool}}}, ::typeof(HTTP.Servers.listen), ::getfield(Main, Symbol("##5#6")), ::Sockets.InetAddr{Sockets.IPv4}) at /home/gearsad/.julia/packages/HTTP/nUK4f/src/Servers.jl:307
 [8] (::getfield(HTTP.Servers, Symbol("#kw##listen")))(::NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}, ::typeof(HTTP.Servers.listen), ::Function, ::Sockets.InetAddr{Sockets.IPv4}) at ./none:0
 [9] #listen#36 at /home/gearsad/.julia/packages/HTTP/nUK4f/src/Servers.jl:287 [inlined]
 [10] (::getfield(HTTP.Servers, Symbol("#kw##listen")))(::NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}, ::typeof(HTTP.Servers.listen), ::Function, ::Sockets.IPv4, ::Int64) at ./none:0
 [11] #listen#37(::Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol,Symbol},NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}}, ::Function, ::Function, ::String, ::Int64) at /home/gearsad/.julia/packages/HTTP/nUK4f/src/Servers.jl:288
 [12] (::getfield(HTTP.Servers, Symbol("#kw##listen")))(::NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}, ::typeof(HTTP.Servers.listen), ::Function, ::String, ::Int64) at ./none:0
 [13] top-level scope at none:0
 [14] include at ./boot.jl:317 [inlined]
 [15] include_relative(::Module, ::String) at ./loading.jl:1038
 [16] include(::Module, ::String) at ./sysimg.jl:29
 [17] exec_options(::Base.JLOptions) at ./client.jl:239
 [18] _start() at ./client.jl:432
in expression starting at /home/gearsad/SlamInDb/tls_research/client-certificate-demo/serverNew.jl:25
WARNING: DBG: => free
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:7542
WARNING: DBG: <= free
 in /workspace/srcdir/mbedtls/library/ssl_tls.c:7607

[mkoonen]

I have some additional information, where the nc command results in termination of the listen() loop because of an Error which I think is not the expected behavior in such a situation.

Version Information Julia Version 1.0.0 (2018-08-08), Ubuntu 18.04 x64 and

julia> Pkg.status()
    Status `~/.julia/environments/v1.0/Project.toml`
  [cd3eb016] HTTP v0.7.0
  [739be429] MbedTLS v0.6.3

Creation of error situation I execute server.jl and I only execute

$ nc dev.gn-as.com 8000
^C

with no other requests. This results in ERROR: LoadError: MbedTLS error code -29312: SSL - The connection indicated an EOF:

[ Info: Listening on: Sockets.InetAddr{Sockets.IPv4}(ip"0.0.0.0", 0x1f40)
[DBG] /workspace/srcdir/mbedtls/library/ssl_srv.c 1228 mbedtls_ssl_fetch_input() returned -29312 (-0x7280)

ERROR: LoadError: MbedTLS error code -29312: SSL - The connection indicated an EOF
Stacktrace:
 [1] mbed_err(::Int32) at /home/mkoonen/.julia/packages/MbedTLS/mkHpa/src/error.jl:17
 [2] handshake(::MbedTLS.SSLContext) at /home/mkoonen/.julia/packages/MbedTLS/mkHpa/src/ssl.jl:180
 [3] handshake! at /home/mkoonen/.julia/packages/MbedTLS/mkHpa/src/MbedTLS.jl:101 [inlined]
 [4] getsslcontext(::Sockets.TCPSocket, ::SSLConfig) at /home/mkoonen/.julia/packages/HTTP/mwR9J/src/Servers.jl:228
 [5] macro expansion at ./logging.jl:309 [inlined]
 [6] #listenloop#48(::Base.Iterators.Pairs{Symbol,Bool,Tuple{Symbol},NamedTuple{(:verbose,),Tuple{Bool}}}, ::Function, ::Function, ::Sockets.TCPServer, ::SSLConfig, ::String, ::String, ::Int64, ::Bool, ::getfield(HTTP.Servers, Symbol("##42#47")), ::Base.RefValue{Int64}) at /home/mkoonen/.julia/packages/HTTP/mwR9J/src/Servers.jl:336
 [7] (::getfield(HTTP.Servers, Symbol("#kw##listenloop")))(::NamedTuple{(:verbose,),Tuple{Bool}}, ::typeof(HTTP.Servers.listenloop), ::Function, ::Sockets.TCPServer, ::SSLConfig, ::String, ::String, ::Int64, ::Bool, ::getfield(HTTP.Servers, Symbol("##42#47")), ::Base.RefValue{Int64}) at ./none:0
 [8] #listen#39(::Bool, ::Bool, ::SSLConfig, ::Int64, ::Function, ::Base.RefValue{Base.IOServer}, ::Bool, ::Base.RefValue{Int64}, ::Base.Iterators.Pairs{Symbol,Bool,Tuple{Symbol},NamedTuple{(:verbose,),Tuple{Bool}}}, ::typeof(HTTP.Servers.listen), ::getfield(Main, Symbol("##3#4")), ::Sockets.InetAddr{Sockets.IPv4}) at /home/mkoonen/.julia/packages/HTTP/mwR9J/src/Servers.jl:303
 [9] (::getfield(HTTP.Servers, Symbol("#kw##listen")))(::NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}, ::typeof(HTTP.Servers.listen), ::Function, ::Sockets.InetAddr{Sockets.IPv4}) at ./none:0
 [10] #listen#36 at /home/mkoonen/.julia/packages/HTTP/mwR9J/src/Servers.jl:280 [inlined]
 [11] (::getfield(HTTP.Servers, Symbol("#kw##listen")))(::NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}, ::typeof(HTTP.Servers.listen), ::Function, ::Sockets.IPv4, ::Int64) at ./none:0
 [12] #listen#37(::Base.Iterators.Pairs{Symbol,Any,Tuple{Symbol,Symbol,Symbol},NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}}, ::Function, ::Function, ::String, ::Int64) at /home/mkoonen/.julia/packages/HTTP/mwR9J/src/Servers.jl:281
 [13] (::getfield(HTTP.Servers, Symbol("#kw##listen")))(::NamedTuple{(:ssl, :sslconfig, :verbose),Tuple{Bool,SSLConfig,Bool}}, ::typeof(HTTP.Servers.listen), ::Function, ::String, ::Int64) at ./none:0
 [14] top-level scope at none:0
 [15] include at ./boot.jl:317 [inlined]
 [16] include_relative(::Module, ::String) at ./loading.jl:1038
 [17] include(::Module, ::String) at ./sysimg.jl:29
 [18] include(::String) at ./client.jl:388
 [19] top-level scope at none:0
in expression starting at /home/mkoonen/issues/julia/mbedtls/rca/server.jl:25

julia> 

I would expect the request flow is terminated but not the entire listen() loop?

[mkoonen]

If I change these lines in Servers.jl from HTTP.jl

                if e isa Base.IOError
                    @warn "$e"
                    break
                else
                    rethrow(e)
                end

into

if e isa Base.IOError
  @warn "$e"
  break
else
  if e isa MbedException
    @warn "$e"
  else
    rethrow(e)
  end
end

it works like expected for the test cases I described in this issue.

Next question for me would be if

if e isa MbedException
# ...
else
# ...
end

is the exact/correct check here.

[mkoonen]

After discussion with @quinnj I created issue #318 for HTTP.jl