Use tracing.

Improved logging by using tracing and tracing-subscriber rather than
log and env_logger.

CHANGELOG.md

@@ -6,8 +6,10 @@ The format is based on
 
 ## Unreleased
 
-* Check for null bytes in autocomplete patterns, make them an bad
-  request rather than an internal server error.
+* Check for null bytes in autocomplete patterns, make them result in a
+  400 bad request rather than a 500 internal server error.
+* Improved logging by using tracing and tracing-subscriber rather than
+  log and env_logger.
 * Two more kinds of OSM area to recognize.
 * Add this changelog.
 

Cargo.toml

@@ -14,14 +14,12 @@ brotli = "3.3.0"
 chrono = "0.4.0" # Must match version used by diesel
 clap = { version = "3.2.8", features = ["derive", "terminal_size", "wrap_help", "env"] }
 dotenv = "0.15"
-env_logger = "0.9.0"
 flate2 = "1.0.14"
 image = "0.24.0"
 medallion = "2.3.1"
 kamadak-exif = "0.5.0"
 lazy-regex = "2.2.2"
 libc = "0.2.68"
-log = "0.4.8"
 mime = "0.3.0"
 r2d2-memcache = "0.6"
 rand = "0.8"
@@ -30,6 +28,8 @@ serde = { version = "1.0.0", features = ["derive"] }
 serde_json = "1.0"
 slug = "0.1"
 tokio = { version = "1.0.2", features = ["macros", "rt-multi-thread"] }
+tracing = "0.1.35"
+tracing-subscriber = { version = "0.3.14", features = ["env-filter"] }
 
 [dependencies.djangohashers]
 default-features = false

src/adm/findphotos.rs

@@ -6,8 +6,8 @@ use crate::{DbOpt, DirOpt};
 use diesel::insert_into;
 use diesel::pg::PgConnection;
 use diesel::prelude::*;
-use log::{debug, info, warn};
 use std::path::Path;
+use tracing::{debug, info, warn};
 
 #[derive(clap::Parser)]
 pub struct Findphotos {

src/adm/precache.rs

@@ -4,9 +4,9 @@ use crate::photosdir::{get_scaled_jpeg, PhotosDir};
 use crate::schema::photos::dsl::{date, is_public};
 use crate::{CacheOpt, DbOpt, DirOpt};
 use diesel::prelude::*;
-use log::{debug, info};
 use r2d2_memcache::memcache::Client;
 use std::time::{Duration, Instant};
+use tracing::{debug, info};
 
 #[derive(clap::Parser)]
 pub struct Args {

src/dbopt.rs

@@ -2,8 +2,8 @@ use crate::Error;
 use diesel::pg::PgConnection;
 use diesel::r2d2::{ConnectionManager, Pool, PooledConnection};
 use diesel::{Connection, ConnectionError};
-use log::debug;
 use std::time::{Duration, Instant};
+use tracing::debug;
 
 pub type PgPool = Pool<ConnectionManager<PgConnection>>;
 pub type PooledPg = PooledConnection<ConnectionManager<PgConnection>>;

src/fetch_places.rs

@@ -2,10 +2,10 @@ use crate::dbopt::PgPool;
 use crate::models::{Coord, Place};
 use crate::DbOpt;
 use diesel::prelude::*;
-use log::{debug, info};
 use reqwest::{self, Client, Response};
 use serde_json::Value;
 use slug::slugify;
+use tracing::{debug, info, instrument};
 
 #[derive(clap::Parser)]
 pub struct Fetchplaces {
@@ -63,6 +63,7 @@ pub struct OverpassOpt {
 }
 
 impl OverpassOpt {
+    #[instrument(skip(self, db))]
     pub async fn update_image_places(
         &self,
         db: &PgPool,
@@ -78,7 +79,7 @@ impl OverpassOpt {
             .optional()
             .map_err(|e| Error::Db(image, e))?
             .ok_or(Error::NoPosition(image))?;
-        debug!("Should get places for #{} at {:?}", image, coord);
+        debug!(?coord, "Should get places");
         let data = Client::new()
             .post(&self.overpass_url)
             .body(format!("[out:json];is_in({},{});out;", coord.x, coord.y))
@@ -270,7 +271,6 @@ fn name_and_level(obj: &Value) -> Option<(&str, i16)> {
                 .find_map(|(name, values)| tag_level(tags, name, values))
         })?;
 
-    debug!("{} is level {}", name, level);
     Some((name, level))
 }
 

src/main.rs

@@ -84,7 +84,11 @@ struct DirOpt {
 #[tokio::main]
 async fn main() {
     dotenv().ok();
-    env_logger::init();
+    tracing_subscriber::fmt()
+        .with_env_filter(
+            std::env::var("RUST_LOG").as_deref().unwrap_or("info"),
+        )
+        .init();
     match run(&RPhotos::from_args()).await {
         Ok(()) => (),
         Err(err) => {

src/myexif.rs

@@ -2,11 +2,11 @@
 use crate::adm::result::Error;
 use chrono::{Date, Local, NaiveDate, NaiveDateTime, NaiveTime, Utc};
 use exif::{Field, In, Reader, Tag, Value};
-use log::{debug, error, warn};
 use std::fs::File;
 use std::io::BufReader;
 use std::path::Path;
 use std::str::from_utf8;
+use tracing::{debug, error, warn};
 
 #[derive(Debug, Default)]
 pub struct ExifData {

src/photosdir.rs

@@ -1,12 +1,13 @@
 use crate::models::Photo;
 use crate::myexif::ExifData;
 use image::imageops::FilterType;
-use image::{self, ImageError, ImageFormat};
-use log::{debug, info, warn};
+use image::{self, DynamicImage, ImageError, ImageFormat};
 use std::ffi::OsStr;
 use std::path::{Path, PathBuf};
+use std::time::Instant;
 use std::{fs, io};
 use tokio::task::{spawn_blocking, JoinError};
+use tracing::{debug, info, warn};
 
 pub struct PhotosDir {
     basedir: PathBuf,
@@ -126,45 +127,59 @@ pub async fn get_scaled_jpeg(
     rotation: i16,
     size: u32,
 ) -> Result<Vec<u8>, ImageLoadFailed> {
-    spawn_blocking(move || {
-        info!("Should open {:?}", path);
+    spawn_blocking(move || do_get_scaled_jpeg(path, rotation, size)).await?
+}
 
-        let img = if is_jpeg(&path) {
-            use std::fs::File;
-            use std::io::BufReader;
-            let file = BufReader::new(File::open(path)?);
-            let mut decoder = image::codecs::jpeg::JpegDecoder::new(file)?;
-            decoder.scale(size as u16, size as u16)?;
-            image::DynamicImage::from_decoder(decoder)?
-        } else {
-            image::open(path)?
-        };
+#[tracing::instrument]
+fn do_get_scaled_jpeg(
+    path: PathBuf,
+    rotation: i16,
+    size: u32,
+) -> Result<Vec<u8>, ImageLoadFailed> {
+    let start = Instant::now();
+    let img = if is_jpeg(&path) {
+        use std::fs::File;
+        use std::io::BufReader;
+        let file = BufReader::new(File::open(path)?);
+        let mut decoder = image::codecs::jpeg::JpegDecoder::new(file)?;
+        decoder.scale(size as u16, size as u16)?;
+        DynamicImage::from_decoder(decoder)?
+    } else {
+        image::open(path)?
+    };
 
-        let img = if 3 * size <= img.width() || 3 * size <= img.height() {
-            info!("T-nail from {}x{} to {}", img.width(), img.height(), size);
-            img.thumbnail(size, size)
-        } else if size < img.width() || size < img.height() {
-            info!("Scaling from {}x{} to {}", img.width(), img.height(), size);
-            img.resize(size, size, FilterType::CatmullRom)
-        } else {
+    debug!(size = %Size(&img), elapsed = ?start.elapsed(), "Loaded image.");
+    let img = if 3 * size <= img.width() || 3 * size <= img.height() {
+        img.thumbnail(size, size)
+    } else if size < img.width() || size < img.height() {
+        img.resize(size, size, FilterType::CatmullRom)
+    } else {
+        img
+    };
+    debug!(size = %Size(&img), elapsed = ?start.elapsed(), "Scaled image.");
+    let img = match rotation {
+        _x @ 0..=44 | _x @ 315..=360 => img,
+        _x @ 45..=134 => img.rotate90(),
+        _x @ 135..=224 => img.rotate180(),
+        _x @ 225..=314 => img.rotate270(),
+        x => {
+            warn!("Should rotate photo {} deg, which is unsupported.", x);
             img
-        };
-        let img = match rotation {
-            _x @ 0..=44 | _x @ 315..=360 => img,
-            _x @ 45..=134 => img.rotate90(),
-            _x @ 135..=224 => img.rotate180(),
-            _x @ 225..=314 => img.rotate270(),
-            x => {
-                warn!("Should rotate photo {} deg, which is unsupported", x);
-                img
-            }
-        };
-        let mut buf = Vec::new();
-        use std::io::Cursor;
-        img.write_to(&mut Cursor::new(&mut buf), ImageFormat::Jpeg)?;
-        Ok(buf)
-    })
-    .await?
+        }
+    };
+    debug!(elapsed = ?start.elapsed(), "Ready to save.");
+    let mut buf = Vec::new();
+    use std::io::Cursor;
+    img.write_to(&mut Cursor::new(&mut buf), ImageFormat::Jpeg)?;
+    info!(elapsed = ?start.elapsed(), "Done.");
+    Ok(buf)
+}
+
+struct Size<'a>(&'a DynamicImage);
+impl<'a> std::fmt::Display for Size<'a> {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        write!(f, "{}x{}", self.0.width(), self.0.height())
+    }
 }
 
 fn is_jpeg(path: &Path) -> bool {

src/pidfiles.rs

@@ -1,10 +1,10 @@
 use crate::adm::result::Error;
 use libc::{kill, pid_t, SIGHUP};
-use log::{debug, info};
 use std::fs::{read_to_string, write};
 use std::io::ErrorKind;
 use std::path::Path;
 use std::process;
+use tracing::{debug, info};
 
 pub fn handle_pid_file(pidfile: &Path, replace: bool) -> Result<(), Error> {
     if replace {

src/server/admin.rs

@@ -3,9 +3,9 @@ use super::error::ViewResult;
 use super::{redirect_to_img, wrap, Context, Result, ViewError};
 use crate::models::{Coord, Photo, SizeTag};
 use diesel::{self, prelude::*};
-use log::{info, warn};
 use serde::Deserialize;
 use slug::slugify;
+use tracing::{info, warn};
 use warp::filters::BoxedFilter;
 use warp::http::response::Builder;
 use warp::reply::Response;

src/server/api.rs

@@ -45,7 +45,7 @@ async fn api_recover(err: Rejection) -> Result<Response, Rejection> {
     } else if err.find::<MethodNotAllowed>().is_some() {
         StatusCode::METHOD_NOT_ALLOWED
     } else {
-        log::error!("Internal server error in api from {err:?}");
+        tracing::error!("Internal server error in api from {err:?}");
         StatusCode::INTERNAL_SERVER_ERROR
     };
     let msg = code.canonical_reason().unwrap_or("error");
@@ -64,7 +64,7 @@ fn login(context: Context, form: LoginForm) -> ApiResult<LoginOk> {
     let user = form
         .validate(&db)
         .ok_or_else(|| ApiError::bad_request("login failed"))?;
-    log::info!("Api login {user:?} ok");
+    tracing::info!("Api login {user:?} ok");
     Ok(LoginOk {
         token: context.make_token(&user)?,
     })

src/server/context.rs

@@ -4,12 +4,12 @@ use crate::dbopt::{PgPool, PooledPg};
 use crate::fetch_places::OverpassOpt;
 use crate::photosdir::PhotosDir;
 use diesel::r2d2::{Pool, PooledConnection};
-use log::{debug, warn};
 use medallion::{Header, Payload, Token};
 use r2d2_memcache::MemcacheConnectionManager;
 use std::future::Future;
 use std::sync::Arc;
 use std::time::Duration;
+use tracing::{debug, warn};
 use warp::filters::{cookie, header, BoxedFilter};
 use warp::path::{self, FullPath};
 use warp::{self, Filter};

src/server/error.rs

@@ -1,7 +1,7 @@
 use super::Context;
 use crate::photosdir::ImageLoadFailed;
 use crate::templates::{self, RenderError, RenderRucte};
-use log::{error, warn};
+use tracing::{error, warn};
 use warp::http::response::Builder;
 use warp::http::status::StatusCode;
 use warp::reply::Response;

src/server/login.rs

@@ -2,8 +2,8 @@ use super::{wrap, BuilderExt, Context, ContextFilter, RenderRucte, Result};
 use crate::templates;
 use diesel::prelude::*;
 use lazy_regex::regex_is_match;
-use log::info;
 use serde::Deserialize;
+use tracing::info;
 use warp::filters::BoxedFilter;
 use warp::http::header;
 use warp::http::response::Builder;

src/server/mod.rs

@@ -30,10 +30,10 @@ use crate::pidfiles::handle_pid_file;
 use crate::templates::{self, Html, RenderRucte};
 use chrono::Datelike;
 use diesel::prelude::*;
-use log::info;
 use serde::Deserialize;
 use std::net::SocketAddr;
 use std::path::PathBuf;
+use tracing::info;
 use warp::filters::path::Tail;
 use warp::http::{header, response::Builder, StatusCode};
 use warp::reply::Response;

src/server/search.rs

@@ -11,7 +11,7 @@ use crate::templates;
 use chrono::{NaiveDate, NaiveDateTime, NaiveTime};
 use diesel::pg::PgConnection;
 use diesel::prelude::*;
-use log::warn;
+use tracing::warn;
 use warp::http::response::Builder;
 use warp::reply::Response;
 

src/server/splitlist.rs

@@ -5,7 +5,7 @@ use crate::models::{Coord, Photo};
 use crate::schema::photos;
 use diesel::pg::{Pg, PgConnection};
 use diesel::prelude::*;
-use log::debug;
+use tracing::debug;
 
 pub fn links_by_time(
     context: &Context,