BoundsError when closing MbedTLS.SSLContext #148

quinnj · 2018-01-17T21:11:46Z

noticed a bunch of logs/errors like this when doing some trial runs for FemtoCleaner.jl.

SERVER ERROR: BoundsError: attempt to access 1-element Array{StackFrame,1} at index [2]
Stacktrace:
 [1] check_open(::TCPSocket) at ./stream.jl:251
 [2] uv_write(::TCPSocket, ::Ptr{UInt8}, ::UInt64) at ./stream.jl:795
 [3] unsafe_write(::TCPSocket, ::Ptr{UInt8}, ::UInt64) at ./stream.jl:832
 [4] write(::TCPSocket, ::Array{UInt8,1}) at ./io.jl:313
 [5] f_send(::Ptr{Void}, ::Ptr{UInt8}, ::UInt64) at /opt/pkgs/v0.6/MbedTLS/src/ssl.jl:99
 [6] close(::MbedTLS.SSLContext) at /opt/pkgs/v0.6/MbedTLS/src/ssl.jl:233
 [7] close(::HTTP.ConnectionPool.Connection{MbedTLS.SSLContext}) at /opt/pkgs/v0.6/HTTP/src/ConnectionPool.jl:310

@samoconnor

KristofferC · 2018-01-17T21:32:42Z

Note 1-element Array{StackFrame,1} which is odd.

samoconnor · 2018-01-17T21:45:34Z

Is that the whole stack trace?
My first thought is: could this be related to double-closing causing a problem in an error-cleanup situation. In which case it would be good to see the whole stack trace.

index[2] makes me think of debug.jl trying to get the name of the current function.
Can you try out this patch: ?

--- a/src/debug.jl
+++ b/src/debug.jl
@@ -24,8 +24,8 @@ printlncompact(x) = println(sprint(showcompact, x))


 @noinline function precondition_error(msg, frame)
-    msg = string(sprint(StackTraces.show_spec_linfo,
-                        StackTraces.lookup(frame)[2]),
+    msg = string(#=sprint(StackTraces.show_spec_linfo,
+                        StackTrace0.lookup(frame)[2])=# "function",
                  " requires ", msg)
     return ArgumentError(msg)
 end
@@ -41,8 +41,8 @@ end


 @noinline function postcondition_error(msg, frame, ls="", l="", rs="", r="")
-    msg = string(sprint(StackTraces.show_spec_linfo,
-                        StackTraces.lookup(frame)[2]),
+    msg = string(#= sprint(StackTraces.show_spec_linfo,
+                        StackTraces.lookup(frame)[2]) =# "function",
                  " failed to ensure ", msg)
     if ls != ""
         msg = string(msg, "\n", ls, " = ", sprint(show, l),

quinnj · 2018-01-17T21:46:11Z

@Keno, @KristofferC ^^

Keno · 2018-01-17T21:56:39Z

SERVER ERROR: ArgumentError: function requires !(isempty(bytes))
Stacktrace:
 [1] check_open(::TCPSocket) at ./stream.jl:251
 [2] uv_write(::TCPSocket, ::Ptr{UInt8}, ::UInt64) at ./stream.jl:795
 [3] unsafe_write(::TCPSocket, ::Ptr{UInt8}, ::UInt64) at ./stream.jl:832
 [4] write(::TCPSocket, ::Array{UInt8,1}) at ./io.jl:313
 [5] f_send(::Ptr{Void}, ::Ptr{UInt8}, ::UInt64) at /opt/pkgs/v0.6/MbedTLS/src/ssl.jl:99
 [6] close(::MbedTLS.SSLContext) at /opt/pkgs/v0.6/MbedTLS/src/ssl.jl:233
 [7] close(::HTTP.ConnectionPool.Connection{MbedTLS.SSLContext}) at /opt/pkgs/v0.6/HTTP/src/ConnectionPool.jl:310
 [8] close(::HTTP.ConnectionPool.Transaction{MbedTLS.SSLContext}) at /opt/pkgs/v0.6/HTTP/src/ConnectionPool.jl:299
 [9] #request#1(::Type{T} where T, ::Array{Any,1}, ::Function, ::Type{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}, ::HTTP.URIs.URI, ::HTTP.Messages.Request, ::String) at /opt/pkgs/v0.6/HTTP/src/ConnectionRequest.jl:37
 [10] (::HTTP.#kw##request)(::Array{Any,1}, ::HTTP.#request, ::Type{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}, ::HTTP.URIs.URI, ::HTTP.Messages.Request, ::String) at ./<missing>:0
 [11] (::Base.###49#50#52{ExponentialBackOff,HTTP.RetryRequest.##2#3{Bool,HTTP.Messages.Request},HTTP.#request})(::Array{Any,1}, ::Function, ::Type{T} where T, ::Vararg{Any,N} where N) at ./error.jl:139
 [12] (::Base.#kw###49#51)(::Array{Any,1}, ::Base.##49#51, ::Type{T} where T, ::Vararg{Any,N} where N) at ./<missing>:0
 [13] #request#1(::Int64, ::Bool, ::Array{Any,1}, ::Function, ::Type{HTTP.RetryRequest.RetryLayer{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}}, ::HTTP.URIs.URI, ::HTTP.Messages.Request, ::String) at /opt/pkgs/v0.6/HTTP/src/RetryRequest.jl:45
 [14] (::HTTP.#kw##request)(::Array{Any,1}, ::HTTP.#request, ::Type{HTTP.RetryRequest.RetryLayer{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}}, ::HTTP.URIs.URI, ::HTTP.Messages.Request, ::String) at ./<missing>:0
 [15] #request#1(::VersionNumber, ::String, ::Void, ::Void, ::Array{Any,1}, ::Function, ::Type{HTTP.MessageRequest.MessageLayer{HTTP.RetryRequest.RetryLayer{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}}}, ::String, ::HTTP.URIs.URI, ::Array{Pair{String,String},1}, ::String) at /opt/pkgs/v0.6/HTTP/src/MessageRequest.jl:44
 [16] (::HTTP.#kw##request)(::Array{Any,1}, ::HTTP.#request, ::Type{HTTP.MessageRequest.MessageLayer{HTTP.RetryRequest.RetryLayer{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}}}, ::String, ::HTTP.URIs.URI, ::Array{Pair{String,String},1}, ::String) at ./<missing>:0
 [17] #request#1(::Int64, ::Bool, ::Array{Any,1}, ::Function, ::Type{HTTP.RedirectRequest.RedirectLayer{HTTP.MessageRequest.MessageLayer{HTTP.RetryRequest.RetryLayer{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}}}}, ::String, ::HTTP.URIs.URI, ::Array{Pair{String,String},1}, ::String) at /opt/pkgs/v0.6/HTTP/src/RedirectRequest.jl:26
 [18] (::HTTP.#kw##request)(::Array{Any,1}, ::HTTP.#request, ::Type{HTTP.RedirectRequest.RedirectLayer{HTTP.MessageRequest.MessageLayer{HTTP.RetryRequest.RetryLayer{HTTP.ConnectionRequest.ConnectionPoolLayer{HTTP.StreamRequest.StreamLayer}}}}}, ::String, ::HTTP.URIs.URI, ::Array{Pair{String,String},1}, ::String) at ./<missing>:0
 [19] #request#5(::Array{Any,1}, ::Function, ::String, ::HTTP.URIs.URI, ::Array{Pair{String,String},1}, ::String) at /opt/pkgs/v0.6/HTTP/src/HTTP.jl:284
 [20] (::HTTP.#kw##request)(::Array{Any,1}, ::HTTP.#request, ::String, ::HTTP.URIs.URI, ::Array{Pair{String,String},1}, ::String) at ./<missing>:0
 [21] #request#6(::Array{Any,1}, ::Function, ::String, ::String, ::Dict{String,String}, ::String) at /opt/pkgs/v0.6/HTTP/src/HTTP.jl:289
 [22] (::HTTP.#kw##request)(::Array{Any,1}, ::HTTP.#request, ::String, ::String, ::Dict{String,String}, ::String) at ./<missing>:0
 [23] #post#10 at /opt/pkgs/v0.6/HTTP/src/HTTP.jl:345 [inlined]
 [24] (::HTTP.#kw##post)(::Array{Any,1}, ::HTTP.#post, ::String, ::Dict{String,String}, ::String) at ./<missing>:0
 [25] #github_request#3(::GitHub.JWTAuth, ::Bool, ::Dict{Any,Any}, ::Dict{Any,Any}, ::Bool, ::Function, ::GitHub.GitHubWebAPI, ::Function, ::String) at /opt/pkgs/v0.6/GitHub/src/utils/requests.jl:61
 [26] (::GitHub.#kw##github_request)(::Array{Any,1}, ::GitHub.#github_request, ::GitHub.GitHubWebAPI, ::Function, ::String) at ./<missing>:0
 [27] #gh_post#5 at /opt/pkgs/v0.6/GitHub/src/utils/requests.jl:68 [inlined]
 [28] (::GitHub.#kw##gh_post)(::Array{Any,1}, ::GitHub.#gh_post, ::GitHub.GitHubWebAPI, ::String) at ./<missing>:0
 [29] #gh_post_json#10(::Array{Any,1}, ::Function, ::GitHub.GitHubWebAPI, ::String) at /opt/pkgs/v0.6/GitHub/src/utils/requests.jl:74
 [30] (::GitHub.#kw##gh_post_json)(::Array{Any,1}, ::GitHub.#gh_post_json, ::GitHub.GitHubWebAPI, ::String) at ./<missing>:0
 [31] #create_access_token#199(::Dict{Any,Any}, ::Array{Any,1}, ::Function, ::GitHub.GitHubWebAPI, ::GitHub.Installation, ::GitHub.JWTAuth) at /opt/pkgs/v0.6/GitHub/src/apps/installations.jl:12
 [32] create_access_token(::GitHub.GitHubWebAPI, ::GitHub.Installation, ::GitHub.JWTAuth) at /opt/pkgs/v0.6/GitHub/src/apps/installations.jl:11
 [33] event_callback(::GitHub.GitHubWebAPI, ::String, ::MbedTLS.PKContext, ::Int64, ::Int64, ::Base.LibGit2.Signature, ::GitHub.EventListener, ::String, ::GitHub.WebhookEvent) at /opt/pkgs/v0.6/FemtoCleaner/src/FemtoCleaner.jl:250
 [34] #handle_event_request#169(::GitHub.AnonymousAuth, ::String, ::Void, ::Void, ::Void, ::Function, ::HTTP.Messages.Request, ::FemtoCleaner.##60#61{MbedTLS.PKContext,Int64,Int64,String}) at /opt/pkgs/v0.6/GitHub/src/activity/events.jl:120
 [35] (::GitHub.#kw##handle_event_request)(::Array{Any,1}, ::GitHub.#handle_event_request, ::HTTP.Messages.Request, ::Function) at ./<missing>:0
 [36] (::GitHub.##166#168{GitHub.AnonymousAuth,String,Void,FemtoCleaner.##60#61{MbedTLS.PKContext,Int64,Int64,String}})(::HTTP.Messages.Request, ::HTTP.Messages.Response) at /opt/pkgs/v0.6/GitHub/src/activity/events.jl:81
 [37] (::HTTP.Servers.##8#12{HTTP.Servers.Server{HTTP.Servers.http,HTTP.Handlers.HandlerFunction{GitHub.##166#168{GitHub.AnonymousAuth,String,Void,FemtoCleaner.##60#61{MbedTLS.PKContext,Int64,Int64,String}}}}})(::HTTP.Streams.Stream{HTTP.Messages.Request,HTTP.ConnectionPool.Transaction{TCPSocket}}) at /opt/pkgs/v0.6/HTTP/src/Servers.jl:171
 [38] handle_stream(::HTTP.Servers.##8#12{HTTP.Servers.Server{HTTP.Servers.http,HTTP.Handlers.HandlerFunction{GitHub.##166#168{GitHub.AnonymousAuth,String,Void,FemtoCleaner.##60#61{MbedTLS.PKContext,Int64,Int64,String}}}}}, ::HTTP.Streams.Stream{HTTP.Messages.Request,HTTP.ConnectionPool.Transaction{TCPSocket}}) at /opt/pkgs/v0.6/HTTP/src/Servers.jl:457
 [39] (::HTTP.Servers.##46#47{HTTP.Servers.##8#12{HTTP.Servers.Server{HTTP.Servers.http,HTTP.Handlers.HandlerFunction{GitHub.##166#168{GitHub.AnonymousAuth,String,Void,FemtoCleaner.##60#61{MbedTLS.PKContext,Int64,Int64,String}}}}},HTTP.ConnectionPool.Transaction{TCPSocket},HTTP.Streams.Stream{HTTP.Messages.Request,HTTP.ConnectionPool.Transaction{TCPSocket}}})() at ./task.jl:335

samoconnor · 2018-01-19T22:19:03Z

ArgumentError: function requires !(isempty(bytes)) can only come from one of two places:

HTTP.jl/src/Parsers.jl

Lines 292 to 296 in 621e25f

 function parseheaders(onheader::Function #=f(::Pair{String,String}) =#, 

 parser::Parser, bytes::ByteView)::ByteView 

 @require !isempty(bytes) 

 @require messagehastrailing(parser) || !headerscomplete(parser)

HTTP.jl/src/Parsers.jl

Lines 713 to 716 in 621e25f

 function parsebody(parser::Parser, bytes::ByteView)::Tuple{ByteView,ByteView} 

 @require !isempty(bytes) 

 @require headerscomplete(parser)

The stack trace above is messed up (JuliaLang/julia#19979) by the rethrow here:

HTTP.jl/src/ConnectionRequest.jl

Lines 35 to 39 in 621e25f

 catch e 

 @debug 1 "❗️ ConnectionLayer $e. Closing: $io" 

 close(io) 

 rethrow(isioerror(e) ? IOError(e) : e) 

 end

Temporarily commenting out the catch above might reveal the original stack trace.

Is this problem still happening with latest master?

@Keno maybe you can help here.
I was trying to get the name of the calling function like this:

HTTP.jl/src/debug.jl

Lines 26 to 31 in 621e25f

 @noinline function precondition_error(msg, frame) 

 msg = string(#=sprint(StackTraces.show_spec_linfo, 

  StackTrace0.lookup(frame)[2])=# "function", 

 " requires ", msg) 

 return ArgumentError(msg) 

 end

Is there a better way?
Should Base have an API for getting the name of the calling function (or even just the current function)? (or method?)

quinnj · 2018-01-25T03:16:19Z

@samoconnor, couldn't you just pass the name of the function in as a string?

julia> string(sum)
"sum"

Keno · 2018-01-27T21:24:22Z

FWIW, I'm still seeing the isempty error show up in the logs, which ends up as an error 500 to GitHub. What can I do to help debug?

Keno · 2018-01-27T21:25:23Z

I should probably note that the server makes HTTP requests back to GitHub while processing the requests it gets from GitHub, so maybe there's some global state that gets messed up?

samoconnor · 2018-02-05T13:22:14Z

@samoconnor, couldn't you just pass the name of the function in as a string?

Is there a way to get the name of the enclosing function from a macro?

samoconnor · 2018-02-05T13:26:49Z

I'm still seeing the isempty error

Re: "function requires !(isempty(bytes))", I don't think that assertion exists in the latest version.

ccb7091#diff-f0790d123318fb66d9dbb0cd3556edb8L401

251deac#diff-f0790d123318fb66d9dbb0cd3556edb8L468

Can you rerun the test with the latest version?

samoconnor · 2018-02-08T21:42:29Z

Apparently @noinline is ignored in some cases? JuliaLang/julia#19418 (comment)

samoconnor · 2018-03-07T10:40:35Z

closing in favour of #214

samoconnor added a commit that referenced this issue Jan 17, 2018

disable function name printing for now due to #148

38310b5

quinnj mentioned this issue Feb 4, 2018

Improve server error handling and logging. #189

Closed

samoconnor mentioned this issue Feb 5, 2018

add builtin @__FUNCTION__ macros JuliaLang/julia#6733

Open

samoconnor added the ⏳waiting for feedback label Feb 26, 2018

samoconnor closed this as completed Mar 7, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

BoundsError when closing MbedTLS.SSLContext #148

BoundsError when closing MbedTLS.SSLContext #148

quinnj commented Jan 17, 2018

KristofferC commented Jan 17, 2018

samoconnor commented Jan 17, 2018

quinnj commented Jan 17, 2018

Keno commented Jan 17, 2018

samoconnor commented Jan 19, 2018

quinnj commented Jan 25, 2018

Keno commented Jan 27, 2018

Keno commented Jan 27, 2018

samoconnor commented Feb 5, 2018

samoconnor commented Feb 5, 2018

samoconnor commented Feb 8, 2018

samoconnor commented Mar 7, 2018

BoundsError when closing MbedTLS.SSLContext #148

BoundsError when closing MbedTLS.SSLContext #148

Comments

quinnj commented Jan 17, 2018

KristofferC commented Jan 17, 2018

samoconnor commented Jan 17, 2018

quinnj commented Jan 17, 2018

Keno commented Jan 17, 2018

samoconnor commented Jan 19, 2018

quinnj commented Jan 25, 2018

Keno commented Jan 27, 2018

Keno commented Jan 27, 2018

samoconnor commented Feb 5, 2018

samoconnor commented Feb 5, 2018

samoconnor commented Feb 8, 2018

samoconnor commented Mar 7, 2018