chj_unix_util/
logging.rs

1use std::{
2    fs::{remove_file, rename, File},
3    io::{stderr, BufRead, BufReader, Write},
4    os::{fd::FromRawFd, unix::fs::MetadataExt},
5    path::{Path, PathBuf},
6    str::FromStr,
7    sync::Arc,
8    time::SystemTime,
9};
10
11use anyhow::{anyhow, Context};
12use cj_path_util::path_util::AppendToPath;
13use nix::unistd::{close, dup2, pipe, setsid, Pid};
14
15use crate::{
16    daemon::DaemonError, eval_with_default::EvalWithDefault, file_util::open_append,
17    timestamp_formatter::TimestampFormatter, unix::easy_fork,
18};
19
20// Expecting a tab between timestamp and the rest of the line! Also,
21// expecting no slashes.
22pub fn starts_with_timestamp(line: &str) -> bool {
23    let mut digits = 0;
24    let mut minus = 0;
25    let mut plus = 0;
26    let mut t = 0;
27    let mut slash = 0;
28    let mut colon = 0;
29    let mut space = 0;
30    let mut dot = 0;
31    let mut other = 0;
32    for (i, c) in line.chars().enumerate() {
33        if i > 40 {
34            return false;
35        }
36        if c == '\t' {
37            return other <= 5
38                && digits >= 16
39                && slash == 0
40                && colon >= 2
41                && dot <= 1
42                && space <= 2
43                && minus <= 3
44                && plus <= 1
45                && t <= 1;
46        }
47        if c.is_ascii_digit() {
48            digits += 1;
49        } else if c == '-' {
50            minus += 1;
51        } else if c == ':' {
52            colon += 1;
53        } else if c == ' ' {
54            space += 1;
55        } else if c == '+' {
56            plus += 1;
57        } else if c == 'T' {
58            t += 1;
59        } else if c == '/' {
60            slash += 1;
61        } else if c == '.' {
62            dot += 1;
63        } else {
64            other += 1;
65        }
66    }
67    // found no tab
68    false
69}
70
71#[test]
72fn t_starts_with_timestamp() {
73    let cases = [
74        ("2026-01-11 15:25:12.000445551 +01:00	src/run/working_directory_pool.rs:552:17	process_working_directory D40 (None for test-running versioned dataset search at_2026-01-11T15:25:11.936345998+01:00) succeeded.", true),
75        ("2026-01-11T15:25:12.000319897+01:00	src/run/working_directory_pool.rs:552:17	process_working_directory D40 (None for test-running versioned dataset search at_2026-01-11T15:25:11.936345998+01:00) succeeded.", true),
76        ("src/run/working_directory_pool.rs:552:17	process_working_directory D40 (None for test-running versioned dataset search at_2026-01-11T15:25:11.936345998+01:00) succeeded.", false),
77    ];
78    for (s, expected) in &cases {
79        assert!(
80            starts_with_timestamp(s) == *expected,
81            "{s:?} to yield {expected:?}"
82        );
83    }
84}
85
86#[derive(Debug, Clone)]
87pub enum TimestampMode {
88    /// Always add a timestamp
89    Always,
90    /// Add a timestamp if none is found, checking each line
91    Automatic {
92        /// Whether a "," is appended to timestamps that the logger
93        /// daemon adds (could be useful if the app itself (usually)
94        /// also adds timestamps, to be able to distinguish, since
95        /// there is a time delay for the times from the logger
96        /// daemon).
97        mark_added_timestamps: bool,
98    },
99    /// Never add timestamps, assumes the application reliably adds
100    /// them
101    Never,
102}
103
104/// These settings will better be set statically by the app, rather
105/// than exposed to the user, thus not deriving clap::Args.
106#[derive(Debug, Clone)]
107pub struct TimestampOpts {
108    /// Whether rfc3339 format is to be used (default: whatever chrono
109    /// uses for `Display`).
110    pub use_rfc3339: bool,
111
112    pub mode: TimestampMode,
113}
114
115#[derive(Debug, Clone, Default, clap::Args)]
116pub struct LocalTimeOpts {
117    /// If true, write log time stamps in the local time zone (the
118    /// default depends on the application)
119    #[clap(long)]
120    pub local_time: bool,
121
122    /// If true, write log time stamps in UTC (the default depends on
123    /// the application)
124    #[clap(long)]
125    pub utc_time: bool,
126}
127
128impl EvalWithDefault for LocalTimeOpts {
129    fn explicit_yes_and_no(&self) -> (bool, bool) {
130        let Self {
131            local_time,
132            utc_time,
133        } = self;
134        (*local_time, *utc_time)
135    }
136}
137
138#[derive(Debug, Clone, Default, clap::Args)]
139pub struct LoggingOpts {
140    #[clap(flatten)]
141    pub local_time_opts: LocalTimeOpts,
142
143    /// The maximum size of the 'current.log' file in bytes before it
144    /// is renamed and a new one opened.
145    #[clap(long, default_value = "10000000")]
146    pub max_log_file_size: u64,
147
148    /// The maximum number of numbered log files (i.e. excluding
149    /// `current.log`) before the oldest are deleted.  Careful: as
150    /// many files are deleted as needed as necessary to get their
151    /// count down to the given number (giving 0 it will delete them
152    /// all)! None means, no files are ever deleted.
153    #[clap(long)]
154    pub max_log_files: Option<u32>,
155}
156
157impl LoggingOpts {
158    pub fn local_time(&self, default: bool) -> bool {
159        self.local_time_opts.eval_with_default(default)
160    }
161}
162
163pub struct Logger {
164    pub logging_opts: LoggingOpts,
165    /// What the default should be if `logging_opts` does not specify
166    /// a local_time setting (or specifies both ambiguously)
167    pub local_time_default: bool,
168    pub timestamp_opts: TimestampOpts,
169    pub dir_path: Arc<Path>,
170}
171
172impl Logger {
173    pub fn current_log_path(&self) -> PathBuf {
174        self.dir_path.append("current.log")
175    }
176
177    /// Rename the "current.log" file (if present) to "000001.log" or
178    /// similar, allocating a new number, and delete old log files if
179    /// there are more than configured.
180    pub fn rotate_logs(&self) -> anyhow::Result<()> {
181        let mut numbered_logfiles = Vec::new();
182        for entry in std::fs::read_dir(&self.dir_path)? {
183            let entry = entry?;
184            let file_name = entry.file_name();
185            if let Some(file_name) = file_name.to_str() {
186                if let Some((numstr, _)) = file_name.split_once('.') {
187                    if let Ok(num) = usize::from_str(numstr) {
188                        numbered_logfiles.push((num, entry.path()));
189                    }
190                }
191            }
192        }
193        numbered_logfiles.sort_by_key(|(num, _)| *num);
194        let last_number = numbered_logfiles.last().map(|(num, _)| *num).unwrap_or(0);
195        let new_number = last_number + 1;
196        let new_log_path = (&self.dir_path).append(&format!("{new_number:06}.log"));
197        let current_log_path = self.current_log_path();
198        match rename(&current_log_path, &new_log_path) {
199            Ok(_) => numbered_logfiles.push((new_number, new_log_path)),
200            Err(_) => (), // guess there's no file? XX look into what error it is
201        };
202        let num_numbered_logfiles = numbered_logfiles.len();
203        if let Some(max_log_files) = self.logging_opts.max_log_files {
204            let max_log_files = usize::try_from(max_log_files).expect("u32 fits in usize");
205            if num_numbered_logfiles > max_log_files {
206                let delete_n = num_numbered_logfiles - max_log_files;
207                for (_, path) in &numbered_logfiles[0..delete_n] {
208                    remove_file(path).with_context(|| anyhow!("deleting log file {path:?}"))?;
209                    // eprintln!("deleted log file {path:?}"); --ah, can't, no logging output
210                }
211            }
212        }
213        Ok(())
214    }
215
216    fn run_logger_proxy(&self, logging_r: i32, session_pid: Pid) -> anyhow::Result<()> {
217        // Put us in a new session again, to prevent the
218        // logging from being killed when the daemon is,
219        // so that we get all output and can log when the
220        // daemon goes away.
221        let _logging_session_pid = setsid()?;
222
223        // XX add a fall back to copying to stderr if
224        // logging fails (which may also happen due to
225        // disk full!)
226
227        let timestamp_formatter = TimestampFormatter {
228            use_rfc3339: self.timestamp_opts.use_rfc3339,
229            local_time: self.logging_opts.local_time(self.local_time_default),
230        };
231
232        // (Instead of BufReader and read_line, just read
233        // chunks? No, since the sending side doesn't
234        // actually buffer ~at all by default!)
235        let mut messagesfh = BufReader::new(unsafe {
236            // Safe because we're careful not to mess up
237            // with the file descriptors (we're not giving
238            // access to `messagesfh` from outside this
239            // function, and we're not calling `close` on
240            // this fd in this process)
241            File::from_raw_fd(logging_r)
242        });
243
244        let mut input_line = String::new();
245        let mut output_line = Vec::new();
246
247        let mut logfh = open_append(self.current_log_path())?;
248        let mut total_written: u64 = logfh.metadata()?.size();
249        loop {
250            input_line.clear();
251            output_line.clear();
252            let nread = messagesfh.read_line(&mut input_line)?;
253            let daemon_ended = nread == 0;
254            let (starts_with_timestamp, mark_added_timestamps) = match &self.timestamp_opts.mode {
255                TimestampMode::Always => (false, false),
256                TimestampMode::Automatic {
257                    mark_added_timestamps,
258                } => (starts_with_timestamp(&input_line), *mark_added_timestamps),
259                TimestampMode::Never => (true, false),
260            };
261            if !starts_with_timestamp {
262                let s = timestamp_formatter.format_systemtime(SystemTime::now());
263                _ = output_line.write_all(s.as_bytes());
264                if mark_added_timestamps {
265                    // The comma is used (and not e.g. the dot) since
266                    // it isn't part of double click auto-selection in
267                    // my terminal, and because it may be treated as a
268                    // column separator (together with '\t'), and
269                    // shifting column in a spreadsheet is perhaps
270                    // better for seeing the difference while allowing
271                    // the timestamps to be identical to the normal
272                    // ones for parsing.
273                    output_line.push(b',');
274                }
275                output_line.push(b'\t');
276            }
277            {
278                let tmp;
279                let rest = if daemon_ended {
280                    tmp = format!("daemon {session_pid} ended");
281                    &tmp
282                } else {
283                    input_line.trim_end()
284                };
285                _ = output_line.write_all(rest.as_bytes());
286                output_line.push(b'\n');
287            }
288
289            logfh.write_all(&output_line)?;
290            total_written += output_line.len() as u64;
291
292            if daemon_ended {
293                break;
294            }
295
296            if total_written >= self.logging_opts.max_log_file_size {
297                logfh.flush()?; // well, not buffering anyway
298                drop(logfh);
299                self.rotate_logs()?;
300                logfh = open_append(self.current_log_path())?;
301                total_written = 0;
302            }
303        }
304        logfh.flush()?; // well, not buffering anyway.
305        Ok(())
306    }
307
308    /// Fork off a logger process (it immediately starts a new unix
309    /// session to avoid being killed when the parent process group is
310    /// killed) and redirect stdout and stderr to it. `session_pid` is
311    /// denoting the daemon instance (the parent process or rather
312    /// process group), it is written to the log when the parent ends
313    /// (or closes stderr and stdout). Make sure stdout and stderr are
314    /// flushed before calling this method.
315    pub fn redirect_to_logger(self, session_pid: Pid) -> Result<(), DaemonError> {
316        // Start logging process
317        let (logging_r, logging_w) = pipe().map_err(|error| DaemonError::ErrnoError {
318            context: "pipe for logging",
319            error,
320        })?;
321
322        if let Some(_logging_pid) = easy_fork().map_err(|error| DaemonError::ErrnoError {
323            context: "forking the logger",
324            error,
325        })? {
326            // In the parent process.
327
328            // Close the reading end of the pipe that we don't
329            // use, and redirect stdout and stderr into the
330            // pipe.
331            close(logging_r).map_err(|error| DaemonError::ErrnoError {
332                context: "daemon: closing logging_r",
333                error,
334            })?;
335            dup2(logging_w, 1).map_err(|error| DaemonError::ErrnoError {
336                context: "daemon: dup to stdout",
337                error,
338            })?;
339            dup2(logging_w, 2).map_err(|error| DaemonError::ErrnoError {
340                context: "daemon: dup to stderr",
341                error,
342            })?;
343            close(logging_w).map_err(|error| DaemonError::ErrnoError {
344                context: "daemon: closing logging_w",
345                error,
346            })?;
347
348            Ok(())
349        } else {
350            // In the logging process.
351
352            // Never writing from this process, close so that
353            // we will detect when the daemon ends.
354            close(logging_w).map_err(|error| DaemonError::ErrnoError {
355                context: "logger: closing logging_w",
356                error,
357            })?;
358
359            // Also, close stdout + stderr as those might be the
360            // dup2 to another logger process, from before a
361            // re-exec.
362            _ = close(1);
363            _ = close(2);
364
365            match self.run_logger_proxy(logging_r, session_pid) {
366                Ok(()) => (),
367                Err(e) => {
368                    // Will fail because we closed stderr. XX have
369                    // some fail over logging location?
370                    _ = writeln!(
371                        &mut stderr(),
372                        "logger process: ending because of error: {e:#}"
373                    );
374                }
375            }
376            std::process::exit(0);
377        }
378    }
379}
chj_unix_util/logging.rs

chj_unix_util/
logging.rs
