fix(logging): load .env before building the log filter

`tracing_subscriber::fmt::init()` reads RUST_LOG when it is called, and it
was called one line before `dotenvy::dotenv()`. The systemd unit sets no
EnvironmentFile on purpose, so RUST_LOG exists only in .env: the filter was
built with no directive and fell back to its default, ERROR.

Production has logged nothing but errors since the 2026-09-20 build. On
smirk-backend, `configuration loaded` has appeared zero times since, and
the 01:53 restart today produced no application output at all. It hides
only in production, since a developer usually has RUST_LOG exported
already.

This also defeats the legacy sign-in migration's designed verification.
`LegacyDirectory::connect` deliberately connects at boot rather than per
request so an operator reads "enabled" or "staying disabled" once, in the
log. Both are `info!`, and the failure branch is a `warn!`, so all three
were being dropped exactly when we need them.

The guard asserts the ordering property and locates the two calls by
crate rather than by line, and carries a test proving it fails on the
inverted order.

Also unbreak the test targets, which have not compiled on main: `AppState`
gained `legacy` and `NewSocialTip` gained `recipient_user_id` without
their fixtures following. Both take the closed value, off and public.
This commit is contained in:
2026-09-24 20:49:47 -04:00
parent e24dd44c69
commit 73d7730c33
4 changed files with 87 additions and 1 deletions
+8 -1
View File
@@ -16,8 +16,15 @@ use smirk_backend_core::{
#[tokio::main]
async fn main() -> Result<(), Box<dyn std::error::Error>> {
tracing_subscriber::fmt::init();
// .env BEFORE the subscriber. The unit deliberately sets no EnvironmentFile,
// so RUST_LOG lives only in .env and dotenv is what puts it into the
// environment. Built first, EnvFilter sees no RUST_LOG and falls back to its
// default directive, ERROR, which silently drops every info! and warn! this
// binary emits: the boot lines an operator reads to confirm a capability came
// up, and the warnings that say why one did not. Production ran that way from
// the 2026-09-20 build until this was found.
let _ = dotenvy::dotenv();
tracing_subscriber::fmt::init();
// Fail-closed: aborts on a weak/missing/inconsistent secret. This is the env-only
// truth; the effective config below layers the validated DB overlay on top.
+3
View File
@@ -92,6 +92,9 @@ pub async fn try_app_with(mutate: impl FnOnce(&mut Config)) -> Option<TestApp> {
config: Arc::new(arc_swap::ArcSwap::from_pointee(config.clone())),
config_base: Arc::new(config),
db,
// Off in tests: the migration is a production transitional path, and a
// test that needed it would configure a legacy database of its own.
legacy: smirk_backend_core::infra::legacy_directory::LegacyDirectory::disabled(),
sessions,
chains,
payment,
+67
View File
@@ -0,0 +1,67 @@
//! The log filter must be built AFTER the environment it reads.
//!
//! `tracing_subscriber::fmt::init()` builds its `EnvFilter` from `RUST_LOG` at
//! the moment it is called. The systemd unit deliberately sets no
//! `EnvironmentFile`, so `RUST_LOG` reaches the process only when `dotenv` has
//! loaded `.env`. Initialising the subscriber first therefore leaves the filter
//! with no directive, and its default is ERROR: every `info!` and `warn!` the
//! binary emits is dropped, silently and in production only, since a developer
//! running with `RUST_LOG` already exported never sees it.
//!
//! That happened. From the 2026-09-20 build until this guard, the deployed
//! backend logged nothing but errors, which also swallowed the boot lines an
//! operator reads to confirm a capability came up.
//!
//! This asserts the ordering property, not any particular spelling of the two
//! calls: it locates them by the crate each belongs to.
const MAIN: &str = include_str!("../src/main.rs");
/// Ignore comments, so prose naming a call cannot satisfy or break the check.
fn code_only(src: &str) -> String {
src.lines()
.map(|l| match l.find("//") {
Some(i) => &l[..i],
None => l,
})
.collect::<Vec<_>>()
.join("\n")
}
#[test]
fn dotenv_runs_before_the_subscriber_is_built() {
let code = code_only(MAIN);
let dotenv = code
.find("dotenvy::")
.expect("main must load .env; without it RUST_LOG never reaches the process");
let subscriber = code
.find("tracing_subscriber::")
.expect("main must install a tracing subscriber");
assert!(
dotenv < subscriber,
"the tracing subscriber is built before dotenv loads .env, so EnvFilter \
sees no RUST_LOG and falls back to ERROR, dropping every info! and \
warn! in production. Move the dotenv call above it."
);
}
#[test]
fn the_guard_can_actually_fail() {
// A check that cannot fail proves nothing. Feed it the inverted order.
let inverted = "tracing_subscriber::fmt::init();\nlet _ = dotenvy::dotenv();";
let code = code_only(inverted);
assert!(code.find("dotenvy::") > code.find("tracing_subscriber::"));
}
#[test]
fn comments_do_not_decide_the_ordering() {
// The real main.rs carries a comment mentioning both names above the code.
// Stripping comments must leave the calls themselves in the right order.
let commented = "// dotenvy:: and tracing_subscriber:: explained here\n\
let _ = dotenvy::dotenv();\n\
tracing_subscriber::fmt::init();";
let code = code_only(commented);
assert!(code.find("dotenvy::") < code.find("tracing_subscriber::"));
}
+9
View File
@@ -124,6 +124,9 @@ async fn db_create_draft_roundtrips_all_columns() {
use smirk_backend_core::infra::db::NewSocialTip;
let enc = hex::decode("cdcd").unwrap();
let new = NewSocialTip {
// Public tip: these predate targeted tips and are claimable by whoever
// holds the share URL.
recipient_user_id: None,
sender_user_id: uid,
asset: "btc",
amount: 100_000,
@@ -227,6 +230,9 @@ async fn make_draft(
view_key: Option<&str>,
) -> uuid::Uuid {
let new = NewSocialTip {
// Public tip: these predate targeted tips and are claimable by whoever
// holds the share URL.
recipient_user_id: None,
sender_user_id: uid,
asset,
amount,
@@ -1336,6 +1342,9 @@ async fn grin_tip_db_lifecycle_columns() {
use smirk_backend_core::infra::db::NewSocialTip;
let new = NewSocialTip {
// Public tip: these predate targeted tips and are claimable by whoever
// holds the share URL.
recipient_user_id: None,
sender_user_id: uid,
asset: "grin",
amount: 500,