From 7b889ae5eeca17af568ede857dba5bc3e9694d27 Mon Sep 17 00:00:00 2001 From: zarazaex69 Date: Thu, 9 Apr 2026 20:34:50 +0300 Subject: [PATCH] feat(client): Add detailed timing and diagnostic logging for SOCKS5 connections --- internal/client/client.go | 9 ++++++++- internal/mux/mux.go | 3 +++ internal/server/server.go | 17 +++++++++++------ internal/telemost/peer.go | 19 +++++++++++++++---- 4 files changed, 37 insertions(+), 11 deletions(-) diff --git a/internal/client/client.go b/internal/client/client.go index 5f267d9..ace4a8b 100644 --- a/internal/client/client.go +++ b/internal/client/client.go @@ -194,6 +194,7 @@ func (c *Client) runSOCKS5(ctx context.Context, port int) error { func (c *Client) handleSOCKS5(conn net.Conn) { defer conn.Close() + startTime := time.Now() buf := make([]byte, 256) @@ -251,7 +252,7 @@ func (c *Client) handleSOCKS5(conn net.Conn) { sid := c.mux.OpenStream() logger.Verbose("SOCKS5 opened stream sid=%d for %s:%d", sid, addr, port) - log.Printf("SOCKS5 connect sid=%d %s:%d", sid, addr, port) + log.Printf("[CLIENT] sid=%d SOCKS5_START %s:%d", sid, addr, port) req := map[string]interface{}{ "cmd": "connect", @@ -260,20 +261,25 @@ func (c *Client) handleSOCKS5(conn net.Conn) { } reqData, _ := json.Marshal(req) + sendTime := time.Now() c.mux.SendData(sid, reqData) + log.Printf("[CLIENT] sid=%d SEND_REQUEST elapsed=%v", sid, time.Since(sendTime)) dataReady := c.mux.WaitForData(sid) timeout := time.NewTimer(10 * time.Second) defer timeout.Stop() + waitStart := time.Now() select { case <-dataReady: + log.Printf("[CLIENT] sid=%d RESPONSE_RECEIVED wait_time=%v total_elapsed=%v", sid, time.Since(waitStart), time.Since(startTime)) stream := c.mux.GetStream(sid) if stream == nil || len(stream.RecvBuf()) == 0 { conn.Write([]byte{5, 4, 0, 1, 0, 0, 0, 0, 0, 0}) return } case <-timeout.C: + log.Printf("[CLIENT] sid=%d TIMEOUT after wait_time=%v total_elapsed=%v", sid, time.Since(waitStart), time.Since(startTime)) conn.Write([]byte{5, 4, 0, 1, 0, 0, 0, 0, 0, 0}) return } @@ -281,6 +287,7 @@ func (c *Client) handleSOCKS5(conn net.Conn) { c.mux.ReadStream(sid) conn.Write([]byte{5, 0, 0, 1, 0, 0, 0, 0, 0, 0}) + log.Printf("[CLIENT] sid=%d SOCKS5_READY total_elapsed=%v", sid, time.Since(startTime)) done := make(chan struct{}) streamClosed := make(chan struct{}) diff --git a/internal/mux/mux.go b/internal/mux/mux.go index 710c43d..bb3713f 100644 --- a/internal/mux/mux.go +++ b/internal/mux/mux.go @@ -111,6 +111,7 @@ func (m *Multiplexer) SendData(sid uint16, data []byte) error { copy(frame[12:], chunk) if err := m.onSend(frame); err != nil { + logger.Debug("[MUX] sid=%d onSend error: %v", sid, err) return err } } @@ -164,6 +165,8 @@ func (m *Multiplexer) HandleFrame(frame []byte) { sid := binary.BigEndian.Uint16(frame[4:6]) length := binary.BigEndian.Uint16(frame[6:8]) seq := binary.BigEndian.Uint32(frame[8:12]) + + logger.Verbose("[MUX] HandleFrame sid=%d len=%d seq=%d", sid, length, seq) if sid == 0xFFFF && length == 0xFFFF { m.mu.Lock() diff --git a/internal/server/server.go b/internal/server/server.go index 5f1b175..1630353 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -229,6 +229,7 @@ func (s *Server) run(ctx context.Context) error { go func(sid uint16) { data := s.mux.ReadStream(sid) if len(data) > 0 { + log.Printf("[SERVER] sid=%d READ_STREAM size=%d", sid, len(data)) s.connMu.RLock() conn, exists := s.connections[sid] s.connMu.RUnlock() @@ -244,6 +245,7 @@ func (s *Server) run(ctx context.Context) error { } else { var req ConnectRequest if err := json.Unmarshal(data, &req); err == nil && req.Cmd == "connect" { + log.Printf("[SERVER] sid=%d RECEIVED_CONNECT_REQUEST %s:%d", sid, req.Addr, req.Port) s.connMu.Lock() if oldConn, exists := s.connections[sid]; exists && oldConn != nil { oldConn.Close() @@ -269,9 +271,10 @@ func (s *Server) run(ctx context.Context) error { } func (s *Server) handleConnect(sid uint16, req ConnectRequest) { + startTime := time.Now() addr := fmt.Sprintf("%s:%d", req.Addr, req.Port) logger.Verbose("Handling connect request sid=%d to %s", sid, addr) - log.Printf("Connecting sid=%d to %s", sid, addr) + log.Printf("[SERVER] sid=%d CONNECT_START %s", sid, addr) s.connMu.Lock() oldConn, exists := s.connections[sid] @@ -282,7 +285,7 @@ func (s *Server) handleConnect(sid uint16, req ConnectRequest) { } s.connMu.Unlock() - start := time.Now() + dialStart := time.Now() resolver := &net.Resolver{ PreferGo: true, @@ -299,23 +302,25 @@ func (s *Server) handleConnect(sid uint16, req ConnectRequest) { } conn, err := dialer.Dial("tcp4", addr) - elapsed := time.Since(start) + dialElapsed := time.Since(dialStart) if err != nil { - log.Printf("Connect failed sid=%d: %v (took %v)", sid, err, elapsed) + log.Printf("[SERVER] sid=%d CONNECT_FAILED dial_time=%v total_elapsed=%v err=%v", sid, dialElapsed, time.Since(startTime), err) go s.mux.CloseStream(sid) return } - logger.Verbose("TCP dial took %v for sid=%d", elapsed, sid) + logger.Verbose("TCP dial took %v for sid=%d", dialElapsed, sid) s.connMu.Lock() s.connections[sid] = conn s.connMu.Unlock() - log.Printf("Connected sid=%d", sid) + log.Printf("[SERVER] sid=%d CONNECT_SUCCESS dial_time=%v", sid, dialElapsed) + sendStart := time.Now() s.mux.SendData(sid, []byte{0x00}) + log.Printf("[SERVER] sid=%d RESPONSE_SENT send_time=%v total_elapsed=%v", sid, time.Since(sendStart), time.Since(startTime)) go func() { defer func() { diff --git a/internal/telemost/peer.go b/internal/telemost/peer.go index 1e3cbb6..be809d9 100644 --- a/internal/telemost/peer.go +++ b/internal/telemost/peer.go @@ -199,14 +199,14 @@ func (p *Peer) Send(data []byte) error { queueLen := len(p.sendQueue) if queueLen > 100 { - logger.Verbose("Send queue length: %d", queueLen) + log.Printf("[SEND_QUEUE] Queue length: %d (high!)", queueLen) } select { case p.sendQueue <- data: return nil default: - logger.Debug("Send queue full! Dropping packet of %d bytes", len(data)) + log.Printf("[SEND_QUEUE] Queue full! Dropping packet of %d bytes", len(data)) return fmt.Errorf("send queue full") } } @@ -699,24 +699,35 @@ func (p *Peer) processSendQueue() { for { select { case data := <-p.sendQueue: + queueStart := time.Now() buffered := uint64(0) if p.dc != nil { buffered = p.dc.BufferedAmount() } if buffered > 256*1024 { - logger.Verbose("DataChannel buffer full: %d bytes, waiting...", buffered) + log.Printf("[DATACHANNEL] Buffer full: %d bytes, waiting...", buffered) } + waitStart := time.Now() for p.dc != nil && p.dc.BufferedAmount() > 256*1024 { time.Sleep(1 * time.Millisecond) } + waitTime := time.Since(waitStart) if p.dc != nil && p.dc.ReadyState() == webrtc.DataChannelStateOpen { + sendStart := time.Now() if err := p.dc.Send(data); err != nil { logger.Debug("DataChannel send error: %v", err) } else { - logger.Verbose("Sent %d bytes to DataChannel (buffered: %d)", len(data), p.dc.BufferedAmount()) + sendTime := time.Since(sendStart) + totalTime := time.Since(queueStart) + if waitTime > 10*time.Millisecond || sendTime > 10*time.Millisecond { + log.Printf("[DATACHANNEL] Sent %d bytes wait=%v send=%v total=%v buffered=%d", + len(data), waitTime, sendTime, totalTime, p.dc.BufferedAmount()) + } else { + logger.Verbose("Sent %d bytes to DataChannel (buffered: %d)", len(data), p.dc.BufferedAmount()) + } } } case <-p.closeCh: