refactor(logging): унифицировать stdlib log.* в logx по client/cmd

internal/client/captcha, captcha/manual, dnsdial: добавить package-level Log +
SetLogger; убрать прямой обход -debug через stdlib log.Printf. cmd/{client,
server}/main.go: сначала строить logger, весь вывод через logger.{Info,Warn,
Error}f; оставлен один log.Fatalf только для сбоя разбора конфига до логгера.
dnsdial: log.Panicf → panic(fmt.Sprintf).

Исправлены уровни:
- vkauth/token.go: пути [FATAL] теперь Errorf; Auto/Manual captcha failed →
  Warnf; ignored-cleanup-error → Debugf.
- vkauth/client.go: HandleAuthError/cache invalidated → Warnf; throttle wait →
  Debugf; Failed-with-client_id → Warnf.
- udprelay: "Backing off 60s" + SetDeadline failed → Warnf.
- captcha: PoW/show_type/check status/debug_info → Debugf; endSession/close-body/
  script-drift → Warnf.

Префиксы нормализованы к [STREAM %d] [Pkg] msg / [Pkg] msg.
This commit is contained in:
samosvalishe
2026-05-20 11:23:05 +03:00
parent 52e7cb83e6
commit 9d7d754740
11 changed files with 146 additions and 112 deletions
+25 -16
View File
@@ -39,51 +39,58 @@ func manualCaptchaSolver(_ context.Context, e *captcha.Error, d net.Dialer) (str
}
func main() {
cfg, err := config.ParseClient(os.Args[1:], os.Stderr)
if err != nil {
// logger not built yet — config parse failure is the only pre-logger fatal.
log.Fatalf("%v", err)
}
logger := logx.New(cfg.Log.Debug)
captcha.SetLogger(logger)
manualcaptcha.SetLogger(logger)
dnsdial.SetLogger(logger)
manualcaptcha.Debug = cfg.Log.Debug
ctx, cancel := context.WithCancel(context.Background())
defer cancel()
signalChan := make(chan os.Signal, 1)
signal.Notify(signalChan, syscall.SIGTERM, syscall.SIGINT)
go func() {
<-signalChan
log.Printf("Terminating...\n")
logger.Infof("Terminating...")
cancel()
select {
case <-signalChan:
case <-time.After(5 * time.Second):
}
log.Fatalf("Exit...\n")
logger.Errorf("Exit...")
os.Exit(1)
}()
cfg, err := config.ParseClient(os.Args[1:], os.Stderr)
if err != nil {
log.Fatalf("%v", err)
}
if cfg.DNS.Servers != nil {
dnsdial.SetUDPDNSServers(cfg.DNS.Servers)
log.Printf("[DNS] using custom UDP servers: %v", cfg.DNS.Servers)
logger.Infof("[DNS] using custom UDP servers: %v", cfg.DNS.Servers)
}
appDialer := dnsdial.AppDialer(cfg.DNS.Mode)
dnsdial.InstallGlobalResolver(cfg.DNS.Mode)
if cfg.Obf.GenWrapKey {
key, gerr := srtpmimicry.GenKeyHex()
if gerr != nil {
log.Panicf("%v", gerr)
logger.Errorf("gen-wrap-key: %v", gerr)
os.Exit(1)
}
fmt.Println(key)
return
}
peer, err := net.ResolveUDPAddr("udp", cfg.Proxy.Peer)
if err != nil {
panic(err)
logger.Errorf("resolve peer addr: %v", err)
os.Exit(1)
}
if cfg.Obf.WrapMode {
log.Printf("WRAP mode enabled: peer server must use matching -wrap-key")
logger.Infof("WRAP mode enabled: peer server must use matching -wrap-key")
}
logger := logx.New(cfg.Log.Debug)
manualcaptcha.Debug = cfg.Log.Debug
var connectedStreams atomic.Int32
vkAuth := vkauth.New(vkauth.Config{
@@ -112,7 +119,8 @@ func main() {
GetCreds: tcpfwd.GetCredsFunc(vkAuth.GetCredentials),
}
if err := tcpfwd.Run(ctx, vlessDeps, vlessParams, peer, cfg.Proxy.Listen, cfg.TURN.N, cfg.Proxy.Mode == config.ProxyModeTCPFwdBond); err != nil {
log.Fatalf("tcpfwd: %v", err)
logger.Errorf("tcpfwd: %v", err)
os.Exit(1)
}
return
}
@@ -130,6 +138,7 @@ func main() {
GetCreds: udprelay.GetCredsFunc(vkAuth.GetCredentials),
}
if err := udprelay.Run(ctx, udpDtlsDialer, vkAuth, logger, &connectedStreams, cancel, udpParams, peer, cfg.Proxy.Listen, cfg.TURN.N); err != nil {
log.Fatalf("udprelay: %v", err)
logger.Errorf("udprelay: %v", err)
os.Exit(1)
}
}
+24 -17
View File
@@ -24,6 +24,7 @@ import (
func main() {
cfg, err := config.ParseServer(os.Args[1:], os.Stderr)
if err != nil {
// logger not built yet — config parse failure is the only pre-logger fatal.
log.Fatalf("%v", err)
}
logger := logx.New(cfg.Log.Debug)
@@ -32,7 +33,8 @@ func main() {
if cfg.Obf.GenWrapKey {
key, gerr := srtpmimicry.GenKeyHex()
if gerr != nil {
log.Fatalf("gen-wrap-key: %v", gerr)
logger.Errorf("gen-wrap-key: %v", gerr)
os.Exit(1)
}
fmt.Println(key)
return
@@ -44,22 +46,25 @@ func main() {
signal.Notify(signalChan, syscall.SIGTERM, syscall.SIGINT)
go func() {
<-signalChan
log.Printf("Terminating...\n")
logger.Infof("Terminating...")
cancel()
<-signalChan
log.Fatalf("Exit...\n")
logger.Errorf("Exit...")
os.Exit(1)
}()
addr, err := net.ResolveUDPAddr("udp", cfg.Proxy.Listen)
if err != nil {
panic(err)
logger.Errorf("resolve listen addr: %v", err)
os.Exit(1)
}
log.Printf("Starting server listen=%s connect=%s vless=%t wrap=%t bond-autodetect=true",
logger.Infof("Starting server listen=%s connect=%s vless=%t wrap=%t bond-autodetect=true",
cfg.Proxy.Listen, cfg.Proxy.Connect, cfg.Proxy.Mode == config.ProxyModeTCPFwd, cfg.Obf.WrapMode)
certificate, genErr := selfsign.GenerateSelfSigned()
if genErr != nil {
panic(genErr)
logger.Errorf("self-signed cert: %v", genErr)
os.Exit(1)
}
dtlsOpts := []dtls.ServerOption{
@@ -70,25 +75,27 @@ func main() {
}
var listener net.Listener
if cfg.Obf.WrapMode {
log.Printf("WRAP mode enabled: listener only accepts clients with matching -wrap-key")
logger.Infof("WRAP mode enabled: listener only accepts clients with matching -wrap-key")
wrapListener, werr := srtpmimicry.Listen(addr, cfg.Obf.WrapKey)
if werr != nil {
panic(werr)
logger.Errorf("wrap listen: %v", werr)
os.Exit(1)
}
listener, err = dtls.NewListenerWithOptions(wrapListener, dtlsOpts...)
} else {
listener, err = dtls.ListenWithOptions("udp", addr, dtlsOpts...)
}
if err != nil {
panic(err)
logger.Errorf("dtls listen: %v", err)
os.Exit(1)
}
context.AfterFunc(ctx, func() {
if err = listener.Close(); err != nil {
panic(err)
logger.Errorf("listener close: %v", err)
}
})
fmt.Println("Listening")
logger.Infof("Listening on %s", cfg.Proxy.Listen)
var wg sync.WaitGroup
for {
@@ -100,7 +107,7 @@ func main() {
}
conn, err := listener.Accept()
if err != nil {
log.Println(err)
logger.Warnf("accept: %v", err)
continue
}
wg.Go(func() {
@@ -112,22 +119,22 @@ func main() {
func handleAccepted(ctx context.Context, logger logx.Logger, registry *bondserver.Registry, conn net.Conn, cfg *config.Server) {
defer func() {
if closeErr := conn.Close(); closeErr != nil {
log.Printf("failed to close incoming connection: %s", closeErr)
logger.Warnf("failed to close incoming connection: %s", closeErr)
}
}()
logger.Debugf("Connection from %s\n", conn.RemoteAddr())
logger.Debugf("Connection from %s", conn.RemoteAddr())
ctx1, cancel1 := context.WithTimeout(ctx, 30*time.Second)
defer cancel1()
dtlsConn, ok := conn.(*dtls.Conn)
if !ok {
log.Println("Type error: expected *dtls.Conn")
logger.Errorf("Type error: expected *dtls.Conn")
return
}
logger.Debugf("Start handshake")
if err := dtlsConn.HandshakeContext(ctx1); err != nil {
log.Printf("Handshake failed: %v", err)
logger.Warnf("Handshake failed: %v", err)
return
}
logger.Debugf("Handshake done")
@@ -138,5 +145,5 @@ func handleAccepted(ctx context.Context, logger logx.Logger, registry *bondserve
udpserver.Handle(ctx, logger, conn, cfg.Proxy.Connect)
}
logger.Debugf("Connection closed: %s\n", conn.RemoteAddr())
logger.Debugf("Connection closed: %s", conn.RemoteAddr())
}
+20 -13
View File
@@ -11,7 +11,6 @@ import (
"errors"
"fmt"
"io"
"log"
mathrand "math/rand"
"regexp"
"strconv"
@@ -23,8 +22,16 @@ import (
tlsclient "github.com/bogdanfinn/tls-client"
"github.com/cacggghp/vk-turn-proxy/internal/client/browserprofile"
"github.com/cacggghp/vk-turn-proxy/internal/logx"
)
// Log is the package-level logger. Defaults to no-op; main wires it via
// SetLogger so captcha output respects the global -debug flag and levels.
var Log logx.Logger = logx.Nop()
// SetLogger installs a logger for this package. Safe to call once at startup.
func SetLogger(l logx.Logger) { Log = logx.OrNop(l) }
const (
captchaAPIVersion = "5.131"
captchaScriptVersion = "1.1.1324"
@@ -121,7 +128,7 @@ func Solve(
if captchaErr == nil || captchaErr.SessionToken == "" {
return "", fmt.Errorf("no session_token in redirect_uri")
}
log.Printf("[STREAM %d] [Captcha] Solving VK Smart Captcha automatically...", streamID)
Log.Infof("[STREAM %d] [Captcha] Solving VK Smart Captcha automatically...", streamID)
s := &captchaSession{ctx: ctx, client: client, profile: profile, savedProfile: savedProfile}
@@ -130,7 +137,7 @@ func Solve(
if solveErr == nil {
return token, nil
}
log.Printf("[STREAM %d] [Captcha] captcha solve attempt %d failed: %v", streamID, attempt, solveErr)
Log.Warnf("[STREAM %d] [Captcha] solve attempt %d failed: %v", streamID, attempt, solveErr)
if errors.Is(solveErr, errCaptchaRateLimit) {
return "", solveErr
}
@@ -176,12 +183,12 @@ func (s *captchaSession) solveOnce(captchaErr *Error) (string, error) {
return "", errors.New("failed to find slider captcha settings")
}
log.Printf("captcha solving pow difficulty=%d", page.PowDifficulty)
Log.Debugf("[Captcha] solving pow difficulty=%d", page.PowDifficulty)
hash := solveCaptchaPoW(s.ctx, page.PowInput, page.PowDifficulty)
if hash == "" {
return "", errors.New("captcha pow failed")
}
log.Printf("captcha pow solved")
Log.Debugf("[Captcha] pow solved")
base := captchaBaseValues(captchaErr.SessionToken)
if _, settingsErr := s.captchaRequest("captchaNotRobot.settings", base); settingsErr != nil {
@@ -198,7 +205,7 @@ func (s *captchaSession) solveOnce(captchaErr *Error) (string, error) {
if m := reCaptchaVersion.FindStringSubmatch(page.ScriptURL); len(m) > 1 {
if m[1] != captchaScriptVersion {
log.Printf("captcha script version drift: known=%s latest=%s", captchaScriptVersion, m[1])
Log.Warnf("[Captcha] script version drift: known=%s latest=%s", captchaScriptVersion, m[1])
}
}
@@ -213,7 +220,7 @@ func (s *captchaSession) solveOnce(captchaErr *Error) (string, error) {
}
var token string
for {
log.Printf("captcha solving show_type=%s", showType)
Log.Debugf("[Captcha] solving show_type=%s", showType)
switch showType {
case "slider":
token, err = s.solveSliderCaptcha(captchaErr.SessionToken, browserFP, hash, sliderSettings, debugInfo)
@@ -226,7 +233,7 @@ func (s *captchaSession) solveOnce(captchaErr *Error) (string, error) {
break
}
if errors.Is(err, errCaptchaBot) && !strings.EqualFold(showType, "slider") && sliderSettings != "" {
log.Printf("captcha checkbox returned BOT, trying slider challenge from page settings")
Log.Infof("[Captcha] checkbox returned BOT, trying slider challenge")
showType = "slider"
continue
}
@@ -238,7 +245,7 @@ func (s *captchaSession) solveOnce(captchaErr *Error) (string, error) {
}
if _, endErr := s.captchaRequest("captchaNotRobot.endSession", base); endErr != nil {
log.Printf("captcha endSession failed: %v", endErr)
Log.Warnf("[Captcha] endSession failed: %v", endErr)
}
return token, nil
}
@@ -293,7 +300,7 @@ func (s *captchaSession) fetchDebugInfo(scriptURL string) (string, error) {
}
v := string(m[1])
captchaDebugCache.Store(scriptURL, v)
log.Printf("captcha debug_info fetched url=%s", scriptURL)
Log.Debugf("[Captcha] debug_info fetched url=%s", scriptURL)
return v, nil
}
@@ -386,9 +393,9 @@ func (s *captchaSession) performCaptchaCheck(
return nil, err
}
if check.ShowType != "" {
log.Printf("captcha check status=%s show_type=%s", check.Status, check.ShowType)
Log.Debugf("[Captcha] check status=%s show_type=%s", check.Status, check.ShowType)
} else {
log.Printf("captcha check status=%s", check.Status)
Log.Debugf("[Captcha] check status=%s", check.Status)
}
return check, nil
}
@@ -521,7 +528,7 @@ func (s *captchaSession) doRaw(
}
defer func() {
if closeErr := resp.Body.Close(); closeErr != nil {
log.Printf("captcha close body: %s", closeErr)
Log.Warnf("[Captcha] close body: %s", closeErr)
}
}()
return io.ReadAll(resp.Body)
+6 -7
View File
@@ -2,7 +2,6 @@ package captcha
import (
"fmt"
"log"
neturl "net/url"
)
@@ -25,14 +24,14 @@ type Error struct {
func ParseError(errData map[string]any) *Error {
codeFloat, ok := errData["error_code"].(float64)
if !ok {
log.Printf("missing error_code in captcha error data")
Log.Warnf("[Captcha] missing error_code in error data")
return nil
}
code := int(codeFloat)
redirectURI, ok := errData["redirect_uri"].(string)
if !ok {
log.Printf("missing redirect_uri in captcha error data")
Log.Warnf("[Captcha] missing redirect_uri in error data")
return nil
}
@@ -41,20 +40,20 @@ func ParseError(errData map[string]any) *Error {
if sidNum, ok2 := errData["captcha_sid"].(float64); ok2 {
captchaSid = fmt.Sprintf("%.0f", sidNum)
} else {
log.Printf("missing captcha_sid in captcha error data")
Log.Warnf("[Captcha] missing captcha_sid in error data")
return nil
}
}
captchaImg, ok := errData["captcha_img"].(string)
if !ok {
log.Printf("missing captcha_img in captcha error data")
Log.Warnf("[Captcha] missing captcha_img in error data")
return nil
}
errorMsg, ok := errData["error_msg"].(string)
if !ok {
log.Printf("missing error_msg in captcha error data")
Log.Warnf("[Captcha] missing error_msg in error data")
return nil
}
@@ -63,7 +62,7 @@ func ParseError(errData map[string]any) *Error {
if parsed, err := neturl.Parse(redirectURI); err == nil {
sessionToken = parsed.Query().Get("session_token")
} else {
log.Printf("failed to parse redirect_uri: %v", err)
Log.Warnf("[Captcha] failed to parse redirect_uri: %v", err)
return nil
}
}
+24 -17
View File
@@ -14,7 +14,6 @@ import (
"errors"
"fmt"
"io"
"log"
"net"
"net/http"
"net/http/httputil"
@@ -27,12 +26,20 @@ import (
"github.com/cacggghp/vk-turn-proxy/internal/client/browserprofile"
"github.com/cacggghp/vk-turn-proxy/internal/client/ish"
"github.com/cacggghp/vk-turn-proxy/internal/logx"
)
// Debug toggles verbose request/response logging for the proxied browser
// traffic. Set from main once cfg is parsed.
var Debug bool
// Log is the package-level logger; defaults to no-op. main wires it via
// SetLogger so manual-captcha output respects -debug and levels.
var Log logx.Logger = logx.Nop()
// SetLogger installs a logger for this package.
func SetLogger(l logx.Logger) { Log = logx.OrNop(l) }
const captchaListenPort = "8765"
type browserCommand struct {
@@ -516,12 +523,12 @@ func startCaptchaServer(srv *http.Server, logPrefix string) error {
listening = true
wrappedListener, err := ish.WrapListener(listener)
if err != nil {
log.Printf("%s: failed to wrap listener for iSH: %v", logPrefix, err)
Log.Warnf("%s: failed to wrap listener for iSH: %v", logPrefix, err)
wrappedListener = listener
}
go func(listener net.Listener) {
if err := srv.Serve(listener); err != nil && !errors.Is(err, http.ErrServerClosed) {
log.Printf("%s: %s", logPrefix, err)
Log.Errorf("%s: %s", logPrefix, err)
}
}(wrappedListener)
}
@@ -548,7 +555,7 @@ func runCaptchaServerAndWait(handler http.Handler, captchaURL string, keyCh <-ch
fmt.Println("==============================================")
fmt.Println()
log.Printf("[%s] Opening browser...", logPrefix)
Log.Infof("[%s] Opening browser...", logPrefix)
openBrowser(captchaURL)
key := <-keyCh
@@ -560,7 +567,7 @@ func runCaptchaServerAndWait(handler http.Handler, captchaURL string, keyCh <-ch
shutCtx, shutCancel := context.WithTimeout(context.Background(), 3*time.Second)
defer shutCancel()
if err := srv.Shutdown(shutCtx); err != nil {
log.Printf("%s: shutdown warning (token already received): %v", logPrefix, err)
Log.Warnf("%s: shutdown warning (token already received): %v", logPrefix, err)
}
return key, nil
@@ -620,22 +627,22 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
if isCaptchaRequest {
b, err := io.ReadAll(req.Body)
if err != nil {
log.Printf("[Captcha Proxy] Failed to read request body: %v", err)
Log.Warnf("[Captcha Proxy] failed to read request body: %v", err)
b = nil
}
req.Body = io.NopCloser(bytes.NewReader(b))
if Debug {
log.Printf("[Captcha Proxy] Real browser sent %s data: %s", req.URL.Path, string(b))
Log.Debugf("[Captcha Proxy] real browser sent %s data: %s", req.URL.Path, string(b))
for k, v := range req.Header {
log.Printf("[Captcha Proxy] Header (%s): %s = %s", req.URL.Path, k, strings.Join(v, ", "))
Log.Debugf("[Captcha Proxy] header (%s): %s = %s", req.URL.Path, k, strings.Join(v, ", "))
}
}
if strings.Contains(req.URL.Path, "captchaNotRobot.componentDone") || strings.Contains(req.URL.Path, "captchaNotRobot.check") {
parsedBody, err := neturl.ParseQuery(string(b))
if err != nil {
log.Printf("[Captcha Proxy] Failed to parse request body: %v", err)
Log.Warnf("[Captcha Proxy] failed to parse request body: %v", err)
}
device := parsedBody.Get("device")
browserFp := parsedBody.Get("browser_fp")
@@ -653,9 +660,9 @@ func (t *loggingTransport) RoundTrip(req *http.Request) (*http.Response, error)
BrowserFp: browserFp,
}
if err := browserprofile.Save(sp); err != nil {
log.Printf("[Captcha Proxy] Failed to save browser profile: %v", err)
Log.Warnf("[Captcha Proxy] failed to save browser profile: %v", err)
} else {
log.Printf("[Captcha Proxy] Successfully intercepted and saved real browser profile!")
Log.Infof("[Captcha Proxy] saved real browser profile")
}
}
}
@@ -683,7 +690,7 @@ func SolveViaProxy(redirectURI string, dialer net.Dialer) (string, error) {
rewriteProxyRequest(req.Out, targetURL)
},
ErrorHandler: func(w http.ResponseWriter, r *http.Request, err error) {
log.Printf("[Captcha Proxy] ERROR for %s %s: %v", r.Method, r.URL.String(), err)
Log.Errorf("[Captcha Proxy] %s %s: %v", r.Method, r.URL.String(), err)
w.Header().Set("Content-Type", "text/html; charset=utf-8")
w.WriteHeader(http.StatusBadGateway)
_, _ = fmt.Fprintf(w, `<!DOCTYPE html><html><body style="font-family:sans-serif;padding:20px"><h2>Captcha proxy error</h2><p>%s %s</p><p>%v</p></body></html>`, r.Method, r.URL.String(), err)
@@ -705,7 +712,7 @@ func SolveViaProxy(redirectURI string, dialer net.Dialer) (string, error) {
contentType := res.Header.Get("Content-Type")
contentEncoding := res.Header.Get("Content-Encoding")
if Debug {
log.Printf("[Captcha Proxy] %s %d | Content-Type: %q, Encoding: %q", res.Request.Method, res.StatusCode, contentType, contentEncoding)
Log.Debugf("[Captcha Proxy] %s %d | Content-Type: %q, Encoding: %q", res.Request.Method, res.StatusCode, contentType, contentEncoding)
}
shouldInspectBody := strings.Contains(contentType, "text/html") ||
@@ -723,7 +730,7 @@ func SolveViaProxy(redirectURI string, dialer net.Dialer) (string, error) {
reader = gzReader
defer func() {
if err := gzReader.Close(); err != nil {
log.Printf("failed to close gzip reader: %v", err)
Log.Warnf("[Captcha Proxy] close gzip reader: %v", err)
}
}()
}
@@ -773,10 +780,10 @@ func SolveViaProxy(redirectURI string, dialer net.Dialer) (string, error) {
mux.HandleFunc("/local-captcha-result", func(w http.ResponseWriter, r *http.Request) {
token := r.FormValue("token")
if token != "" {
log.Printf("[Captcha] Received success token from browser (%d bytes)", len(token))
Log.Infof("[Captcha] received success token from browser (%d bytes)", len(token))
notifyKey(keyCh, token)
} else {
log.Printf("[Captcha] Received empty token from browser")
Log.Warnf("[Captcha] received empty token from browser")
}
w.Header().Set("Access-Control-Allow-Origin", "*")
w.Header().Set("Content-Type", "text/plain")
@@ -838,7 +845,7 @@ func SolveViaProxy(redirectURI string, dialer net.Dialer) (string, error) {
})
mux.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
log.Printf("[Captcha Proxy] HTTP %s %s", r.Method, r.URL.Path)
Log.Debugf("[Captcha Proxy] HTTP %s %s", r.Method, r.URL.Path)
if r.URL.Path == "/" && targetURL.Path != "" && targetURL.Path != "/" && r.URL.RawQuery == "" {
// Don't log the full redirect URL to keep console clean
http.Redirect(w, r, localCaptchaURLForTarget(targetURL), http.StatusTemporaryRedirect)
+5 -6
View File
@@ -9,7 +9,6 @@ import (
"image"
"image/color"
_ "image/jpeg" // register JPEG decoder for image.Decode
"log"
"math"
mathrand "math/rand"
"runtime"
@@ -59,7 +58,7 @@ func (s *captchaSession) solveSliderCaptcha(
if err != nil {
return "", err
}
log.Printf("slider puzzle decoded: grid=%d attempts=%d swaps=%d", puzzle.Size, puzzle.Attempts, len(puzzle.Swaps))
Log.Debugf("[Captcha] slider puzzle decoded: grid=%d attempts=%d swaps=%d", puzzle.Size, puzzle.Attempts, len(puzzle.Swaps))
guesses, err := rankSliderGuesses(puzzle.Image, puzzle.Size, puzzle.Swaps)
if err != nil {
@@ -73,7 +72,7 @@ func (s *captchaSession) solveSliderCaptcha(
if limit <= 0 {
return "", errors.New("slider has no attempts available")
}
log.Printf("slider guesses ranked: total=%d limit=%d", len(guesses), limit)
Log.Debugf("[Captcha] slider guesses ranked: total=%d limit=%d", len(guesses), limit)
deviceJSON := captchaDeviceInfo
if s.savedProfile != nil && strings.TrimSpace(s.savedProfile.DeviceJSON) != "" {
@@ -91,7 +90,7 @@ func (s *captchaSession) solveSliderCaptcha(
}
for i := 0; i < limit; i++ {
log.Printf("slider attempt %d/%d (guess #%d)", i+1, limit, guesses[i].Index)
Log.Debugf("[Captcha] slider attempt %d/%d (guess #%d)", i+1, limit, guesses[i].Index)
answerData, err := json.Marshal(struct {
Value []int `json:"value"`
}{Value: guesses[i].Swaps})
@@ -113,7 +112,7 @@ func (s *captchaSession) solveSliderCaptcha(
if check.SuccessToken == "" {
return "", errors.New("captcha success token not found")
}
log.Printf("slider accepted on attempt %d", i+1)
Log.Infof("[Captcha] slider accepted on attempt %d", i+1)
return check.SuccessToken, nil
}
if strings.EqualFold(check.Status, "error_limit") {
@@ -185,7 +184,7 @@ func splitSliderSteps(steps []int) (int, []int, int, error) {
if len(tail)%2 != 0 {
attempts = tail[len(tail)-1]
tail = tail[:len(tail)-1]
log.Printf("slider payload had odd-length tail; fallback attempts=%d", attempts)
Log.Warnf("[Captcha] slider payload had odd-length tail; fallback attempts=%d", attempts)
}
if attempts <= 0 {
attempts = 4
+19 -12
View File
@@ -10,7 +10,6 @@ import (
"errors"
"fmt"
"io"
"log"
"net"
"net/http"
"strings"
@@ -20,10 +19,19 @@ import (
"github.com/miekg/dns"
"github.com/cacggghp/vk-turn-proxy/internal/logx"
// Embedded Mozilla CA roots for CGO_ENABLED=0 builds (Android).
_ "golang.org/x/crypto/x509roots/fallback"
)
// Log is the package-level logger. Defaults to no-op; main wires it via
// SetLogger so DNS-mode output respects the global -debug flag and levels.
var Log logx.Logger = logx.Nop()
// SetLogger installs a logger for this package.
func SetLogger(l logx.Logger) { Log = logx.OrNop(l) }
const (
dohQueryTimeout = 6 * time.Second
// Total budget across all endpoint attempts in forwardRaw. Must be a
@@ -178,7 +186,7 @@ func (r *DohResolver) forwardRaw(ctx context.Context, query []byte) ([]byte, Doh
body, err := r.postWire(epCtx, ep, query)
cancel()
if err != nil {
log.Printf("[DoH] %s: %v", ep.Hostname, err)
Log.Warnf("[DoH] %s: %v", ep.Hostname, err)
lastErr = err
continue
}
@@ -263,7 +271,7 @@ func startDohForwarder(r *DohResolver) (_ *dohForwarder, err error) {
udpAddr: udpConn.LocalAddr().String(),
tcpAddr: tcpLn.Addr().String(),
}
log.Printf("[DoH] forwarder listening udp=%s tcp=%s", fwd.udpAddr, fwd.tcpAddr)
Log.Infof("[DoH] forwarder listening udp=%s tcp=%s", fwd.udpAddr, fwd.tcpAddr)
go fwd.serveUDP(udpConn, r)
go fwd.serveTCP(tcpLn, r)
@@ -276,7 +284,7 @@ func (f *dohForwarder) serveUDP(conn *net.UDPConn, r *DohResolver) {
for {
n, client, err := conn.ReadFromUDP(buf)
if err != nil {
log.Printf("[DoH] udp read: %v", err)
Log.Errorf("[DoH] udp read: %v", err)
return
}
query := append([]byte(nil), buf[:n]...)
@@ -285,11 +293,11 @@ func (f *dohForwarder) serveUDP(conn *net.UDPConn, r *DohResolver) {
defer cancel()
resp, _, err := r.forwardRaw(ctx, q)
if err != nil {
log.Printf("[DoH] udp forward failed: %v", err)
Log.Warnf("[DoH] udp forward failed: %v", err)
return
}
if _, err := conn.WriteToUDP(resp, c); err != nil {
log.Printf("[DoH] udp write: %v", err)
Log.Warnf("[DoH] udp write: %v", err)
}
}(query, client)
}
@@ -300,7 +308,7 @@ func (f *dohForwarder) serveTCP(ln *net.TCPListener, r *DohResolver) {
for {
conn, err := ln.Accept()
if err != nil {
log.Printf("[DoH] tcp accept: %v", err)
Log.Errorf("[DoH] tcp accept: %v", err)
return
}
go handleDohForwarderTCP(conn, r)
@@ -328,7 +336,7 @@ func handleDohForwarderTCP(conn net.Conn, r *DohResolver) {
resp, _, err := r.forwardRaw(ctx, query)
cancel()
if err != nil {
log.Printf("[DoH] tcp forward failed: %v", err)
Log.Warnf("[DoH] tcp forward failed: %v", err)
return
}
out := make([]byte, 2+len(resp))
@@ -421,8 +429,7 @@ func buildDialer(mode string, r *DohResolver) net.Dialer {
case DNSModeAuto:
return newAppDialer(autoDial(r))
default:
log.Panicf("unknown DNS mode %q", mode)
return net.Dialer{}
panic(fmt.Sprintf("unknown DNS mode %q", mode))
}
}
@@ -472,9 +479,9 @@ func autoDial(r *DohResolver) dialFunc {
return func(ctx context.Context, network, addr string) (net.Conn, error) {
probed.Do(func() {
if udpProbe(autoUDPBudget) {
log.Printf("[DNS] UDP/53 probe OK, using UDP")
Log.Infof("[DNS] UDP/53 probe OK, using UDP")
} else {
log.Printf("[DNS] UDP/53 unreachable; sticky-switching to DoH")
Log.Warnf("[DNS] UDP/53 unreachable; sticky-switching to DoH")
useDoH.Store(true)
}
})
+3 -4
View File
@@ -3,7 +3,6 @@ package vkauth
import (
"context"
"fmt"
"log"
"github.com/cacggghp/vk-turn-proxy/internal/client/browserprofile"
"github.com/cacggghp/vk-turn-proxy/internal/client/captcha"
@@ -21,7 +20,7 @@ func DefaultAutoSolve(
client tlsclient.HttpClient,
profile browserprofile.Profile,
) (string, error) {
log.Printf("[STREAM %d] [Captcha] Solving captcha...", streamID)
captcha.Log.Infof("[STREAM %d] [Captcha] Solving captcha...", streamID)
if captchaErr.SessionToken == "" {
return "", fmt.Errorf("no session_token in redirect_uri for auto-solve")
@@ -32,7 +31,7 @@ func DefaultAutoSolve(
var savedProfile *browserprofile.Saved
if sp, err := browserprofile.Load(); err == nil {
log.Printf("[STREAM %d] [Captcha] Using saved real browser profile", streamID)
captcha.Log.Infof("[STREAM %d] [Captcha] Using saved real browser profile", streamID)
savedProfile = sp
profile = sp.Profile
}
@@ -41,6 +40,6 @@ func DefaultAutoSolve(
if err != nil {
return "", err
}
log.Printf("[STREAM %d] [Captcha] solver succeeded", streamID)
captcha.Log.Infof("[STREAM %d] [Captcha] solver succeeded", streamID)
return successToken, nil
}
+6 -6
View File
@@ -156,12 +156,12 @@ func (c *Client) HandleAuthError(streamID int) bool {
count := cache.errorCount.Add(1)
cache.lastErrorTime.Store(now)
c.log.Infof("[STREAM %d] Auth error (cache=%d, count=%d/%d)", streamID, cacheID, count, MaxCacheErrors)
c.log.Warnf("[STREAM %d] [VK Auth] Auth error (cache=%d, count=%d/%d)", streamID, cacheID, count, MaxCacheErrors)
if count >= MaxCacheErrors {
c.log.Infof("[VK Auth] Multiple auth errors detected (%d), invalidating cache %d for stream %d...", count, cacheID, streamID)
c.log.Warnf("[VK Auth] Multiple auth errors (%d), invalidating cache %d for stream %d", count, cacheID, streamID)
cache.Invalidate()
c.log.Infof("[STREAM %d] [VK Auth] Credentials cache invalidated", streamID)
c.log.Warnf("[STREAM %d] [VK Auth] Credentials cache invalidated", streamID)
return true
}
return false
@@ -197,7 +197,7 @@ func (c *Client) fetchSerialized(ctx context.Context, link string, streamID int)
elapsed := time.Since(c.lastFetchTime)
if !c.lastFetchTime.IsZero() && elapsed < minInterval {
wait := minInterval - elapsed
c.log.Infof("[STREAM %d] [VK Auth] Throttling: waiting %v to prevent rate limit...", streamID, wait.Truncate(time.Millisecond))
c.log.Debugf("[STREAM %d] [VK Auth] Throttling: waiting %v to prevent rate limit", streamID, wait.Truncate(time.Millisecond))
select {
case <-ctx.Done():
return "", "", nil, ctx.Err()
@@ -225,14 +225,14 @@ func (c *Client) fetch(ctx context.Context, link string, streamID int) (string,
return user, pass, addrs, nil
}
lastErr = err
c.log.Infof("[STREAM %d] [VK Auth] Failed with client_id=%s: %v", streamID, creds.ClientID, err)
c.log.Warnf("[STREAM %d] [VK Auth] Failed with client_id=%s: %v", streamID, creds.ClientID, err)
if errors.Is(err, ErrCaptchaWaitRequired) || errors.Is(err, ErrFatalCaptchaNoStreams) {
return "", "", nil, err
}
es := err.Error()
if strings.Contains(es, "error_code:29") || strings.Contains(es, "error_code: 29") || strings.Contains(es, "Rate limit") {
c.log.Infof("[STREAM %d] [VK Auth] Rate limit detected, trying next credentials...", streamID)
c.log.Warnf("[STREAM %d] [VK Auth] Rate limit detected, trying next credentials", streamID)
}
}
return "", "", nil, fmt.Errorf("all VK credentials failed: %w", lastErr)
+12 -12
View File
@@ -75,7 +75,7 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
}
defer func() {
if closeErr := httpResp.Body.Close(); closeErr != nil {
c.log.Infof("close response body: %s", closeErr)
c.log.Warnf("[VK Auth] close response body: %s", closeErr)
}
}()
@@ -109,7 +109,7 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
// Token 1 -> getCallPreview (warmup, non-fatal).
data = fmt.Sprintf("vk_join_link=https://vk.com/call/join/%s&fields=photo_200&access_token=%s", link, token1)
if _, prevErr := doRequest(data, "https://api.vk.ru/method/calls.getCallPreview?v=5.275&client_id="+creds.ClientID); prevErr != nil {
c.log.Infof("[STREAM %d] [VK Auth] Warning: getCallPreview failed: %v", streamID, prevErr)
c.log.Warnf("[STREAM %d] [VK Auth] getCallPreview failed: %v", streamID, prevErr)
}
vkDelayRandom(200, 400)
@@ -130,10 +130,10 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
if captchaErr != nil && captchaErr.IsCaptcha() {
solveMode, hasSolveMode := CaptchaSolveModeForAttempt(attempt, c.manualOnly)
if !hasSolveMode {
c.log.Infof("[STREAM %d] [Captcha] No more solve modes available (attempt %d)", streamID, attempt+1)
c.log.Warnf("[STREAM %d] [Captcha] No more solve modes available (attempt %d)", streamID, attempt+1)
c.engageLockout(60 * time.Second)
if c.streamsFn() == 0 {
c.log.Infof("[STREAM %d] [FATAL] 0 connected streams and captcha solve modes exhausted.", streamID)
c.log.Errorf("[STREAM %d] [Captcha] FATAL: 0 connected streams and solve modes exhausted", streamID)
return "", "", nil, ErrFatalCaptchaNoStreams
}
return "", "", nil, ErrCaptchaWaitRequired
@@ -152,7 +152,7 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
if captchaErr.SessionToken != "" && captchaErr.RedirectURI != "" {
successToken, solveErr = solveFn(ctx, captchaErr, streamID, client, profile)
if solveErr != nil {
c.log.Infof("[STREAM %d] [Captcha] Auto captcha failed: %v", streamID, solveErr)
c.log.Warnf("[STREAM %d] [Captcha] Auto captcha failed: %v", streamID, solveErr)
}
} else {
solveErr = fmt.Errorf("missing fields for auto solve")
@@ -162,7 +162,7 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
solveErr = fmt.Errorf("manual captcha solver not configured")
break
}
c.log.Infof("[STREAM %d] [Captcha] Triggering manual captcha fallback...", streamID)
c.log.Infof("[STREAM %d] [Captcha] Triggering manual captcha fallback", streamID)
// Manual solver gets its own 3-min budget so a tight parent
// deadline doesn't cut user solve time. We still propagate
// parent cancellation (app shutdown) so the in-flight solver
@@ -187,12 +187,12 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
solveErr = res.err
if successToken != "" || captchaKey != "" {
if solveErr != nil {
c.log.Infof("[STREAM %d] [Captcha] Token received (ignoring cleanup error: %v)", streamID, solveErr)
c.log.Debugf("[STREAM %d] [Captcha] Token received (ignoring cleanup error: %v)", streamID, solveErr)
solveErr = nil
}
c.log.Infof("[STREAM %d] [Captcha] Successfully got token from browser", streamID)
c.log.Infof("[STREAM %d] [Captcha] Got token from browser", streamID)
} else if solveErr != nil {
c.log.Infof("[STREAM %d] [Captcha] manual solver returned error: %v", streamID, solveErr)
c.log.Warnf("[STREAM %d] [Captcha] Manual solver error: %v", streamID, solveErr)
}
case <-manualCtx.Done():
if errors.Is(manualCtx.Err(), context.DeadlineExceeded) {
@@ -205,15 +205,15 @@ func (c *Client) getTokenChain(ctx context.Context, link string, streamID int, c
}
if solveErr != nil {
c.log.Infof("[STREAM %d] [Captcha] %s failed (attempt %d): %v", streamID, CaptchaSolveModeLabel(solveMode), attempt+1, solveErr)
c.log.Warnf("[STREAM %d] [Captcha] %s failed (attempt %d): %v", streamID, CaptchaSolveModeLabel(solveMode), attempt+1, solveErr)
nextSolveMode, hasNextSolveMode := CaptchaSolveModeForAttempt(attempt+1, c.manualOnly)
if hasNextSolveMode {
c.log.Infof("[STREAM %d] [Captcha] Falling back to %s...", streamID, CaptchaSolveModeLabel(nextSolveMode))
c.log.Infof("[STREAM %d] [Captcha] Falling back to %s", streamID, CaptchaSolveModeLabel(nextSolveMode))
continue
}
c.engageLockout(60 * time.Second)
if c.streamsFn() == 0 {
c.log.Infof("[STREAM %d] [FATAL] 0 connected streams and manual captcha failed/timed out.", streamID)
c.log.Errorf("[STREAM %d] [Captcha] FATAL: 0 connected streams and manual captcha failed/timed out", streamID)
return "", "", nil, ErrFatalCaptchaNoStreams
}
return "", "", nil, ErrCaptchaWaitRequired
+2 -2
View File
@@ -255,7 +255,7 @@ func TURNLoop(ctx context.Context, deps *Deps, params *Params, peer *net.UDPAddr
}
if errors.Is(err, vkauth.ErrCaptchaWaitRequired) {
if !errors.Is(err, vkauth.ErrLockoutActive) {
deps.log().Errorf("[STREAM %d] Backing off for 60 seconds to avoid IP ban...", streamID)
deps.log().Warnf("[STREAM %d] Backing off for 60 seconds to avoid IP ban", streamID)
select {
case <-ctx.Done():
return
@@ -330,7 +330,7 @@ func oneDTLS(ctx context.Context, deps *Deps, peer *net.UDPAddr, listenConn net.
wg := sync.WaitGroup{}
context.AfterFunc(dtlsctx, func() {
if err := dtlsConn.SetDeadline(time.Now()); err != nil {
deps.log().Errorf("[STREAM %d] Warning: SetDeadline failed: %v", streamID, err)
deps.log().Warnf("[STREAM %d] SetDeadline failed: %v", streamID, err)
}
})