investigate-dropbox-sync-issue

# Investigate a Dropbox sync issue alert ## What the alert means `app/clients/dropbox/init.js` (`validateAllBlogs`) runs at minute 0 of every hour in the **green** container. For each Dropbox blog with a `last_sync` in the last hour it takes the folder lock, does a full resync of the folder from Dropbox (`resetToBlotWithLock`), and counts how many files it had to change. If the count is > 0 the blog goes in the email (`app/helper/email/admin/DROPBOX_SYNC_ISSUE.txt`) — meaning "a full listing of Dropbox disagreed with Blot's copy, so the normal delta/webhook sync missed something (or hadn't caught up yet)". After the resync it runs `fixBlog` and a `catchUpSync`. The email is sent right after the run finishes, so its timestamp ≈ the `Sync validation complete checked=N issues=M` log line (email times are the user's local time; **logs are UTC**). The email's two backtick commands are the starting point: ``` logs green | grep "<first 12 chars of blog id> sync_" access <handle> ``` **Always confirm with the user before running anything against production, and stick to read-only commands** (see `investigate-production-container-restarts` for the SSH host/architecture background: host `blot`, helpers in the remote `~/.bashrc`, containers `blot-container-{blue,green,yellow}`). Sync/validation logs are in **green** only. ## Method Run everything as `ssh blot "docker logs blot-container-green --timestamps 2>&1 | …"`. (`logs green` is a bashrc function and lacks `--timestamps`; use `docker logs` directly so you can window by time.) Docker logs are lost when the container is recreated by a deploy, so investigate promptly and say so if the window is gone. 1. **Find the validation run that sent the alert.** The run's `issues=` is the number of blogs flagged. ``` … | grep -i 'hourly sync validation\|Sync validation complete\|Error validating' | awk '$1>"<UTC day>T<hour-2>"' ``` The run whose `complete` line is ~the email time and has `issues>=1` is yours. `Error validating sync for blog … 401/409` lines from *other* blogs in the same run are disconnected/revoked Dropbox accounts — noise, not related unless the flagged blog appears. 2. **Isolate the validation's own resync of the flagged blog.** It logs under a `sync_<id>` that immediately says `Syncing folder from Dropbox to Blot` followed by `(n/total) Checking /path …` lines. Filter the noise and keep only the actions: ``` … | grep '<blog12>' | grep -v 'Checking /\|Delta' | awk '$1>"…" && $1<"…"' ``` Look for `Removing /…`, `Downloading /…`, `Updating`, `Uploading` lines from the validation's `sync_` id — those *are* the "changes". Note the file(s) involved. 3. **Look at what happened to those file(s) just before.** grep the file name over the previous hour. Questions to answer: - Did a normal sync handle the file a few seconds/minutes earlier (`Fetched N changes` … `Finished sync`)? Was it a move/rename/draft toggle (`Removing from folder` + `Downloading <new path>` in the same sync)? - Did the total in `(n/total)` change mid-run (e.g. `n/T` then `m/T+1`)? A growing total means the user was editing Dropbox *while* validation walked the folder → race, not a missed webhook. - Was a webhook sync dropped? `Failed to acquire lock on folder` while validation held the lock is **by design** (the `catchUpSync` covers it). - Was a sync still running / stuck when validation started (`Starting sync` with no `Finished sync`)? Any slow steps (`Saving file in database` taking many seconds)? - Any `Error`, `Failed`, 401/409, `ETIMEDOUT`, container restart (`Scheduling hourly sync validation` appearing again = process restart) near the file's last change? Cross-check with the restart skill. 4. **Confirm convergence.** Look at the syncs right after (`Folder in sync with Dropbox`) and the next hourly runs (`issues=0` for that blog). If it stays flagged hour after hour, it's a real persistent divergence, not a race. 5. **Check request-level context if useful:** `access <handle>` / `req <pattern>` (bashrc helpers) for dashboard/webhook traffic around the time. 6. **Classify** as one of: - **Race with a live edit** — file moved/edited in Dropbox during the validation window, webhook sync dropped or not yet run, converged within seconds. Benign, expected occasionally. - **Missed/dropped webhook** — Dropbox changed with no corresponding `Starting sync` at all (webhook never arrived / process was down / listBlogs failed after the 200 ack — see root `TODO`). Real, needs follow-up. - **Sync bug** — a sync ran and finished but left Blot differing from Dropbox (rename/case/move handling, stuck lock, error mid-sync). - **Account/auth problem** — 401/409, revoked token, folder moved. 7. **Report** to the user in chat (identifying details are fine here, never in the committed log): blog/handle, run time (UTC + local), the file(s), the timeline, the classification and whether anything needs fixing. Don't change code unless asked; if a fix is warranted, add a compact line under "Improve Dropbox sync" in the root `TODO` (or note it for a PR). 8. **Append an entry to the Incident log below** (newest last), following the privacy rules there. Keep it to ~5 lines. Update the Method above if you learned a better query. ## Incident log Read this first: a repeated pattern changes the classification. Newest entries last. **Privacy: this file is committed to the repo, so entries must contain no customer information.** Do not write blog IDs, blog handles, domains, file names, folder/file paths, post titles, or anything else that identifies a customer or their content. Describe things generically ("a draft file was moved out of and back into a drafts folder"). Also keep out userbase/infra size numbers (e.g. how many blogs were checked). Instead, give a **precise UTC timestamp** (to the second) for the validation run start, the `complete` line and the key events, plus which container and the `sync_` IDs involved (random per-sync tokens, not customer data). A future agent can use those to re-find the incident in the logs (while the container's logs still exist) without the entry itself exposing who or what it was about. Entry template: ``` ### <date> <HH:MM:SS> UTC validation run — <classification> - Alert / trigger: … - Key events (UTC, to the second): … - Cause: … - Follow-up: … ``` ### 2026-09-19 19:00:00 UTC validation run — race with a live edit (benign) - Alert: 1 change for 1 blog, sent after the run completed at 19:05:43 UTC (green container; run started 19:00:00). - Key events (UTC): 19:02:17–19:02:23 a normal sync (`sync_aa1cebb`) applied a user moving a draft post file out of its drafts folder. 19:02:44.954 validation (`sync_c79c5d9`) took the folder lock and began its full listing. While it walked, its running file total grew by one because the user had moved the file back into the drafts folder; validation removed the moved copy from Blot, downloaded the drafts copy and re-uploaded its preview file (the 1 "change"), finishing 19:03:14.714. - The user's webhook sync (`sync_1d0485e`, 19:03:05.679) logged `Failed to acquire lock on folder` because validation held the lock — by design. The catch-up sync (`sync_43caa8d`, 19:03:14.002) re-fetched the same changes as a no-op. Blot matched Dropbox by 19:03:18; every later hourly run had `issues=0`. - Cause: not a missed webhook. Validation counts any diff as an issue, even one a queued webhook sync would deliver seconds later, and the user was actively editing (syncs every few seconds that hour). - Follow-up (not done): skip/defer blogs that synced within ~1 minute, or only alert if the diff persists on the next hourly run. Unrelated 401/409 `Error validating` lines for other blogs appeared in the same run (revoked/moved Dropbox accounts). ### 2026-09-21 15:00:00 UTC validation run — race with a live edit (benign) - Alert: 1 change for 1 blog, sent after the run completed at 15:08:49 UTC (green container; run started 15:00:00). - Key events (UTC): 15:01:18 and 15:01:27 a normal sync (`sync_61eeebe`) applied two draft-toggle renames (file renamed with a leading underscore). 15:01:41.629 validation (`sync_e6eb1b0`) took the folder lock; its running total grew 1614→1615→1616 mid-walk as the user kept editing. It removed one file and re-downloaded/saved another (the 1 "change"), finishing 15:03:11.617. - The user's webhook sync (`sync_76144f8`, 15:02:12) logged `Failed to acquire lock on folder` (by design). Catch-up sync (`sync_d28563b`, 15:03:13) re-applied the same two changes (hash matched, no re-download); in sync by 15:03:17. Further edits synced normally (15:04:12, 15:04:36). Later hourly runs completed with `issues=0` (16:00, 17:00, 19:00). - Cause: not a missed webhook; user editing during the validation walk. - Follow-up: same as the 2026-09-19 entry (defer/skip recently-synced blogs). Separately, the 18:00 and 20:00 runs never logged `complete`: the process restarted (`Scheduling hourly sync validation` at 18:03:16 and 20:01:50), so those runs were cut short — worth checking with the restart skill.