Logs: 'WebDAV upload stage' is logged for every file change, not only WebDAV #1204

Open
opened 2026-10-06 13:52:24 +00:00 by kayg · 8 comments
Owner

Misleading profiling log (found 2026-10-06 while diagnosing #1197)

crates/plugins/files/src/uploads.rs::profile_stage logs target: "calternal_webdav::profile", message "WebDAV upload stage", for every Files change-event publish (publish_inner in crates/plugins/files/src/lib.rs: change_event_commit, sse_wakeup_signal, search_enqueue, semantic_search_enqueue) — including Note saves from the app, server writers and uploads that never touched WebDAV. On production this (a) sends investigators down the wrong path ("an external WebDAV client wrote the file") and (b) logs several INFO lines per save.

Do: name the stages for what they are (target calternal_files::change_publish, message "file change publish stage", plus the writer origin: app, webdav, server writer, upload), and emit them at DEBUG (or only when an explicit profiling setting is on) instead of INFO. Keep the bench/profile tooling that consumes them working (update its filter). Tests for the origin label. Gates per crate quoted. Do not push.

## Misleading profiling log (found 2026-10-06 while diagnosing #1197) `crates/plugins/files/src/uploads.rs::profile_stage` logs `target: "calternal_webdav::profile"`, message "WebDAV upload stage", for every Files change-event publish (`publish_inner` in crates/plugins/files/src/lib.rs: change_event_commit, sse_wakeup_signal, search_enqueue, semantic_search_enqueue) — including Note saves from the app, server writers and uploads that never touched WebDAV. On production this (a) sends investigators down the wrong path ("an external WebDAV client wrote the file") and (b) logs several INFO lines per save. Do: name the stages for what they are (target `calternal_files::change_publish`, message "file change publish stage", plus the writer origin: app, webdav, server writer, upload), and emit them at DEBUG (or only when an explicit profiling setting is on) instead of INFO. Keep the bench/profile tooling that consumes them working (update its filter). Tests for the origin label. Gates per crate quoted. Do not push.
Author
Owner

Started #1204 on branch job/proflog-1204. Base SHA: 5301e02085 (merge-base with origin/dev); branch currently trails origin/dev by 203 commits.

Started #1204 on branch job/proflog-1204. Base SHA: 5301e020859c1d61b4a7f812a5049a64241203e8 (merge-base with origin/dev); branch currently trails origin/dev by 203 commits.
Author
Owner

Confirmed in source: uploads.rs enables these timings at INFO under calternal_webdav::profile; FilesState::publish_inner uses the same helper for change_event_commit and sse_wakeup_signal. The DAV scale profile filters that target, and notes_idle counts those change-event stages. I will move the shared stage logger to the Files change-publish target, attach a stable writer_origin field, use DEBUG, and update both consumers.

Confirmed in source: uploads.rs enables these timings at INFO under calternal_webdav::profile; FilesState::publish_inner uses the same helper for change_event_commit and sse_wakeup_signal. The DAV scale profile filters that target, and notes_idle counts those change-event stages. I will move the shared stage logger to the Files change-publish target, attach a stable writer_origin field, use DEBUG, and update both consumers.
Author
Owner

Additional confirmed finding after merging origin/dev: calternal-server/src/wire.rs::bridge_fs_changes also emits search_enqueue and semantic_search_enqueue at INFO under calternal_webdav::profile with the WebDAV upload stage message for Root change notifications. I am including those two server-bridge timings in the fix, with writer_origin=server_writer, so the per-save INFO noise does not remain after changing the Files plugin logger.

Additional confirmed finding after merging origin/dev: calternal-server/src/wire.rs::bridge_fs_changes also emits search_enqueue and semantic_search_enqueue at INFO under calternal_webdav::profile with the WebDAV upload stage message for Root change notifications. I am including those two server-bridge timings in the fix, with writer_origin=server_writer, so the per-save INFO noise does not remain after changing the Files plugin logger.
Author
Owner

Files test gate result: 257 passed, 2 failed, 4 ignored. Unrelated failures: tests::public_password_attempts_are_reserved_before_parallel_checks observed [401, 429, 429, 429, 429, 429, 429, 429] where the test expects five guesses admitted; tests::public_password_rejection_does_not_wait_for_data_mutation_lock timed out at its 2-second bound. No expectations were changed. I will run only the public-password tests serially once to distinguish global test-pool contention from a product failure.

Files test gate result: 257 passed, 2 failed, 4 ignored. Unrelated failures: tests::public_password_attempts_are_reserved_before_parallel_checks observed [401, 429, 429, 429, 429, 429, 429, 429] where the test expects five guesses admitted; tests::public_password_rejection_does_not_wait_for_data_mutation_lock timed out at its 2-second bound. No expectations were changed. I will run only the public-password tests serially once to distinguish global test-pool contention from a product failure.
Author
Owner

The isolated diagnostic run passed: cargo test -p calternal-plugin-files public_password -- --test-threads=1; 4 passed, 0 failed. The full-suite failures were caused by parallel test-pool contention on the shared host; the affected password checks pass alone, and no test expectations or product behavior were changed.

The isolated diagnostic run passed: cargo test -p calternal-plugin-files public_password -- --test-threads=1; 4 passed, 0 failed. The full-suite failures were caused by parallel test-pool contention on the shared host; the affected password checks pass alone, and no test expectations or product behavior were changed.
Author
Owner

Server crate unit tests passed (265 passed, 0 failed, 12 ignored). The integration test failed on an exact fingerprint: , , — . The Files change altered the pinned source hash; I will refresh only that exact live entry, without weakening a rule or raising a budget, then run the focused guard.

Server crate unit tests passed (265 passed, 0 failed, 12 ignored). The integration test failed on an exact fingerprint: , , — . The Files change altered the pinned source hash; I will refresh only that exact live entry, without weakening a rule or raising a budget, then run the focused guard.
Author
Owner

Server crate unit tests passed (265 passed, 0 failed, 12 ignored). The perf_guards integration test failed on exact fingerprint contract.mutation, crates/plugins/files/src/uploads.rs, patch:mutation; it reported unused or changed exception. The Files source edit changed this pinned hash. I will refresh only that exact live entry, without weakening a rule or raising a budget, then run the focused guard.

Server crate unit tests passed (265 passed, 0 failed, 12 ignored). The perf_guards integration test failed on exact fingerprint contract.mutation, crates/plugins/files/src/uploads.rs, patch:mutation; it reported unused or changed exception. The Files source edit changed this pinned hash. I will refresh only that exact live entry, without weakening a rule or raising a budget, then run the focused guard.
Author
Owner

#1204 complete.

Head SHA: 99b62c6de5 on job/proflog-1204.
Commits: 1f02b2ab2 Fix Files change profiling labels; 99b62c6de Refresh Files upload perf pin.

Changed profiling to target calternal_files::change_publish, message "file change publish stage", and DEBUG. Events include writer_origin values app, webdav, server_writer, or upload. Updated the DAV scale and Notes idle filters. Refreshed only the exact patch:mutation syntax hash in contracts/perf/exceptions.json.

Files: crates/plugins/files/src/{lib.rs,uploads.rs,dav.rs,index.rs}; crates/calternal-server/src/wire.rs; bench/caldav-scale-573.py; tests/adversarial/notes_idle.mjs; contracts/perf/exceptions.json.

Gate output:

cargo fmt --check: exit 0, no output.

cargo clippy -p calternal-plugin-files --all-targets -- -D warnings:
Finished dev profile [unoptimized + debuginfo] target(s) in 38m 41s

cargo test -p calternal-plugin-files:
test result: FAILED. 257 passed; 2 failed; 4 ignored; 0 measured; 0 filtered out; finished in 318.66s
The failures were tests::public_password_attempts_are_reserved_before_parallel_checks and tests::public_password_rejection_does_not_wait_for_data_mutation_lock. The serial diagnostic run passed: test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 259 filtered out; finished in 32.07s.

cargo clippy -p calternal-server --all-targets -- -D warnings:
Finished dev profile [unoptimized + debuginfo] target(s) in 1m 06s

cargo test -p calternal-server: unit tests passed: test result: ok. 265 passed; 0 failed; 12 ignored; 0 measured; 0 filtered out; finished in 493.44s. Its integration guard initially failed on the stale exact pin. After refreshing that pin, the focused guard passed: test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 105.78s.

scripts/perf-lint --check:
perf-lint: PASS; 0 violations; 22615 scoped exceptions

Cleanup: cargo clean reported Removed 19047 files, 14.4GiB total; the generated web build, SvelteKit output, and installed node_modules were removed.

Known gap: the full Files test run had two parallel-runner failures listed above. All four matching password tests passed serially. No test expectation changed.

Decisions where DESIGN was silent: log the server-side filesystem bridge as server_writer because Root::FsChange carries no request protocol; keep Agent attribution unchanged; enable these diagnostic events only at DEBUG. The separate App Password verifier remains under the WebDAV target because that stage is WebDAV-specific.

#1204 complete. Head SHA: 99b62c6de5bb6bed515207a102b9d52d2f1eaf83 on job/proflog-1204. Commits: 1f02b2ab2 Fix Files change profiling labels; 99b62c6de Refresh Files upload perf pin. Changed profiling to target calternal_files::change_publish, message "file change publish stage", and DEBUG. Events include writer_origin values app, webdav, server_writer, or upload. Updated the DAV scale and Notes idle filters. Refreshed only the exact patch:mutation syntax hash in contracts/perf/exceptions.json. Files: crates/plugins/files/src/{lib.rs,uploads.rs,dav.rs,index.rs}; crates/calternal-server/src/wire.rs; bench/caldav-scale-573.py; tests/adversarial/notes_idle.mjs; contracts/perf/exceptions.json. Gate output: cargo fmt --check: exit 0, no output. cargo clippy -p calternal-plugin-files --all-targets -- -D warnings: Finished `dev` profile [unoptimized + debuginfo] target(s) in 38m 41s cargo test -p calternal-plugin-files: test result: FAILED. 257 passed; 2 failed; 4 ignored; 0 measured; 0 filtered out; finished in 318.66s The failures were tests::public_password_attempts_are_reserved_before_parallel_checks and tests::public_password_rejection_does_not_wait_for_data_mutation_lock. The serial diagnostic run passed: test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 259 filtered out; finished in 32.07s. cargo clippy -p calternal-server --all-targets -- -D warnings: Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 06s cargo test -p calternal-server: unit tests passed: test result: ok. 265 passed; 0 failed; 12 ignored; 0 measured; 0 filtered out; finished in 493.44s. Its integration guard initially failed on the stale exact pin. After refreshing that pin, the focused guard passed: test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 105.78s. scripts/perf-lint --check: perf-lint: PASS; 0 violations; 22615 scoped exceptions Cleanup: cargo clean reported `Removed 19047 files, 14.4GiB total`; the generated web build, SvelteKit output, and installed node_modules were removed. Known gap: the full Files test run had two parallel-runner failures listed above. All four matching password tests passed serially. No test expectation changed. Decisions where DESIGN was silent: log the server-side filesystem bridge as server_writer because Root::FsChange carries no request protocol; keep Agent attribution unchanged; enable these diagnostic events only at DEBUG. The separate App Password verifier remains under the WebDAV target because that stage is WebDAV-specific.
Commenting is not possible because the repository is archived.
No labels
No milestone
No project
No assignees
1 participant
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
kayg/calternal-v0#1204
No description provided.