From e57269d38619795477a0daf08a6c411027ca5b29 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 23 Jun 2026 14:20:13 +0000 Subject: [PATCH] feat: add throttled captcha/auth debug logging Under -debug, surface the captcha/auth diagnostics that were previously missing: a redacted breakdown of each error_code:14 challenge (parsed fields, redirect base, session_token preview/length), the chosen solve mode per attempt, the v2 page parse summary (show_type, pow difficulty, slider availability, script URL), and the raw error map whenever an error_code:14 is not recognized as a solvable captcha (so the next VK format change is diagnosable without a code edit). All new lines go through debugThrottledf, which emits at most once per 3s per key, so eight concurrent streams hitting the same challenge no longer flood the log. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01HhExd8rxbEfhzJjBiawRQH --- client/captcha_v2.go | 8 ++++++ client/main.go | 65 ++++++++++++++++++++++++++++++++++++++++++++ client/main_test.go | 35 +++++++++++++++++++++++- 3 files changed, 107 insertions(+), 1 deletion(-) diff --git a/client/captcha_v2.go b/client/captcha_v2.go index 1a3b925..4a43653 100644 --- a/client/captcha_v2.go +++ b/client/captcha_v2.go @@ -172,6 +172,14 @@ func (s *captchaV2Session) solveOnce(captchaErr *VkCaptchaError) (string, error) return "", errors.New("failed to find slider captcha settings") } + pageShowType := "" + if page.Init != nil { + pageShowType = page.Init.Data.ShowCaptchaType + } + debugThrottledf("captcha-v2-page", + "[Captcha][debug] v2 page parsed show_type=%q pow_difficulty=%d slider_available=%t script=%s html_len=%d", + pageShowType, page.PowDifficulty, sliderSettings != "", page.ScriptURL, len(html)) + log.Printf("v2 captcha solving pow difficulty=%d", page.PowDifficulty) hash := solveCaptchaPoWV2(s.ctx, page.PowInput, page.PowDifficulty) if hash == "" { diff --git a/client/main.go b/client/main.go index 6e1bdaf..f470ecd 100644 --- a/client/main.go +++ b/client/main.go @@ -78,6 +78,58 @@ func debugf(format string, v ...any) { } } +// debugThrottleInterval is the minimum gap between two emissions of the same +// throttled debug key. It keeps verbose per-stream diagnostics readable when +// many streams hit the same code path at once (e.g. all of them getting the +// same captcha challenge within a second). +const debugThrottleInterval = 3 * time.Second + +var debugThrottleState sync.Map // key string -> *atomic.Int64 (last emit, unix nano) + +// debugThrottledf logs like debugf but at most once per debugThrottleInterval +// for a given key. Use distinct keys for distinct message groups. +func debugThrottledf(key, format string, v ...any) { + if !isDebug { + return + } + now := time.Now().UnixNano() + val, _ := debugThrottleState.LoadOrStore(key, new(atomic.Int64)) + last, ok := val.(*atomic.Int64) + if !ok { + return + } + prev := last.Load() + if prev != 0 && now-prev < int64(debugThrottleInterval) { + return + } + // CompareAndSwap ensures only one goroutine wins the slot per interval. + if !last.CompareAndSwap(prev, now) { + return + } + log.Printf(format, v...) +} + +// debugCaptchaError emits a throttled, human-readable breakdown of a captcha +// challenge: the parsed fields plus a redacted session_token preview, without +// dumping the multi-kilobyte raw redirect_uri on every stream. +func debugCaptchaError(streamID int, c *VkCaptchaError) { + if !isDebug || c == nil { + return + } + redirectBase := c.RedirectURI + if u, err := neturl.Parse(c.RedirectURI); err == nil { + redirectBase = u.Scheme + "://" + u.Host + u.Path + } + tokenPreview := c.SessionToken + if len(tokenPreview) > 12 { + tokenPreview = tokenPreview[:12] + "…" + } + debugThrottledf("captcha-error", + "[STREAM %d] [Captcha][debug] code=%d msg=%q captcha_sid=%q captcha_img=%t redirect=%s session_token=%s (len=%d)", + streamID, c.ErrorCode, c.ErrorMsg, c.CaptchaSid, c.CaptchaImg != "", + redirectBase, tokenPreview, len(c.SessionToken)) +} + type captchaSolveMode int const ( @@ -1160,6 +1212,7 @@ func getTokenChain(ctx context.Context, link string, streamID int, creds VKCrede if errObj, hasErr := resp["error"].(map[string]interface{}); hasErr { captchaErr := ParseVkCaptchaError(errObj) if captchaErr != nil && captchaErr.IsCaptchaError() { + debugCaptchaError(streamID, captchaErr) solveMode, hasSolveMode := captchaSolveModeForAttempt(attempt, manualCaptcha, autoCaptchaSliderPOC) if !hasSolveMode { log.Printf("[STREAM %d] [Captcha] No more solve modes available (attempt %d)", streamID, attempt+1) @@ -1175,6 +1228,10 @@ func getTokenChain(ctx context.Context, link string, streamID int, creds VKCrede return "", "", nil, fmt.Errorf("CAPTCHA_WAIT_REQUIRED") } + debugThrottledf("captcha-mode", + "[STREAM %d] [Captcha][debug] attempt=%d solving via %s", + streamID, attempt+1, captchaSolveModeLabel(solveMode)) + var successToken string var captchaKey string var solveErr error @@ -1286,6 +1343,14 @@ func getTokenChain(ctx context.Context, link string, streamID int, creds VKCrede } continue } + // error_code:14 that did not pass IsCaptchaError means VK changed the + // challenge shape again — surface the raw map under -debug so the next + // breakage is diagnosable without a code change. + if code, _ := errObj["error_code"].(float64); int(code) == 14 { + debugThrottledf("captcha-unrecognized", + "[STREAM %d] [Captcha][debug] error_code:14 not recognized as solvable captcha, raw=%v", + streamID, errObj) + } return "", "", nil, fmt.Errorf("VK API error: %v", errObj) } diff --git a/client/main_test.go b/client/main_test.go index 1a49653..1e4f2c0 100644 --- a/client/main_test.go +++ b/client/main_test.go @@ -1,6 +1,11 @@ package main -import "testing" +import ( + "bytes" + "log" + "strings" + "testing" +) func TestCaptchaSolveModeForAttempt(t *testing.T) { t.Parallel() @@ -111,3 +116,31 @@ func TestParseVkCaptchaErrorLegacySid(t *testing.T) { t.Fatal("expected captcha_img to be preserved") } } + +func TestDebugThrottledfSuppressesRepeats(t *testing.T) { + // Not parallel: mutates package-global isDebug and log output. + prevDebug := isDebug + isDebug = true + defer func() { isDebug = prevDebug }() + + var buf bytes.Buffer + prevOut := log.Writer() + prevFlags := log.Flags() + log.SetOutput(&buf) + log.SetFlags(0) + defer func() { + log.SetOutput(prevOut) + log.SetFlags(prevFlags) + }() + + key := "test-throttle-" + t.Name() + debugThrottleState.Delete(key) + + for i := 0; i < 5; i++ { + debugThrottledf(key, "tick %d", i) + } + + if got := strings.Count(buf.String(), "tick "); got != 1 { + t.Fatalf("expected throttle to emit exactly once within interval, got %d lines: %q", got, buf.String()) + } +}