Connection Reset and Trace Logging

[d00z3l]

Expected Behavior

Each request should work as expected. Trace/debug logs should be displayed.

Current Behavior

I am using Postman to test my actix web server and are getting random "connection reset" errors when using a POST request. They are random in that they could happen every n-th time I issue a request. It could happen every 20th time, 5th or two in a row. Re-issuing the request will normally be successful. When it fails it fails immediately.

I am using CookieSession, not sue if that has anything to do with it.

POST http://localhost:5050/view/Flight/execute
Error: read ECONNRESET

I have tried to enable the trace logs for actix_web and actix_net that other people have referred to but can't get any log messages. I am on Windows and have tried the following RUST_LOG values:

set RUST_LOG=info,actix_web=trace,actix_net=trace
set RUST_LOG=actix_web=trace,actix_net=trace
set RUST_LOG=trace

The standalone trace value will log trace logs for actix_server, actix_http and mio, for all 3 I never see any actix_web or actix_net logs. Should I be using different logs?

Possible Solution

If I could get the logs working I can probably find the issue myself.

Steps to Reproduce (for bugs)

1. Execute POST request using Postman N times
2. Receive ECONNRESET

Context

It isn't a big impact while testing but I am worried it will fail when going to production.

Your Environment

• Rust Version (I.e, output of rustc -V): rustc 1.48.0 (7eac88abb 2020-11-16)
• Actix Web Version: 3.2.0

[robjtede]

Do you have env_logger crate initialized? If not, check out the examples repo, most of those projects use it.

[d00z3l]

Yep, I do.

env_logger::init();

I can change the default logger to error or trace but can't change specific loggers. Below works, it removes the INFO logs from actix_server.

set RUST_LOG=error,actix_web=trace,actix_net=trace

[robjtede]

actix_net is not a crate name

try this: set RUST_LOG=error,actix=trace since actix is actually a prefix here

[d00z3l]

Thanks, that gave me some trace logs (actix_http and actix_server) but not more info about the cause. Below is the output issuing the same request multiple times, at 01:51 it failed but nothing appeared in the logs just read ECONNRESET in Postman. It might be possible that Postman is the issue but I have never seen it before.

Are there any other logs/traces I can enable?

[2020-11-24T01:49:05Z TRACE actix_http::h1::decoder] Length read: 1419
[2020-11-24T01:49:16Z TRACE actix_http::h1::dispatcher] Keep-alive timeout, close connection
[2020-11-24T01:49:28Z TRACE actix_http::h1::decoder] Length read: 1419
[2020-11-24T01:49:41Z TRACE actix_http::h1::decoder] Length read: 1419
[2020-11-24T01:50:42Z TRACE actix_http::h1::dispatcher] Keep-alive timeout, close connection
[2020-11-24T01:53:07Z TRACE actix_http::h1::decoder] Length read: 1419
[2020-11-24T01:53:23Z TRACE actix_http::h1::dispatcher] Keep-alive timeout, close connection
[2020-11-24T01:53:24Z TRACE actix_http::h1::decoder] Length read: 1419
[2020-11-24T01:53:40Z TRACE actix_http::h1::dispatcher] Keep-alive timeout, close connection

[robjtede]

weird, i don't think we can help much without some minimal reproduction

[d00z3l]

Thanks for following up. I have tried to replicate while using Fiddler and it doesn't reset while it is running. I will try to find some more details.

[d00z3l]

Hi @robjtede ,

I have spent some more time debugging this and although I can't create a simple test case I have found a workaround. It seems to be related to keep alive, if I disable it (set it to zero) I no longer have the issue.

I can replicate the issue on my server by running consecutive long running processes, at least a couple of them need to be take longer that the default keep alive setting (i.e. 5 secs). In my case it fails consistently after 4 or 5 requests (but not on every request). There is no logging on the actix side so I assume the socket has been closed or some other issue at that level. Postman must have a connection pool which contributes to the issue.