Browse Source

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 <[email protected]>
Claude-Session: https://claude.ai/code/session_01HhExd8rxbEfhzJjBiawRQH
pull/181/head
Claude 3 weeks ago
parent
commit
e57269d386
Failed to extract signature
  1. 8
      client/captcha_v2.go
  2. 65
      client/main.go
  3. 35
      client/main_test.go

8
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") 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) log.Printf("v2 captcha solving pow difficulty=%d", page.PowDifficulty)
hash := solveCaptchaPoWV2(s.ctx, page.PowInput, page.PowDifficulty) hash := solveCaptchaPoWV2(s.ctx, page.PowInput, page.PowDifficulty)
if hash == "" { if hash == "" {

65
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 type captchaSolveMode int
const ( 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 { if errObj, hasErr := resp["error"].(map[string]interface{}); hasErr {
captchaErr := ParseVkCaptchaError(errObj) captchaErr := ParseVkCaptchaError(errObj)
if captchaErr != nil && captchaErr.IsCaptchaError() { if captchaErr != nil && captchaErr.IsCaptchaError() {
debugCaptchaError(streamID, captchaErr)
solveMode, hasSolveMode := captchaSolveModeForAttempt(attempt, manualCaptcha, autoCaptchaSliderPOC) solveMode, hasSolveMode := captchaSolveModeForAttempt(attempt, manualCaptcha, autoCaptchaSliderPOC)
if !hasSolveMode { if !hasSolveMode {
log.Printf("[STREAM %d] [Captcha] No more solve modes available (attempt %d)", streamID, attempt+1) 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") 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 successToken string
var captchaKey string var captchaKey string
var solveErr error var solveErr error
@ -1286,6 +1343,14 @@ func getTokenChain(ctx context.Context, link string, streamID int, creds VKCrede
} }
continue 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) return "", "", nil, fmt.Errorf("VK API error: %v", errObj)
} }

35
client/main_test.go

@ -1,6 +1,11 @@
package main package main
import "testing" import (
"bytes"
"log"
"strings"
"testing"
)
func TestCaptchaSolveModeForAttempt(t *testing.T) { func TestCaptchaSolveModeForAttempt(t *testing.T) {
t.Parallel() t.Parallel()
@ -111,3 +116,31 @@ func TestParseVkCaptchaErrorLegacySid(t *testing.T) {
t.Fatal("expected captcha_img to be preserved") 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())
}
}

Loading…
Cancel
Save