Repository: mbrubeck/agate (language: rust)

Issue:
improved logging
agate has made it onto the mailing list, but not with the best of news:
> Personally, I test locally with agate, since I can easily run it with flags and no config files [...] I used to run it on my server as well, but I switch to gmnisrv for the better logging.
> -- https://lists.orbitalfox.eu/archives/gemini/2021/004869.html

### logging IP addresses 

I think for a start it would be nice to give the **possibility of logging client IP addresses**. I am not sure if this should be enabled by default. I am not a lawyer, but to the best of my knowledge IP addresses are personal data within the meaning of the GDPR, so server admins might get in trouble if we start logging IP addresses without their knowledge, especially because previous versions did not do this. Or we could enable it by default after a **breaking version change**.

### logging format

Also it would be nice if everything that belonged to one request would be logged **on one line**. Currently a request is logged on usually two lines.
```text
[2021-01-21T22:39:00Z INFO agate] Responding with status "59 Request ended unexpectedly"
[2021-01-21T22:40:00Z INFO agate] Got request for "gemini://localhost/index.gmi"
[2021-01-21T22:40:00Z INFO agate] Responding with status "20 text/gemini;lang=en"
```
The first line was from testing how agate handles overlong request strings. Notice that the request itself is not logged.
The other two lines are from one single request. It would be nicer if this information was on one line. The theoretical problem is also that if there are simultaneous requests, you might not be able to discern from the logs which request correlates with which response, which would make it difficult for using the logging output with tools like fail2ban or other automated tools.

There is a small Problem: The start of a log line would somehow have to be transferred from within `parse_request` and used together with whatever the resulting status code and `META` might be to finish off the log line. Changing the return type is not a nice solution since this would make the `?` operator unusable within that function. Another solution might be to use a struct for handling a request, which could then store this partial log line for example. It could also store the `TlsStream`.

Any Ideas how to best implement this?


Discussion / hints:

Fix patch:
diff --git a/src/main.rs b/src/main.rs
index ef4906f..ec649f8 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -9,6 +9,7 @@ use {
         borrow::Cow,
         error::Error,
         ffi::OsStr,
+        fmt::Write,
         fs::File,
         io::BufReader,
         net::SocketAddr,
@@ -34,8 +35,14 @@ fn main() -> Result {
         loop {
             let (stream, _) = listener.accept().await?;
             tokio::spawn(async {
-                if let Err(e) = handle_request(stream).await {
-                    log::error!("{:?}", e);
+                match RequestHandle::new(stream).await {
+                    Ok(handle) => match handle.handle().await {
+                        Ok(info) => log::info!("{}", info),
+                        Err(err) => log::warn!("{}", err),
+                    },
+                    Err(log_line) => {
+                        log::warn!("{}", log_line);
+                    }
                 }
             });
         }
@@ -60,6 +67,7 @@ struct Args {
     language: Option<String>,
     silent: bool,
     serve_secret: bool,
+    log_ips: bool,
 }
 
 fn args() -> Result<Args> {
@@ -74,6 +82,7 @@ fn args() -> Result<Args> {
     opts.optflag("s", "silent", "Disable logging output");
     opts.optflag("h", "help", "Print this help menu");
     opts.optflag("", "serve-secret", "Enable serving secret files (files/directories starting with a dot)");
+    opts.optflag("", "log-ip", "Output IP addresses when logging");
 
     let matches = opts.parse(&args[1..]).map_err(|f| f.to_string())?;
     if matches.opt_present("h") {
@@ -103,6 +112,7 @@ fn args() -> Result<Args> {
         language: matches.opt_str("lang"),
         silent: matches.opt_present("s"),
         serve_secret: matches.opt_present("serve-secret"),
+        log_ips: matches.opt_present("ip"),
     })
 }
 
@@ -114,18 +124,6 @@ fn check_path(s: String) -> Result<String, String> {
     }
 }
 
-/// Handle a single client session (request + response).
-async fn handle_request(stream: TcpStream) -> Result {
-    let stream = &mut TLS.accept(stream).await?;
-
-    match parse_request(stream).await {
-        Ok(url) => send_response(url, stream).await?,
-        Err((status, msg)) => send_header(stream, status, &[msg]).await?,
-    }
-    stream.shutdown().await?;
-    Ok(())
-}
-
 /// TLS configuration.
 static TLS: Lazy<TlsAcceptor> = Lazy::new(|| acceptor().unwrap());
 
@@ -141,151 +139,220 @@ fn acceptor() -> Result<TlsAcceptor> {
     Ok(TlsAcceptor::from(Arc::new(config)))
 }
 
-/// Return the URL requested by the client.
-async fn parse_request(stream: &mut TlsStream<TcpStream>) -> std::result::Result<Url, (u8, &'static str)> {
-    // Because requests are limited to 1024 bytes (plus 2 bytes for CRLF), we
-    // can use a fixed-sized buffer on the stack, avoiding allocations and
-    // copying, and stopping bad clients from making us use too much memory.
-    let mut request = [0; 1026];
-    let mut buf = &mut request[..];
-    let mut len = 0;
+struct RequestHandle {
+    stream: TlsStream<TcpStream>,
+    log_line: String,
+}
 
-    // Read until CRLF, end-of-stream, or there's no buffer space left.
-    loop {
-        let bytes_read = stream.read(buf).await.or(Err((59, "Request ended unexpectedly")))?;
-        len += bytes_read;
-        if request[..len].ends_with(b"\r\n") {
-            break;
-        } else if bytes_read == 0 {
-            return Err((59, "Request ended unexpectedly"));
+impl RequestHandle {
+    /// Creates a new request handle for the given stream. If establishing the TLS
+    /// session fails, returns a corresponding log line.
+    async fn new(stream: TcpStream) -> Result<Self, String> {
+        let log_line = format!(
+            "{} {}",
+            stream.local_addr().unwrap(),
+            if ARGS.log_ips {
+                stream
+                    .peer_addr()
+                    .expect("could not get peer address")
+                    .to_string()
+            } else {
+                // Do not log IP address, but something else so columns still line up.
+                "-".into()
+            }
+        );
+
+        match TLS.accept(stream).await {
+            Ok(stream) => Ok(Self { stream, log_line }),
+            Err(e) => Err(format!("{} error:{}", log_line, e)),
         }
-        buf = &mut request[len..];
     }
-    let request = std::str::from_utf8(&request[..len - 2]).or(Err((59, "Non-UTF-8 request")))?;
-    log::info!("Got request for {:?}", request);
 
-    let url = Url::parse(request).or(Err((59, "Invalid URL")))?;
+    /// Do the necessary actions to handle this request. Returns a corresponding
+    /// log line as Err or Ok, depending on if the request finished with or
+    /// without errors.
+    async fn handle(mut self) -> Result<String, String> {
+        // not already in error condition
+        let result = match self.parse_request().await {
+            Ok(url) => self.send_response(url).await,
+            Err((status, msg)) => self.send_header(status, msg).await,
+        };
 
-    // Validate the URL, host and port.
-    if url.scheme() != "gemini" {
-        return Err((53, "Unsupported URL scheme"));
-    }
-    // TODO: Can be simplified by https://github.com/servo/rust-url/pull/651
-    if let (Some(Host::Domain(expected)), Some(Host::Domain(host))) = (url.host(), &ARGS.hostname) {
-        if host != expected {
-            return Err((53, "Proxy request refused"));
+        if let Err(e) = result {
+            Err(format!("{} error:{}", self.log_line, e))
+        } else if let Err(e) = self.stream.shutdown().await {
+            Err(format!("{} error:{}", self.log_line, e))
+        } else {
+            Ok(self.log_line)
         }
     }
-    if let Some(port) = url.port() {
-        // Validate that the port in the URL is the same as for the stream this request came in on.
-        if port != stream.get_ref().0.local_addr().unwrap().port() {
-            return Err((53, "proxy request refused"));
+
+    /// Return the URL requested by the client.
+    async fn parse_request(&mut self) -> std::result::Result<Url, (u8, &'static str)> {
+        // Because requests are limited to 1024 bytes (plus 2 bytes for CRLF), we
+        // can use a fixed-sized buffer on the stack, avoiding allocations and
+        // copying, and stopping bad clients from making us use too much memory.
+        let mut request = [0; 1026];
+        let mut buf = &mut request[..];
+        let mut len = 0;
+
+        // Read until CRLF, end-of-stream, or there's no buffer space left.
+        loop {
+            let bytes_read = self
+                .stream
+                .read(buf)
+                .await
+                .or(Err((59, "Request ended unexpectedly")))?;
+            len += bytes_read;
+            if request[..len].ends_with(b"\r\n") {
+                break;
+            } else if bytes_read == 0 {
+                return Err((59, "Request ended unexpectedly"));
+            }
+            buf = &mut request[len..];
         }
-    }
-    Ok(url)
-}
+        let request =
+            std::str::from_utf8(&request[..len - 2]).or(Err((59, "Non-UTF-8 request")))?;
+
+        // log literal request (might be different from or not an actual URL)
+        write!(self.log_line, " \"{}\"", request).unwrap();
 
-/// Send the client the file located at the requested URL.
-async fn send_response(url: Url, stream: &mut TlsStream<TcpStream>) -> Result {
-    let mut path = std::path::PathBuf::from(&ARGS.content_dir);
-    if let Some(segments) = url.path_segments() {
-        for segment in segments {
-            if !ARGS.serve_secret && segment.starts_with('.') {
-                // Do not serve anything that looks like a hidden file.
-                return send_header(stream, 52, &["If I told you, it would not be a secret."])
-                    .await;
+        let url = Url::parse(request).or(Err((59, "Invalid URL")))?;
+
+        // Validate the URL, host and port.
+        if url.scheme() != "gemini" {
+            return Err((53, "Unsupported URL scheme"));
+        }
+        // TODO: Can be simplified by https://github.com/servo/rust-url/pull/651
+        if let (Some(Host::Domain(expected)), Some(Host::Domain(host))) =
+            (url.host(), &ARGS.hostname)
+        {
+            if host != expected {
+                return Err((53, "Proxy request refused"));
             }
-            path.push(&*percent_decode_str(segment).decode_utf8()?);
         }
+        if let Some(port) = url.port() {
+            // Validate that the port in the URL is the same as for the stream this request came in on.
+            if port != self.stream.get_ref().0.local_addr().unwrap().port() {
+                return Err((53, "proxy request refused"));
+            }
+        }
+        Ok(url)
     }
 
-    if let Ok(metadata) = tokio::fs::metadata(&path).await {
-        if metadata.is_dir() {
-            if url.path().ends_with('/') || url.path().is_empty() {
-                // if the path ends with a slash or the path is empty, the links will work the same
-                // without a redirect
-                path.push("index.gmi");
-                if !path.exists() && path.with_file_name(".directory-listing-ok").exists() {
-                    path.pop();
-                    return list_directory(stream, &path).await;
+    /// Send the client the file located at the requested URL.
+    async fn send_response(&mut self, url: Url) -> Result {
+        let mut path = std::path::PathBuf::from(&ARGS.content_dir);
+        if let Some(segments) = url.path_segments() {
+            for segment in segments {
+                if !ARGS.serve_secret && segment.starts_with('.') {
+                    // Do not serve anything that looks like a hidden file.
+                    return self
+                        .send_header(52, "If I told you, it would not be a secret.")
+                        .await;
                 }
-            } else {
-                // if client is not redirected, links may not work as expected without trailing slash
-                let mut url = url;
-                url.set_path(&format!("{}/", url.path()));
-                return send_header(stream, 31, &[url.as_str()]).await;
+                path.push(&*percent_decode_str(segment).decode_utf8()?);
             }
         }
-    }
 
-    // Make sure the file opens successfully before sending the success header.
-    let mut file = match tokio::fs::File::open(&path).await {
-        Ok(file) => file,
-        Err(e) => {
-            send_header(stream, 51, &["Not found, sorry."]).await?;
-            Err(e)?
+        if let Ok(metadata) = tokio::fs::metadata(&path).await {
+            if metadata.is_dir() {
+                if url.path().ends_with('/') || url.path().is_empty() {
+                    // if the path ends with a slash or the path is empty, the links will work the same
+                    // without a redirect
+                    path.push("index.gmi");
+                    if !path.exists() && path.with_file_name(".directory-listing-ok").exists() {
+                        path.pop();
+                        return self.list_directory(&path).await;
+                    }
+                } else {
+                    // if client is not redirected, links may not work as expected without trailing slash
+                    let mut url = url;
+                    url.set_path(&format!("{}/", url.path()));
+                    return self.send_header(31, url.as_str()).await;
+                }
+            }
         }
-    };
 
-    // Send header.
-    if path.extension() == Some(OsStr::new("gmi")) {
-        send_text_gemini_header(stream).await?;
-    } else {
-        let mime = mime_guess::from_path(&path).first_or_octet_stream();
-        send_header(stream, 20, &[mime.essence_str()]).await?;
-    }
+        // Make sure the file opens successfully before sending the success header.
+        let mut file = match tokio::fs::File::open(&path).await {
+            Ok(file) => file,
+            Err(e) => {
+                self.send_header(51, "Not found, sorry.").await?;
+                Err(e)?
+            }
+        };
 
-    // Send body.
-    tokio::io::copy(&mut file, stream).await?;
-    Ok(())
-}
+        // Send header.
+        if path.extension() == Some(OsStr::new("gmi")) {
+            self.send_text_gemini_header().await?;
+        } else {
+            let mime = mime_guess::from_path(&path).first_or_octet_stream();
+            self.send_header(20, mime.essence_str()).await?;
+        }
+
+        // Send body.
+        tokio::io::copy(&mut file, &mut self.stream).await?;
+        Ok(())
+    }
 
-async fn list_directory(stream: &mut TlsStream<TcpStream>, path: &Path) -> Result {
-    // https://url.spec.whatwg.org/#path-percent-encode-set
-    const ENCODE_SET: AsciiSet = CONTROLS.add(b' ')
-        .add(b'"').add(b'#').add(b'<').add(b'>')
-        .add(b'?').add(b'`').add(b'{').add(b'}');
+    async fn list_directory(&mut self, path: &Path) -> Result {
+        // https://url.spec.whatwg.org/#path-percent-encode-set
+        const ENCODE_SET: AsciiSet = CONTROLS
+            .add(b' ')
+            .add(b'"')
+            .add(b'#')
+            .add(b'<')
+            .add(b'>')
+            .add(b'?')
+            .add(b'`')
+            .add(b'{')
+            .add(b'}');
 
-    log::info!("Listing directory {:?}", path);
-    send_text_gemini_header(stream).await?;
-    let mut entries = tokio::fs::read_dir(path).await?;
-    let mut lines = vec![];
-    while let Some(entry) = entries.next_entry().await? {
-        let mut name = entry.file_name().into_string().or(Err("Non-Unicode filename"))?;
-        if name.starts_with('.') {
-            continue;
+        log::info!("Listing directory {:?}", path);
+        self.send_text_gemini_header().await?;
+        let mut entries = tokio::fs::read_dir(path).await?;
+        let mut lines = vec![];
+        while let Some(entry) = entries.next_entry().await? {
+            let mut name = entry
+                .file_name()
+                .into_string()
+                .or(Err("Non-Unicode filename"))?;
+            if name.starts_with('.') {
+                continue;
+            }
+            if entry.file_type().await?.is_dir() {
+                name += "/";
+            }
+            let line = match percent_encode(name.as_bytes(), &ENCODE_SET).into() {
+                Cow::Owned(url) => format!("=> {} {}\n", url, name),
+                Cow::Borrowed(url) => format!("=> {}\n", url), // url and name are identical
+            };
+            lines.push(line);
         }
-        if entry.file_type().await?.is_dir() {
-            name += "/";
+        lines.sort();
+        for line in lines {
+            self.stream.write_all(line.as_bytes()).await?;
         }
-        let line = match percent_encode(name.as_bytes(), &ENCODE_SET).into() {
-            Cow::Owned(url) => format!("=> {} {}\n", url, name),
-            Cow::Borrowed(url) => format!("=> {}\n", url), // url and name are identical
-        };
-        lines.push(line);
-    }
-    lines.sort();
-    for line in lines {
-        stream.write_all(line.as_bytes()).await?;
+        Ok(())
     }
-    Ok(())
-}
 
-async fn send_header(stream: &mut TlsStream<TcpStream>, status: u8, meta: &[&str]) -> Result {
-    use std::fmt::Write;
-    let mut response = String::with_capacity(64);
-    write!(response, "{} ", status)?;
-    response.extend(meta.iter().copied());
-    log::info!("Responding with status {:?}", response);
-    response.push_str("\r\n");
-    stream.write_all(response.as_bytes()).await?;
-    Ok(())
-}
+    async fn send_header(&mut self, status: u8, meta: &str) -> Result {
+        // add response status and response meta
+        write!(self.log_line, " {} \"{}\"", status, meta)?;
 
-async fn send_text_gemini_header(stream: &mut TlsStream<TcpStream>) -> Result {
-    if let Some(lang) = ARGS.language.as_deref() {
-        send_header(stream, 20, &["text/gemini;lang=", lang]).await
-    } else {
-        send_header(stream, 20, &["text/gemini"]).await
+        self.stream
+            .write_all(format!("{} {}\r\n", status, meta).as_bytes())
+            .await?;
+        Ok(())
+    }
+
+    async fn send_text_gemini_header(&mut self) -> Result {
+        if let Some(lang) = ARGS.language.as_deref() {
+            self.send_header(20, &format!("text/gemini;lang={}", lang))
+                .await
+        } else {
+            self.send_header(20, "text/gemini").await
+        }
     }
 }


Test patch: