diff --git a/cmd/mark2note/main.go b/cmd/mark2note/main.go index 39c0c4e..f60aaff 100644 --- a/cmd/mark2note/main.go +++ b/cmd/mark2note/main.go @@ -18,6 +18,7 @@ import ( "github.com/walker1211/mark2note/internal/deck" "github.com/walker1211/mark2note/internal/poster" "github.com/walker1211/mark2note/internal/render" + "github.com/walker1211/mark2note/internal/timing" "github.com/walker1211/mark2note/internal/xhs" "gopkg.in/yaml.v3" ) @@ -1175,7 +1176,9 @@ func runPrepareXHS(renderOpts Options, renderResult app.Result, stdout io.Writer } func runAutoPublishXHS(renderOpts Options, renderResult app.Result, stdout io.Writer, stderr io.Writer) int { + buildDone := timing.Stage("cmd.runAutoPublishXHS.build_options", timing.Field("images", len(renderResult.ImagePaths))) publishOpts, err := buildAutoPublishXHSOptions(renderOpts, renderResult) + buildDone(err) if err != nil { switch { case errors.Is(err, app.ErrLoadConfig): @@ -1191,7 +1194,9 @@ func runAutoPublishXHS(renderOpts Options, renderResult app.Result, stdout io.Wr fmt.Fprintf(stderr, "auto publish xhs failed: write xhs publish metadata: %v\n", err) return 1 } + publishDone := timing.Stage("cmd.runAutoPublishXHS.publish", timing.Field("images", len(publishOpts.ImagePaths)), timing.Field("mode", publishOpts.Mode)) result, err := publishXHS(publishOpts) + publishDone(err) if err != nil { printPublishXHSError(stderr, err) return 1 @@ -1210,7 +1215,7 @@ func nonEmptyStrings(values []string) []string { return result } -func run(args []string, stdout io.Writer, stderr io.Writer) int { +func run(args []string, stdout io.Writer, stderr io.Writer) (code int) { if len(args) > 0 { switch args[0] { case "capture-html": @@ -1236,6 +1241,15 @@ func run(args []string, stdout io.Writer, stderr io.Writer) int { return 1 } + done := timing.Stage("cmd.run") + defer func() { + var err error + if code != 0 { + err = errors.New("exit_nonzero") + } + done(err) + }() + generate := generatePreview if strings.TrimSpace(opts.FromDeckPath) != "" { generate = generateFromDeck @@ -1446,7 +1460,9 @@ func runPublishXHS(args []string, stdout io.Writer, stderr io.Writer) int { fmt.Fprintf(stderr, "error parsing flags: --meta cannot be combined with manual publish fields: %s\n", strings.Join(cliOpts.MetaConflictFlags, ", ")) return 1 } + metaDone := timing.Stage("cmd.runPublishXHS.read_metadata") opts, err := readXHSPublishMeta(cliOpts.MetaPath) + metaDone(err) if err != nil { fmt.Fprintf(stderr, "error reading xhs publish metadata: %v\n", err) return 1 @@ -1460,7 +1476,9 @@ func runPublishXHS(args []string, stdout io.Writer, stderr io.Writer) int { fmt.Fprintf(stderr, "error validating xhs publish metadata: %v\n", err) return 1 } + publishDone := timing.Stage("cmd.runPublishXHS.publish_metadata", timing.Field("images", len(opts.ImagePaths)), timing.Field("mode", opts.Mode)) result, err := publishXHS(opts) + publishDone(err) if err != nil { printPublishXHSError(stderr, err) return 1 @@ -1477,7 +1495,9 @@ func runPublishXHS(args []string, stdout io.Writer, stderr io.Writer) int { fmt.Fprintf(stderr, "error parsing flags: %v\n", err) return 1 } + publishDone := timing.Stage("cmd.runPublishXHS.publish", timing.Field("images", len(opts.ImagePaths)), timing.Field("mode", opts.Mode)) result, err := publishXHS(opts) + publishDone(err) if err != nil { printPublishXHSError(stderr, err) return 1 diff --git a/internal/app/publish_service.go b/internal/app/publish_service.go index 74fd2d1..c9345b3 100644 --- a/internal/app/publish_service.go +++ b/internal/app/publish_service.go @@ -8,6 +8,7 @@ import ( "strings" "time" + "github.com/walker1211/mark2note/internal/timing" "github.com/walker1211/mark2note/internal/xhs" ) @@ -63,15 +64,24 @@ var ( ErrPublishExecute = errors.New("publish execute failed") ) -func (s PublishService) Publish(opts PublishOptions) (PublishResult, error) { +func (s PublishService) Publish(opts PublishOptions) (result PublishResult, err error) { + done := timing.Stage("app.PublishService.Publish", timing.Field("images", len(opts.ImagePaths)), timing.Field("live", strings.TrimSpace(opts.LiveReportPath) != "")) + defer func() { done(err) }() + + resolveDone := timing.Stage("app.PublishService.resolve_title_content") title, err := s.resolveTextInput(opts.Title, opts.TitleFile, "title") - if err != nil { - return PublishResult{}, err - } - content, err := s.resolveOptionalTextInput(opts.Content, opts.ContentFile, "content") - if err != nil { - return PublishResult{}, err + if err == nil { + content, err := s.resolveOptionalTextInput(opts.Content, opts.ContentFile, "content") + if err == nil { + resolveDone(nil) + return s.publishResolved(opts, title, content) + } } + resolveDone(err) + return PublishResult{}, err +} + +func (s PublishService) publishResolved(opts PublishOptions, title string, content string) (PublishResult, error) { mode, err := xhs.ValidateMode(opts.Mode) if err != nil { return PublishResult{}, fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err) @@ -81,15 +91,22 @@ func (s PublishService) Publish(opts PublishOptions) (PublishResult, error) { if err != nil { return PublishResult{}, fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err) } + buildDone := timing.Stage("app.PublishService.build_request") request, err := buildPublishRequest(opts, title, content, mode, scheduleTime) + if err == nil { + err = request.Validate(now) + if err != nil { + err = fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err) + } + } + buildDone(err) if err != nil { return PublishResult{}, err } - if err := request.Validate(now); err != nil { - return PublishResult{}, fmt.Errorf("%w: %v", ErrPublishRequestInvalid, err) - } runtime := PublishRuntimeOptions{ChromePath: strings.TrimSpace(opts.ChromePath), Headless: opts.Headless, ProfileDir: strings.TrimSpace(opts.ProfileDir), ChromeArgs: trimOptionalSlice(opts.ChromeArgs)} + publishDone := timing.Stage("app.PublishService.orchestrator_publish", timing.Field("media", request.MediaKind), timing.Field("mode", request.Mode)) result, err := s.effectiveNewOrchestrator()(runtime).Publish(request, runtime) + publishDone(err) if err != nil { return PublishResult{Request: request, Result: result}, fmt.Errorf("%w: %w", ErrPublishExecute, err) } diff --git a/internal/app/service.go b/internal/app/service.go index 41f5a81..70cb7ba 100644 --- a/internal/app/service.go +++ b/internal/app/service.go @@ -18,6 +18,7 @@ import ( "github.com/walker1211/mark2note/internal/deck" "github.com/walker1211/mark2note/internal/poster" "github.com/walker1211/mark2note/internal/render" + "github.com/walker1211/mark2note/internal/timing" ) type AnimatedOptions struct { @@ -131,8 +132,13 @@ var ( ErrRenderPreview = errors.New("render preview failed") ) -func (s Service) GeneratePreview(opts Options) (Result, error) { +func (s Service) GeneratePreview(opts Options) (result Result, err error) { + done := timing.Stage("app.GeneratePreview") + defer func() { done(err) }() + + loadConfigDone := timing.Stage("app.GeneratePreview.load_config") cfg, err := s.effectiveLoadConfig()(opts.ConfigPath) + loadConfigDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %v", ErrLoadConfig, err) } @@ -146,7 +152,9 @@ func (s Service) GeneratePreview(opts Options) (Result, error) { } } + readMarkdownDone := timing.Stage("app.GeneratePreview.read_markdown") markdownBytes, err := s.effectiveReadFile()(opts.InputPath) + readMarkdownDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %v", ErrReadMarkdown, err) } @@ -158,30 +166,44 @@ func (s Service) GeneratePreview(opts Options) (Result, error) { } if !matched { s.PromptExtra = opts.PromptExtra + buildDeckDone := timing.Stage("app.GeneratePreview.ai_build_deck_json") rawJSON, err = s.effectiveBuildDeckJSON()(cfg, markdown) + buildDeckDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %w", ErrBuildDeckJSON, err) } } + parseDeckDone := timing.Stage("app.GeneratePreview.parse_deck") d, err := deck.FromJSONWithMaxPages(rawJSON, opts.OutDir, cfg.Deck.MaxPages) + parseDeckDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %v", ErrParseDeck, err) } d = moveLeadingMarkdownImageToCover(d, markdown) var posterWarnings []string - if d, posterWarnings, err = s.hydratePosters(opts, d, markdown); err != nil { + hydratePostersDone := timing.Stage("app.GeneratePreview.hydrate_posters") + d, posterWarnings, err = s.hydratePosters(opts, d, markdown) + hydratePostersDone(err) + if err != nil { return Result{}, err } d = hydrateLocalImageAssets(d, filepath.Dir(opts.InputPath)) - result, err := s.renderDeck(opts, cfg, d, sourceRenderMeta{}) + renderDeckDone := timing.Stage("app.GeneratePreview.render_deck") + result, err = s.renderDeck(opts, cfg, d, sourceRenderMeta{}) + renderDeckDone(err) result.Warnings = append(posterWarnings, result.Warnings...) return result, err } -func (s Service) GenerateFromDeck(opts Options) (Result, error) { +func (s Service) GenerateFromDeck(opts Options) (result Result, err error) { + done := timing.Stage("app.GenerateFromDeck") + defer func() { done(err) }() + + loadConfigDone := timing.Stage("app.GenerateFromDeck.load_config") cfg, err := s.effectiveLoadConfig()(opts.ConfigPath) + loadConfigDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %v", ErrLoadConfig, err) } @@ -193,24 +215,35 @@ func (s Service) GenerateFromDeck(opts Options) (Result, error) { opts.OutDir = abs } } + readDeckDone := timing.Stage("app.GenerateFromDeck.read_deck") deckBytes, err := s.effectiveReadFile()(opts.FromDeckPath) + readDeckDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %v", ErrReadDeck, err) } + parseDeckDone := timing.Stage("app.GenerateFromDeck.parse_deck") d, err := deck.FromJSONWithMaxPages(string(deckBytes), opts.OutDir, cfg.Deck.MaxPages) + parseDeckDone(err) if err != nil { return Result{}, fmt.Errorf("%w: %v", ErrParseDeck, err) } var posterWarnings []string - if d, posterWarnings, err = s.hydratePosters(opts, d, ""); err != nil { + hydratePostersDone := timing.Stage("app.GenerateFromDeck.hydrate_posters") + d, posterWarnings, err = s.hydratePosters(opts, d, "") + hydratePostersDone(err) + if err != nil { return Result{}, err } d = hydrateLocalImageAssets(d, filepath.Dir(opts.FromDeckPath)) + readMetaDone := timing.Stage("app.GenerateFromDeck.read_render_meta") meta, err := s.readRenderMetaForDeck(opts.FromDeckPath) + readMetaDone(err) if err != nil { return Result{}, err } - result, err := s.renderDeck(opts, cfg, d, sourceRenderMeta{FromDeck: true, Meta: meta}) + renderDeckDone := timing.Stage("app.GenerateFromDeck.render_deck") + result, err = s.renderDeck(opts, cfg, d, sourceRenderMeta{FromDeck: true, Meta: meta}) + renderDeckDone(err) result.Warnings = append(posterWarnings, result.Warnings...) return result, err } diff --git a/internal/render/renderer.go b/internal/render/renderer.go index 39277af..c480dee 100644 --- a/internal/render/renderer.go +++ b/internal/render/renderer.go @@ -12,6 +12,7 @@ import ( "time" "github.com/walker1211/mark2note/internal/deck" + "github.com/walker1211/mark2note/internal/timing" ) const defaultChromePath = "/Applications/Google Chrome.app/Contents/MacOS/Google Chrome" @@ -92,7 +93,10 @@ func (execRunner) Run(name string, args ...string) error { return cmd.Run() } -func (r Renderer) Render(d deck.Deck) (RenderResult, error) { +func (r Renderer) Render(d deck.Deck) (result RenderResult, err error) { + done := timing.Stage("render.Render", timing.Field("pages", len(d.Pages))) + defer func() { done(err) }() + if len(d.Pages) == 0 { return RenderResult{}, fmt.Errorf("deck must contain at least 1 page for render") } @@ -105,10 +109,16 @@ func (r Renderer) Render(d deck.Deck) (RenderResult, error) { mode, animatedResult := r.normalizedAnimated() liveMode, liveWarnings := normalizeLiveOptions(r.Live) captureMode, captureWarnings := r.normalizedCaptureTiming(mode, liveMode.Enabled) - if err := r.renderHTMLPages(d, captureMode); err != nil { + renderHTMLDone := timing.Stage("render.Render.renderHTMLPages", timing.Field("pages", len(d.Pages))) + err = r.renderHTMLPages(d, captureMode) + renderHTMLDone(err) + if err != nil { return RenderResult{}, err } - if err := r.CapturePNGs(d.Pages, outDir); err != nil { + captureDone := timing.Stage("render.Render.CapturePNGs", timing.Field("pages", len(d.Pages))) + err = r.CapturePNGs(d.Pages, outDir) + captureDone(err) + if err != nil { return RenderResult{}, err } imagePaths := generatedPNGPaths(d.Pages, outDir) @@ -116,11 +126,16 @@ func (r Renderer) Render(d deck.Deck) (RenderResult, error) { warnings = append(warnings, liveWarnings...) warnings = append(warnings, captureWarnings...) if captureMode.Enabled && (mode.Enabled || liveMode.Enabled) { - warnings = append(warnings, r.runAnimatedExports(d.Pages, outDir, captureMode, mode, liveMode)...) + animatedDone := timing.Stage("render.Render.animated_live_exports", timing.Field("pages", len(d.Pages)), timing.Field("animated", mode.Enabled), timing.Field("live", liveMode.Enabled)) + animatedWarnings := r.runAnimatedExports(d.Pages, outDir, captureMode, mode, liveMode) + animatedDone(nil) + warnings = append(warnings, animatedWarnings...) } - result := RenderResult{Warnings: warnings, ImagePaths: imagePaths} + result = RenderResult{Warnings: warnings, ImagePaths: imagePaths} if r.ImportPhotos { + importDone := timing.Stage("render.Render.import_photos", timing.Field("pages", len(d.Pages))) delivery, err := r.deliverPNGImport(outDir, d.Pages) + importDone(err) result.ImportReport = &delivery.Report result.ImportReportPath = delivery.ReportPath if err != nil { @@ -128,8 +143,10 @@ func (r Renderer) Render(d deck.Deck) (RenderResult, error) { } } if liveMode.Enabled && liveMode.Assemble && liveMode.ImportPhotos { + liveImportDone := timing.Stage("render.Render.live_import_photos", timing.Field("pages", len(d.Pages))) sourceDir, importDir, err := r.liveImportSourceDirs(outDir, d.Pages, liveMode) if err != nil { + liveImportDone(err) return result, err } delivery, err := r.liveDeliveryOrchestrator().Deliver(liveDeliveryRequest{ @@ -138,6 +155,7 @@ func (r Renderer) Render(d deck.Deck) (RenderResult, error) { AlbumName: liveMode.ImportAlbum, ImportTimeout: liveMode.ImportTimeout, }) + liveImportDone(err) result.DeliveryReport = &delivery.Report result.DeliveryReportPath = delivery.ReportPath if err != nil { @@ -351,7 +369,10 @@ func (r Renderer) CaptureHTMLPath(inputPath string) error { return r.runCaptureTasksWithJobs(tasks, r.effectiveJobs()) } -func (r Renderer) runAnimatedExports(pages []deck.Page, outDir string, captureMode normalizedAnimatedOptions, animated normalizedAnimatedOptions, live normalizedLiveOptions) []string { +func (r Renderer) runAnimatedExports(pages []deck.Page, outDir string, captureMode normalizedAnimatedOptions, animated normalizedAnimatedOptions, live normalizedLiveOptions) (warnings []string) { + done := timing.Stage("render.runAnimatedExports", timing.Field("pages", len(pages)), timing.Field("animated", animated.Enabled), timing.Field("live", live.Enabled)) + defer func() { done(nil) }() + tasks := buildAnimatedCaptureTasks(pages, outDir, captureMode) warningsList := make([]string, 0, 3) if len(tasks) == 0 { @@ -452,14 +473,18 @@ func (r Renderer) runAnimatedExports(pages []deck.Page, outDir string, captureMo // while frame capture within a single page stays serial (1) to preserve frame // order. Concurrent makelive invocations have shown intermittent segfaults in // practice, so assemble runs sequentially here in original page order. + assembleDone := timing.Stage("render.runAnimatedExports.live_assemble", timing.Field("pages", len(assembleTasks))) + var assembleErr error for _, task := range assembleTasks { if task == nil { continue } if err := liveAssembler.Assemble(*task); err != nil { + assembleErr = err collected = append(collected, fmt.Sprintf("live assemble failed for %s: %v", task.PageName, err)) } } + assembleDone(assembleErr) } sort.Strings(collected) return collected diff --git a/internal/timing/timing.go b/internal/timing/timing.go new file mode 100644 index 0000000..4e18a6b --- /dev/null +++ b/internal/timing/timing.go @@ -0,0 +1,84 @@ +package timing + +import ( + "fmt" + "io" + "os" + "regexp" + "strings" + "sync" + "time" +) + +const prefix = "MARK2NOTE_TIMING" + +var ( + outputMu sync.Mutex + output io.Writer = os.Stderr + keyRe = regexp.MustCompile(`[^A-Za-z0-9_\-]+`) +) + +// Field returns an optional key=value detail for a timing line. +func Field(key string, value any) string { + key = keyRe.ReplaceAllString(strings.TrimSpace(key), "_") + key = strings.Trim(key, "_") + if key == "" { + return "" + } + valueText := strings.Join(strings.Fields(fmt.Sprint(value)), "_") + valueText = strings.ReplaceAll(valueText, "/", "_") + valueText = strings.ReplaceAll(valueText, `\\`, "_") + if valueText == "" { + return "" + } + return key + "=" + valueText +} + +// SetOutput changes the timing output writer and returns the previous writer. +// It is intended for tests; production code writes to stderr by default. +func SetOutput(w io.Writer) io.Writer { + outputMu.Lock() + defer outputMu.Unlock() + old := output + if w == nil { + output = io.Discard + } else { + output = w + } + return old +} + +// Stage starts a timer and returns a function that emits one stable timing line. +func Stage(name string, details ...string) func(error) { + start := time.Now() + stage := sanitizeValue(name) + return func(err error) { + elapsed := time.Since(start).Milliseconds() + if elapsed < 0 { + elapsed = 0 + } + status := "ok" + if err != nil { + status = "error" + } + fields := []string{prefix, Field("stage", stage), Field("elapsed_ms", elapsed), Field("status", status)} + for _, detail := range details { + if strings.TrimSpace(detail) != "" { + fields = append(fields, detail) + } + } + outputMu.Lock() + defer outputMu.Unlock() + fmt.Fprintln(output, strings.Join(fields, " ")) + } +} + +func sanitizeValue(value string) string { + value = strings.TrimSpace(value) + value = strings.Join(strings.Fields(value), "_") + value = strings.ReplaceAll(value, string(os.PathSeparator), "_") + if value == "" { + return "unknown" + } + return value +} diff --git a/internal/timing/timing_test.go b/internal/timing/timing_test.go new file mode 100644 index 0000000..79d4278 --- /dev/null +++ b/internal/timing/timing_test.go @@ -0,0 +1,53 @@ +package timing + +import ( + "bytes" + "errors" + "strings" + "testing" + "time" +) + +func TestStageWritesStableOKLine(t *testing.T) { + var buf bytes.Buffer + old := SetOutput(&buf) + defer SetOutput(old) + + done := Stage("render", Field("pages", 3)) + time.Sleep(time.Millisecond) + done(nil) + + line := strings.TrimSpace(buf.String()) + if !strings.HasPrefix(line, "MARK2NOTE_TIMING ") { + t.Fatalf("line prefix = %q", line) + } + for _, want := range []string{"stage=render", "elapsed_ms=", "status=ok", "pages=3"} { + if !strings.Contains(line, want) { + t.Fatalf("line %q does not contain %q", line, want) + } + } + if strings.Contains(line, "/Users/") { + t.Fatalf("line leaks local absolute path: %q", line) + } +} + +func TestStageWritesErrorStatus(t *testing.T) { + var buf bytes.Buffer + old := SetOutput(&buf) + defer SetOutput(old) + + done := Stage("publish") + done(errors.New("boom")) + + line := strings.TrimSpace(buf.String()) + if !strings.Contains(line, "stage=publish") || !strings.Contains(line, "status=error") { + t.Fatalf("unexpected timing line: %q", line) + } +} + +func TestFieldDoesNotPreserveAbsolutePathShape(t *testing.T) { + field := Field("path", "/Users/me/project/file.md") + if strings.Contains(field, "/Users/") || strings.Contains(field, "/") { + t.Fatalf("field preserves path shape: %q", field) + } +} diff --git a/internal/xhs/orchestrator.go b/internal/xhs/orchestrator.go index 4a83163..0b5c089 100644 --- a/internal/xhs/orchestrator.go +++ b/internal/xhs/orchestrator.go @@ -3,6 +3,8 @@ package xhs import ( "context" "fmt" + + "github.com/walker1211/mark2note/internal/timing" ) type Orchestrator struct { @@ -15,25 +17,36 @@ func NewOrchestrator(session BrowserSession) *Orchestrator { return &Orchestrator{session: session, publisher: Publisher{}, liveBridge: newDefaultLiveBridge()} } -func (o *Orchestrator) Publish(ctx context.Context, request PublishRequest) (PublishResult, error) { +func (o *Orchestrator) Publish(ctx context.Context, request PublishRequest) (result PublishResult, err error) { + done := timing.Stage("xhs.Orchestrator.Publish", timing.Field("mode", request.Mode), timing.Field("media", request.MediaKind)) + defer func() { done(err) }() + defaultXHSLogger("publish start account=%s mode=%s media=%s", request.Account, request.Mode, request.MediaKind) - result := PublishResult{ + result = PublishResult{ TargetAccount: request.Account, Mode: request.Mode, MediaKind: request.MediaKind, ScheduleTime: request.ScheduleTime, } defaultXHSLogger("publish open session") - if err := o.session.Open(ctx); err != nil { + openDone := timing.Stage("xhs.Orchestrator.session_open") + err = o.session.Open(ctx) + openDone(err) + if err != nil { return result, err } defaultXHSLogger("publish ensure login") - if err := o.session.EnsureLoggedIn(ctx); err != nil { + loginDone := timing.Stage("xhs.Orchestrator.ensure_login") + err = o.session.EnsureLoggedIn(ctx) + loginDone(err) + if err != nil { result.BrowserKept = true return result, err } defaultXHSLogger("publish get publisher page") + pageDone := timing.Stage("xhs.Orchestrator.get_publisher_page") page, err := o.session.PublisherPage(ctx) + pageDone(err) if err != nil { result.BrowserKept = true return result, err @@ -46,7 +59,9 @@ func (o *Orchestrator) Publish(ctx context.Context, request PublishRequest) (Pub return result, err } defaultXHSLogger("publish live attach run album=%s items=%d", attachRequest.AlbumName, len(attachRequest.Items)) + attachDone := timing.Stage("xhs.Orchestrator.live_attach", timing.Field("items", len(attachRequest.Items))) attachResult, err := o.liveBridge.Attach(ctx, attachRequest) + attachDone(err) if err != nil { result.BrowserKept = true return result, err @@ -57,7 +72,10 @@ func (o *Orchestrator) Publish(ctx context.Context, request PublishRequest) (Pub } switch request.Mode { case PublishModeOnlySelf: - if err := o.publishOnlySelf(ctx, page, request); err != nil { + publishDone := timing.Stage("xhs.Orchestrator.publish_only_self", timing.Field("media", request.MediaKind)) + err = o.publishOnlySelf(ctx, page, request) + publishDone(err) + if err != nil { result.BrowserKept = true return result, err } @@ -65,7 +83,10 @@ func (o *Orchestrator) Publish(ctx context.Context, request PublishRequest) (Pub result.OnlySelfPublished = true } case PublishModeSchedule: - if err := o.publishScheduled(ctx, page, request); err != nil { + publishDone := timing.Stage("xhs.Orchestrator.publish_scheduled", timing.Field("media", request.MediaKind)) + err = o.publishScheduled(ctx, page, request) + publishDone(err) + if err != nil { result.BrowserKept = true return result, err } @@ -78,7 +99,10 @@ func (o *Orchestrator) Publish(ctx context.Context, request PublishRequest) (Pub result.BrowserKept = true return result, nil } - if err := o.session.Close(); err != nil { + closeDone := timing.Stage("xhs.Orchestrator.session_close") + err = o.session.Close() + closeDone(err) + if err != nil { return result, err } return result, nil diff --git a/internal/xhs/publisher.go b/internal/xhs/publisher.go index a6402f3..57b536f 100644 --- a/internal/xhs/publisher.go +++ b/internal/xhs/publisher.go @@ -10,6 +10,7 @@ import ( "github.com/go-rod/rod" "github.com/go-rod/rod/lib/input" "github.com/go-rod/rod/lib/proto" + "github.com/walker1211/mark2note/internal/timing" ) var ( @@ -46,29 +47,50 @@ type onlySelfPreSubmitPage interface { type Publisher struct{} -func (Publisher) PublishStandardOnlySelf(ctx context.Context, page PublishPage, request PublishRequest) error { +func (Publisher) PublishStandardOnlySelf(ctx context.Context, page PublishPage, request PublishRequest) (err error) { + done := timing.Stage("xhs.Publisher.PublishStandardOnlySelf", timing.Field("images", len(request.ImagePaths)), timing.Field("topics", len(request.Tags))) + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } - if err := page.Open(ctx); err != nil { + openDone := timing.Stage("xhs.Publisher.open_page") + err = page.Open(ctx) + openDone(err) + if err != nil { return err } - if err := page.UploadImages(ctx, request.ImagePaths); err != nil { + uploadDone := timing.Stage("xhs.Publisher.UploadImages", timing.Field("images", len(request.ImagePaths))) + err = page.UploadImages(ctx, request.ImagePaths) + uploadDone(err) + if err != nil { return fmt.Errorf("%w: %w", ErrUploadFailed, err) } - if err := page.FillTitle(ctx, request.Title); err != nil { + fillTitleDone := timing.Stage("xhs.Publisher.FillTitle") + err = page.FillTitle(ctx, request.Title) + fillTitleDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrFillFailed, err) } - if err := page.FillContent(ctx, request.Content, request.Tags); err != nil { + fillContentDone := timing.Stage("xhs.Publisher.FillContent", timing.Field("topics", len(request.Tags))) + err = page.FillContent(ctx, request.Content, request.Tags) + fillContentDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrFillFailed, err) } if request.StopBeforeSubmit { return prepareOnlySelfBeforeSubmit(page, request) } - if err := page.PublishOnlySelf(ctx, request); err != nil { + publishDone := timing.Stage("xhs.Publisher.PublishOnlySelf") + err = page.PublishOnlySelf(ctx, request) + publishDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrSubmitFailed, err) } - if err := page.ConfirmOnlySelfPublished(ctx); err != nil { + confirmDone := timing.Stage("xhs.Publisher.ConfirmOnlySelfPublished") + err = page.ConfirmOnlySelfPublished(ctx) + confirmDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrSubmitFailed, err) } return nil @@ -124,7 +146,10 @@ func (p *rodPage) Open(ctx context.Context) error { return p.Navigate(xhsPublishURL) } -func (p *rodPage) UploadImages(ctx context.Context, paths []string) error { +func (p *rodPage) UploadImages(ctx context.Context, paths []string) (err error) { + done := timing.Stage("xhs.rodPage.UploadImages", timing.Field("images", len(paths))) + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } @@ -146,7 +171,10 @@ func (p *rodPage) UploadImages(ctx context.Context, paths []string) error { return p.waitForEditorReady(ctx, 30*time.Second) } -func (p *rodPage) FillTitle(ctx context.Context, title string) error { +func (p *rodPage) FillTitle(ctx context.Context, title string) (err error) { + done := timing.Stage("xhs.rodPage.FillTitle") + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } @@ -159,7 +187,10 @@ func (p *rodPage) FillTitle(ctx context.Context, title string) error { }) } -func (p *rodPage) FillContent(ctx context.Context, content string, tags []string) error { +func (p *rodPage) FillContent(ctx context.Context, content string, tags []string) (err error) { + done := timing.Stage("xhs.rodPage.FillContent", timing.Field("tags", len(tags))) + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } @@ -185,11 +216,18 @@ func (p *rodPage) FillContent(ctx context.Context, content string, tags []string return err } } + topicInputDone := timing.Stage("xhs.rodPage.FillContent.input_topics", timing.Field("count", len(topicTags))) + var topicErr error for _, tag := range topicTags { if err := p.inputTopicByKeyboard(field, tag); err != nil { - return fmt.Errorf("input topic %q: %w", tag, err) + topicErr = fmt.Errorf("input topic: %w", err) + break } } + topicInputDone(topicErr) + if topicErr != nil { + return topicErr + } return nil } @@ -365,7 +403,10 @@ func shouldSetOnlySelfVisibility(request PublishRequest) bool { return visibility == PublishVisibilityOnlySelf } -func (p *rodPage) PublishOnlySelf(ctx context.Context, request PublishRequest) error { +func (p *rodPage) PublishOnlySelf(ctx context.Context, request PublishRequest) (err error) { + done := timing.Stage("xhs.rodPage.PublishOnlySelf", timing.Field("visibility", request.Visibility)) + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } @@ -440,7 +481,10 @@ func (p *rodPage) clickOnlySelfPublishButton() (bool, error) { return clicked, nil } -func (p *rodPage) ConfirmOnlySelfPublished(ctx context.Context) error { +func (p *rodPage) ConfirmOnlySelfPublished(ctx context.Context) (err error) { + done := timing.Stage("xhs.rodPage.ConfirmOnlySelfPublished") + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } @@ -452,38 +496,62 @@ func (p *rodPage) ConfirmOnlySelfPublished(ctx context.Context) error { return fmt.Errorf("only-self publish confirmation not observed") } -func (Publisher) PublishStandardScheduled(ctx context.Context, page PublishPage, request PublishRequest) error { +func (Publisher) PublishStandardScheduled(ctx context.Context, page PublishPage, request PublishRequest) (err error) { + done := timing.Stage("xhs.Publisher.PublishStandardScheduled", timing.Field("images", len(request.ImagePaths)), timing.Field("topics", len(request.Tags))) + defer func() { done(err) }() + if err := ctx.Err(); err != nil { return err } if request.ScheduleTime == nil { return fmt.Errorf("%w: schedule time is required", ErrScheduleFailed) } - if err := page.Open(ctx); err != nil { + openDone := timing.Stage("xhs.Publisher.open_page") + err = page.Open(ctx) + openDone(err) + if err != nil { return err } - if err := page.UploadImages(ctx, request.ImagePaths); err != nil { + uploadDone := timing.Stage("xhs.Publisher.UploadImages", timing.Field("images", len(request.ImagePaths))) + err = page.UploadImages(ctx, request.ImagePaths) + uploadDone(err) + if err != nil { return fmt.Errorf("%w: %w", ErrUploadFailed, err) } - if err := page.FillTitle(ctx, request.Title); err != nil { + fillTitleDone := timing.Stage("xhs.Publisher.FillTitle") + err = page.FillTitle(ctx, request.Title) + fillTitleDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrFillFailed, err) } - if err := page.FillContent(ctx, request.Content, request.Tags); err != nil { + fillContentDone := timing.Stage("xhs.Publisher.FillContent", timing.Field("topics", len(request.Tags))) + err = page.FillContent(ctx, request.Content, request.Tags) + fillContentDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrFillFailed, err) } if err := runScheduledPreSubmitHooks(page, request); err != nil { return err } - if err := page.SetSchedule(ctx, *request.ScheduleTime); err != nil { + setScheduleDone := timing.Stage("xhs.Publisher.SetSchedule") + err = page.SetSchedule(ctx, *request.ScheduleTime) + setScheduleDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrScheduleFailed, err) } if request.StopBeforeSubmit { return nil } - if err := page.SubmitScheduled(ctx); err != nil { + submitDone := timing.Stage("xhs.Publisher.SubmitScheduled") + err = page.SubmitScheduled(ctx) + submitDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrSubmitFailed, err) } - if err := page.ConfirmScheduledSubmitted(ctx); err != nil { + confirmDone := timing.Stage("xhs.Publisher.ConfirmScheduledSubmitted") + err = page.ConfirmScheduledSubmitted(ctx) + confirmDone(err) + if err != nil { return fmt.Errorf("%w: %v", ErrSubmitFailed, err) } return nil