HTTP Server Write Timeout #26
Comments
|
I think if the client closed the write pipe (read pipe, from the client POV) you should get an error... Do you experience this? |
|
I am trying to drill down into it. I seem to be experiencing something like this where the http server begins to refuse connections. The remaining services seem to continue working (mqtt, modbus, uart , WiFi etc) , but http goes dark. It’s kind of hard to replicate, and I’ve only noticed it after coming back to an esp32 that’s been running for a few days |
|
Can you check if it's happening for a specific connection type. |
|
Actually I just realized I'm hitting this exact same issue without edge-net/edge-http/src/io/server.rs Line 170 in 6a0451b Perhaps yours is the same issue I'm hitting. |
|
I think there is a bug indeed, and I might understand from where it is coming: a request with
Finally, if the server gets Let me see how to fix that. In any case, if you have a wireshark or Chrome header of the HTTP client request that cause the server to hang, that would be very useful! |
|
Here's a trace of the request that's giving me issues. As you can see, the server (192.168.11.1) never sends a response
|
|
I think I fixed it. Can you try this branch? Unfortunately, I managed to mess up my fix together with my other commit which adds inline documentation, so I could imagine, the fix would be very difficult to review. :( |
|
PR here: #33 |
|
I tested on my side, thinking initially that it worked, but it turns out it still hangs when I send a request with $ curl -v http://192.168.11.1/hotspot-detect.html
* Trying 192.168.11.1:80...
* Connected to 192.168.11.1 (192.168.11.1) port 80
> GET /hotspot-detect.html HTTP/1.1
> Host: 192.168.11.1
> User-Agent: curl/8.9.1
> Accept: */*
>
* Request completely sent off
< HTTP/1.1 302 Found
< Location: /
< Connection: Keep-Alive
< Transfer-Encoding: Chunked
<
* Connection #0 to host 192.168.11.1 left intact
$ curl -v http://192.168.11.1/hotspot-detect.html -H "connection: close"
* Trying 192.168.11.1:80...
* Connected to 192.168.11.1 (192.168.11.1) port 80
> GET /hotspot-detect.html HTTP/1.1
> Host: 192.168.11.1
> User-Agent: curl/8.9.1
> Accept: */*
> connection: close
>
* Request completely sent off
< HTTP/1.1 302 Found
< Location: /
< Connection: Close
< |
|
Huh... Here's the same test that you did except I did it with the For me, it works in both cases (keep-alive and close) and - for close - the connection is closed immediately. |
|
I'm testing with struct CaptivePortalHandler;
impl<'b, T, const N: usize> Handler<'b, T, N> for CaptivePortalHandler
where
T: Read + Write,
T::Error: Send + Sync,
{
type Error = HandlerError<T>;
async fn handle(
&self,
connection: &mut edge_http::io::server::Connection<'b, T, N>,
) -> Result<(), Self::Error> {
let headers = connection.headers().unwrap();
log::warn!("got request: {:?}", headers);
let r = match (headers.method, headers.path.unwrap_or("")) {
// Captive portal configuration page
(Some(Method::Get), "/") | (Some(Method::Get), "") => {
connection
.initiate_response(200, Some("OK"), &[("Content-Type", "text/html")])
.await?;
connection
.write_all(DEFAULT_CAPTIVE.as_bytes())
.await
}
// Routes to redirect to trigger a captive portal detection
(Some(Method::Get), "/generate_204") // Android captive portal redirect
| (Some(Method::Get), "/redirect") // Microsoft redirect
| (Some(Method::Get), "/hotspot-detect.html") // Apple iOS
| (Some(Method::Get), "/canonical.html") // Firefox captive portal
=> {
log::error!("Captive portal URL. Redirecting...");
connection
.initiate_response(302, Some("Found"), &[("Location", "/")])
.await
}
(_, path) => {
log::warn!("404 Not found: {:?}", path);
connection
.initiate_response(404, Some("Not Found"), &[("Content-Type", "text/plain")])
.await?;
connection.write_all(path.as_bytes()).await
}
};
log::error!("Request done");
r
}
}My handler logs the following: Interestingly wireshark sees the response as TCP raw bytes, and not as an HTTP stream Here's the wireshark trace for the request above: |
But in your own logs, I can see the "Request done" being printed?
As in here ^^^ ? |
|
Are you saying that - before the PR - it used to freeze before reaching "Request done"? Now - with the PR - it does NOT freeze and logs "Request done". If so, can you describe, like what happens now? This is what I still do not understand? The connection is not physically closed (the socket itself), or...? |
|
Yes. Before the PR, making a request would freeze before reaching "Request done" Now, with this PR, it does successfully send a response but Wireshark sees the response as TCP bytes (underlined in red), not HTTP. Now, with this PR, it hangs after receiving the response, as if cURL was expecting the socket to be closed.
EDIT: For context, this trace contains two requests, the first one ending with a The second request, I let it hang until it got closed by the server. |
|
Just tried this out and getting the expected behavior on connection close: Still doesn't cover my refused connections, which I came back to yesterday after the esp ran for the weekend. It seems like after a while, the http server does recover and begin accepting requests again, but I'm struggling to figure out what the issue is. esp@b887d62fc147:~/http_test$ /http_test$ curl -v http://192.16
* Trying 192.168.1.100:8881...
* Connected to 192.168.1.100 (192.168.1.100) port 8881 (#0)
> GET / HTTP/1.1
> Host: 192.168.1.100:8881
> User-Agent: curl/7.88.1
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Type: text/plain
< Connection: Keep-Alive
< Transfer-Encoding: Chunked
<
* Connection #0 to host 192.168.1.100 left intact
Hello world!esp@b887d62fc147:~/http_test$ curl -v http://192.168.1.100:8881 -H "Connection:close"
* Trying 192.168.1.100:8881...
* Connected to 192.168.1.100 (192.168.1.100) port 8881 (#0)
> GET / HTTP/1.1
> Host: 192.168.1.100:8881
> User-Agent: curl/7.88.1
> Accept: */*
> Connection:close
>
< HTTP/1.1 200 OK
< Content-Type: text/plain
< Connection: Close
<
* Closing connection 0My code is based on esp-idf though with my dependencies as [dependencies]
log = { version = "0.4", default-features = false }
esp-idf-svc = { version = "0.49", default-features = false }
edge-http = { git = "https://github.com/ivmarkov/edge-net.git", branch = "connection-type", features = [
"std",
] }
edge-nal = { git = "https://github.com/ivmarkov/edge-net.git", branch = "connection-type" }
edge-nal-std = { git = "https://github.com/ivmarkov/edge-net.git", branch = "connection-type" }
embedded-io-async = { version = "0.6", default-features = false }
futures-lite = "2.3.0"
anyhow = "1"
embassy-time = { version = "0.3.0", features = ["generic-queue"] }
futures = "*"main.rs use std::thread::Scope;
use edge_http::io::server::{Connection, DefaultServer, Handler};
use edge_http::Method;
use edge_nal::TcpBind;
use embedded_io_async::{Read, Write};
use esp_idf_svc::eventloop::EspSystemEventLoop;
use esp_idf_svc::hal::prelude::Peripherals;
use esp_idf_svc::hal::task::block_on;
use esp_idf_svc::log::EspLogger;
use esp_idf_svc::nvs::EspDefaultNvsPartition;
use esp_idf_svc::sys::EspError;
use esp_idf_svc::timer::EspTaskTimerService;
use esp_idf_svc::wifi::{AsyncWifi, AuthMethod, ClientConfiguration, Configuration, EspWifi};
use futures::executor::LocalPool;
use futures::task::LocalSpawnExt;
use futures::FutureExt;
use log::info;
const SSID: &str = "redacted";
const PASSWORD: &str = "redacted";
fn main() -> Result<(), anyhow::Error> {
// env_logger::init_from_env(
// env_logger::Env::default().filter_or(env_logger::DEFAULT_FILTER_ENV, "info"),
// );
esp_idf_svc::sys::link_patches();
esp_idf_svc::timer::embassy_time_driver::link();
esp_idf_svc::io::vfs::initialize_eventfd(5)?;
EspLogger::initialize_default();
std::thread::Builder::new()
.stack_size(60000)
.spawn(run_main)
.unwrap()
.join()
.unwrap()
.unwrap();
Ok(())
}
fn run_main() -> Result<(), anyhow::Error> {
let mut local_executor = LocalPool::new();
// let spawner = local_executor.spawner();
local_executor.spawner().spawn_local(
async move {
let _wifi = wifi_create().await?;
let mut server = DefaultServer::new();
run(&mut server).await?;
Result::<_, anyhow::Error>::Ok(())
}
.map(Result::unwrap),
)?;
local_executor.run();
log::info!("Thread execution finised ");
Ok(())
}
pub async fn run(server: &mut DefaultServer) -> Result<(), anyhow::Error> {
let addr = "0.0.0.0:8881";
info!("Running HTTP server on {addr}");
let acceptor = edge_nal_std::Stack::new()
.bind(addr.parse().unwrap())
.await?;
info!("bind");
server.run(acceptor, HttpHandler, None).await?;
info!("run");
Ok(())
}
struct HttpHandler;
impl<'b, T, const N: usize> Handler<'b, T, N> for HttpHandler
where
T: Read + Write,
T::Error: Send + Sync + std::error::Error + 'static,
{
type Error = anyhow::Error;
async fn handle(&self, conn: &mut Connection<'b, T, N>) -> Result<(), Self::Error> {
let headers = conn.headers()?;
if !matches!(headers.method, Some(Method::Get)) {
conn.initiate_response(405, Some("Method Not Allowed"), &[])
.await?;
} else if !matches!(headers.path, Some("/")) {
conn.initiate_response(404, Some("Not Found"), &[]).await?;
} else {
conn.initiate_response(200, Some("OK"), &[("Content-Type", "text/plain")])
.await?;
conn.write_all(b"Hello world!").await?;
}
Ok(())
}
}
async fn wifi_create() -> Result<esp_idf_svc::wifi::EspWifi<'static>, EspError> {
use esp_idf_svc::eventloop::*;
use esp_idf_svc::hal::prelude::Peripherals;
use esp_idf_svc::nvs::*;
use esp_idf_svc::wifi::*;
let sys_loop = EspSystemEventLoop::take()?;
let timer_service = EspTaskTimerService::new()?;
let nvs = EspDefaultNvsPartition::take()?;
let peripherals = Peripherals::take()?;
let mut esp_wifi = EspWifi::new(peripherals.modem, sys_loop.clone(), Some(nvs.clone()))?;
let mut wifi = AsyncWifi::wrap(&mut esp_wifi, sys_loop.clone(), timer_service)?;
wifi.set_configuration(&Configuration::Client(ClientConfiguration {
ssid: SSID.try_into().unwrap(),
password: PASSWORD.try_into().unwrap(),
..Default::default()
}))?;
wifi.start().await?;
info!("Wifi started");
wifi.connect().await?;
info!("Wifi connected");
wifi.wait_netif_up().await?;
info!("Wifi netif up");
Ok(esp_wifi)
} |
|
Yes, the problem is only with Though for STD we also don't call |
|
I have confirmed with the following handler that if I close the browser halfway through the async fn handle(&self, conn: &mut Connection<'b, T, N>) -> Result<(), Self::Error> {
let headers = conn.headers()?;
if !matches!(headers.method, Some(Method::Get)) {
conn.initiate_response(405, Some("Method Not Allowed"), &[])
.await?;
} else if !matches!(headers.path, Some("/")) {
conn.initiate_response(404, Some("Not Found"), &[]).await?;
} else {
conn.initiate_response(200, Some("OK"), &[("Content-Type", "text/plain")])
.await?;
for i in 0..10 {
conn.write_all(b"Hello world!").await?;
info!("i = {i}");
esp_idf_svc::hal::delay::FreeRtos::delay_ms(1000);
}
// conn.
}
Ok(())
}.[0;33mW (61655) edge_http::io::server: Handler task 0: Error when handling request: Handler(Connection reset by peer (os error 104)).[0m
.[0;32mI (61685) http_test: i = 0.[0m
.[0;32mI (62685) http_test: i = 1.[0m
.[0;32mI (63685) http_test: i = 2.[0m
.[0;33mW (64685) edge_http::io::server: Handler task 0: Error when handling request: Handler(Connection reset by peer (os error 104)).[0m
.[0;32mI (64715) http_test: i = 0.[0m
.[0;32mI (65715) http_test: i = 1.[0m
.[0;32mI (66715) http_test: i = 2.[0m
.[0;32mI (67715) http_test: i = 3.[0m
.[0;32mI (68715) http_test: i = 4.[0m
.[0;32mI (69715) http_test: i = 5.[0m
.[0;32mI (70715) http_test: i = 6.[0m
.[0;33mW (71715) edge_http::io::server: Handler task 0: Error when handling request: Handler(Connection reset by peer (os error 104)).[0m
So I really am struggling to re-create my issue in a reproducable way, but perhaps I'll point my code to this branch and see if it also helps things with the server write. I suspect that futures in rust are cancelled when they are dropped, do you have any literature on that? |
This branch is now in
TL;DR: Yes, they are. Future drop in Rust means cancellation. So futures routinely "close" stuff in their Elaboration: Anyway, I digress. I'm planning to put some "global" timeouts in the HTTP server handling code too, so whatever happens, at some point the HTTP handlers will always get un-stuck. |
|
@DaneSlattery @AnthonyGrondin There's this branch now and the corresponding PR
Also, and based on the yesterday's discussion with Dario, I hope the socket shutdown logic is as simple as it gets, and as correct as it gets (modulo trivial bugs), so once we confirm it works fine, you might want to replicate it in the |
Is it possible for a handler to be stuck during the
write_allphase of a response? Take the code below, ifconn.write_allwas writing a large buffer or over a slow connection, and the client closed the connection.Would the handler be stuck trying to
write_allforever?The text was updated successfully, but these errors were encountered: