+16 -37

bundle/manager.go

··· 408 408 } 409 409 410 410 // SaveBundle saves a bundle to disk and updates the index 411 411 - func (m *Manager) SaveBundle(ctx context.Context, bundle *Bundle, quiet bool) error { 411 411 + // Returns the DID index update duration 412 412 + func (m *Manager) SaveBundle(ctx context.Context, bundle *Bundle, quiet bool) (time.Duration, error) { 412 413 if err := bundle.ValidateForSave(); err != nil { 413 413 - return fmt.Errorf("bundle validation failed: %w", err) 414 414 + return 0, fmt.Errorf("bundle validation failed: %w", err) 414 415 } 415 416 416 417 path := filepath.Join(m.config.BundleDir, fmt.Sprintf("%06d.jsonl.zst", bundle.BundleNumber)) ··· 418 419 // Save to disk 419 420 uncompressedHash, compressedHash, uncompressedSize, compressedSize, err := m.operations.SaveBundle(path, bundle.Operations) 420 421 if err != nil { 421 421 - return fmt.Errorf("failed to save bundle: %w", err) 422 422 + return 0, fmt.Errorf("failed to save bundle: %w", err) 422 423 } 423 424 424 425 bundle.ContentHash = uncompressedHash ··· 448 449 449 450 // Save index 450 451 if err := m.SaveIndex(); err != nil { 451 451 - return fmt.Errorf("failed to save index: %w", err) 452 452 + return 0, fmt.Errorf("failed to save index: %w", err) 452 453 } 453 454 454 454 - // Clean up old mempool (silent unless verbose) 455 455 + // Clean up old mempool 455 456 oldMempoolFile := m.mempool.GetFilename() 456 457 if err := m.mempool.Delete(); err != nil && !quiet { 457 458 m.logger.Printf("Warning: failed to delete old mempool %s: %v", oldMempoolFile, err) ··· 463 464 464 465 newMempool, err := mempool.NewMempool(m.config.BundleDir, nextBundle, minTimestamp, m.logger) 465 466 if err != nil { 466 466 - return fmt.Errorf("failed to create new mempool: %w", err) 467 467 + return 0, fmt.Errorf("failed to create new mempool: %w", err) 467 468 } 468 469 469 470 m.mempool = newMempool 470 471 471 471 - // Update DID index if enabled (ONLY when bundle is created) 472 472 + // ✨ Update DID index if enabled and track timing 473 473 + var indexUpdateDuration time.Duration 472 474 if m.didIndex != nil && m.didIndex.Exists() { 473 475 indexUpdateStart := time.Now() 474 476 475 477 if err := m.updateDIDIndexForBundle(ctx, bundle); err != nil { 476 478 m.logger.Printf("Warning: failed to update DID index: %v", err) 477 479 } else { 478 478 - indexUpdateDuration := time.Since(indexUpdateStart) 480 480 + indexUpdateDuration = time.Since(indexUpdateStart) 479 481 480 482 if !quiet { 481 483 m.logger.Printf(" [DID Index] Updated in %s", indexUpdateDuration) ··· 483 485 } 484 486 } 485 487 486 486 - return nil 488 488 + return indexUpdateDuration, nil 487 489 } 488 490 489 491 // GetMempoolStats returns mempool statistics ··· 1127 1129 m.logger.Printf("Starting cursor: %s", afterTime) 1128 1130 } 1129 1131 1130 1130 - // Track total fetches and timing 1131 1132 totalFetches := 0 1132 1133 maxAttempts := 50 1133 1134 attempt := 0 ··· 1149 1150 prevBoundaryCIDs, 1150 1151 needed, 1151 1152 quiet, 1152 1152 - m.mempool.Count(), 1153 1153 + m.mempool, 1153 1154 totalFetches, 1154 1155 ) 1155 1156 ··· 1158 1159 // Check if we got an incomplete batch 1159 1160 gotIncompleteBatch := len(newOps) > 0 && len(newOps) < needed && err == nil 1160 1161 1161 1161 - // Add operations if we got any 1162 1162 - if len(newOps) > 0 { 1163 1163 - added, addErr := m.mempool.Add(newOps) 1164 1164 - if addErr != nil { 1165 1165 - m.mempool.Save() 1166 1166 - return nil, fmt.Errorf("chronological validation failed: %w", addErr) 1167 1167 - } 1168 1168 - 1169 1169 - // ✨ ALWAYS update cursor from mempool (source of truth) 1162 1162 + // Update cursor from mempool if we got new ops 1163 1163 + if len(newOps) > 0 && m.mempool.Count() > 0 { 1170 1164 afterTime = m.mempool.GetLastTime() 1171 1171 - 1172 1172 - if !quiet && added > 0 { 1173 1173 - addRejected := len(newOps) - added 1174 1174 - if addRejected > 0 { 1175 1175 - m.logger.Printf(" Added %d ops (mempool: %d, rejected: %d dupes, cursor: %s)", 1176 1176 - added, m.mempool.Count(), addRejected, afterTime[:19]) 1177 1177 - } else { 1178 1178 - m.logger.Printf(" Added %d ops (mempool: %d, cursor: %s)", 1179 1179 - added, m.mempool.Count(), afterTime[:19]) 1180 1180 - } 1181 1181 - } 1182 1165 } 1183 1166 1184 1167 // Stop if caught up or error ··· 1190 1173 break 1191 1174 } 1192 1175 1193 1193 - // If we have enough, break 1194 1176 if m.mempool.Count() >= types.BUNDLE_SIZE { 1195 1177 break 1196 1178 } 1197 1179 } 1198 1180 1199 1199 - // Save mempool state 1200 1200 - m.mempool.Save() 1181 1181 + // ✨ REMOVED: m.mempool.Save() - now handled by FetchToMempool 1201 1182 1202 1183 totalDuration := time.Since(attemptStart) 1203 1184 1204 1204 - // Check if we have enough for a bundle 1205 1185 if m.mempool.Count() < types.BUNDLE_SIZE { 1206 1186 if caughtUp { 1207 1187 return nil, fmt.Errorf("insufficient operations: have %d, need %d (caught up to latest PLC data)", ··· 1218 1198 return nil, err 1219 1199 } 1220 1200 1221 1221 - // Create bundle structure 1222 1201 syncBundle := internalsync.CreateBundle(nextBundleNum, operations, afterTime, prevBundleHash, m.operations) 1223 1202 1224 1203 bundle := &Bundle{ ··· 1237 1216 if !quiet { 1238 1217 avgPerFetch := float64(types.BUNDLE_SIZE) / float64(totalFetches) 1239 1218 throughput := float64(types.BUNDLE_SIZE) / totalDuration.Seconds() 1240 1240 - m.logger.Printf("✓ Bundle %06d ready (%d ops, %d DIDs) - %d fetches in %s (avg %.0f unique/fetch, %.0f ops/sec)", 1219 1219 + m.logger.Printf("✓ Bundle %06d ready (%d ops, %d DIDs) - %d fetches in %s (avg %.0f/fetch, %.0f ops/sec)", 1241 1220 bundle.BundleNumber, len(bundle.Operations), bundle.DIDCount, 1242 1221 totalFetches, totalDuration.Round(time.Millisecond), avgPerFetch, throughput) 1243 1222 }

+1 -1

cmd/plcbundle/commands/backfill.go

··· 66 66 break 67 67 } 68 68 69 69 - if err := mgr.SaveBundle(ctx, bundle, !*verbose); err != nil { 69 69 + if _, err := mgr.SaveBundle(ctx, bundle, !*verbose); err != nil { 70 70 return fmt.Errorf("error saving: %w", err) 71 71 } 72 72

+2 -1

cmd/plcbundle/commands/common.go

··· 28 28 RefreshMempool() error 29 29 ClearMempool() error 30 30 FetchNextBundle(ctx context.Context, quiet bool) (*bundle.Bundle, error) 31 31 - SaveBundle(ctx context.Context, b *bundle.Bundle, quiet bool) error 31 31 + SaveBundle(ctx context.Context, b *bundle.Bundle, quiet bool) (time.Duration, error) // ✨ Updated signature 32 32 GetDIDIndexStats() map[string]interface{} 33 33 GetDIDIndex() *didindex.Manager 34 34 BuildDIDIndex(ctx context.Context, progress func(int, int)) error ··· 37 37 GetLatestDIDOperation(ctx context.Context, did string) (*plcclient.PLCOperation, error) 38 38 LoadOperation(ctx context.Context, bundleNum, position int) (*plcclient.PLCOperation, error) 39 39 CloneFromRemote(ctx context.Context, opts internalsync.CloneOptions) (*internalsync.CloneResult, error) 40 40 + ResolveDID(ctx context.Context, did string) (*bundle.ResolveDIDResult, error) 40 41 } 41 42 42 43 // PLCOperationWithLocation wraps operation with location info

+2 -1

cmd/plcbundle/commands/fetch.go

··· 88 88 // Reset error counter on success 89 89 consecutiveErrors = 0 90 90 91 91 - if err := mgr.SaveBundle(ctx, b, !*verbose); err != nil { 91 91 + _, err = mgr.SaveBundle(ctx, b, !*verbose) 92 92 + if err != nil { 92 93 return fmt.Errorf("error saving bundle %06d: %w", b.BundleNumber, err) 93 94 } 94 95

+35 -72

cmd/plcbundle/commands/server.go

··· 266 266 267 267 // runSyncLoop runs the background sync loop 268 268 func runSyncLoop(ctx context.Context, mgr *bundle.Manager, interval time.Duration, verbose bool, resolverEnabled bool) { 269 269 - // Initial sync 270 270 - syncBundles(ctx, mgr, verbose, resolverEnabled) 269 269 + // ✨ Initial sync - ALWAYS show detailed progress 270 270 + fmt.Fprintf(os.Stderr, "[Sync] Initial sync starting...\n") 271 271 + syncBundles(ctx, mgr, true, resolverEnabled) // Force verbose=true for initial sync 271 272 272 272 - fmt.Fprintf(os.Stderr, "[Sync] Starting sync loop (interval: %s)\n", interval) 273 273 + fmt.Fprintf(os.Stderr, "[Sync] Loop started (interval: %s)\n", interval) 273 274 274 275 ticker := time.NewTicker(interval) 275 276 defer ticker.Stop() 276 277 277 277 - saveTicker := time.NewTicker(5 * time.Minute) 278 278 - defer saveTicker.Stop() 279 279 - 280 278 for { 281 279 select { 282 280 case <-ctx.Done(): ··· 287 285 return 288 286 289 287 case <-ticker.C: 288 288 + // ✨ Loop iterations - respect user's verbose flag 290 289 syncBundles(ctx, mgr, verbose, resolverEnabled) 291 291 - 292 292 - case <-saveTicker.C: 293 293 - stats := mgr.GetMempoolStats() 294 294 - if stats["count"].(int) > 0 && verbose { 295 295 - fmt.Fprintf(os.Stderr, "[Sync] Saving mempool (%d ops)\n", stats["count"]) 296 296 - mgr.SaveMempool() 297 297 - } 298 290 } 299 291 } 300 292 } 301 293 302 302 - // syncBundles performs a sync cycle with detailed progress 294 294 + // syncBundles performs a sync cycle 303 295 func syncBundles(ctx context.Context, mgr *bundle.Manager, verbose bool, resolverEnabled bool) { 304 296 cycleStart := time.Now() 305 297 ··· 312 304 313 305 mempoolBefore := mgr.GetMempoolStats()["count"].(int) 314 306 fetchedCount := 0 315 315 - totalOps := 0 316 316 - totalDIDs := 0 317 317 - 318 318 - fmt.Fprintf(os.Stderr, "[Sync] Starting from bundle %06d (mempool: %d ops)\n", 319 319 - startBundle, mempoolBefore) 307 307 + var totalIndexTime time.Duration 320 308 321 309 // Keep fetching until caught up 322 310 for { 323 323 - bundleStart := time.Now() 324 324 - 311 311 + // quiet = !verbose (show details only if verbose) 325 312 b, err := mgr.FetchNextBundle(ctx, !verbose) 326 313 if err != nil { 327 314 if isEndOfDataError(err) { 328 328 - // Caught up - show summary 329 329 - mempoolAfter := mgr.GetMempoolStats()["count"].(int) 330 330 - addedOps := mempoolAfter - mempoolBefore 331 331 - duration := time.Since(cycleStart) 332 332 - 333 333 - if fetchedCount > 0 { 334 334 - avgBundleTime := duration / time.Duration(fetchedCount) 335 335 - opsPerSec := float64(totalOps) / duration.Seconds() 336 336 - 337 337 - fmt.Fprintf(os.Stderr, "[Sync] ✓ Synced %d bundles in %s\n", 338 338 - fetchedCount, duration.Round(time.Millisecond)) 339 339 - fmt.Fprintf(os.Stderr, "[Sync] Range: %06d → %06d\n", 340 340 - startBundle, startBundle+fetchedCount-1) 341 341 - fmt.Fprintf(os.Stderr, "[Sync] Total: %d ops, %d unique DIDs\n", 342 342 - totalOps, totalDIDs) 343 343 - fmt.Fprintf(os.Stderr, "[Sync] Speed: %.1f bundles/sec, %.0f ops/sec\n", 344 344 - float64(fetchedCount)/duration.Seconds(), opsPerSec) 345 345 - fmt.Fprintf(os.Stderr, "[Sync] Avg: %s per bundle\n", 346 346 - avgBundleTime.Round(time.Millisecond)) 347 347 - fmt.Fprintf(os.Stderr, "[Sync] Mempool: %d ops (+%d)\n", 348 348 - mempoolAfter, addedOps) 349 349 - } else { 350 350 - fmt.Fprintf(os.Stderr, "[Sync] ✓ Already up to date (mempool: %d, +%d ops in %s)\n", 351 351 - mempoolAfter, addedOps, duration.Round(time.Millisecond)) 352 352 - } 353 315 break 354 316 } 355 355 - 356 356 - // Real error 357 317 fmt.Fprintf(os.Stderr, "[Sync] ✗ Error: %v\n", err) 358 318 break 359 319 } 360 320 361 361 - bundleDuration := time.Since(bundleStart) 362 362 - 363 363 - // Save bundle 364 364 - saveStart := time.Now() 365 365 - if err := mgr.SaveBundle(ctx, b, !verbose); err != nil { 321 321 + // Save bundle and track index update time 322 322 + indexTime, err := mgr.SaveBundle(ctx, b, !verbose) 323 323 + if err != nil { 366 324 fmt.Fprintf(os.Stderr, "[Sync] ✗ Error saving bundle %06d: %v\n", b.BundleNumber, err) 367 325 break 368 326 } 369 369 - saveDuration := time.Since(saveStart) 370 327 371 328 fetchedCount++ 372 372 - totalOps += len(b.Operations) 373 373 - totalDIDs += b.DIDCount 329 329 + totalIndexTime += indexTime 330 330 + 331 331 + time.Sleep(500 * time.Millisecond) 332 332 + } 333 333 + 334 334 + // ✨ ONE LINE SUMMARY with optional index timing 335 335 + mempoolAfter := mgr.GetMempoolStats()["count"].(int) 336 336 + addedOps := mempoolAfter - mempoolBefore 337 337 + duration := time.Since(cycleStart) 374 338 375 375 - // ✨ Enhanced progress log 376 376 - totalElapsed := time.Since(cycleStart) 377 377 - bundlesPerSec := float64(fetchedCount) / totalElapsed.Seconds() 378 378 - opsPerSec := float64(totalOps) / totalElapsed.Seconds() 339 339 + currentBundle := startBundle + fetchedCount - 1 340 340 + if fetchedCount == 0 { 341 341 + currentBundle = startBundle - 1 342 342 + } 379 343 380 380 - if verbose { 381 381 - fmt.Fprintf(os.Stderr, "[Sync] ✓ Bundle %06d | %d ops, %d DIDs | fetch: %s, save: %s, total: %s\n", 382 382 - b.BundleNumber, len(b.Operations), b.DIDCount, 383 383 - bundleDuration.Round(time.Millisecond), 384 384 - saveDuration.Round(time.Millisecond), 385 385 - totalElapsed.Round(time.Millisecond)) 344 344 + if fetchedCount > 0 { 345 345 + // Show index time if it was significant (>10ms) 346 346 + if totalIndexTime > 10*time.Millisecond { 347 347 + fmt.Fprintf(os.Stderr, "[Sync] ✓ Bundle %06d | Synced: %d | Mempool: %d (+%d) | %s (index: %s)\n", 348 348 + currentBundle, fetchedCount, mempoolAfter, addedOps, 349 349 + duration.Round(time.Millisecond), totalIndexTime.Round(time.Millisecond)) 386 350 } else { 387 387 - fmt.Fprintf(os.Stderr, "[Sync] ✓ %06d | %d ops, %d DIDs | %.1f b/s, %.0f ops/s | %s total\n", 388 388 - b.BundleNumber, len(b.Operations), b.DIDCount, 389 389 - bundlesPerSec, opsPerSec, totalElapsed.Round(time.Second)) 351 351 + fmt.Fprintf(os.Stderr, "[Sync] ✓ Bundle %06d | Synced: %d | Mempool: %d (+%d) | %s\n", 352 352 + currentBundle, fetchedCount, mempoolAfter, addedOps, duration.Round(time.Millisecond)) 390 353 } 391 391 - 392 392 - // Small delay to prevent hammering 393 393 - time.Sleep(500 * time.Millisecond) 354 354 + } else { 355 355 + fmt.Fprintf(os.Stderr, "[Sync] ✓ Bundle %06d | Up to date | Mempool: %d (+%d) | %s\n", 356 356 + currentBundle, mempoolAfter, addedOps, duration.Round(time.Millisecond)) 394 357 } 395 358 } 396 359

+41 -11

internal/sync/fetcher.go

··· 17 17 logger types.Logger 18 18 } 19 19 20 20 + // MempoolInterface defines what we need from mempool 21 21 + type MempoolInterface interface { 22 22 + Add(ops []plcclient.PLCOperation) (int, error) 23 23 + Save() error 24 24 + Count() int 25 25 + GetLastTime() string 26 26 + } 27 27 + 20 28 // NewFetcher creates a new fetcher 21 29 func NewFetcher(plcClient *plcclient.Client, operations *storage.Operations, logger types.Logger) *Fetcher { 22 30 return &Fetcher{ ··· 26 34 } 27 35 } 28 36 29 29 - // FetchToMempool fetches operations and returns them 37 37 + // FetchToMempool fetches operations and adds them to mempool (with auto-save) 30 38 func (f *Fetcher) FetchToMempool( 31 39 ctx context.Context, 32 40 afterTime string, 33 41 prevBoundaryCIDs map[string]bool, 34 42 target int, 35 43 quiet bool, 36 36 - currentMempoolCount int, 44 44 + mempool MempoolInterface, // NEW: pass mempool directly 37 45 totalFetchesSoFar int, 38 46 ) ([]plcclient.PLCOperation, int, error) { 39 47 ··· 100 108 return allNewOps, fetchesMade, nil 101 109 } 102 110 103 103 - // Store counts for metrics 104 111 originalBatchSize := len(batch) 105 112 totalReceived += originalBatchSize 106 113 ··· 117 124 dupesFiltered := originalBatchSize - uniqueAdded 118 125 totalDupes += dupesFiltered 119 126 120 120 - // ✨ Show fetch result with running totals 127 127 + // Show fetch result with running totals 121 128 if !quiet { 122 129 opsPerSec := float64(originalBatchSize) / fetchDuration.Seconds() 123 130 124 131 if dupesFiltered > 0 { 125 125 - f.logger.Printf(" → +%d unique (%d dupes) in %s • Running: %d/%d unique (%.0f ops/sec)", 132 132 + f.logger.Printf(" → +%d unique (%d dupes) in %s • Running: %d/%d (%.0f ops/sec)", 126 133 uniqueAdded, dupesFiltered, fetchDuration, len(allNewOps), target, opsPerSec) 127 134 } else { 128 135 f.logger.Printf(" → +%d unique in %s • Running: %d/%d (%.0f ops/sec)", ··· 130 137 } 131 138 } 132 139 140 140 + // ✨ ADD TO MEMPOOL AND SAVE after each fetch 141 141 + if uniqueAdded > 0 && mempool != nil { 142 142 + added, addErr := mempool.Add(allNewOps[beforeDedup:]) 143 143 + if addErr != nil { 144 144 + // Save before returning error 145 145 + mempool.Save() 146 146 + return allNewOps, fetchesMade, fmt.Errorf("mempool add failed: %w", addErr) 147 147 + } 148 148 + 149 149 + // ✨ Auto-save after each successful add 150 150 + if err := mempool.Save(); err != nil { 151 151 + f.logger.Printf(" Warning: failed to save mempool: %v", err) 152 152 + } 153 153 + 154 154 + if !quiet && added > 0 { 155 155 + cursor := mempool.GetLastTime() 156 156 + f.logger.Printf(" Saved to mempool: %d ops (total: %d, cursor: %s)", 157 157 + added, mempool.Count(), cursor[:19]) 158 158 + } 159 159 + } 160 160 + 133 161 // Update cursor 134 162 if len(batch) > 0 { 135 163 currentAfter = batch[len(batch)-1].CreatedAt.Format(time.RFC3339Nano) 136 164 } 137 165 138 138 - // Check completeness using ORIGINAL batch size 166 166 + // Check completeness 139 167 if originalBatchSize < batchSize { 140 168 if !quiet { 141 169 f.logger.Printf(" Incomplete batch (%d/%d) → caught up", originalBatchSize, batchSize) ··· 143 171 return allNewOps, fetchesMade, nil 144 172 } 145 173 146 146 - // If we have enough unique ops, stop 147 174 if len(allNewOps) >= target { 148 175 break 149 176 } 150 177 } 151 178 152 152 - // ✨ Summary at the end 179 179 + // Summary 153 180 if !quiet && fetchesMade > 0 { 154 154 - dedupRate := float64(totalDupes) / float64(totalReceived) * 100 155 155 - f.logger.Printf(" ✓ Fetched %d ops total, %d unique (%.1f%% dedup rate)", 156 156 - totalReceived, len(allNewOps), dedupRate) 181 181 + dedupRate := 0.0 182 182 + if totalReceived > 0 { 183 183 + dedupRate = float64(totalDupes) / float64(totalReceived) * 100 184 184 + } 185 185 + f.logger.Printf(" ✓ Collected %d unique ops from %d fetches (%.1f%% dedup)", 186 186 + len(allNewOps), fetchesMade, dedupRate) 157 187 } 158 188 159 189 return allNewOps, fetchesMade, nil