monochromatic-git-policy-cli 0.5.33

//! 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, index_update_ms_of, 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 INDEX_UPDATE_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),
        index_update: Duration::from_millis(INDEX_UPDATE_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.index_update + 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),
        quiet: &[],
    });
}

/// 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["index_update_ms"], INDEX_UPDATE_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", "index_update_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.index_update;
    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)..]);
}

/// The answered line states the longest quiet gap of the steps that ended by themselves, and each step's gap by name, with a
///  step that was ended for being quiet kept out of the longest; a request that met no step states an empty list.
#[test]
fn the_answered_line_states_the_quiet_gaps_of_the_steps() {
    let landing: LandTiming = LandTiming::default();
    let quiet = vec![
        (String::from("git fast-import"), Duration::from_millis(300)),
        (String::from("git update-ref"), Duration::from_micros(2500)),
        (format!("git reset{}", crate::quiet_ledger::ENDED_SUFFIX), Duration::from_millis(9000)),
    ];
    let line: String = answered_line(&Answered {
        request: "r",
        reference: "refs/heads/main",
        outcome: "landed",
        batch: 1,
        size: 1,
        position: 1,
        arrival: Arrival { accepted: Instant::now(), read: Duration::ZERO },
        queued: Duration::ZERO,
        settle: Duration::ZERO,
        landing: &landing,
        land_total: Duration::ZERO,
        answer: Duration::ZERO,
        total: Duration::ZERO,
        quiet: quiet.as_slice(),
    });
    assert!(line.contains(" quiet_ms=300.000 "), "{line}");
    assert!(
        line.contains("quiet_steps=\"git fast-import=300.000;git update-ref=2.500;git reset [ended for being quiet]=9000.000\""),
        "{line}"
    );
    assert!(line_for("r", "refs/heads/main", &landing).ends_with("quiet_ms=0.000 quiet_steps=\"\""));
}

/// An `answered` line written before the index step was named by its role calls the same duration `sync_ms`: the reader of a
/// line finds it under either name, and a line that holds both (never written) is read by the new name.
#[test]
fn a_record_from_before_the_rename_still_gives_its_index_update() {
    let recorded: &str = "answered request=\"r\" branch=\"refs/heads/main\" outcome=landed batch=1 size=1 position=1 read_ms=0 queued_ms=0 settle_ms=0 \
                          lock_wait_ms=0 lock_hold_ms=21 reads_ms=2 objects_ms=3 journal_ms=1 ref_ms=2 sync_ms=19 attempts=1 landing_ms=27";
    assert_eq!(index_update_ms_of(recorded), Some(19), "the old name is read");
    let written: String = line_for("req-3", "refs/heads/main", &landing());
    assert_eq!(index_update_ms_of(written.as_str()), Some(INDEX_UPDATE_MS), "the new name is read");
    assert!(!written.contains(" sync_ms="), "the new line no longer calls the step a sync: {written}");
    let both: String = format!("{recorded} index_update_ms=5");
    assert_eq!(index_update_ms_of(both.as_str()), Some(5));
    assert_eq!(index_update_ms_of("answered request=\"r\""), None, "a line without the step gives none");
}