monochromatic-git-policy-cli 0.5.25

//! What:
//!  The service's log lines:
//! the answered request,
//! the start,
//! the retire request and the exit.
//! Why:
//!  A line that loses a phase,
//! counts a stretch twice,
//! or lets a client's text break the line cannot split a slow commit;
//! the
//!  phases of one request have to add up to the time from acceptance to answer.
//!
//! In TS you'd write (pseudocode):
//! ```ts
//! // expect(fields(answeredLine(record)).queued_ms).toBe(String(queued));
//! ```

/// The lines and the phase arithmetic.
use super::{Answered, Arrival, ExitReason, LOG_PREFIX, LandTiming, SLOW_LOCK_STEP, WaitNotes, answered_line, exit_line, retire_line, stamped_line, started_line, wait_line};
use std::collections::HashMap;
use std::time::{Duration, Instant};

/// Milliseconds each phase is given in the controls;
/// all different,
/// so a field read from the wrong phase shows.
const READ_MS: u64 = 3;
const QUEUED_MS: u64 = 5;
const SETTLE_MS: u64 = 7;
const LOCK_WAIT_MS: u64 = 1_000;
const OBJECTS_MS: u64 = 13;
const JOURNAL_MS: u64 = 17;
const REF_MS: u64 = 19;
const SYNC_MS: u64 = 23;
/// How long the index lock was held in the controls' landing: the branch move and the index build, so within their sum.
const HOLD_MS: u64 = 31;
/// Time of the landing no named phase covers.
const READS_MS: u64 = 29;
const ANSWER_MS: u64 = 31;
/// The flush of the marker and the wait for the holder,
/// which the controls give other numbers than the phases.
const STAGE_MS: u64 = 37;
const PLACE_MS: u64 = 953;

/// The `key=value` words of a line (a quoted value is taken whole),
/// after the leading word.
fn fields(line: &str) -> HashMap<String, String> {
    let mut found: HashMap<String, String> = HashMap::new();
    let mut rest: &str = line.split_once(' ').map_or("", |(_, tail)| { return tail; });
    while !rest.is_empty() {
        let Some((key, after)) = rest.split_once('=') else { break };
        let (value, tail): (String, &str) = if let Some(quoted) = after.strip_prefix('"') {
            let mut end: usize = 0;
            let mut escaped: bool = false;
            for (at, character) in quoted.char_indices() {
                if escaped {
                    escaped = false;
                } else if character == '\\' {
                    escaped = true;
                } else if character == '"' {
                    end = at;
                    break;
                }
            }
            (quoted[..end].to_string(), quoted[end + 1..].trim_start())
        } else {
            let (word, tail) = after.split_once(' ').unwrap_or((after, ""));
            (word.to_string(), tail)
        };
        found.insert(key.to_string(), value);
        rest = tail;
    }
    return found;
}

/// The landing of the controls.
fn landing() -> LandTiming {
    return LandTiming {
        lock_wait: Duration::from_millis(LOCK_WAIT_MS),
        lock_holder: Some(String::from("Process 4242 (git)")),
        objects: Duration::from_millis(OBJECTS_MS),
        journal: Duration::from_millis(JOURNAL_MS),
        ref_update: Duration::from_millis(REF_MS),
        sync: Duration::from_millis(SYNC_MS),
        hold: Duration::from_millis(HOLD_MS),
        attempts: 2,
        lock_notes: WaitNotes {
            holder: Some(String::from("Process 4242 (git)")),
            found: Some(String::from("foreign no-marker size=0 age_ms=40 open_by=[4242 (git)]")),
            last: Some(String::from("service seq=7 pid=77 state=running age_ms=900")),
            looks: 4,
            staging: Duration::from_millis(STAGE_MS),
            stage_kind: "cold",
            placing: Duration::from_millis(PLACE_MS),
        },
    };
}

/// The line for the controls' request.
fn line_for(request: &str, reference: &str, landing: &LandTiming) -> String {
    let land_total: Duration = landing.lock_wait + landing.objects + landing.journal + landing.ref_update + landing.sync + Duration::from_millis(READS_MS);
    return answered_line(&Answered {
        request,
        reference,
        outcome: "landed",
        batch: 9,
        size: 3,
        position: 2,
        arrival: Arrival { accepted: Instant::now(), read: Duration::from_millis(READ_MS) },
        queued: Duration::from_millis(QUEUED_MS),
        settle: Duration::from_millis(SETTLE_MS),
        landing,
        land_total,
        answer: Duration::from_millis(ANSWER_MS),
        total: Duration::from_millis(READ_MS + QUEUED_MS + SETTLE_MS) + land_total + Duration::from_millis(ANSWER_MS),
    });
}

/// Every field states what the request met.
#[test]
fn the_answered_line_states_each_phase_of_the_wait() {
    let line: String = line_for("req-1", "refs/heads/main", &landing());
    assert!(line.starts_with("answered "), "{line}");
    assert!(!line.contains('\n'));
    let found: HashMap<String, String> = fields(line.as_str());
    assert_eq!(found["request"], "req-1");
    assert_eq!(found["branch"], "refs/heads/main");
    assert_eq!(found["outcome"], "landed");
    assert_eq!(found["batch"], "9");
    assert_eq!(found["size"], "3");
    assert_eq!(found["position"], "2");
    assert_eq!(found["read_ms"], READ_MS.to_string());
    assert_eq!(found["queued_ms"], QUEUED_MS.to_string());
    assert_eq!(found["settle_ms"], SETTLE_MS.to_string());
    assert_eq!(found["lock_wait_ms"], LOCK_WAIT_MS.to_string());
    assert_eq!(found["lock_holder"], "Process 4242 (git)");
    assert_eq!(found["reads_ms"], READS_MS.to_string());
    assert_eq!(found["objects_ms"], OBJECTS_MS.to_string());
    assert_eq!(found["journal_ms"], JOURNAL_MS.to_string());
    assert_eq!(found["ref_ms"], REF_MS.to_string());
    assert_eq!(found["sync_ms"], SYNC_MS.to_string());
    assert_eq!(found["lock_hold_ms"], HOLD_MS.to_string(), "the hold is stated, and is no phase of the landing");
    assert_eq!(found["attempts"], "2");
    assert_eq!(found["answer_ms"], ANSWER_MS.to_string());
}

/// The phases of the landing add up to its total,
/// and the request's phases to the total from acceptance to answer.
#[test]
fn the_phases_add_up_to_the_totals() {
    let found: HashMap<String, String> = fields(line_for("req-2", "refs/heads/main", &landing()).as_str());
    let number = |name: &str| -> u64 { return found[name].parse::<u64>().expect("a number"); };
    let landing_phases: u64 = ["lock_wait_ms", "reads_ms", "objects_ms", "journal_ms", "ref_ms", "sync_ms"].iter().map(|name| { return number(name); }).sum();
    assert_eq!(landing_phases, number("landing_ms"));
    let request_phases: u64 = ["read_ms", "queued_ms", "settle_ms", "landing_ms", "answer_ms"].iter().map(|name| { return number(name); }).sum();
    assert_eq!(request_phases, number("total_ms"));
}

/// A landing that waited for nobody names no holder.
#[test]
fn a_landing_with_no_holder_names_none() {
    let mut unheld: LandTiming = landing();
    unheld.lock_holder = None;
    unheld.lock_wait = Duration::ZERO;
    let line: String = line_for("req-3", "refs/heads/main", &unheld);
    assert!(!line.contains("lock_holder"), "{line}");
    assert_eq!(fields(line.as_str())["lock_wait_ms"], "0");
}

/// Text a client chose cannot end the line or hide a field.
#[test]
fn a_hostile_request_text_stays_one_line_and_reads_back() {
    let hostile: &str = "id\" outcome=forged\nanswered request=\"x";
    let reference: &str = "refs/heads/a\"b\\c\td";
    let line: String = line_for(hostile, reference, &landing());
    assert!(!line.contains('\n'), "{line}");
    assert_eq!(line.matches("outcome=").count(), 2, "the forged word is inside the quoted request: {line}");
    let found: HashMap<String, String> = fields(line.as_str());
    assert_eq!(found["outcome"], "landed");
    assert_eq!(found["request"], format!("{hostile:?}").trim_matches('"'));
}

/// The reads are what the named phases leave of the landing,
/// never negative.
#[test]
fn the_reads_are_the_remainder_of_the_landing() {
    let phases: LandTiming = landing();
    let named: Duration = phases.lock_wait + phases.objects + phases.journal + phases.ref_update + phases.sync;
    assert_eq!(phases.reads(named + Duration::from_millis(READS_MS)), Duration::from_millis(READS_MS));
    assert_eq!(phases.reads(Duration::ZERO), Duration::ZERO);
}

/// The start line names the release,
/// the protocol and the instance;
/// a development run says it serves any.
#[test]
fn the_start_line_names_release_protocol_and_instance() {
    let served: HashMap<String, String> = fields(started_line("0.5.8", 7, Some("abc123")).as_str());
    assert_eq!(served["release"], "0.5.8");
    assert_eq!(served["protocol"], "7");
    assert_eq!(served["pid"], std::process::id().to_string());
    assert_eq!(served["instance"], "abc123");
    assert_eq!(fields(started_line("0.5.8", 7, None).as_str())["instance"], "any");
}

/// The retire line names the release of the service that is asked to go.
#[test]
fn the_retire_line_names_the_release_that_retires() {
    let line: String = retire_line("0.5.7");
    assert!(line.contains("\"0.5.7\""), "{line}");
    assert!(line.starts_with("retire requested"), "{line}");
}

/// Each reason has its word,
/// and the exit line states the uptime.
#[test]
fn the_exit_line_states_reason_and_uptime() {
    let up: Duration = Duration::from_millis(READS_MS * 1_000);
    for (reason, word) in [(ExitReason::Idle, "idle"), (ExitReason::Retire, "retire"), (ExitReason::Error, "error")] {
        let found: HashMap<String, String> = fields(exit_line(reason, up).as_str());
        assert_eq!(found["reason"], word);
        assert_eq!(found["uptime_ms"], up.as_millis().to_string());
    }
    assert!(LOG_PREFIX.ends_with(": "));
}

/// The answered line says what the wait was for:
/// the flush of the marker and the wait for the holder apart,
/// how many times the lock was found held,
/// and the first and the last description of it.
#[test]
fn the_answered_line_says_what_the_wait_for_the_lock_was_for() {
    let found: HashMap<String, String> = fields(line_for("req-4", "refs/heads/main", &landing()).as_str());
    assert_eq!(found["lock_stage_ms"], STAGE_MS.to_string());
    assert_eq!(found["lock_stage_kind"], "cold");
    assert_eq!(found["lock_place_ms"], PLACE_MS.to_string());
    assert_eq!(found["lock_looks"], "4");
    assert_eq!(found["lock_found"], "foreign no-marker size=0 age_ms=40 open_by=[4242 (git)]");
    assert_eq!(found["lock_last"], "service seq=7 pid=77 state=running age_ms=900");
    let mut free: LandTiming = landing();
    free.lock_notes = WaitNotes { staging: Duration::from_millis(STAGE_MS), stage_kind: "pre", ..WaitNotes::default() };
    let line: String = line_for("req-5", "refs/heads/main", &free);
    assert_eq!(fields(line.as_str())["lock_stage_ms"], STAGE_MS.to_string(), "{line}");
    assert_eq!(fields(line.as_str())["lock_stage_kind"], "pre", "{line}");
    assert!(!line.contains("lock_found") && !line.contains("lock_looks"), "a lock that was free names no holder: {line}");
    assert!(fields(line.as_str()).contains_key("lock_place_ms"), "the placement time is always stated: {line}");
}

/// The line for the end of a wait is written when the lock was found held or a step took long,
/// and names the result;
/// a quick free lock leaves nothing.
#[test]
fn the_wait_line_is_written_for_a_held_lock_or_a_slow_step_and_not_for_a_quick_free_one() {
    let notes: WaitNotes = landing().lock_notes;
    let line: String = wait_line(7, Duration::from_millis(990), &notes, true).expect("a held lock is written down");
    assert!(line.starts_with("waited for the index lock batch=7 result=taken lock_wait_ms=990 "), "{line}");
    assert!(line.contains("lock_found=") && line.contains("lock_last="), "{line}");
    assert!(wait_line(7, Duration::from_millis(990), &notes, false).expect("refused").contains("result=refused"));
    let quick: WaitNotes = WaitNotes { staging: Duration::from_millis(3), ..WaitNotes::default() };
    assert_eq!(wait_line(8, Duration::from_millis(5), &quick, true), None);
    let slow_flush: WaitNotes = WaitNotes { staging: SLOW_LOCK_STEP, ..WaitNotes::default() };
    let slow: String = wait_line(9, SLOW_LOCK_STEP, &slow_flush, true).expect("a slow flush is written down");
    assert!(slow.contains(format!("lock_stage_ms={}", SLOW_LOCK_STEP.as_millis()).as_str()) && !slow.contains("lock_found"), "{slow}");
}

/// Every line states its own time at the end,
/// in whole milliseconds,
/// so the prefix and the first word stay where readers
/// look for them and the time survives a journal that receives the line late.
#[test]
fn a_log_line_states_its_own_time_at_its_end() {
    let line: String = stamped_line("answered request=\"r\" total_ms=3", 1_793_648_794_987);
    assert_eq!(line, format!("{LOG_PREFIX}answered request=\"r\" total_ms=3 at_ms=1793648794987\n"));
    assert_eq!(line.matches('\n').count(), 1);
}

/// What a push, a review or a server said can name a remote with a password in it; the entry carries the URL without it,
/// in the message and in a field, and the other words are as they were.
#[test]
fn the_userinfo_of_a_url_never_reaches_an_entry() {
    use crate::service_timing::capture::entries_of;
    let secret_url: &str = "https://robot:hunter2@example.invalid/r.git";
    let entries = entries_of(|| {
        crate::service_warn!("the review of abc failed: could not reach {secret_url} (status 401)");
        let _delivery = super::log_entry(crate::journald_native::Priority::Info, "x", &[("CLI_GIT_URL", secret_url.to_string())]);
    });
    assert_eq!(entries.len(), 2);
    for entry in &entries {
        assert!(!entry.message.contains("hunter2") && entry.fields.iter().all(|(_, value)| { return !value.contains("hunter2"); }), "{entry:?}");
    }
    assert!(entries[0].message.starts_with("the review of abc failed: could not reach https://<credentials>@example.invalid/r.git (status 401) at_ms="), "{}", entries[0].message);
    assert!(entries[1].fields.contains(&(String::from("CLI_GIT_URL"), String::from("https://<credentials>@example.invalid/r.git"))), "{:?}", entries[1].fields);
}

/// The macros write at the priority their name says, and the plain one at `info`.
#[test]
fn the_macros_write_at_the_priority_their_name_says() {
    use crate::journald_native::Priority;
    let entries = crate::service_timing::capture::entries_of(|| {
        crate::service_log!("a");
        crate::service_warn!("b");
        crate::service_error!("c");
    });
    assert_eq!(entries.iter().map(|entry| { return entry.priority; }).collect::<Vec<_>>(), vec![Priority::Info, Priority::Warning, Priority::Error]);
}

/// A message with a newline in it is one entry; a native entry keeps the newline, as written, and the line on standard
/// error is one line, so it cannot start a second line there.
#[test]
fn a_message_with_a_newline_is_one_entry_and_one_line_on_standard_error() {
    let entries = crate::service_timing::capture::entries_of(|| { crate::service_log!("first\nsecond"); });
    assert!(entries[0].message.starts_with("first\nsecond at_ms="), "{}", entries[0].message);
    let line: String = crate::service_timing::stamped_line(crate::journald_native::one_line("first\nsecond", crate::journald_native::MESSAGE_LIMIT).as_str(), 7);
    assert_eq!(line, format!("{}first second at_ms=7\n", crate::service_timing::LOG_PREFIX));
}

/// A cut that falls just before the `@` of a URL's userinfo must not leave the password: the text is masked whole, then cut.
#[test]
fn a_cut_just_before_the_at_sign_leaves_no_password() {
    use crate::journald_native::MESSAGE_LIMIT;
    let url_start: &str = "https://u:TOPSECRET";
    let padding: String = "p".repeat(MESSAGE_LIMIT - url_start.len());
    let entries = crate::service_timing::capture::entries_of(|| { crate::service_log!("{padding}{url_start}@host/ tail"); });
    assert!(!entries[0].message.contains("TOPSECRET"), "{}", &entries[0].message[entries[0].message.len().saturating_sub(80)..]);
}