GitHub/olcrtc
1
0
Fork 0
mirror of https://github.com/openlibrecommunity/olcrtc.git synced 2026-06-06 04:19:46 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(client): Add detailed timing and diagnostic logging for SOCKS5 connections

Browse Source
This commit is contained in:
zarazaex69
2026-04-09 20:34:50 +03:00
parent e02df7d896
commit 7b889ae5ee
4 changed files with 37 additions and 11 deletions
Download Patch File Download Diff File Expand all files Collapse all files

9
internal/client/client.go
View File

@@ -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{})

3
internal/mux/mux.go
View File

@@ -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()

17
internal/server/server.go
View File

@@ -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() {

19
internal/telemost/peer.go
View File

@@ -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: