diff --git a/.github/workflows/pr-build.yaml b/.github/workflows/pr-build.yaml index 4b3cbb57..fcd37c50 100644 --- a/.github/workflows/pr-build.yaml +++ b/.github/workflows/pr-build.yaml @@ -17,6 +17,11 @@ on: permissions: {} +# Only the build job checks out anything, so `gh` has no git remote to read the +# repository from and has to be told which one it is working in. +env: + GH_REPO: ${{ github.repository }} + jobs: request: name: Read the request diff --git a/crates/soar-cli/src/json2db.rs b/crates/soar-cli/src/json2db.rs index ec2d6fec..d2b3d665 100644 --- a/crates/soar-cli/src/json2db.rs +++ b/crates/soar-cli/src/json2db.rs @@ -26,7 +26,11 @@ pub fn json_to_db(input_path: &str, output_path: &str, repo_name: Option<&str>) let packages: Vec = soar_registry::parse_index(json_content.as_bytes()) .map_err(|e| SoarError::Custom(format!("parsing JSON from {}: {}", input_path, e)))?; - info!(count = packages.len(), "Parsed JSON metadata"); + // The count is both said and recorded: the message is what a reader sees, + // since info fields are the event stream's rather than the terminal's, and + // the field is what `--json` carries. + let count = packages.len(); + info!(count, "Parsed JSON metadata for {count} packages"); if packages.is_empty() { info!("No packages found in JSON file"); diff --git a/crates/soar-cli/src/logging.rs b/crates/soar-cli/src/logging.rs index 567b3dd6..eb788a63 100644 --- a/crates/soar-cli/src/logging.rs +++ b/crates/soar-cli/src/logging.rs @@ -11,19 +11,36 @@ use tracing_subscriber::{ use crate::{cli::Args, utils::Colored}; +/// Collects an event's message and the fields recorded alongside it. +/// +/// The fields are what say which repository or database a record is about, so a +/// log that drops them leaves every repetition of a message looking the same. #[derive(Default)] struct MessageVisitor { message: Option, + fields: Vec<(&'static str, String)>, } -impl tracing::field::Visit for MessageVisitor { - fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { +impl MessageVisitor { + fn record(&mut self, field: &tracing::field::Field, value: String) { if field.name() == "message" { - self.message = Some(format!("{value:?}")); + self.message = Some(value); + } else { + self.fields.push((field.name(), value)); } } } +impl tracing::field::Visit for MessageVisitor { + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + self.record(field, value.to_string()); + } + + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + self.record(field, format!("{value:?}")); + } +} + pub struct CustomFormatter; impl FormatEvent for CustomFormatter @@ -40,7 +57,8 @@ where let mut visitor = MessageVisitor::default(); event.record(&mut visitor); - match *event.metadata().level() { + let level = *event.metadata().level(); + match level { Level::TRACE => write!(writer, "{} ", Colored(Magenta, "[TRACE]")), Level::DEBUG => write!(writer, "{} ", Colored(Blue, "[DEBUG]")), Level::INFO => write!(writer, ""), @@ -49,10 +67,18 @@ where }?; if let Some(message) = visitor.message { - writeln!(writer, "{message}") - } else { - writeln!(writer) + write!(writer, "{message}")?; } + + // Info is soar's own output, where the fields carry what `--json` prints + // rather than anything a reader of the line needs appended to it. + if level != Level::INFO { + for (name, value) in visitor.fields { + write!(writer, " {}={value}", Colored(Blue, name))?; + } + } + + writeln!(writer) } } diff --git a/crates/soar-db/src/connection.rs b/crates/soar-db/src/connection.rs index cc638c8c..119df485 100644 --- a/crates/soar-db/src/connection.rs +++ b/crates/soar-db/src/connection.rs @@ -11,7 +11,7 @@ use std::{collections::HashMap, path::Path}; use diesel::{sql_query, Connection, ConnectionError, RunQueryDsl, SqliteConnection}; use tracing::{debug, trace}; -use crate::migration::{apply_migrations, migrate_json_to_jsonb, DbType}; +use crate::migration::{apply_migrations, migrate_metadata_json_to_jsonb, DbType}; /// How long to wait for another process to let go of the database. /// @@ -64,14 +64,6 @@ impl DbConnection { .map_err(|e| ConnectionError::BadConnection(e.to_string()))?; trace!("migrations applied"); - // Migrate text JSON to JSONB for core database - // Metadata databases are generated externally and migrated on fetch - if matches!(db_type, DbType::Core) { - migrate_json_to_jsonb(&mut conn, db_type) - .map_err(|e| ConnectionError::BadConnection(e.to_string()))?; - trace!("JSON to JSONB migration completed"); - } - debug!(path = %path_str, "database opened successfully"); Ok(Self { conn, @@ -134,8 +126,7 @@ impl DbConnection { prepare(&mut conn)?; - // Migrate text JSON to JSONB binary format - migrate_json_to_jsonb(&mut conn, DbType::Metadata) + migrate_metadata_json_to_jsonb(&mut conn) .map_err(|e| ConnectionError::BadConnection(e.to_string()))?; trace!("JSON to JSONB migration completed"); diff --git a/crates/soar-db/src/migration.rs b/crates/soar-db/src/migration.rs index 343ab005..46402354 100644 --- a/crates/soar-db/src/migration.rs +++ b/crates/soar-db/src/migration.rs @@ -1,7 +1,15 @@ +// `QueryableByName` expands to `Type { field: field }`, which clippy +// reports against the field it was generated from. +#![allow(clippy::redundant_field_names)] + use std::error::Error; -use diesel::{sql_query, RunQueryDsl, SqliteConnection}; +use diesel::{ + sql_query, sql_types::Integer, Connection, QueryResult, QueryableByName, RunQueryDsl, + SqliteConnection, +}; use diesel_migrations::{embed_migrations, EmbeddedMigrations, MigrationHarness}; +use tracing::trace; pub const CORE_MIGRATIONS: EmbeddedMigrations = embed_migrations!("migrations/core"); pub const METADATA_MIGRATIONS: EmbeddedMigrations = embed_migrations!("migrations/metadata"); @@ -50,90 +58,236 @@ fn mark_first_pending( Ok(()) } -/// Migrate text JSON columns to JSONB binary format. +/// The JSON columns of a published metadata database. +const METADATA_JSON_COLUMNS: [&str; 8] = [ + "licenses", + "homepages", + "notes", + "source_urls", + "categories", + "provides", + "snapshots", + "replaces", +]; + +/// The table soar writes into a metadata database once its JSON columns hold +/// JSONB, so the conversion runs once per fetched database instead of on every +/// open. /// -/// This is needed when migrating from rusqlite (which stores JSON as text) -/// to diesel (which uses SQLite's native JSONB format). +/// `user_version` is where a mark like this would otherwise go, but a published +/// database is generated elsewhere and that field belongs to whoever generated +/// it: writing to it would overwrite whatever it meant to them, and a value +/// that happened to match would leave text JSON in place with nothing to say +/// so. A table of soar's own can mean only what soar means by it. +const JSONB_MARKER_TABLE: &str = "soar_jsonb_converted"; + +#[derive(QueryableByName)] +struct Count { + #[diesel(sql_type = Integer)] + n: i32, +} + +/// Whether this database has already had its JSON columns converted. +/// +/// Read from `sqlite_master`, which answers without writing anything, so a +/// database this process cannot write is still one it can open. +fn holds_jsonb(conn: &mut SqliteConnection) -> QueryResult { + let found = sql_query(format!( + "SELECT count(*) AS n FROM sqlite_master WHERE type = 'table' AND name = '{JSONB_MARKER_TABLE}'" + )) + .get_result::(conn)?; + + Ok(found.n > 0) +} + +/// Whether a column still holds JSON as text rather than JSONB. /// -/// Handles both: -/// - Text type columns (typeof = 'text') -/// - Blob columns containing text JSON (starts with '[' or '{') +/// `json_valid` with flag 8 answers "is this definitely JSONB", and with flag 1 +/// "is this text that parses as JSON", which a blob holding text JSON also +/// satisfies. The first byte cannot tell the two apart: `5B` and `7B` open a +/// text array and object, but are equally the header of a JSONB array with a 5 +/// or 7 byte payload, so `["htop"]` re-encoded as JSONB still looks unconverted +/// to that test. Anything that is neither is left alone, since `jsonb()` would +/// only fail on it. +fn is_text_json(column: &str) -> String { + format!("{column} IS NOT NULL AND json_valid({column}, 1) AND NOT json_valid({column}, 8)") +} + +/// Convert a metadata database's text JSON columns to JSONB binary format. /// -/// # Performance Note +/// Published metadata is generated elsewhere and an older generator stores JSON +/// as text, which the queries here cannot read. Only this path still needs the +/// conversion: the core database has been written as JSONB for several releases. /// -/// This runs on every database open but is essentially a no-op after the first -/// successful migration. The WHERE clause only matches rows with text-based JSON, -/// so once all rows are converted to JSONB binary format, no rows will be updated. +/// The database records that it has been converted, so one opened again is a +/// single read of `sqlite_master` away from being left alone. /// -/// TODO: Remove this migration in a future version (v0.10 or v1.0) once users -/// have had sufficient time to migrate their databases. -pub fn migrate_json_to_jsonb( +/// Every column and the mark itself land together, so a pass that fails partway +/// leaves the database as it was rather than converted in part, and the mark can +/// never outlast the conversion it stands for. +pub fn migrate_metadata_json_to_jsonb( conn: &mut SqliteConnection, - db_type: DbType, ) -> Result> { - // Check for text type OR blob containing text JSON (starts with '[' or '{') - // Use hex comparison for blobs: 5B = '[', 7B = '{' - let json_condition = |col: &str| { - format!( - "{col} IS NOT NULL AND (typeof({col}) = 'text' OR (typeof({col}) = 'blob' AND hex(substr({col}, 1, 1)) IN ('5B', '7B')))" - ) - }; - - let queries: Vec = match db_type { - DbType::Core => { - vec![ - format!( - "UPDATE packages SET provides = jsonb(provides) WHERE {}", - json_condition("provides") - ), - format!( - "UPDATE packages SET install_patterns = jsonb(install_patterns) WHERE {}", - json_condition("install_patterns") - ), - ] - } - DbType::Metadata => { - vec![ - format!( - "UPDATE packages SET licenses = jsonb(licenses) WHERE {}", - json_condition("licenses") - ), - format!( - "UPDATE packages SET homepages = jsonb(homepages) WHERE {}", - json_condition("homepages") - ), - format!( - "UPDATE packages SET notes = jsonb(notes) WHERE {}", - json_condition("notes") - ), - format!( - "UPDATE packages SET source_urls = jsonb(source_urls) WHERE {}", - json_condition("source_urls") - ), - format!( - "UPDATE packages SET categories = jsonb(categories) WHERE {}", - json_condition("categories") - ), - format!( - "UPDATE packages SET provides = jsonb(provides) WHERE {}", - json_condition("provides") - ), - format!( - "UPDATE packages SET snapshots = jsonb(snapshots) WHERE {}", - json_condition("snapshots") - ), - format!( - "UPDATE packages SET replaces = jsonb(replaces) WHERE {}", - json_condition("replaces") - ), - ] + if holds_jsonb(conn)? { + trace!("metadata JSON columns already hold JSONB"); + return Ok(0); + } + + let total = conn.transaction(|conn| { + let mut total = 0; + for column in METADATA_JSON_COLUMNS { + trace!(column, "converting JSON column to JSONB"); + let query = format!( + "UPDATE packages SET {column} = jsonb({column}) WHERE {}", + is_text_json(column) + ); + total += sql_query(&query).execute(conn)?; } - }; - let mut total = 0; - for query in queries { - total += sql_query(&query).execute(conn)?; - } + sql_query(format!( + "CREATE TABLE IF NOT EXISTS {JSONB_MARKER_TABLE} (converted_at TEXT NOT NULL)" + )) + .execute(conn)?; + sql_query(format!( + "INSERT INTO {JSONB_MARKER_TABLE} (converted_at) VALUES (datetime('now'))" + )) + .execute(conn)?; + + QueryResult::Ok(total) + })?; Ok(total) } + +#[cfg(test)] +mod tests { + use super::*; + + #[derive(QueryableByName)] + struct UserVersion { + #[diesel(sql_type = Integer)] + user_version: i32, + } + + fn packages_db() -> SqliteConnection { + db_with_columns(&METADATA_JSON_COLUMNS) + } + + fn db_with_columns(columns: &[&str]) -> SqliteConnection { + let mut conn = SqliteConnection::establish(":memory:").unwrap(); + sql_query(format!("CREATE TABLE packages ({});", columns.join(", "))) + .execute(&mut conn) + .unwrap(); + conn + } + + fn user_version(conn: &mut SqliteConnection) -> i32 { + sql_query("PRAGMA user_version;") + .get_result::(conn) + .unwrap() + .user_version + } + + fn set_user_version(conn: &mut SqliteConnection, version: i32) { + sql_query(format!("PRAGMA user_version = {version};")) + .execute(conn) + .unwrap(); + } + + fn insert(conn: &mut SqliteConnection, licenses: &str) { + sql_query(format!( + "INSERT INTO packages (licenses) VALUES ({licenses});" + )) + .execute(conn) + .unwrap(); + } + + fn count(conn: &mut SqliteConnection, predicate: &str) -> i32 { + sql_query(format!( + "SELECT count(*) AS n FROM packages WHERE {predicate};" + )) + .get_result::(conn) + .unwrap() + .n + } + + #[test] + fn text_json_becomes_jsonb() { + let mut conn = packages_db(); + insert(&mut conn, "'[\"MIT\"]'"); + + assert_eq!(migrate_metadata_json_to_jsonb(&mut conn).unwrap(), 1); + assert_eq!(count(&mut conn, "json_valid(licenses, 8)"), 1); + } + + #[test] + fn a_jsonb_array_is_not_mistaken_for_text_json() { + // `jsonb('["htop"]')` is a five byte payload, giving it the header byte + // 5B that also opens a text array. + let mut conn = packages_db(); + insert(&mut conn, "jsonb('[\"htop\"]')"); + insert(&mut conn, "jsonb('[\"abcdef\"]')"); + + assert_eq!(migrate_metadata_json_to_jsonb(&mut conn).unwrap(), 0); + } + + #[test] + fn text_that_is_not_json_is_left_alone() { + let mut conn = packages_db(); + insert(&mut conn, "'not json at all'"); + + assert_eq!(migrate_metadata_json_to_jsonb(&mut conn).unwrap(), 0); + assert_eq!(count(&mut conn, "typeof(licenses) = 'text'"), 1); + } + + #[test] + fn a_pass_that_fails_partway_converts_nothing() { + // A database missing the column converted last: the columns before it + // convert, and then the pass fails with seven updates to undo. + let (last, rest) = METADATA_JSON_COLUMNS.split_last().unwrap(); + let mut conn = db_with_columns(rest); + insert(&mut conn, "'[\"MIT\"]'"); + + let err = migrate_metadata_json_to_jsonb(&mut conn).unwrap_err(); + assert!(err.to_string().contains(last), "unexpected error: {err}"); + assert_eq!(count(&mut conn, "typeof(licenses) = 'text'"), 1); + assert!(!holds_jsonb(&mut conn).unwrap()); + } + + #[test] + fn a_converted_database_is_left_alone() { + let mut conn = packages_db(); + insert(&mut conn, "'[\"MIT\"]'"); + + migrate_metadata_json_to_jsonb(&mut conn).unwrap(); + insert(&mut conn, "'[\"GPL-3.0\"]'"); + + // The mark says the database has been converted, so a row added + // afterwards is the writer's business rather than this migration's. + assert_eq!(migrate_metadata_json_to_jsonb(&mut conn).unwrap(), 0); + } + + #[test] + fn the_publishers_user_version_is_left_alone() { + let mut conn = packages_db(); + set_user_version(&mut conn, 7); + insert(&mut conn, "'[\"MIT\"]'"); + + assert_eq!(migrate_metadata_json_to_jsonb(&mut conn).unwrap(), 1); + assert_eq!(user_version(&mut conn), 7); + } + + #[test] + fn a_user_version_that_looks_like_a_mark_is_not_one() { + // 20260817 marked a converted database while the mark lived in + // `user_version`. A publisher is free to use that number for something + // else, and doing so must not pass for a conversion that never ran. + let mut conn = packages_db(); + set_user_version(&mut conn, 20260817); + insert(&mut conn, "'[\"MIT\"]'"); + + assert_eq!(migrate_metadata_json_to_jsonb(&mut conn).unwrap(), 1); + assert_eq!(count(&mut conn, "json_valid(licenses, 8)"), 1); + assert_eq!(user_version(&mut conn), 20260817); + } +} diff --git a/crates/soar-operations/src/context.rs b/crates/soar-operations/src/context.rs index cfe70477..fbac0ace 100644 --- a/crates/soar-operations/src/context.rs +++ b/crates/soar-operations/src/context.rs @@ -145,7 +145,11 @@ impl SoarContext { .iter() .filter(|r| r.is_enabled()) { - trace!(repo_name = repo.name, "scheduling repository sync"); + trace!( + repo_name = repo.name, + url = repo.url, + "scheduling repository sync" + ); let repo_clone = repo.clone(); let etag = self.read_repo_etag(&repo_clone); let events = self.inner.events.clone(); @@ -355,6 +359,12 @@ impl SoarContext { return None; } + trace!( + repo_name = repo.name, + url = repo.url, + path = %metadata_db.display(), + "reading stored etag" + ); let mut conn = DbConnection::open(&metadata_db, DbType::Metadata).ok()?; MetadataRepository::get_repo_etag(conn.conn()) .ok() diff --git a/crates/soar-registry/src/metadata.rs b/crates/soar-registry/src/metadata.rs index a971415d..45647bf2 100644 --- a/crates/soar-registry/src/metadata.rs +++ b/crates/soar-registry/src/metadata.rs @@ -191,7 +191,7 @@ pub async fn fetch_metadata( .map(String::from) .ok_or(RegistryError::MissingEtag)?; - debug!("Fetching metadata from {}", repo.url); + debug!(repo_name = repo.name, url = repo.url, "fetching metadata"); let content = resp .into_body()