Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unwind triggered while reading from TcpStream. #6979

Closed
fooooter opened this issue Nov 17, 2024 · 14 comments
Closed

Unwind triggered while reading from TcpStream. #6979

fooooter opened this issue Nov 17, 2024 · 14 comments
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug.

Comments

@fooooter
Copy link

fooooter commented Nov 17, 2024

Version

└── tokio v1.41.1
    └── tokio-macros v2.4.0 (proc-macro)

Platform
Linux area51 6.6.58-gentoo-r1 #1 SMP PREEMPT_DYNAMIC Tue Nov 5 19:10:09 CET 2024 x86_64 Intel(R) Core(TM) i5-9300H CPU @ 2.40GHz GenuineIntel GNU/Linux

Description
I'm currently writing a PoC HTTP web server (a working example) and I've stumbled across an issue, where an unwind is generated while reading a request from a client (I used Firefox and Chromium) using BufReader (right before reading a request body, to be exact). I've tested several different methods, like read_to_string, read_line or read_to_end, but the outcome was still the same. Unfortunately, I cannot provide any backtrace, as it's a "weird" kind of unwind without any output whatsoever, even though I have RUST_BACKTRACE set to full. As I've tested this mostly with read_line, I found out, that the condition for this to occur is when a line being read consists only of \r\n. Might be a similar case to #2532.

I tried this code:

pub async fn receive_request(mut stream: &mut TcpStream, request: &mut String) {
    let mut reader = BufReader::new(&mut *stream);

    loop {
        match reader.read_line(request).await {
            Ok(l) => {
                if l == 0 {
                    return;
                }
            },
            Err(e1) => {
                eprintln!("[receive_request():{}] An error occurred while reading a request from a client. Error information:\n{:?}\nAttempting to close connection...", line!(), e1);
                if let Err(e2) = stream.shutdown().await {
                    eprintln!("[receive_request():{}] FAILED. Error information:\n{:?}", line!(), e2);
                }
                panic!("Unrecoverable error occurred while handling connection.");
            }
        };
    }
}

This code is partially working (cannot read POST request body, but the rest is properly appended into request string):

pub async fn receive_request(mut stream: &mut TcpStream, request: &mut String) {
    let reader = BufReader::new(&mut stream);
    let mut request_iter = reader.lines();

    let mut line = match request_iter.next_line().await {
        Ok(line) => line.unwrap(),
        Err(e1) => {
            eprintln!("[receive_request():{}] An error occurred while reading a request from a client. Error information:\n{:?}\n\
                        Attempting to close connection...", line!(), e1);
            if let Err(e2) = stream.shutdown().await {
                eprintln!("[receive_request():{}] FAILED. Error information:\n{:?}", line!(), e2);
            }
            panic!("Unrecoverable error occurred while handling a connection.");
        }
    };

    while !line.is_empty() {
        (*request).push_str(format!("{line}\r\n").as_str());
        line = match request_iter.next_line().await {
            Ok(line) => line.unwrap(),
            Err(e1) => {
                eprintln!("[receive_request():{}] An error occurred while reading a request from a client. Error information:\n{:?}\nAttempting to close connection...", line!(), e1);
                if let Err(e2) = stream.shutdown().await {
                    eprintln!("[receive_request():{}] FAILED. Error information:\n{:?}", line!(), e2);
                }
                panic!("Unrecoverable error occurred while handling connection.");
            }
        };
    }
}
@fooooter fooooter added A-tokio Area: The main tokio crate C-bug Category: This is a bug. labels Nov 17, 2024
@mox692
Copy link
Member

mox692 commented Nov 18, 2024

Not much comes to mind for me. Are you able to create a small program that reproduce this?

@Darksonn
Copy link
Contributor

Alternatively, try running the program under gdb to get a better stack trace.

@fooooter
Copy link
Author

@mox692

use tokio::io::{AsyncBufReadExt, BufReader};
use tokio::net::TcpListener;

#[tokio::main]

async fn main() -> Result<(), Box<dyn std::error::Error>> {
    let listener = TcpListener::bind("127.0.0.1:8080").await?;

    loop {
        let (stream, _) = listener.accept().await?;
        tokio::spawn(async move {
            let mut reader = BufReader::new(stream);
            let mut buf = String::new();

            loop {
                match reader.read_line(&mut buf).await {
                    Ok(l) => {
                        if l == 0 {
                            return;
                        }
                    },
                    Err(_) => {
                        return;
                    }
                };
            }
        });
    }
}

Is this enough, or do I need to create a separate repository for this, or do something else?

@sfackler
Copy link
Contributor

If there was no output, how do you know it unwound?

@fooooter
Copy link
Author

I used catch_unwind and a debugger.

@Darksonn
Copy link
Contributor

I tried running your code and connecting with telnet; I was unable to observe any issues. Please provide more information on what actually goes wrong.

@fooooter
Copy link
Author

It fails during regular HTTP requests. To reproduce this bug, a regular browser should suffice (tried Firefox and Chromium, as I said earlier).

Alright, I tried using GDB, and here's what happened AFTER read_line read the request line successfully for the last time (I've got mistaken - it unwinds AFTER \r\n is SUCCESSFULLY appended to string):

(gdb) n
16                      match reader.read_line(&mut buf).await { // this is a call to read_line() that fails
(gdb) n
tokio::runtime::task::core::Core<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>::poll<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> (self=0x555555702320, cx=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/task/core.rs:320
320                 self.stage.stage.with_mut(|ptr| {
(gdb) n
335             if res.is_ready() {
(gdb) n
335             if res.is_ready() {
(gdb) n
339             res
(gdb) n
340         }
(gdb) n
tokio::runtime::task::harness::poll_future::{closure#0}<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> ()
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/task/harness.rs:499
499             let res = guard.core.poll(cx);
(gdb) n
500             mem::forget(guard);
(gdb) n
core::panic::unwind_safe::{impl#23}::call_once<core::task::poll::Poll<()>, tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>> (self=...) at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs:273
warning: 273    /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panic/unwind_safe.rs: No such file or directory
(gdb) n
std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>>, core::task::poll::Poll<()>> (data=0x7ffff71076c8) at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:559
warning: 559    /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs: No such file or directory
(gdb) n
0x0000555555573d5b in __rust_try ()
(gdb) n
Single stepping until exit from function __rust_try,
which has no line number information.
std::panicking::try<core::task::poll::Poll<()>, core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>>> (f=<error reading variable: Cannot access memory at address 0x18>)
    at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:522
warning: 522    /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs: No such file or directory
(gdb) n
521     in /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs
(gdb) n
warning: 351    /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panic.rs: No such file or directory
(gdb) n
tokio::runtime::task::harness::poll_future<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> (
    core=0x555555702320, cx=...) at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/task/harness.rs:505
505         let output = match output {
(gdb) n
506             Ok(Poll::Pending) => return Poll::Pending,
(gdb) n
521     }

But ends up there:

tokio::runtime::task::harness::Harness<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>::poll_inner<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> (self=0x7ffff7107908)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/task/harness.rs:211
211                     if res == Poll::Ready(()) {
(gdb) n
216                     let transition_res = self.state().transition_to_idle();
(gdb) n
217                     if let TransitionToIdle::Cancelled = transition_res {
(gdb) n
222                     transition_result_to_poll_future(transition_res)
(gdb) n
231         }
(gdb) n
tokio::runtime::task::harness::Harness<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>::poll<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> (self=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/task/harness.rs:176
176         }
(gdb) n
tokio::runtime::task::raw::poll<tokio_bug_demo::main::{async_block#0}::{async_block_env#0}, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> (ptr=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/task/raw.rs:272
272     }
(gdb) n
tokio::runtime::task::raw::RawTask::poll (self=...) at src/runtime/task/raw.rs:202
202         }
(gdb) n
tokio::runtime::task::LocalNotified<alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>>::run<alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle, alloc::alloc::Global>> (self=...) at src/runtime/task/mod.rs:436
436         }
(gdb) n
tokio::runtime::scheduler::multi_thread::worker::{impl#1}::run_task::{closure#0} () at src/runtime/scheduler/multi_thread/worker.rs:597
597                 let mut lifo_polls = 0;
(gdb) n
604                     let mut core = match self.core.borrow_mut().take() {
(gdb) n
604                     let mut core = match self.core.borrow_mut().take() {
(gdb) n
605                         Some(core) => core,
(gdb) n
612                     };
(gdb) n
615                     let task = match core.lifo_slot.take() {
(gdb) n
618                             self.reset_lifo_enabled(&mut core);
(gdb) n
619                             core.stats.end_poll();
(gdb) n
620                             return Ok(core);
(gdb) n
660                 }
(gdb) n
661             })
(gdb) n
tokio::runtime::coop::budget<core::result::Result<alloc::boxed::Box<tokio::runtime::scheduler::multi_thread::worker::Core, alloc::alloc::Global>, ()>, tokio::runtime::scheduler::multi_thread::worker::{impl#1}::run_task::{closure_env#0}> (f=...) at src/runtime/coop.rs:74
74      }
(gdb) n
tokio::runtime::scheduler::multi_thread::worker::Context::run_task (self=0x7ffff7107f68, task=..., core=0x5555556ff9c0) at src/runtime/scheduler/multi_thread/worker.rs:662
662         }
(gdb) n
tokio::runtime::scheduler::multi_thread::worker::Context::run (self=0x7ffff7107f68, core=0x5555556ff9c0) at src/runtime/scheduler/multi_thread/worker.rs:546
546                     core = self.run_task(task, core)?;
(gdb) n
1       #![allow(unknown_lints, unexpected_cfgs)]
(gdb) n
531             while !core.is_shutdown {
(gdb) n
532                 self.assert_lifo_enabled_is_correct(&core);
(gdb) n
534                 if core.is_traced {
(gdb) n
539                 core.tick();
(gdb) n
542                 core = self.maintenance(core);
(gdb) n
545                 if let Some(task) = core.next_task(&self.worker) {
(gdb) n
548                 }
(gdb) n
551                 core.stats.end_processing_scheduled_tasks();
(gdb) n
555                 if let Some(task) = core.steal_work(&self.worker) {
(gdb) n
561                     core = if !self.defer.is_empty() {
(gdb) n
561                     core = if !self.defer.is_empty() {
(gdb) n
564                         self.park(core)

Here's a backtrace of a moment right before it starts hanging forever:

#0  0x00007ffff7e0600d in syscall () from /usr/lib64/libc.so.6
#1  0x000055555562a0a3 in parking_lot_core::thread_parker::imp::ThreadParker::futex_wait (self=0x7ffff7d10c18, ts=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/parking_lot_core-0.9.10/src/thread_parker/linux.rs:112
#2  0x0000555555629e64 in parking_lot_core::thread_parker::imp::{impl#0}::park (self=0x7ffff7d10c18)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/parking_lot_core-0.9.10/src/thread_parker/linux.rs:66
#3  0x0000555555634d5e in parking_lot_core::parking_lot::park::{closure#0}<parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#0}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#1}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#2}> (thread_data=0x7ffff7d10bf8) at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/parking_lot_core-0.9.10/src/parking_lot.rs:635
#4  0x0000555555633109 in parking_lot_core::parking_lot::with_thread_data<parking_lot_core::parking_lot::ParkResult, parking_lot_core::parking_lot::park::{closure_env#0}<parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#0}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#1}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#2}>> (f=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/parking_lot_core-0.9.10/src/parking_lot.rs:207
#5  parking_lot_core::parking_lot::park<parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#0}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#1}, parking_lot::condvar::{impl#1}::wait_until_internal::{closure_env#2}> (key=93824993992552, validate=..., before_sleep=..., timed_out=..., park_token=..., timeout=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/parking_lot_core-0.9.10/src/parking_lot.rs:600
#6  0x000055555562f5ac in parking_lot::condvar::Condvar::wait_until_internal (self=0x555555701f68, mutex=0x555555701f70, timeout=...) at src/condvar.rs:334
#7  0x00005555555930ae in parking_lot::condvar::Condvar::wait<()> (self=0x555555701f68, mutex_guard=0x7fffffffc448)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/parking_lot-0.12.3/src/condvar.rs:256
#8  0x00005555555cdddc in tokio::loom::std::parking_lot::Condvar::wait<()> (self=0x555555701f68, guard=...) at src/loom/std/parking_lot.rs:157
--Type <RET> for more, q to quit, c to continue without paging--
#9  0x00005555555c5e21 in tokio::runtime::park::Inner::park (self=0x555555701f60) at src/runtime/park.rs:116
#10 0x00005555555c69c7 in tokio::runtime::park::{impl#4}::park::{closure#0} (park_thread=0x7ffff7d10be8) at src/runtime/park.rs:254
#11 0x00005555555c6b0e in tokio::runtime::park::{impl#4}::with_current::{closure#0}<tokio::runtime::park::{impl#4}::park::{closure_env#0}, ()> (inner=0x7ffff7d10be8) at src/runtime/park.rs:268
#12 0x00005555555c1d55 in std::thread::local::LocalKey<tokio::runtime::park::ParkThread>::try_with<tokio::runtime::park::ParkThread, tokio::runtime::park::{impl#4}::with_current::{closure_env#0}<tokio::runtime::park::{impl#4}::park::{closure_env#0}, ()>, ()> (self=0x5555556d9428, f=...) at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:283
#13 0x00005555555c6aa6 in tokio::runtime::park::CachedParkThread::with_current<tokio::runtime::park::{impl#4}::park::{closure_env#0}, ()> (self=0x7fffffffca3f, f=...) at src/runtime/park.rs:268
#14 0x00005555555c694e in tokio::runtime::park::CachedParkThread::park (self=0x7fffffffca3f) at src/runtime/park.rs:254
#15 0x0000555555583b62 in tokio::runtime::park::CachedParkThread::block_on<tokio_bug_demo::main::{async_block_env#0}> (self=0x7fffffffca3f, f=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/park.rs:285
#16 0x00005555555873b4 in tokio::runtime::context::blocking::BlockingRegionGuard::block_on<tokio_bug_demo::main::{async_block_env#0}> (self=0x7fffffffcd00, f=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/context/blocking.rs:66
#17 0x00005555555795cb in tokio::runtime::scheduler::multi_thread::{impl#0}::block_on::{closure#0}<tokio_bug_demo::main::{async_block_env#0}> (blocking=0x7fffffffcd00)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/scheduler/multi_thread/mod.rs:87
#18 0x0000555555580c83 in tokio::runtime::context::runtime::enter_runtime<tokio::runtime::scheduler::multi_thread::{impl#0}::block_on::{closure_env#0}<tokio_bug_demo::main::{async_block_env#0}>, core::result::Result<(), alloc::boxed::Box<dyn core::error::Error, alloc::alloc::Global>>> (handle=0x7fffffffd5e8, allow_block_in_place=true, f=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/context/runtime.rs:65
#19 0x000055555557952c in tokio::runtime::scheduler::multi_thread::MultiThread::block_on<tokio_bug_demo::main::{async_block_env#0}> (self=0x7fffffffd5c0, handle=0x7fffffffd5e8, future=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/scheduler/multi_thread/mod.rs:86
#20 0x0000555555586dab in tokio::runtime::runtime::Runtime::block_on_inner<tokio_bug_demo::main::{async_block_env#0}> (self=0x7fffffffd5b8, future=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/runtime.rs:370
#21 0x0000555555587184 in tokio::runtime::runtime::Runtime::block_on<tokio_bug_demo::main::{async_block_env#0}> (self=0x7fffffffd5b8, future=...)
    at /home/footer/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.41.1/src/runtime/runtime.rs:342
#22 0x000055555558064c in tokio_bug_demo::main () at src/main.rs:9

Hope it suffices. I'm kind of worried, that I have my standard library corrupted or something, because of those "No such file or directory" warnings.

@Darksonn
Copy link
Contributor

That's not unwinding (i.e. there's no panic). You hit a Poll::Pending and the task yielded to the runtime. Then, the runtime went to sleep by calling park. The runtime went to sleep because all tasks are idle, and its waiting for new IO events.

What happens is that first the browser sent a bunch of lines describing the web page it wants to open. Then, it waits for a reply. However, now both your program and the browser is waiting for more data forever, so the result is that both sleep forever, because they're waiting for each other.

@fooooter
Copy link
Author

fooooter commented Nov 18, 2024

I understand, but now this begs the question whether all read methods check for stuff like EOF in order to return Poll::Ready, because those two browsers must signalize the end of a request in some way, right? I'll try debugging it once more, but now with stepping into read_line. Though it's still weird, that catch_unwind was able to pinpoint the exact object that caused it, or maybe I got bamboozled by the debugger or something, I don't know.

@Darksonn
Copy link
Contributor

HTTP requests do not signal the end of the request with EOF because they might want to send another request afterwards. Instead, that is done by sending an empty line after the last header. Once you get an empty line, you should send the reply

@fooooter
Copy link
Author

What about the request body then which is after a blank line?

@sfackler
Copy link
Contributor

Your code needs to parse the HTTP response to understand how the body is framed.

@Darksonn
Copy link
Contributor

Yeah, basically the http headers explain how to read the body. There are several different ways you might need to do it, and servers must support them all to be complete.

@fooooter
Copy link
Author

Yeah, I'll probably need to get the value of Content-Length header and read the number of bytes it specifies. Anyway, thanks for help!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug.
Projects
None yet
Development

No branches or pull requests

4 participants