bug: async fn resumed after completion during write #4012
Description
Our CI has failed for the same reason for twice. We need to look into this.
2024-01-18T02:58:14.855454Z ERROR opendal::services: service=s3 operation=Writer::close path=196bb82b-1576-4c6b-ba80-c1fa889ebb71 written=10485760B -> data close failed: Unexpected (temporary) at Writer::write => send http request
Context:
url: https://s3.***.amazonaws.com/***/***c753bb91-5217-4bbd-b368-659ed5f15e42/196bb82b-1576-4c6b-ba80-c1fa889ebb71?uploads
called: http_util::Client::send
service: s3
path: 196bb82b-1576-4c6b-ba80-c1fa889ebb71
write_buf: 5242880
Source:
error sending request for url (https://s3.***.amazonaws.com/***/***c753bb91-5217-4bbd-b368-659ed5f15e42/196bb82b-1576-4c6b-ba80-c1fa889ebb71?uploads): connection closed before message completed: connection closed before message completed
Backtrace:
0: opendal::types::error::Error::new
at ./src/types/error.rs:338:24
1: opendal::raw::http_util::client::HttpClient::send::{{closure}}::{{closure}}
at ./src/raw/http_util/client.rs:159:28
2: core::result::Result<T,E>::map_err
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/result.rs:829:27
3: opendal::raw::http_util::client::HttpClient::send::{{closure}}
at ./src/raw/http_util/client.rs:145:24
4: opendal::services::s3::core::S3Core::send::{{closure}}
at ./src/services/s3/core.rs:186:31
5: opendal::services::s3::core::S3Core::s3_initiate_multipart_upload::{{closure}}
at ./src/services/s3/core.rs:589:24
6: <opendal::services::s3::writer::S3Writer as opendal::raw::oio::write::multipart_write::MultipartWrite>::initiate_part::{{closure}}
at ./src/services/s3/writer.rs:74:14
7: <core::pin::Pin<P> as core::future::future::Future>::poll
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/future/future.rs:125:9
8: <opendal::raw::oio::write::multipart_write::MultipartWriter<W> as opendal::raw::oio::write::api::Write>::poll_write::{{closure}}
at ./src/raw/oio/write/multipart_write.rs:269:85
9: <opendal::raw::oio::write::multipart_write::MultipartWriter<W> as opendal::raw::oio::write::api::Write>::poll_write
at ./src/raw/oio/write/multipart_write.rs:274:44
10: <opendal::layers::error_context::ErrorContextWrapper<T> as opendal::raw::oio::write::api::Write>::poll_write
at ./src/layers/error_context.rs:411:9
11: <opendal::layers::complete::CompleteWriter<W> as opendal::raw::oio::write::api::Write>::poll_write
at ./src/layers/complete.rs:718:24
12: <opendal::raw::oio::write::exact_buf_write::ExactBufWriter<W> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/exact_buf_write.rs:70:28
13: <opendal::raw::enum_utils::TwoWays<ONE,TWO> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/enum_utils.rs:117:29
14: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
15: <opendal::layers::logging::LoggingWriter<W> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/layers/logging.rs:1336:22
16: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
17: <opendal::layers::timeout::TimeoutWrapper<R> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/layers/timeout.rs:408:15
18: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
19: <opendal::layers::retry::RetryWrapper<R,I> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/layers/retry.rs:973:22
20: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
21: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
22: <opendal::raw::oio::write::api::CloseFuture<W> as core::future::future::Future>::poll
at ./src/raw/oio/write/api.rs:197:9
23: opendal::types::writer::Writer::close::{{closure}}
at ./src/types/writer.rs:208:28
24: behavior::async_write::test_writer_sink::{{closure}}
at ./tests/behavior/async_write.rs:341:15
25: tokio::runtime::park::CachedParkThread::block_on::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/park.rs:282:63
26: tokio::runtime::coop::with_budget
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/coop.rs:107:5
27: tokio::runtime::coop::budget
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/coop.rs:73:5
28: tokio::runtime::park::CachedParkThread::block_on
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/park.rs:282:31
29: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context/blocking.rs:66:9
30: tokio::runtime::handle::Handle::block_on::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/handle.rs:310:13
31: tokio::runtime::context::runtime::enter_runtime
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context/runtime.rs:65:16
32: tokio::runtime::handle::Handle::block_on
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/handle.rs:309:9
33: behavior::utils::build_async_trial::{{closure}}
at ./tests/behavior/utils.rs:71:9
34: libtest_mimic::Trial::test::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:112:54
35: core::ops::function::FnOnce::call_once{{vtable.shim}}
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/ops/function.rs:250:5
36: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/alloc/src/boxed.rs:2007:9
37: libtest_mimic::run_single::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:505:43
38: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panic/unwind_safe.rs:272:9
39: std::panicking::try::do_call
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:552:40
40: __rust_try
41: std::panicking::try
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:516:19
42: std::panic::catch_unwind
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panic.rs:142:14
43: libtest_mimic::run_single
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:505:5
44: libtest_mimic::run::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:476:35
45: <F as threadpool::FnBox>::call_box
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/threadpool-1.8.1/src/lib.rs:95:9
46: threadpool::spawn_in_pool::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/threadpool-1.8.1/src/lib.rs:769:17
47: std::sys_common::backtrace::__rust_begin_short_backtrace
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys_common/backtrace.rs:154:18
48: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/thread/mod.rs:529:17
49: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panic/unwind_safe.rs:272:9
50: std::panicking::try::do_call
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:552:40
51: __rust_try
52: std::panicking::try
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:516:19
53: std::panic::catch_unwind
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panic.rs:142:14
54: std::thread::Builder::spawn_unchecked_::{{closure}}
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/thread/mod.rs:528:30
55: core::ops::function::FnOnce::call_once{{vtable.shim}}
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/ops/function.rs:250:5
56: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/alloc/src/boxed.rs:2007:9
57: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/alloc/src/boxed.rs:2007:9
58: std::sys::unix::thread::Thread::new::thread_start
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys/unix/thread.rs:108:17
59: <unknown>
60: <unknown>
at core/src/layers/logging.rs:1350
thread '<unnamed>' panicked at core/src/raw/oio/write/multipart_write.rs:269:54:
`async fn` resumed after completion
stack backtrace:
0: rust_begin_unwind
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:645:5
1: core::panicking::panic_fmt
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panicking.rs:72:14
2: core::panicking::panic
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panicking.rs:127:5
3: <opendal::raw::oio::write::multipart_write::MultipartWriter<W> as opendal::raw::oio::write::api::Write>::poll_write::{{closure}}
at ./src/raw/oio/write/multipart_write.rs:269:54
4: <opendal::raw::oio::write::multipart_write::MultipartWriter<W> as opendal::raw::oio::write::api::Write>::poll_write
at ./src/raw/oio/write/multipart_write.rs:274:44
5: <opendal::layers::error_context::ErrorContextWrapper<T> as opendal::raw::oio::write::api::Write>::poll_write
at ./src/layers/error_context.rs:411:9
6: <opendal::layers::complete::CompleteWriter<W> as opendal::raw::oio::write::api::Write>::poll_write
at ./src/layers/complete.rs:718:24
7: <opendal::raw::oio::write::exact_buf_write::ExactBufWriter<W> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/exact_buf_write.rs:70:28
8: <opendal::raw::enum_utils::TwoWays<ONE,TWO> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/enum_utils.rs:117:29
9: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
10: <opendal::layers::logging::LoggingWriter<W> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/layers/logging.rs:1336:22
11: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
12: <opendal::layers::timeout::TimeoutWrapper<R> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/layers/timeout.rs:408:15
13: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
14: <opendal::layers::retry::RetryWrapper<R,I> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/layers/retry.rs:973:22
15: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
16: <alloc::boxed::Box<T> as opendal::raw::oio::write::api::Write>::poll_close
at ./src/raw/oio/write/api.rs:125:9
17: <opendal::raw::oio::write::api::CloseFuture<W> as core::future::future::Future>::poll
at ./src/raw/oio/write/api.rs:197:9
18: opendal::types::writer::Writer::close::{{closure}}
at ./src/types/writer.rs:208:28
19: behavior::async_write::test_writer_sink::{{closure}}
at ./tests/behavior/async_write.rs:341:15
20: tokio::runtime::park::CachedParkThread::block_on::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/park.rs:282:63
21: tokio::runtime::coop::with_budget
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/coop.rs:107:5
22: tokio::runtime::coop::budget
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/coop.rs:73:5
23: tokio::runtime::park::CachedParkThread::block_on
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/park.rs:282:31
24: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context/blocking.rs:66:9
25: tokio::runtime::handle::Handle::block_on::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/handle.rs:310:13
26: tokio::runtime::context::runtime::enter_runtime
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/context/runtime.rs:65:16
27: tokio::runtime::handle::Handle::block_on
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.34.0/src/runtime/handle.rs:309:9
28: behavior::utils::build_async_trial::{{closure}}
at ./tests/behavior/utils.rs:71:9
29: libtest_mimic::Trial::test::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:112:54
30: core::ops::function::FnOnce::call_once{{vtable.shim}}
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/ops/function.rs:250:5
31: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/alloc/src/boxed.rs:2007:9
32: libtest_mimic::run_single::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:505:43
33: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panic/unwind_safe.rs:272:9
34: std::panicking::try::do_call
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:552:40
35: __rust_try
36: std::panicking::try
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:516:19
37: std::panic::catch_unwind
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panic.rs:142:14
38: libtest_mimic::run_single
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:505:5
39: libtest_mimic::run::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libtest-mimic-0.6.1/src/lib.rs:476:35
40: <F as threadpool::FnBox>::call_box
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/threadpool-1.8.1/src/lib.rs:95:9
41: threadpool::spawn_in_pool::{{closure}}
at /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/threadpool-1.8.1/src/lib.rs:769:17
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
2024-01-18T02:58:15.859576Z WARN opendal::layers::complete: writer has not been closed or aborted, must be a bug
at core/src/layers/complete.rs:705
test behavior::test_writer_sink ... FAILEDhttps://github.com/apache/incubator-opendal/actions/runs/7565987347/job/20602684491