From 6fec2455d87afce26ef0ae785ad9b51a461ca283 Mon Sep 17 00:00:00 2001 From: Sung Date: Sun, 26 Oct 2025 09:54:55 -0700 Subject: [PATCH] Add debug logs --- pkg/cli/client/client.go | 4 +- pkg/cli/cmd/sync/sync.go | 155 +++++++++++++++++++++++++++++++- pkg/cli/infra/init.go | 2 +- pkg/cli/log/log.go | 19 +++- pkg/cli/migrate/migrate.go | 2 +- pkg/server/controllers/notes.go | 2 +- 6 files changed, 175 insertions(+), 9 deletions(-) diff --git a/pkg/cli/client/client.go b/pkg/cli/client/client.go index 1e122a3d..3fea9d21 100644 --- a/pkg/cli/client/client.go +++ b/pkg/cli/client/client.go @@ -176,7 +176,7 @@ func doReq(ctx context.DnoteCtx, method, path, body string, options *requestOpti return nil, errors.Wrap(err, "getting request") } - log.Debug("HTTP request: %+v\n", req) + log.Debug("HTTP %s %s\n", method, path) hc := getHTTPClient(ctx, options) res, err := hc.Do(req) @@ -184,7 +184,7 @@ func doReq(ctx context.DnoteCtx, method, path, body string, options *requestOpti return res, errors.Wrap(err, "making http request") } - log.Debug("HTTP response: %+v\n", res) + log.Debug("HTTP %d %s\n", res.StatusCode, res.Status) if err = checkRespErr(res); err != nil { return res, errors.Wrap(err, "server responded with an error") diff --git a/pkg/cli/cmd/sync/sync.go b/pkg/cli/cmd/sync/sync.go index 8ce08282..fcfc31fd 100644 --- a/pkg/cli/cmd/sync/sync.go +++ b/pkg/cli/cmd/sync/sync.go @@ -186,11 +186,68 @@ func getSyncFragments(ctx context.DnoteCtx, afterUSN int) ([]client.SyncFragment } } - log.Debug("received sync fragments: %+v\n", buf) + log.Debug("received sync fragments: %+v\n", redactSyncFragments(buf)) return buf, nil } +// redactSyncFragments returns a deep copy of sync fragments with sensitive fields (note body, book label) removed for safe logging +func redactSyncFragments(fragments []client.SyncFragment) []client.SyncFragment { + redacted := make([]client.SyncFragment, len(fragments)) + for i, frag := range fragments { + // Create new notes with redacted bodies + notes := make([]client.SyncFragNote, len(frag.Notes)) + for j, note := range frag.Notes { + notes[j] = client.SyncFragNote{ + UUID: note.UUID, + BookUUID: note.BookUUID, + USN: note.USN, + CreatedAt: note.CreatedAt, + UpdatedAt: note.UpdatedAt, + AddedOn: note.AddedOn, + EditedOn: note.EditedOn, + Body: func() string { + if note.Body != "" { + return "" + } + return "" + }(), + Deleted: note.Deleted, + } + } + + // Create new books with redacted labels + books := make([]client.SyncFragBook, len(frag.Books)) + for j, book := range frag.Books { + books[j] = client.SyncFragBook{ + UUID: book.UUID, + USN: book.USN, + CreatedAt: book.CreatedAt, + UpdatedAt: book.UpdatedAt, + AddedOn: book.AddedOn, + Label: func() string { + if book.Label != "" { + return "" + } + return "" + }(), + Deleted: book.Deleted, + } + } + + redacted[i] = client.SyncFragment{ + FragMaxUSN: frag.FragMaxUSN, + UserMaxUSN: frag.UserMaxUSN, + CurrentTime: frag.CurrentTime, + Notes: notes, + Books: books, + ExpungedNotes: frag.ExpungedNotes, + ExpungedBooks: frag.ExpungedBooks, + } + } + return redacted +} + // resolveLabel resolves a book label conflict by repeatedly appending an increasing integer // to the label until it finds a unique label. It returns the first non-conflicting label. func resolveLabel(tx *database.DB, label string) (string, error) { @@ -546,6 +603,8 @@ func fullSync(ctx context.DnoteCtx, tx *database.DB) error { log.Debug("performing a full sync\n") log.Info("resolving delta.") + log.DebugNewline() + list, err := getSyncList(ctx, 0) if err != nil { return errors.Wrap(err, "getting sync list") @@ -553,6 +612,8 @@ func fullSync(ctx context.DnoteCtx, tx *database.DB) error { fmt.Printf(" (total %d).", list.getLength()) + log.DebugNewline() + // clean resources that are in erroneous states if err := cleanLocalNotes(tx, &list); err != nil { return errors.Wrap(err, "cleaning up local notes") @@ -598,6 +659,8 @@ func stepSync(ctx context.DnoteCtx, tx *database.DB, afterUSN int) error { log.Info("resolving delta.") + log.DebugNewline() + list, err := getSyncList(ctx, afterUSN) if err != nil { return errors.Wrap(err, "getting sync list") @@ -757,9 +820,91 @@ func sendBooks(ctx context.DnoteCtx, tx *database.DB) (bool, error) { return isBehind, nil } +// findOrphanedNotes returns a list of all orphaned notes +func findOrphanedNotes(db *database.DB) (int, []struct{ noteUUID, bookUUID string }, error) { + var orphanCount int + err := db.QueryRow(` + SELECT COUNT(*) FROM notes n + WHERE NOT EXISTS ( + SELECT 1 FROM books b + WHERE b.uuid = n.book_uuid + AND NOT b.deleted + ) + `).Scan(&orphanCount) + if err != nil { + return 0, nil, err + } + + if orphanCount == 0 { + return 0, nil, nil + } + + rows, err := db.Query(` + SELECT n.uuid, n.book_uuid + FROM notes n + WHERE NOT EXISTS ( + SELECT 1 FROM books b + WHERE b.uuid = n.book_uuid + AND NOT b.deleted + ) + `) + if err != nil { + return orphanCount, nil, err + } + defer rows.Close() + + var orphans []struct{ noteUUID, bookUUID string } + for rows.Next() { + var noteUUID, bookUUID string + if err := rows.Scan(¬eUUID, &bookUUID); err != nil { + continue + } + orphans = append(orphans, struct{ noteUUID, bookUUID string }{noteUUID, bookUUID}) + } + + return orphanCount, orphans, nil +} + +func warnOrphanedNotes(tx *database.DB) { + count, orphans, err := findOrphanedNotes(tx) + if err != nil { + log.Debug("error checking orphaned notes: %v\n", err) + return + } + + if count == 0 { + return + } + + log.Debug("Found %d orphaned notes (book doesn't exist locally):\n", count) + for _, o := range orphans { + log.Debug("note %s (book %s)\n", o.noteUUID, o.bookUUID) + } +} + +// checkPostSyncIntegrity checks for data integrity issues after sync and warns the user +func checkPostSyncIntegrity(db *database.DB) { + count, orphans, err := findOrphanedNotes(db) + if err != nil { + log.Debug("error checking orphaned notes: %v\n", err) + return + } + + if count == 0 { + return + } + + log.Warnf("Found %d orphaned notes (referencing non-existent or deleted books):\n", count) + for _, o := range orphans { + log.Plainf(" - note %s (missing book: %s)\n", o.noteUUID, o.bookUUID) + } +} + func sendNotes(ctx context.DnoteCtx, tx *database.DB) (bool, error) { isBehind := false + warnOrphanedNotes(tx) + rows, err := tx.Query("SELECT uuid, book_uuid, body, deleted, usn, added_on FROM notes WHERE dirty") if err != nil { return isBehind, errors.Wrap(err, "getting syncable notes") @@ -773,7 +918,7 @@ func sendNotes(ctx context.DnoteCtx, tx *database.DB) (bool, error) { return isBehind, errors.Wrap(err, "scanning a syncable note") } - log.Debug("sending note %s\n", note.UUID) + log.Debug("sending note %s (book: %s)\n", note.UUID, note.BookUUID) var respUSN int @@ -790,7 +935,7 @@ func sendNotes(ctx context.DnoteCtx, tx *database.DB) (bool, error) { } else { resp, err := client.CreateNote(ctx, note.BookUUID, note.Body) if err != nil { - log.Debug("error creating note (will retry after stepSync): %v\n", err) + log.Debug("failed to create note %s (book: %s): %v\n", note.UUID, note.BookUUID, err) isBehind = true continue } @@ -867,6 +1012,8 @@ func sendChanges(ctx context.DnoteCtx, tx *database.DB) (bool, error) { fmt.Printf(" (total %d).", delta) + log.DebugNewline() + behind1, err := sendBooks(ctx, tx) if err != nil { return behind1, errors.Wrap(err, "sending books") @@ -1080,6 +1227,8 @@ func newRun(ctx context.DnoteCtx) infra.RunEFunc { log.Success("success\n") + checkPostSyncIntegrity(ctx.DB) + if err := upgrade.Check(ctx); err != nil { log.Error(errors.Wrap(err, "automatically checking updates").Error()) } diff --git a/pkg/cli/infra/init.go b/pkg/cli/infra/init.go index 1e572cf7..b87cfdd4 100644 --- a/pkg/cli/infra/init.go +++ b/pkg/cli/infra/init.go @@ -137,7 +137,7 @@ func Init(versionTag, apiEndpoint, dbPath string) (*context.DnoteCtx, error) { return nil, errors.Wrap(err, "setting up the context") } - log.Debug("Running with Dnote context: %+v\n", context.Redact(ctx)) + log.Debug("context: %+v\n", context.Redact(ctx)) return &ctx, nil } diff --git a/pkg/cli/log/log.go b/pkg/cli/log/log.go index 36c8cdd1..dc78e2b4 100644 --- a/pkg/cli/log/log.go +++ b/pkg/cli/log/log.go @@ -25,6 +25,11 @@ import ( "github.com/fatih/color" ) +const ( + debugEnvName = "DNOTE_DEBUG" + debugEnvValue = "1" +) + var ( // ColorRed is a red foreground color ColorRed = color.New(color.FgRed) @@ -105,9 +110,21 @@ func Askf(msg string, masked bool, v ...interface{}) { fmt.Fprintf(color.Output, "%s%s %s: ", indent, symbol, fmt.Sprintf(msg, v...)) } +// isDebug returns true if debug mode is enabled +func isDebug() bool { + return os.Getenv(debugEnvName) == debugEnvValue +} + // Debug prints to the console if DNOTE_DEBUG is set func Debug(msg string, v ...interface{}) { - if os.Getenv("DNOTE_DEBUG") == "1" { + if isDebug() { fmt.Fprintf(color.Output, "%s %s", ColorGray.Sprint("DEBUG:"), fmt.Sprintf(msg, v...)) } } + +// DebugNewline prints a newline only in debug mode +func DebugNewline() { + if isDebug() { + fmt.Println() + } +} diff --git a/pkg/cli/migrate/migrate.go b/pkg/cli/migrate/migrate.go index eadfeda4..d579ffb7 100644 --- a/pkg/cli/migrate/migrate.go +++ b/pkg/cli/migrate/migrate.go @@ -144,7 +144,7 @@ func Run(ctx context.DnoteCtx, migrations []migration, mode int) error { return errors.Wrap(err, "getting the current schema") } - log.Debug("current schema: %s %d of %d\n", consts.SystemSchema, schema, len(migrations)) + log.Debug("%s: %d of %d\n", schemaKey, schema, len(migrations)) toRun := migrations[schema:] diff --git a/pkg/server/controllers/notes.go b/pkg/server/controllers/notes.go index dd34a78d..4db709da 100644 --- a/pkg/server/controllers/notes.go +++ b/pkg/server/controllers/notes.go @@ -218,7 +218,7 @@ func (n *Notes) create(r *http.Request) (database.Note, error) { var book database.Book if err := n.app.DB.Where("uuid = ? AND user_id = ?", params.BookUUID, user.ID).First(&book).Error; err != nil { - return database.Note{}, errors.Wrap(err, "finding book") + return database.Note{}, errors.Wrapf(err, "finding book %s", params.BookUUID) } client := getClientType(r)