Added debug logging option.

2024-07-07 11:36:21 +03:00 · 2024-04-26 11:44:26 +02:00 · 2024-04-26 11:44:26 +02:00 · 6b4a41e7f7
commit 6b4a41e7f7
parent 514f065e4d
13 changed files with 291 additions and 22 deletions
--- a/.github/ISSUE_TEMPLATE/bug_report.md
+++ b/.github/ISSUE_TEMPLATE/bug_report.md
@ -22,10 +22,14 @@ A clear and concise description of what you expected to happen.

 **System information:**
 - Distribution:
- - `greetd` version: 
+ - `greetd` version:
 - `tuigreet` version:
 - Installation method (from source, package, binary, etc.):
 - `tuigreet` command line:

 **Additional context**
 Add any other context about the problem here.
+
+**Debug log**
+Run `tuigreet` with the `-d [FILE]` option to log tracing information into the
+specified file, to append here.
--- a/.github/ISSUE_TEMPLATE/other-issue.md
+++ b/.github/ISSUE_TEMPLATE/other-issue.md
@ -1,10 +0,0 @@
---
-name: Other issue
-about: Feature idea, comment, anything, really
-title: ''
-labels: ''
-assignees: ''
-
---
-
-
--- a/Cargo.lock
+++ b/Cargo.lock
@ -232,6 +232,21 @@ dependencies = [
 "libc",
 ]

+[[package]]
+name = "crossbeam-channel"
+version = "0.5.12"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ab3db02a9c5b5121e1e42fbdb1aeb65f5e02624cc58c43f2884c6ccac0b82f95"
+dependencies = [
+ "crossbeam-utils",
+]
+
+[[package]]
+name = "crossbeam-utils"
+version = "0.8.19"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "248e3bacc7dc6baa3b21e405ee045c3047101a49145e7e9eca583ab4c2ca5345"
+
 [[package]]
 name = "crossterm"
 version = "0.27.0"
@ -287,6 +302,15 @@ dependencies = [
 "parking_lot_core",
 ]

+[[package]]
+name = "deranged"
+version = "0.3.11"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b42b6fa04a440b495c8b04d0e71b707c585f83cb9cb28cf8cd0d976c315e31b4"
+dependencies = [
+ "powerfmt",
+]
+
 [[package]]
 name = "digest"
 version = "0.10.7"
@ -792,6 +816,22 @@ dependencies = [
 "libc",
 ]

+[[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
+[[package]]
+name = "num-conv"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "51d515d32fb182ee37cda2ccdcb92950d6a3c2893aa280e540671c2cd0f3b1d9"
+
 [[package]]
 name = "num-traits"
 version = "0.2.18"
@ -865,6 +905,12 @@ dependencies = [
 "hashbrown",
 ]

+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "parking_lot"
 version = "0.12.1"
@ -906,6 +952,12 @@ version = "0.1.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "8b870d8c151b6f2fb93e84a13146138f05d02ed11c7e7c54f8826aaaf7c9f184"

+[[package]]
+name = "powerfmt"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391"
+
 [[package]]
 name = "ppv-lite86"
 version = "0.2.17"
@ -1198,6 +1250,15 @@ dependencies = [
 "digest",
 ]

+[[package]]
+name = "sharded-slab"
+version = "0.1.7"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "signal-hook"
 version = "0.3.17"
@ -1366,6 +1427,47 @@ dependencies = [
 "syn 2.0.60",
 ]

+[[package]]
+name = "thread_local"
+version = "1.1.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c"
+dependencies = [
+ "cfg-if",
+ "once_cell",
+]
+
+[[package]]
+name = "time"
+version = "0.3.36"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5dfd88e563464686c916c7e46e623e520ddc6d79fa6641390f2e3fa86e83e885"
+dependencies = [
+ "deranged",
+ "itoa",
+ "num-conv",
+ "powerfmt",
+ "serde",
+ "time-core",
+ "time-macros",
+]
+
+[[package]]
+name = "time-core"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ef927ca75afb808a4d64dd374f00a2adf8d0fcff8e7b184af886c3c87ec4a3f3"
+
+[[package]]
+name = "time-macros"
+version = "0.2.18"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3f252a68540fde3a3877aeea552b832b40ab9a69e318efd078774a01ddee1ccf"
+dependencies = [
+ "num-conv",
+ "time-core",
+]
+
 [[package]]
 name = "tiny-keccak"
 version = "2.0.2"
@ -1456,6 +1558,75 @@ dependencies = [
 "winnow",
 ]

+[[package]]
+name = "tracing"
+version = "0.1.40"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c3523ab5a71916ccf420eebdf5521fcef02141234bbc0b8a49f2fdc4544364ef"
+dependencies = [
+ "pin-project-lite",
+ "tracing-attributes",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-appender"
+version = "0.2.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf"
+dependencies = [
+ "crossbeam-channel",
+ "thiserror",
+ "time",
+ "tracing-subscriber",
+]
+
+[[package]]
+name = "tracing-attributes"
+version = "0.1.27"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "34704c8d6ebcbc939824180af020566b01a7c01f80641264eba0999f6c2b6be7"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn 2.0.60",
+]
+
+[[package]]
+name = "tracing-core"
+version = "0.1.32"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54"
+dependencies = [
+ "once_cell",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.2.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
+dependencies = [
+ "log",
+ "once_cell",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.18"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
+dependencies = [
+ "nu-ansi-term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
+]
+
 [[package]]
 name = "trim-in-place"
 version = "0.1.7"
@ -1482,6 +1653,9 @@ dependencies = [
 "smart-default",
 "textwrap",
 "tokio",
+ "tracing",
+ "tracing-appender",
+ "tracing-subscriber",
 "unic-langid",
 "uzers",
 "zeroize",
@ -1555,6 +1729,12 @@ dependencies = [
 "log",
 ]

+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "version_check"
 version = "0.9.4"
--- a/Cargo.toml
+++ b/Cargo.toml
@ -41,6 +41,9 @@ unic-langid = "^0.9"
 zeroize = "^1.3"
 uzers = "0.12"
 rand = "0.8.5"
+tracing-appender = "0.2.3"
+tracing-subscriber = "0.3.18"
+tracing = "0.1.40"

 [profile.release]
 lto = true
--- a/README.md
+++ b/README.md
@ -10,6 +10,8 @@ Usage: tuigreet [OPTIONS]
 Options:
    -h, --help          show this usage information
    -v, --version       print version information
+    -d, --debug [FILE]  enable debug logging to the provided file, or to
+                        /tmp/tuigreet.log
    -c, --cmd COMMAND   command to run
    -s, --sessions DIRS colon-separated list of Wayland session paths
        --session-wrapper 'CMD [ARGS]...'
--- a/contrib/man/tuigreet-1.scd
+++ b/contrib/man/tuigreet-1.scd
@ -16,6 +16,10 @@ tuigreet - A graphical console greeter for greetd
 *-v, --version*
 	Print program version and exit.

+*-d, --debug [FILE]*
+	Enables debug logging to the provided FILE path, or to /tmp/tuigreet.log if no
+	file is specified.
+
 *-c, --cmd CMD*
 	Specify which command to run on successful authentication. This can be
 	overridden by manual selection within *tuigreet*.
--- a/src/greeter.rs
+++ b/src/greeter.rs
@ -34,6 +34,7 @@ use crate::{
  },
 };

+const DEFAULT_LOG_FILE: &str = "/tmp/tuigreet.log";
 const DEFAULT_LOCALE: Locale = Locale::en_US;
 const DEFAULT_ASTERISKS_CHARS: &str = "*";
 // `startx` wants an absolute path to the executable as a first argument.
@ -91,6 +92,9 @@ impl SecretDisplay {

 #[derive(SmartDefault)]
 pub struct Greeter {
+  pub debug: bool,
+  pub logfile: String,
+
  #[default(DEFAULT_LOCALE)]
  pub locale: Locale,
  pub config: Option<Matches>,
@ -354,6 +358,7 @@ impl Greeter {

    opts.optflag("h", "help", "show this usage information");
    opts.optflag("v", "version", "print version information");
+    opts.optflagopt("d", "debug", "enable debug logging to the provided file, or to /tmp/tuigreet.log", "FILE");
    opts.optopt("c", "cmd", "command to run", "COMMAND");
    opts.optopt("s", "sessions", "colon-separated list of Wayland session paths", "DIRS");
    opts.optopt("", "session-wrapper", "wrapper command to initialize the non-X11 session", "'CMD [ARGS]...'");
@ -419,6 +424,15 @@ impl Greeter {
      }
    }

+    if self.config().opt_present("debug") {
+      self.debug = true;
+
+      self.logfile = match self.config().opt_str("debug") {
+        Some(file) => file.to_string(),
+        None => DEFAULT_LOG_FILE.to_string(),
+      }
+    }
+
    if self.config().opt_present("issue") && self.config().opt_present("greeting") {
      eprintln!("Only one of --issue and --greeting may be used at the same time");
      print_usage(opts);
@ -455,6 +469,8 @@ impl Greeter {
      let max_uid = self.config().opt_str("user-menu-max-uid").and_then(|uid| uid.parse::<u16>().ok());
      let (min_uid, max_uid) = get_min_max_uids(min_uid, max_uid);

+      tracing::info!("min/max UIDs are {}/{}", min_uid, max_uid);
+
      if min_uid >= max_uid {
        eprintln!("Minimum UID ({min_uid}) must be less than maximum UID ({max_uid})");
        process::exit(1);
@ -464,7 +480,9 @@ impl Greeter {
        title: fl!("title_users"),
        options: get_users(min_uid, max_uid),
        selected: 0,
-      }
+      };
+
+      tracing::info!("found {} users", self.users.options.len());
    }

    if self.config().opt_present("remember-session") && self.config().opt_present("remember-user-session") {
--- a/src/info.rs
+++ b/src/info.rs
@ -229,6 +229,8 @@ pub fn get_sessions(greeter: &Greeter) -> Result<Vec<Session>, Box<dyn Error>> {

  files.sort_by(|a, b| a.name.cmp(&b.name));

+  tracing::info!("found {} sessions", files.len());
+
  Ok(files)
 }

--- a/src/ipc.rs
+++ b/src/ipc.rs
@ -9,6 +9,7 @@ use tokio::sync::{
 use crate::{
  event::Event,
  info::{delete_last_user_session, delete_last_user_session_path, write_last_user_session, write_last_user_session_path, write_last_username},
+  macros::SafeDebug,
  ui::sessions::{Session, SessionSource, SessionType},
  AuthStatus, Greeter, Mode,
 };
@ -32,6 +33,8 @@ impl Ipc {
  }

  pub async fn send(&self, request: Request) {
+    tracing::info!("sending request to greetd: {}", request.safe_repr());
+
    let _ = self.0.tx.read().await.send(request).await;
  }

@ -66,6 +69,8 @@ impl Ipc {
  }

  async fn parse_response(&mut self, greeter: &mut Greeter, response: Response) -> Result<(), Box<dyn Error>> {
+    tracing::info!("received greetd message: {:?}", response);
+
    match response {
      Response::AuthMessage { auth_message_type, auth_message } => match auth_message_type {
        AuthMessageType::Secret => {
@ -107,18 +112,26 @@ impl Ipc {

      Response::Success => {
        if greeter.done {
+          tracing::info!("greetd acknowledged session start, exiting");
+
          if greeter.remember {
+            tracing::info!("caching last successful username");
+
            write_last_username(&greeter.username);

            if greeter.remember_user_session {
              match greeter.session_source {
                SessionSource::Command(ref command) => {
+                  tracing::info!("caching last user command: {command}");
+
                  write_last_user_session(&greeter.username.value, command);
                  delete_last_user_session_path(&greeter.username.value);
                }

                SessionSource::Session(index) => {
                  if let Some(Session { path: Some(session_path), .. }) = greeter.sessions.options.get(index) {
+                    tracing::info!("caching last user session: {session_path:?}");
+
                    write_last_user_session_path(&greeter.username.value, session_path);
                    delete_last_user_session(&greeter.username.value);
                  }
@ -133,6 +146,8 @@ impl Ipc {
            let _ = sender.send(Event::Exit(AuthStatus::Success)).await;
          }
        } else {
+          tracing::info!("authentication successful, starting session");
+
          let command = greeter.session_source.command(greeter).map(str::to_string);

          if let Some(command) = command {
@ -162,6 +177,8 @@ impl Ipc {
      }

      Response::Error { error_type, description } => {
+        tracing::info!("received an error from greetd: {error_type:?} - {description}");
+
        Ipc::cancel(greeter).await;

        match error_type {
@ -187,6 +204,8 @@ impl Ipc {
  }

  pub async fn cancel(greeter: &mut Greeter) {
+    tracing::info!("cancelling session");
+
    let _ = Request::CancelSession.write_to(&mut *greeter.stream().await).await;
  }
 }
--- a/src/keyboard.rs
+++ b/src/keyboard.rs
@ -367,12 +367,16 @@ async fn validate_username(greeter: &mut Greeter, ipc: &Ipc) {
  if greeter.remember_user_session {
    if let Ok(last_session) = get_last_user_session_path(&greeter.username.value) {
      if let Some(last_session) = Session::from_path(greeter, last_session).cloned() {
+        tracing::info!("remembered user session is {}", last_session.name);
+
        greeter.sessions.selected = greeter.sessions.options.iter().position(|sess| sess.path == last_session.path).unwrap_or(0);
        greeter.session_source = SessionSource::Session(greeter.sessions.selected);
      }
    }

    if let Ok(command) = get_last_user_session(&greeter.username.value) {
+      tracing::info!("remembered user command is {}", command);
+
      greeter.session_source = SessionSource::Command(command);
    }
  }
--- a/src/macros.rs
+++ b/src/macros.rs
@ -1,9 +1,26 @@
+use greetd_ipc::Request;
+
+pub trait SafeDebug {
+  fn safe_repr(&self) -> String;
+}
+
+impl SafeDebug for Request {
+  fn safe_repr(&self) -> String {
+    match self {
+      msg @ &Request::CancelSession => format!("{:?}", msg),
+      msg @ &Request::CreateSession { .. } => format!("{:?}", msg),
+      &Request::PostAuthMessageResponse { .. } => "PostAuthMessageResponse".to_string(),
+      msg @ &Request::StartSession { .. } => format!("{:?}", msg),
+    }
+  }
+}
+
 macro_rules! fl {
  ($message_id:literal) => {{
    i18n_embed_fl::fl!($crate::ui::MESSAGES, $message_id)
  }};

  ($message_id:literal, $($args:expr),*) => {{
-    i18n_embed_fl::fl!($crate::ui::MESSAGES, $message_id, $($args), *)
+    i18n_embed_fl::fl!($crate::ui::MESSAGES, $message_id, $($args),*)
  }};
 }
--- a/src/main.rs
+++ b/src/main.rs
@ -12,7 +12,7 @@ mod keyboard;
 mod power;
 mod ui;

-use std::{error::Error, io, process, sync::Arc};
+use std::{error::Error, fs::OpenOptions, io, process, sync::Arc};

 use crossterm::{
  execute,
@ -21,6 +21,7 @@ use crossterm::{
 use event::Event;
 use greetd_ipc::Request;
 use tokio::sync::RwLock;
+use tracing_appender::non_blocking::WorkerGuard;
 use tui::{backend::CrosstermBackend, Terminal};

 pub use self::greeter::*;
@ -42,6 +43,10 @@ async fn run() -> Result<(), Box<dyn Error>> {
  let mut greeter = Greeter::new(events.sender()).await;
  let mut stdout = io::stdout();

+  let _guard = init_logger(&greeter);
+
+  tracing::info!("tuigreet started");
+
  register_panic_handler();

  enable_raw_mode()?;
@ -57,6 +62,8 @@ async fn run() -> Result<(), Box<dyn Error>> {
  if greeter.remember && !greeter.username.value.is_empty() {
    greeter.working = true;

+    tracing::info!("creating remembered session for user {}", greeter.username.value);
+
    ipc
      .send(Request::CreateSession {
        username: greeter.username.value.clone(),
@ -79,6 +86,8 @@ async fn run() -> Result<(), Box<dyn Error>> {

  loop {
    if let Some(status) = greeter.read().await.exit {
+      tracing::info!("exiting main loop");
+
      return Err(status.into());
    }

@ -100,6 +109,8 @@ async fn run() -> Result<(), Box<dyn Error>> {
 }

 async fn exit(greeter: &mut Greeter, status: AuthStatus) {
+  tracing::info!("preparing exit with status {}", status);
+
  match status {
    AuthStatus::Success => {}
    AuthStatus::Cancel | AuthStatus::Failure => Ipc::cancel(greeter).await,
@ -133,14 +144,25 @@ pub fn clear_screen() {
  }
 }

-#[cfg(debug_assertions)]
-pub fn log(msg: &str) {
-  use std::io::Write;
+fn init_logger(greeter: &Greeter) -> Option<WorkerGuard> {
+  use tracing_subscriber::filter::{LevelFilter, Targets};
+  use tracing_subscriber::prelude::*;

-  let time = chrono::Utc::now();
+  let logfile = OpenOptions::new().write(true).create(true).append(true).clone();

-  let mut file = std::fs::OpenOptions::new().create(true).append(true).open("/tmp/tuigreet.log").unwrap();
-  file.write_all(format!("{:?} - ", time).as_ref()).unwrap();
-  file.write_all(msg.as_ref()).unwrap();
-  file.write_all("\n".as_bytes()).unwrap();
+  match (greeter.debug, logfile.open(&greeter.logfile)) {
+    (true, Ok(file)) => {
+      let (appender, guard) = tracing_appender::non_blocking(file);
+      let target = Targets::new().with_target("tuigreet", LevelFilter::DEBUG);
+
+      tracing_subscriber::registry()
+        .with(tracing_subscriber::fmt::layer().with_writer(appender).with_line_number(true))
+        .with(target)
+        .init();
+
+      Some(guard)
+    }
+
+    _ => None,
+  }
 }
--- a/src/power.rs
+++ b/src/power.rs
@ -61,6 +61,8 @@ pub async fn power(greeter: &mut Greeter, option: PowerOption) {
 }

 pub async fn run(greeter: &Arc<RwLock<Greeter>>, mut command: Command) {
+  tracing::info!("executing power command: {:?}", command);
+
  greeter.write().await.mode = Mode::Processing;

  let message = match command.output().await {
@ -77,6 +79,8 @@ pub async fn run(greeter: &Arc<RwLock<Greeter>>, mut command: Command) {
    Err(err) => Some(format!("{}: {err}", fl!("command_failed"))),
  };

+  tracing::info!("power command exited with: {:?}", message);
+
  let mode = greeter.read().await.previous_mode;

  let mut greeter = greeter.write().await;