JuliaWeb / HTTP.jl

HTTP for Julia
https://juliaweb.github.io/HTTP.jl/stable/
Other
626 stars 177 forks source link

"handler error": show request in log #1163

Closed fonsp closed 3 months ago

fonsp commented 3 months ago

This will show the request that caused a handler error in the log.

For example, if I add error("Test") in my handler, I get this log:

┌ Error: handle_connection handler error. 
│ 
│ ===========================
│ HTTP Error message:
│ 
│ ERROR: Test
│ Stacktrace:
│  [1] error(s::String)
│    @ Base ./error.jl:35
│  [2] is_authenticated(session::Pluto.ServerSession, request::HTTP.Messages.Request)
│    @ Pluto ~/Documents/Pluto.jl/src/webserver/Authentication.jl:8
│  [3] (::Pluto.var"#385#395"{Pluto.ServerSession, Pluto.var"#280#282"{Pluto.var"#283#285"{HTTP.Handlers.Router{typeof(Pluto.default_404), typeof(HTTP.Handlers.default405), Nothing}}, Pluto.ServerSession}})(http::HTTP.Streams.Stream{HTTP.Messages.Request, HTTP.Connections.Connection{Sockets.TCPSocket}})
│    @ Pluto ~/Documents/Pluto.jl/src/webserver/WebServer.jl:193
│  [4] #invokelatest#2
│    @ ./essentials.jl:887 [inlined]
│  [5] invokelatest
│    @ ./essentials.jl:884 [inlined]
│  [6] handle_connection(f::Function, c::HTTP.Connections.Connection{Sockets.TCPSocket}, listener::HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, readtimeout::Int64, access_log::Nothing)
│    @ HTTP.Servers ~/.julia/packages/HTTP/P8MWj/src/Servers.jl:469
│  [7] (::HTTP.Servers.var"#16#17"{Pluto.var"#385#395"{Pluto.ServerSession, Pluto.var"#280#282"{Pluto.var"#283#285"{HTTP.Handlers.Router{typeof(Pluto.default_404), typeof(HTTP.Handlers.default405), Nothing}}, Pluto.ServerSession}}, HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, Set{HTTP.Connections.Connection}, Int64, Nothing, ReentrantLock, Base.Semaphore, HTTP.Connections.Connection{Sockets.TCPSocket}})()
│    @ HTTP.Servers ~/.julia/packages/HTTP/P8MWj/src/Servers.jl:401
│   request =
│    HTTP.Messages.Request:
│    """
│    GET / HTTP/1.1
│    Host: localhost:1234
│    Pragma: no-cache
│    Accept: */*
│    Sec-WebSocket-Key: S12qX44J2ZL/2yAUCTzNgA==
│    Sec-Fetch-Site: same-origin
│    Sec-WebSocket-Version: 13
│    Sec-WebSocket-Extensions: permessage-deflate
│    Cache-Control: no-cache
│    Sec-Fetch-Mode: websocket
│    Accept-Language: nl-NL,nl;q=0.9
│    Origin: http://localhost:1234
│    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.3.1 Safari/605.1.15
│    Connection: Upgrade
│    Accept-Encoding: gzip, deflate
│    Upgrade: websocket
│    Sec-Fetch-Dest: websocket
│    Cookie: ******
│    
│    """
└ @ HTTP.Servers ~/.julia/packages/HTTP/P8MWj/src/Servers.jl:483

Instead of this:

┌ Error: handle_connection handler error. 
│ 
│ ===========================
│ HTTP Error message:
│ 
│ ERROR: Test
│ Stacktrace:
│  [1] error(s::String)
│    @ Base ./error.jl:35
│  [2] is_authenticated(session::Pluto.ServerSession, request::HTTP.Messages.Request)
│    @ Pluto ~/Documents/Pluto.jl/src/webserver/Authentication.jl:8
│  [3] (::Pluto.var"#385#395"{Pluto.ServerSession, Pluto.var"#280#282"{Pluto.var"#283#285"{HTTP.Handlers.Router{typeof(Pluto.default_404), typeof(HTTP.Handlers.default405), Nothing}}, Pluto.ServerSession}})(http::HTTP.Streams.Stream{HTTP.Messages.Request, HTTP.Connections.Connection{Sockets.TCPSocket}})
│    @ Pluto ~/Documents/Pluto.jl/src/webserver/WebServer.jl:193
│  [4] #invokelatest#2
│    @ ./essentials.jl:887 [inlined]
│  [5] invokelatest
│    @ ./essentials.jl:884 [inlined]
│  [6] handle_connection(f::Function, c::HTTP.Connections.Connection{Sockets.TCPSocket}, listener::HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, readtimeout::Int64, access_log::Nothing)
│    @ HTTP.Servers ~/.julia/packages/HTTP/P8MWj/src/Servers.jl:469
│  [7] (::HTTP.Servers.var"#16#17"{Pluto.var"#385#395"{Pluto.ServerSession, Pluto.var"#280#282"{Pluto.var"#283#285"{HTTP.Handlers.Router{typeof(Pluto.default_404), typeof(HTTP.Handlers.default405), Nothing}}, Pluto.ServerSession}}, HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, Set{HTTP.Connections.Connection}, Int64, Nothing, ReentrantLock, Base.Semaphore, HTTP.Connections.Connection{Sockets.TCPSocket}})()
│    @ HTTP.Servers ~/.julia/packages/HTTP/P8MWj/src/Servers.jl:401
└ @ HTTP.Servers ~/.julia/packages/HTTP/P8MWj/src/Servers.jl:483

I think this is useful debugging information! For example, I am currently trying to chase down the origin of a "Server never wrote a response" (like #1023 and #1156). Since my app is quite complex, it's really useful to know the path and method of the request that was handled wrong.

fonsp commented 3 months ago

My goal is to be able to trace the "Server never wrote a response" error to its request. If you prefer, I can also add this information to https://github.com/JuliaWeb/HTTP.jl/blob/eb1d2a9dfcec489eac17f4f34190df45b7873d66/src/Servers.jl#L472 and leave the logging for other handler errors as-is.

codecov-commenter commented 3 months ago

Codecov Report

Attention: Patch coverage is 0% with 1 lines in your changes are missing coverage. Please review.

Project coverage is 83.19%. Comparing base (eb1d2a9) to head (28ed65b).

Files Patch % Lines
src/Servers.jl 0.00% 1 Missing :warning:
Additional details and impacted files ```diff @@ Coverage Diff @@ ## master #1163 +/- ## ======================================= Coverage 83.19% 83.19% ======================================= Files 32 32 Lines 3058 3058 ======================================= Hits 2544 2544 Misses 514 514 ```

:umbrella: View full report in Codecov by Sentry.
:loudspeaker: Have feedback on the report? Share it here.