actix-web icon indicating copy to clipboard operation
actix-web copied to clipboard

file upload timeout

Open jjpe opened this issue 4 years ago • 19 comments

I have a POST request that does some complex processing. However, for debug purposes I have commented out the meat of the handler body. This is what's left:


// For details on the available formatting options for `LOG_FMT`, see
// https://docs.rs/actix-web/3.0.2/actix_web/middleware/struct.Logger.html
const LOG_FMT: &str = r#"{
    remote_ip: %a,
    serve_time: %D ms,
    status: %s,
    request: "%r",
    response_size: %b bytes,
    user_agent: "%{User-Agent}i",
}"#;

#[actix_rt::main]
async fn main() -> std::io::Result<()> {
    // some code here
    let mut settings = Settings::parse_toml("Server.toml")?;
    // more code here 
    let settings = Arc::new(settings); // Leverage `Arc` to not waste memory
    let insettings = Arc::clone(&settings);
    HttpServer::new(move || {
        let route = |path| if insettings.actix.enable_log { "N/A" } else { path };
        App::new()
            .wrap(Compress::new(if insettings.actix.enable_compression {
                ContentEncoding::Deflate
            } else {
                ContentEncoding::Identity
            }))
            .wrap(
                Logger::new(LOG_FMT)
                    .exclude(route("/"))
                    .exclude(route("/favicon.ico"))
            )
            .data(insettings.clone())
        // Define routes:
            .service(index)
            .service(upload)
    })
        .apply_settings(&settings) // This comes from the actix-settings crate; all it does is apply the settings in a file using APIs defined by `actix-web`.
        .run()
        .await
}

#[get("/")]
async fn index() -> impl Responder {
    let html = r#"
        <html>
            <head><title>Upload Test</title></head>
            <body style="background: #3c3c3c;">
                <form target="/" method="post" enctype="multipart/form-data">
                    <input type="file" multiple name="file"/>
                    <button type="submit">Submit</button>
                </form>
            </body>
        </html>
    "#;
    HttpResponse::Ok().body(html)
}

#[post("/")]
async fn upload(
    mut payload: Multipart,
    settings: web::Data<Arc<Settings>>,
) -> ActixResult<impl Responder> {
    // NOTE: The original body has been replaced by returning a simple string
    Ok("[upload] foo bar".to_string())
}

Expected Behavior

I expect the POST request to complete, and quickly too.

Current Behavior

The POST request hangs indefinitely until the connection with the client is broken. Altering the keep-alive setting merely keeps the connection hanging for longer.

Possible Solution

No clue, as I'm not familiar with actix-web internals.

Steps to Reproduce (for bugs)

  1. Run the server
  2. Send the POST request to / to engage the upload route using the HTML form located at get("/")
  3. A new tab/page appears...
  4. ...and it never completes, instead just timing out.

Context

This is a show-stopper bug. The entire server is unusable like this during development, never mind production.

Your Environment

The environment doesn't really matter as the issue is reproducible on a regular OS install as well as in a Kubernetes cluster. In all cases the OS is linux-based.

  • Ubuntu Linux 19.10

  • rustc 1.48.0 (7eac88abb 2020-11-16)

  • Actix-web 3.3.0

  • actix-settings 0.5

  • Rust Version (I.e, output of rustc -V):

  • Actix Web Version:

jjpe avatar Dec 01 '20 11:12 jjpe

Using this code (stripped out the Settings parts):

use actix_multipart::Multipart;
use actix_web::{
    get, middleware::Logger, post, App, HttpResponse, HttpServer, Responder, Result as ActixResult,
};

// For details on the available formatting options for `LOG_FMT`, see
// https://docs.rs/actix-web/3.0.2/actix_web/middleware/struct.Logger.html
const LOG_FMT: &str = r#"{
    remote_ip: %a,
    serve_time: %D ms,
    status: %s,
    request: "%r",
    response_size: %b bytes,
    user_agent: "%{User-Agent}i",
}"#;

#[actix_web::main]
async fn main() -> std::io::Result<()> {
    HttpServer::new(move || {
        App::new()
            .wrap(Logger::new(LOG_FMT))
            .service(index)
            .service(upload)
    })
    .bind(("127.0.0.1", 8080))?
    .run()
    .await
}

#[get("/")]
async fn index() -> impl Responder {
    let html = r#"
        <html>
            <head><title>Upload Test</title></head>
            <body style="background: #3c3c3c;">
                <form target="/" method="post" enctype="multipart/form-data">
                    <input type="file" multiple name="file"/>
                    <button type="submit">Submit</button>
                </form>
            </body>
        </html>
    "#;
    HttpResponse::Ok().body(html)
}

#[post("/")]
async fn upload(mut payload: Multipart) -> ActixResult<impl Responder> {
    eprintln!("in handler");

    // NOTE: The original body has been replaced by returning a simple string
    Ok("[upload] foo bar".to_string())
}

Using the file upload form results in the [upload] foo bar page without delay and no timeouts. Is the Settings parts integral to the problem?

robjtede avatar Dec 01 '20 11:12 robjtede

Is the Settings parts integral to the problem?

I replaced the .apply_settings(&settings) method call with .bind("0.0.0.0:9000")?. It does reach the handler (it seems a bit nondeterministic since it reaches the handler twice sometimes, which shouldn't happen here because there's only 1 request being sent), but ultimately I get exactly the same results as I got before, so I'm gonna answer your question with no.

jjpe avatar Dec 01 '20 11:12 jjpe

I've written a small binary that just calls the function (let's call it foo()) responsible for what the post(/upload) route is supposed to do, and put that on a loop within the binary's main() fn.

It consumed around 370 MB each loop, but the RAM usage did not accumulate beyond that like it does in the server. This has a very strong implication: the bug is definitely within the actix libraries somewhere, as opposed to in the library that defines the foo() fn. It could, from my perspective, be any actix crate in use by the server crate:

  • actix-web
  • actix-multipart
  • actix-rt

The tricky part (now that it's been proven that the bug is in actix) is that debugging async code is far from trivial. So I'm open to suggestions as to how to go about that.

jjpe avatar Dec 11 '20 07:12 jjpe

Can you try with master branch with tracing log enable? A couple of tracing log has been added to help monitor incoming io.

fakeshadow avatar Feb 07 '21 13:02 fakeshadow

I've tried using master using the relevant TOML snippet below, but I'm running into dependency issues:

[dependencies]
actix-multipart = { git = "https://github.com/actix/actix-web.git", branch = "master" }
actix-rt = { git = "https://github.com/actix/actix-net.git", branch = "master" }
actix-settings = "0.5"
actix-web = { git = "https://github.com/actix/actix-web.git", branch = "master" }
actix-router = { git = "https://github.com/actix/actix-net.git", branch = "master" }

What am I doing wrong?

jjpe avatar Feb 07 '21 22:02 jjpe

[dependencies]
actix-web = { git = "https://github.com/actix/actix-web.git" }

[patch.crates-io]
actix-http = { git = "https://github.com/actix/actix-web.git" }
awc = { git = "https://github.com/actix/actix-web.git" }
actix-web-codegen = { git = "https://github.com/actix/actix-web.git" }

For workplace deps used by your project have to patch them to git repo.

fakeshadow avatar Feb 07 '21 22:02 fakeshadow

I see. When I do that, I get this console output:

   Compiling sbr-analysis-engine-server v0.5.4 (/home/j/dev/accept/sbr-analysis-engine-server)
error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:161:41
    |
161 |         let mut byte_stream_field = item?;
    |                                         ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:163:48
    |
163 |           let content_type: ContentDisposition = byte_stream_field
    |  ________________________________________________^
164 | |             .content_disposition()
165 | |             .ok_or_else(|| ParseError::Incomplete)?;
    | |___________________________________________________^ expected struct `ContentDisposition`, found struct `actix_http::header::common::content_disposition::ContentDisposition`
    |
    = note: perhaps two different versions of crate `actix_http` are being used?

error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:187:29
    |
187 |             let data = chunk?;
    |                             ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0599]: no method named `write_all` found for enum `std::result::Result<std::fs::File, std::io::Error>` in the current scope
   --> src/main.rs:190:38
    |
190 |             f = web::block(move || f.write_all(&data).map(|_| f)).await?;
    |                                      ^^^^^^^^^ method not found in `std::result::Result<std::fs::File, std::io::Error>`

error[E0599]: no method named `flush` found for enum `std::result::Result<std::fs::File, std::io::Error>` in the current scope
   --> src/main.rs:193:30
    |
193 |         web::block(move || f.flush()).await?;
    |                              ^^^^^ method not found in `std::result::Result<std::fs::File, std::io::Error>`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:203:36
    |
203 |           let output_json: String  = web::block(move || {
    |  ____________________________________^
204 | |             let requires_xhtml = false;
205 | |             let cache_path = PathBuf::from("./cache"); // #FRK: lokaal in windows nodig!!
206 | |             // let _ = std::fs::remove_dir_all(&cache_path);
...   |
213 | |             )
214 | |         }).await?;
    | |_________________^ expected struct `std::string::String`, found enum `std::result::Result`
    |
    = note: expected struct `std::string::String`
                 found enum `std::result::Result<std::string::String, analysis_engine::taxonomy::PathError>`

error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:244:41
    |
244 |         let mut byte_stream_field = item?;
    |                                         ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:246:48
    |
246 |           let content_type: ContentDisposition = byte_stream_field
    |  ________________________________________________^
247 | |             .content_disposition()
248 | |             .ok_or_else(|| ParseError::Incomplete)?;
    | |___________________________________________________^ expected struct `ContentDisposition`, found struct `actix_http::header::common::content_disposition::ContentDisposition`
    |
    = note: perhaps two different versions of crate `actix_http` are being used?

error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:253:29
    |
253 |             let data = chunk?;
    |                             ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:266:36
    |
266 |           let output_json: String  = web::block(move || {
    |  ____________________________________^
267 | |             let cache_path = PathBuf::from("./cache");    // #FRK: lokaal in windows nodig!!
268 | |             // let _ = std::fs::remove_dir_all(&cache_path);
269 | |             let _ = std::fs::create_dir(&cache_path);
...   |
274 | |             )
275 | |         }).await?;
    | |_________________^ expected struct `std::string::String`, found enum `std::result::Result`
    |
    = note: expected struct `std::string::String`
                 found enum `std::result::Result<std::string::String, analysis_engine::taxonomy::PathError>`

error[E0599]: no method named `apply_settings` found for struct `HttpServer<[closure@src/main.rs:52:21: 70:6], App<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, actix_web::app_service::AppInit<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>` in the current scope
  --> src/main.rs:71:10
   |
71 |         .apply_settings(&settings)
   |          ^^^^^^^^^^^^^^ method not found in `HttpServer<[closure@src/main.rs:52:21: 70:6], App<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, actix_web::app_service::AppInit<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>`

error[E0277]: the trait bound `Multipart: FromRequest` is not satisfied
   --> src/main.rs:144:1
    |
144 | #[post("/")]
    | ^^^^^^^^^^^^ the trait `FromRequest` is not implemented for `Multipart`
    |
    = note: required because of the requirements on the impl of `FromRequest` for `(Multipart, Data<std::sync::Arc<BasicSettings<NoSettings>>>)`
    = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)

error[E0277]: the trait bound `Multipart: FromRequest` is not satisfied
   --> src/main.rs:227:1
    |
227 | #[post("/entrypoint-templates")]
    | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ the trait `FromRequest` is not implemented for `Multipart`
    |
    = note: required because of the requirements on the impl of `FromRequest` for `(Multipart, Data<std::sync::Arc<BasicSettings<NoSettings>>>)`
    = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)

warning: unused import: `ApplySettings`
 --> src/main.rs:7:14
  |
7 |     Address, ApplySettings, AtResult, BasicSettings, Settings, Mode
  |              ^^^^^^^^^^^^^
  |
  = note: `#[warn(unused_imports)]` on by default

warning: unused import: `Write`
  --> src/main.rs:24:44
   |
24 | use std::io::{Error as IoError, ErrorKind, Write};
   |                                            ^^^^^

error: aborting due to 13 previous errors; 2 warnings emitted

Some errors have detailed explanations: E0277, E0308, E0599.
For more information about an error, try `rustc --explain E0277`.
error: could not compile `sbr-analysis-engine-server`

To learn more, run the command again with --verbose.

Cargo-Process exited abnormally with code 101 at Mon Feb  8 13:32:49

Given the first error I also tried including actix-multipart into the patch list in Cargo.toml, but that doesn't work. The output for cargo update is:

    Updating git repository `https://github.com/actix/actix-web.git`
    Updating crates.io index
warning: Patch `actix-multipart v0.4.0-beta.1 (https://github.com/actix/actix-web.git#dddb623a)` was not used in the crate graph.
Check that the patched package version and available features are compatible
with the dependency requirements. If the patch has a different version from
what is locked in the Cargo.lock file, run `cargo update` to use the new
version. This may also occur with an optional dependency that is not enabled.

Cargo-Process finished at Mon Feb  8 13:33:36

And the update for compilation is largely the same:

warning: Patch `actix-multipart v0.4.0-beta.1 (https://github.com/actix/actix-web.git#dddb623a)` was not used in the crate graph.
Check that the patched package version and available features are compatible
with the dependency requirements. If the patch has a different version from
what is locked in the Cargo.lock file, run `cargo update` to use the new
version. This may also occur with an optional dependency that is not enabled.
   Compiling sbr-analysis-engine-server v0.5.4 (/home/j/dev/accept/sbr-analysis-engine-server)
error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:161:41
    |
161 |         let mut byte_stream_field = item?;
    |                                         ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:163:48
    |
163 |           let content_type: ContentDisposition = byte_stream_field
    |  ________________________________________________^
164 | |             .content_disposition()
165 | |             .ok_or_else(|| ParseError::Incomplete)?;
    | |___________________________________________________^ expected struct `ContentDisposition`, found struct `actix_http::header::common::content_disposition::ContentDisposition`
    |
    = note: perhaps two different versions of crate `actix_http` are being used?

error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:187:29
    |
187 |             let data = chunk?;
    |                             ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0599]: no method named `write_all` found for enum `std::result::Result<std::fs::File, std::io::Error>` in the current scope
   --> src/main.rs:190:38
    |
190 |             f = web::block(move || f.write_all(&data).map(|_| f)).await?;
    |                                      ^^^^^^^^^ method not found in `std::result::Result<std::fs::File, std::io::Error>`

error[E0599]: no method named `flush` found for enum `std::result::Result<std::fs::File, std::io::Error>` in the current scope
   --> src/main.rs:193:30
    |
193 |         web::block(move || f.flush()).await?;
    |                              ^^^^^ method not found in `std::result::Result<std::fs::File, std::io::Error>`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:203:36
    |
203 |           let output_json: String  = web::block(move || {
    |  ____________________________________^
204 | |             let requires_xhtml = false;
205 | |             let cache_path = PathBuf::from("./cache"); // #FRK: lokaal in windows nodig!!
206 | |             // let _ = std::fs::remove_dir_all(&cache_path);
...   |
213 | |             )
214 | |         }).await?;
    | |_________________^ expected struct `std::string::String`, found enum `std::result::Result`
    |
    = note: expected struct `std::string::String`
                 found enum `std::result::Result<std::string::String, analysis_engine::taxonomy::PathError>`

error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:244:41
    |
244 |         let mut byte_stream_field = item?;
    |                                         ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:246:48
    |
246 |           let content_type: ContentDisposition = byte_stream_field
    |  ________________________________________________^
247 | |             .content_disposition()
248 | |             .ok_or_else(|| ParseError::Incomplete)?;
    | |___________________________________________________^ expected struct `ContentDisposition`, found struct `actix_http::header::common::content_disposition::ContentDisposition`
    |
    = note: perhaps two different versions of crate `actix_http` are being used?

error[E0277]: the trait bound `MultipartError: ResponseError` is not satisfied
   --> src/main.rs:253:29
    |
253 |             let data = chunk?;
    |                             ^ the trait `ResponseError` is not implemented for `MultipartError`
    |
    = note: required because of the requirements on the impl of `From<MultipartError>` for `actix_web::Error`
    = note: required by `std::convert::From::from`

error[E0308]: try expression alternatives have incompatible types
   --> src/main.rs:266:36
    |
266 |           let output_json: String  = web::block(move || {
    |  ____________________________________^
267 | |             let cache_path = PathBuf::from("./cache");    // #FRK: lokaal in windows nodig!!
268 | |             // let _ = std::fs::remove_dir_all(&cache_path);
269 | |             let _ = std::fs::create_dir(&cache_path);
...   |
274 | |             )
275 | |         }).await?;
    | |_________________^ expected struct `std::string::String`, found enum `std::result::Result`
    |
    = note: expected struct `std::string::String`
                 found enum `std::result::Result<std::string::String, analysis_engine::taxonomy::PathError>`

error[E0599]: no method named `apply_settings` found for struct `HttpServer<[closure@src/main.rs:52:21: 70:6], App<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, actix_web::app_service::AppInit<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>` in the current scope
  --> src/main.rs:71:10
   |
71 |         .apply_settings(&settings)
   |          ^^^^^^^^^^^^^^ method not found in `HttpServer<[closure@src/main.rs:52:21: 70:6], App<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, actix_web::app_service::AppInit<impl actix_service::ServiceFactory<ServiceRequest>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>, middleware::logger::StreamLog<actix_http::encoding::encoder::Encoder<actix_web::dev::Body>>>`

error[E0277]: the trait bound `Multipart: FromRequest` is not satisfied
   --> src/main.rs:144:1
    |
144 | #[post("/")]
    | ^^^^^^^^^^^^ the trait `FromRequest` is not implemented for `Multipart`
    |
    = note: required because of the requirements on the impl of `FromRequest` for `(Multipart, Data<std::sync::Arc<BasicSettings<NoSettings>>>)`
    = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)

error[E0277]: the trait bound `Multipart: FromRequest` is not satisfied
   --> src/main.rs:227:1
    |
227 | #[post("/entrypoint-templates")]
    | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ the trait `FromRequest` is not implemented for `Multipart`
    |
    = note: required because of the requirements on the impl of `FromRequest` for `(Multipart, Data<std::sync::Arc<BasicSettings<NoSettings>>>)`
    = note: this error originates in an attribute macro (in Nightly builds, run with -Z macro-backtrace for more info)

warning: unused import: `ApplySettings`
 --> src/main.rs:7:14
  |
7 |     Address, ApplySettings, AtResult, BasicSettings, Settings, Mode
  |              ^^^^^^^^^^^^^
  |
  = note: `#[warn(unused_imports)]` on by default

warning: unused import: `Write`
  --> src/main.rs:24:44
   |
24 | use std::io::{Error as IoError, ErrorKind, Write};
   |                                            ^^^^^

error: aborting due to 13 previous errors; 2 warnings emitted

Some errors have detailed explanations: E0277, E0308, E0599.
For more information about an error, try `rustc --explain E0277`.
error: could not compile `sbr-analysis-engine-server`

To learn more, run the command again with --verbose.

Cargo-Process exited abnormally with code 101 at Mon Feb  8 13:34:27

jjpe avatar Feb 08 '21 12:02 jjpe

Add actix-web to your patch session.

actix-web = { git = "https://github.com/actix/actix-web.git" }

The way patch work is to override the dependencies every crate use in your project. The git version of actix-multiplart still points to actix-web v4 beta.1.

fakeshadow avatar Feb 08 '21 13:02 fakeshadow

Add actix-web to your patch session. Unfortunately that doesn't fix the build issues.

I think I know what's going wrong now. It appears I'll have to re-author the server crate to work with the APIs that have changed in the patch session. The thing I'm concerned about is that when I add actix-multipart to the patch session, this warning appears:

/home/j/.cargo/bin/cargo update --manifest-path /home/j/dev/accept/sbr-analysis-engine-server/Cargo.toml 
    Updating git repository `https://github.com/actix/actix-web.git`
    Updating git repository `https://github.com/actix/actix-net.git`
    Updating crates.io index
warning: Patch `actix-multipart v0.4.0-beta.1 (https://github.com/actix/actix-web.git#dddb623a)` was not used in the crate graph.
Check that the patched package version and available features are compatible
with the dependency requirements. If the patch has a different version from
what is locked in the Cargo.lock file, run `cargo update` to use the new
version. This may also occur with an optional dependency that is not enabled.

Cargo-Process finished at Mon Feb  8 17:52:40

So before I invest time in that, is actix-multipart v0.4.0-beta.1 compatible with actix-web v4.0.0-beta.1? The semver would suggest it is, but it would be nice to know for sure before investing the time.

jjpe avatar Feb 08 '21 16:02 jjpe

Why do you add actix-multipart to patch session? Nothing is depend on actix-multipart expect your project. patch in this case is used to override the deps of your deps or in-direct deps so to speak.

fakeshadow avatar Feb 08 '21 17:02 fakeshadow

I tried it out after compilation continued to fail. I've removed it since.

Nothing is depend on actix-multipart expect your project.

I need the middleware because it's core to the REST API provided by the server, and it's also core to reproducing the issue. So since I need the updated APIs, I need to add that dependency somewhere.

jjpe avatar Feb 08 '21 17:02 jjpe

Interesting. A couple of observations:

  1. I had to at least partially rewrite the code
  2. After rebasing on the beta version of actix, the memory leak has certainly decreased in scope (by 100s of megabytes per request, which is by far most of it) but it isn't completely gone. Each multipart request still leaks approximately between 8-20MB of RAM.
  3. The tracing logs seem to have no useful information whatsoever, because the formatting specifiers aren't substituted for real data (see below)

Below are the tracing logs. I don't know how useful they will be, since actually responding to a multipart request doesn't trigger any tracing logs; only starting the server seems to do so. The last 2 log entries (the INFO ones) are respectively requesting the form and using the form to send a large file using a multipart POST request. In addition, all tracing logs seem to fail to substitute actual data for the formatting specifiers, making them rather useless. FWIW, I'm using Logger::default() which is also why the warning w.r.t. LOG_FMT appears below.

 j$ cargo run --release
   Compiling sbr-analysis-engine-server v0.5.4 (/home/j/dev/accept/sbr-analysis-engine-server)
warning: constant is never used: `LOG_FMT`
  --> src/main.rs:35:1
   |
35 | / const LOG_FMT: &str = r#"{
36 | |     remote_ip: %a,
37 | |     serve_time: %D ms,
38 | |     status: %s,
...  |
41 | |     user_agent: "%{User-Agent}i",
42 | | }"#;
   | |____^
   |
   = note: `#[warn(dead_code)]` on by default

warning: 1 warning emitted

    Finished release [optimized] target(s) in 5.38s
     Running `target/release/sbr-analysis-engine-server`
Running sbr-analysis-engine-server v0.5.4
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:16Z TRACE actix_web::middleware::logger] Access log format: %a "%r" %s %b "%{Referer}i" "%{User-Agent}i" %T
[2021-02-11T11:10:35Z INFO  actix_web::middleware::logger] 127.0.0.1:44848 "GET / HTTP/1.1" 200 198 "-" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:85.0) Gecko/20100101 Firefox/85.0" 0.000273
[2021-02-11T11:10:39Z INFO  actix_web::middleware::logger] 127.0.0.1:44848 "POST / HTTP/1.1" 200 1428733 "http://localhost:8080/" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:85.0) Gecko/20100101 Firefox/85.0" 0.756448

jjpe avatar Feb 11 '21 11:02 jjpe

I can't produce memory leak with current beta on multipart.

From your code previously pasted are you testing with actively drop the multipart instead of collecting it? If you are actively dropping the payload you can not really reuse one connection and every new request would be a new one. So there would be some memory usage observed as your next request is dispatched to a new worker as new connection.

You can try to properly collect the payload and see if it would result in memory leak.

That said there indeed is a bug introduced by recent change of max buffer size which would happen on actively dropping payload. It would be fixed by this PR. https://github.com/actix/actix-web/pull/1984

fakeshadow avatar Feb 12 '21 05:02 fakeshadow

From your code previously pasted are you testing with actively drop the multipart instead of collecting it?

No, drop isn't explicitly used in the server code at all, nor in the library backing the server (i.e. the analysis-engine crate). I grepped for it in both code bases.

Below is essentially the code for the server. It is somewhat simplified and cleaned up, but this contains all the server code relating to the handling of multipart requests. Please note that the analysis-engine::taxonomy::get_templates_from_package() call consumed ~370MB. Based on the stable actix code that memory simply is never released, based on the beta most of it is released eventually except for ~8-20MB. That is, after every request to the post("/") route, the memory usage of the server process as a whole increases permanently by 8-20 MB after the initial dip in RAM where the rest is released.

mod error;


use env_logger;
use actix_multipart::Multipart;
use actix_web::{
    web, get/*macro*/, post/*macro*/,
    App, HttpResponse, HttpServer, Responder, Result as ActixResult
};
use actix_web::error::ParseError;
use actix_web::http::ContentEncoding;
use actix_web::http::header::ContentDisposition;
use actix_web::middleware::{Compress, Logger};
use analysis_engine::enums::Log;
use analysis_engine::taxonomy;
use futures_util::stream::StreamExt;
use std::env;
use std::fs::File;
use std::io::{Error as IoError, ErrorKind, Write};
use std::path::PathBuf;


const APP_NAME:    &str = env!("CARGO_PKG_NAME");
const APP_VERSION: &str = env!("CARGO_PKG_VERSION");

#[actix_rt::main]
async fn main() -> std::io::Result<()> {
   println!("Running {} v{}", APP_NAME, APP_VERSION);
   init_logger();
   let server = HttpServer::new(move || {
        App::new()
            .wrap(Compress::new(ContentEncoding::Deflate))
            .wrap(Logger::default())
        // Define routes:
            .service(index)
            .service(upload)
            .service(entrypoint_templates)
    });
    server
        .bind("0.0.0.0:8080")?
        .run()
        .await
}

/// Initialize the logging infrastructure
fn init_logger() {
    std::env::set_var("RUST_LOG", "actix_web=trace");
    std::env::set_var("RUST_BACKTRACE", "1");
    env_logger::init();
}

#[get("/")]
async fn index() -> impl Responder {
    let html = r#"
        <html>
            <head><title>Upload Test</title></head>
            <body style="background: #3c3c3c;">
                <form target="/" method="post" enctype="multipart/form-data">
                    <input type="file" multiple name="file"/>
                    <button type="submit">Submit</button>
                </form>
            </body>
        </html>
    "#;
    HttpResponse::Ok().body(html)
}


#[post("/")]
async fn upload(mut payload: Multipart) -> ActixResult<impl Responder> {
    let mut output: Vec<String> = vec![];
    while let Some(item) = payload.next().await {
        let mut byte_stream_field = item?;
        let content_type: ContentDisposition = byte_stream_field
            .content_disposition()
            .ok_or_else(|| ParseError::Incomplete)?;
        let tmp_dir = PathBuf::from("./tmp");
        let filename: &str = content_type
            .get_filename()
            .ok_or_else(|| ParseError::Incomplete)?;
        let filepath = tmp_dir.join(sanitize_filename::sanitize(&filename));
        web::block(|| {
            let _ = std::fs::remove_dir_all("./tmp");
            std::io::Result::Ok(())
        }).await??;
        web::block(|| std::fs::create_dir_all("./tmp/templates")).await??;
        
        // File::create is a blocking operation, so use a thread pool
        let in_path = PathBuf::from(&filepath);
        let mut f: File = web::block(|| File::create(in_path)).await??;
        while let Some(chunk) = byte_stream_field.next().await {
            let data = chunk?;
            // Writing a file is also a blocking operation, so use a thread pool
            f = web::block(move || f.write_all(&data).map(|_| f)).await??;
        }

        web::block(move || f.flush()).await??;

        // Process the provided zip file:
        let in_path = PathBuf::from(&filepath);
        let log_enabled = Log::Disabled;
        let output_json: String  = web::block(move || {
            let requires_xhtml = false;
            let cache_path = PathBuf::from("./cache"); // #FRK: lokaal in windows nodig!!
            let _ = std::fs::create_dir(&cache_path);
            taxonomy::get_templates_from_package(
                &in_path,
                requires_xhtml,
                &cache_path,
                log_enabled
            )
        }).await?.unwrap(/*TODO*/);
        output.push(output_json);
    }

    // Send the output zip file back to the client
    match output.len() {
        1 => Ok(output.remove(0)),
        _ => Err(HttpResponse::BadRequest().into()),
    }
}

#[allow(unused_variables)]
#[post("/entrypoint-templates")]
async fn entrypoint_templates(mut payload: Multipart) -> ActixResult<impl Responder> {
    let mut output: Vec<String> = vec![];
    while let Some(item) = payload.next().await {
        let mut byte_stream_field = item?;
        let content_type: ContentDisposition = byte_stream_field
            .content_disposition()
            .ok_or_else(|| ParseError::Incomplete)?;
        
        let mut bytes = vec![];
        while let Some(chunk) = byte_stream_field.next().await {
            let data = chunk?;
            bytes.extend(data);
        }
        let entrypoint_path = String::from_utf8(bytes).map_err(|from_utf8_err| {
            IoError::new(ErrorKind::InvalidInput, from_utf8_err)
        })?;

        let log_enabled = Log::Disabled;
        let output_json: String  = web::block(move || {
            let cache_path = PathBuf::from("./cache");    // #FRK: lokaal in windows nodig!!
            // let _ = std::fs::remove_dir_all(&cache_path);
            let _ = std::fs::create_dir(&cache_path);
            taxonomy::get_templates_from_entrypoint(
                &entrypoint_path,
                &cache_path,
                log_enabled
            )
        }).await?.unwrap(/*TODD: ResponseError/PathError */);
        output.push(output_json);
    }

    // Send the output back to the client
    match output.len() {
        1 => Ok(output.remove(0)),
        _ => Err(HttpResponse::BadRequest().into()),
    }
}

jjpe avatar Feb 12 '21 13:02 jjpe

That's a lot of code. Please try to make a minimal reproduce able one so the problem can be more clear.

fakeshadow avatar Feb 12 '21 19:02 fakeshadow

That's a lot of code. Please try to make a minimal reproduce able one so the problem can be more clear.

About 90-95% of it is merely handling the async bytestream, so I'm not sure how exactly you'd want it minified? If I were to strip out any code, it would be the exact same snippet except with the post("/entrypoint-templates") path (i.e. the entrypoint_templates() fn) removed. The snipped is meant to highlight a couple of things:

  1. Logging is enabled
  2. It shows how the server is set up at the moment
  3. It shows precisely what the code is doing

This snippet (with or without post("/entrypoint-templates")) exhibits the memory leak when sent an appropriate request (which has to be multipart), whereas putting a call to taxonomy::get_templates_from_entrypoint() in a synchronous for-loop and feeding it the information manually does not.

jjpe avatar Feb 15 '21 15:02 jjpe

Bump

jjpe avatar Apr 13 '21 06:04 jjpe

Like I said please make a minimal example. For example you don't need three endpoints to produce a leak. You don't need logger. You don't need middleware.

There is not enough man power to look into your big block of code and analyze it.

fakeshadow avatar Apr 13 '21 06:04 fakeshadow

Sad! I thought it would be better now however these response to issues like this is sad.

sunshine69 avatar Sep 05 '21 08:09 sunshine69