Every request errors after some time

[kawild]

Hi,

a continuous running application with some requests per second becomes unavailable after a few days of running without any problems.
Every request to every path fails because of an internal error, maybe related to some deque from metrics.

The following stacktrace ist inverted by journalctl and some long lines are cut. But I guess for a first view it should be enough.
I will test the application with disabled metrics.

Thanks for this great package!

Jun 06 09:32:59 julia[3904]: └ @ Oxygen.Core.Util ~/.julia/packages/Oxygen/LWjgB/src/utilities/misc.jl:40
Jun 06 09:32:59 julia[3904]: │ @ HTTP.Servers ~/.julia/packages/HTTP/sJD5V/src/Servers.jl:401
Jun 06 09:32:59 julia[3904]: │ [16] (::HTTP.Servers.var"#16#17"{Oxygen.Core.var"#15#16"{Oxygen.Core.var"#29#31"{Oxygen.Core.var"#40#44"{var"#39#40"{Oxygen.Core.var"#34#37"{HTTP.Handlers.Router{typeof(HTTP.Handlers.de>
Jun 06 09:32:59 julia[3904]: │ @ HTTP.Servers ~/.julia/packages/HTTP/sJD5V/src/Servers.jl:469
Jun 06 09:32:59 julia[3904]: │ [15] handle_connection(f::Function, c::HTTP.Connections.Connection{Sockets.TCPSocket}, listener::HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, readtimeout::Int64, access_log::Funct>
Jun 06 09:32:59 julia[3904]: │ @ ./essentials.jl:889 [inlined]
Jun 06 09:32:59 julia[3904]: │ [14] invokelatest
Jun 06 09:32:59 julia[3904]: │ @ ./essentials.jl:892 [inlined]
Jun 06 09:32:59 julia[3904]: │ [13] #invokelatest#2
Jun 06 09:32:59 julia[3904]: │ @ Oxygen.Core ~/.julia/packages/Oxygen/LWjgB/src/core.jl:208
Jun 06 09:32:59 julia[3904]: │ [12] (::Oxygen.Core.var"#15#16"{Oxygen.Core.var"#29#31"{Oxygen.Core.var"#40#44"{var"#39#40"{Oxygen.Core.var"#34#37"{HTTP.Handlers.Router{typeof(HTTP.Handlers.default404), typeof(HTTP.Ha>
Jun 06 09:32:59 julia[3904]: │ @ HTTP.Handlers ~/.julia/packages/HTTP/sJD5V/src/Handlers.jl:58
Jun 06 09:32:59 julia[3904]: │ [11] (::HTTP.Handlers.var"#1#2"{Oxygen.Core.var"#12#14"{Oxygen.Core.var"#29#31"{Oxygen.Core.var"#40#44"{var"#39#40"{Oxygen.Core.var"#34#37"{HTTP.Handlers.Router{typeof(HTTP.Handlers.def>
Jun 06 09:32:59 julia[3904]: │ @ ~/.julia/packages/Oxygen/LWjgB/src/core.jl:191 [inlined]
Jun 06 09:32:59 julia[3904]: │ [10] #12
Jun 06 09:32:59 julia[3904]: │ @ Oxygen.Core ~/.julia/packages/Oxygen/LWjgB/src/core.jl:331
Jun 06 09:32:59 julia[3904]: │ [9] (::Oxygen.Core.var"#29#31"{Oxygen.Core.var"#40#44"{var"#39#40"{Oxygen.Core.var"#34#37"{HTTP.Handlers.Router{typeof(HTTP.Handlers.default404), typeof(HTTP.Handlers.default405), Noth>
Jun 06 09:32:59 julia[3904]: │ @ ~/.julia/packages/Oxygen/LWjgB/src/core.jl:358 [inlined]
Jun 06 09:32:59 julia[3904]: │ [8] #40
Jun 06 09:32:59 julia[3904]: │ @ ~/.julia/packages/Oxygen/LWjgB/src/utilities/misc.jl:32 [inlined]
Jun 06 09:32:59 julia[3904]: │ [7] handlerequest
Jun 06 09:32:59 julia[3904]: │ @ Oxygen.Core.Util ~/.julia/packages/Oxygen/LWjgB/src/utilities/misc.jl:37
Jun 06 09:32:59 julia[3904]: │ [6] handlerequest(getresponse::Oxygen.Core.var"#41#45"{Request, var"#39#40"{Oxygen.Core.var"#34#37"{HTTP.Handlers.Router{typeof(HTTP.Handlers.default404), typeof(HTTP.Handlers.default4>
Jun 06 09:32:59 julia[3904]: │ @ ~/.julia/packages/Oxygen/LWjgB/src/core.jl:365 [inlined]
Jun 06 09:32:59 julia[3904]: │ [5] #41
Jun 06 09:32:59 julia[3904]: │ @ Base ./lock.jl:229
Jun 06 09:32:59 julia[3904]: │ [4] lock(f::Oxygen.Core.var"#42#46"{Float64, Response, Request, Oxygen.Core.AppContext.Service}, l::ReentrantLock)
Jun 06 09:32:59 julia[3904]: │ @ Oxygen.Core ~/.julia/packages/Oxygen/LWjgB/src/core.jl:367
Jun 06 09:32:59 julia[3904]: │ [3] (::Oxygen.Core.var"#42#46"{Float64, Response, Request, Oxygen.Core.AppContext.Service})()
Jun 06 09:32:59 julia[3904]: │ @ ~/.julia/packages/Oxygen/LWjgB/src/metrics.jl:26 [inlined]
Jun 06 09:32:59 julia[3904]: │ [2] push_history
Jun 06 09:32:59 julia[3904]: │ @ ~/.julia/packages/DataStructures/95DJa/src/circ_deque.jl:79 [inlined]
Jun 06 09:32:59 julia[3904]: │ [1] pushfirst!
Jun 06 09:32:59 julia[3904]: │ Stacktrace:
Jun 06 09:32:59 julia[3904]: │ BoundsError
Jun 06 09:32:59 julia[3904]: │ exception =

[ndortega]

Hi @kawild,

Thanks for the logs, I'm sorry you're running into this issue with metrics. You're right on the money, this issue appears to be coming from the metrics collection middleware function.

I will admit this is super weird, I chose a CircularDeque data structure specifically to avoid using too much memory and avoid index out of bounds issues. Is there any more information? You cut off the logs right at the exception which will have the info I need to debug this better. Depending on that log output, we may have to raise this issue with the DataStrutures.jl package if it's something I can't fix within Oxygen.

[kawild]

Thanks for your response, but I´m sorry, it seems I don´t have the complete logs anymore.
Also this error is hard to reproduce, because it occured after nearly 2 weeks of runtime and only within an productive environment.

Please let me know, If I can help any further!

[ndortega]

No worries, do you have a rough number of requests that were sent? Are the request bodies large? I can setup a server and mock a bunch of requests to see how well it holds up under high load.

If you're not sure how much load your app is getting, I'll try to mock a couple million requests to see how the server holds up over time with metrics enabled.

[kawild]

The app has a request rate of about 10/sec.
The request bodies are empty, because it is also called from Grafana, and there I can not interpolate something into the body, so everything is handled via request parameters.
So the url can be quite long - about 2000 signs and even longer.

[ndortega]

I'm going to close this issue for now, feel free to reopen this issue if you run into it again.