Skip to content

Commit 9881442

Browse files
ignoramousignoramous
committed
tcp,udp,icmp: guard verbose/debug logs
some logs are in the critical path, that is, exec on every packet flow and so they cause connection slow downs. The Golang logger is not lightweight and acquires mutexes on every write. Firestack's logger also does a bunch of bookkeeping to prevent spammy logs and calls up the runtime to print stacktraces.
1 parent f22cf91 commit 9881442

File tree

4 files changed

+75
-33
lines changed

4 files changed

+75
-33
lines changed

‎intra/common.go‎

Lines changed: 30 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -189,7 +189,7 @@ func (h *baseHandler) onFlow(localaddr, target netip.AddrPort) (fm *Mark, undidA
189189
hasNewIPs := false
190190
if hasPre {
191191
for d := range strings.SplitSeq(doms, ",") {
192-
if len(d) <= 0 {
192+
if len(d) <= 0 && settings.Debug {
193193
log.V("com: %s: onFlow: preflow: empty domain in %v from %v => %v for %s; skip!",
194194
h.proto, doms, src, target, preuid)
195195
continue
@@ -211,12 +211,16 @@ func (h *baseHandler) onFlow(localaddr, target netip.AddrPort) (fm *Mark, undidA
211211
return fm, undidAlg, "", ""
212212
} // else: if we've got target and/or old ips, dial them
213213
} else {
214-
log.D("com: %s: onFlow: noalg? %t or hasips? %t", h.proto, !undidAlg, hasOldIPs)
214+
if settings.Debug {
215+
log.D("com: %s: onFlow: noalg? %t or hasips? %t", h.proto, !undidAlg, hasOldIPs)
216+
}
215217
}
216218

217219
if len(ips) <= 0 || len(doms) <= 0 {
218-
log.D("com: %s: onFlow: no realips(%s) or domains(%s + %s), for src=%s dst=%s",
219-
h.proto, ips, doms, pdoms, localaddr, target)
220+
if settings.Debug {
221+
log.D("com: %s: onFlow: no realips(%s) or domains(%s + %s), for src=%s dst=%s",
222+
h.proto, ips, doms, pdoms, localaddr, target)
223+
}
220224
}
221225

222226
fm, ok := core.Grx(h.proto+".flow", func(_ context.Context) (*Mark, error) {
@@ -306,7 +310,9 @@ func (h *baseHandler) queueSummary(s *SocketSummary) {
306310
// log.VV("com: %s: queueSummary: %x %x %s", h.proto, h.smmch, h.ctx, s.ID)
307311
select {
308312
case <-h.ctx.Done():
309-
log.D("%s: queueSummary: end: %s", h.proto, s)
313+
if settings.Debug {
314+
log.D("%s: queueSummary: end: %s", h.proto, s)
315+
}
310316
default:
311317
select {
312318
case <-h.ctx.Done():
@@ -343,7 +349,9 @@ func (h *baseHandler) sendSummary(s *SocketSummary, after time.Duration) {
343349
time.Sleep(after)
344350
}
345351

346-
log.VV("com: %s: end? sendNotif: %s", h.proto, s)
352+
if settings.Debug {
353+
log.VV("com: %s: end? sendNotif: %s", h.proto, s)
354+
}
347355
h.listener.OnSocketClosed(s) // s.Duration may be uninitialized (zero)
348356
}
349357

@@ -431,8 +439,10 @@ func upload(id string, local, remote net.Conn, ioch chan<- ioinfo) {
431439

432440
n, err := core.Pipe(remote, local)
433441

434-
log.D("com: %s upload(%d) done(%v) b/w %s",
435-
id, n, err, conn2str(local, remote))
442+
if settings.Debug {
443+
log.D("com: %s upload(%d) done(%v) b/w %s",
444+
id, n, err, conn2str(local, remote))
445+
}
436446
ioch <- ioinfo{n, err}
437447
}
438448

@@ -442,8 +452,10 @@ func download(id string, local, remote net.Conn) (n int64, err error) {
442452

443453
n, err = core.Pipe(local, remote)
444454

445-
log.D("com: %s download(%d) done(%v) b/w %s",
446-
id, n, err, conn2str(local, remote))
455+
if settings.Debug {
456+
log.D("com: %s download(%d) done(%v) b/w %s",
457+
id, n, err, conn2str(local, remote))
458+
}
447459
return
448460
}
449461

@@ -488,8 +500,10 @@ func makeIPPorts(ips []netip.Addr, origipp netip.AddrPort, cap int) []netip.Addr
488500
} // else: discard ip
489501
}
490502

491-
log.VV("com: makeIPPorts(v4? %t, v6? %t) for %v; tot: %d; in: %v, out: %v",
492-
use4, use6, origipp, len(ips), ips, r)
503+
if settings.Debug {
504+
log.VV("com: makeIPPorts(v4? %t, v6? %t) for %v; tot: %d; in: %v, out: %v",
505+
use4, use6, origipp, len(ips), ips, r)
506+
}
493507

494508
if len(r) > 0 {
495509
return core.ShuffleInPlace(r)
@@ -604,8 +618,10 @@ func (h *baseHandler) maybeReplaceDest(res *Mark, target *netip.AddrPort) {
604618
return
605619
} else if resip, err := netip.ParseAddr(res.IP); resip.IsValid() && err == nil {
606620
// if res.IP is set, then use it as the target
607-
log.D("%s: proxy: %s %s target instead of %s",
608-
h.proto, res.CID, resip, target)
621+
if settings.Debug {
622+
log.D("%s: proxy: %s %s target instead of %s",
623+
h.proto, res.CID, resip, target)
624+
}
609625
*target = netip.AddrPortFrom(resip, target.Port())
610626
}
611627
}

‎intra/tcp.go‎

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -168,7 +168,9 @@ func (h *tcpHandler) Proxy(gconn *netstack.GTCPConn, src, target netip.AddrPort)
168168

169169
if h.status.Load() == HDLEND {
170170
err = errTcpEnd
171-
log.D("tcp: proxy: %s end %s => %s [%v]", cid, src, target, actualTargets)
171+
if settings.Debug {
172+
log.D("tcp: proxy: %s end %s => %s [%v]", cid, src, target, actualTargets)
173+
}
172174
clos(gconn)
173175
h.queueSummary(smm.done(err))
174176
return deny
@@ -206,8 +208,10 @@ func (h *tcpHandler) Proxy(gconn *netstack.GTCPConn, src, target netip.AddrPort)
206208
} // else not a dns request
207209
} // if ipn.Exit then let it connect as-is (aka exit)
208210

209-
log.VV("tcp: %s proxying %s => %s [%v] for %s; pids: %s",
210-
cid, src, target, actualTargets, uid, pids)
211+
if settings.Debug {
212+
log.VV("tcp: %s proxying %s => %s [%v] for %s; pids: %s",
213+
cid, src, target, actualTargets, uid, pids)
214+
}
211215

212216
boundSrc := makeAnyAddrPort(src)
213217
// pick all realips to connect to
@@ -251,8 +255,10 @@ func (h *tcpHandler) handle(px ipn.Proxy, src *netstack.GTCPConn, boundSrc, targ
251255

252256
start := time.Now()
253257

254-
log.VV("tcp: %s dial %s: attempt: %s [%s] => %s for %s",
255-
smm.ID, pidstr(px), src.LocalAddr(), boundSrc, target, smm.UID)
258+
if settings.Debug {
259+
log.VV("tcp: %s dial %s: attempt: %s [%s] => %s for %s",
260+
smm.ID, pidstr(px), src.LocalAddr(), boundSrc, target, smm.UID)
261+
}
256262

257263
// github.com/google/gvisor/blob/5ba35f516b5c2/test/benchmarks/tcp/tcp_proxy.go#L359
258264
// ref: stackoverflow.com/questions/63656117

‎intra/udp.go‎

Lines changed: 15 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -195,7 +195,9 @@ func (h *udpHandler) Connect(gconn *netstack.GUDPConn, src, target netip.AddrPor
195195
smm = udpSummary(cid, uid, actualTargets[0].Addr())
196196

197197
if h.status.Load() == HDLEND {
198-
log.D("udp: connect: %s %v => %v, end", cid, src, target)
198+
if settings.Debug {
199+
log.D("udp: connect: %s %v => %v, end", cid, src, target)
200+
}
199201
return nil, smm, errUdpEnd // disconnect, no nat
200202
}
201203

@@ -259,14 +261,18 @@ func (h *udpHandler) Connect(gconn *netstack.GUDPConn, src, target netip.AddrPor
259261

260262
if mux {
261263
if muxpid := h.mux.pid(src); len(muxpid) > 0 && containsPid(pids, muxpid) {
262-
log.D("udp: connect: %s mux: %s => %s using muxed-pid %s; all pids %s",
263-
cid, src, target, muxpid, pids)
264+
if settings.Debug {
265+
log.D("udp: connect: %s mux: %s => %s using muxed-pid %s; all pids %s",
266+
cid, src, target, muxpid, pids)
267+
}
264268
pids = []string{muxpid}
265269
} // else: mxr will dial this conn with a different pid
266270
}
267271

268-
log.VV("udp: connect: %s proxying %s => %s [%v] for %s; pids: %s, mux? %t",
269-
cid, src, target, actualTargets, uid, pids, mux)
272+
if settings.Debug {
273+
log.VV("udp: connect: %s proxying %s => %s [%v] for %s; pids: %s, mux? %t",
274+
cid, src, target, actualTargets, uid, pids, mux)
275+
}
270276

271277
// note: fake-dns-ips shouldn't be un-nated / un-alg'd
272278
for i, dstipp := range actualTargets {
@@ -290,8 +296,10 @@ func (h *udpHandler) Connect(gconn *netstack.GUDPConn, src, target netip.AddrPor
290296
if mux { // mux is not supported by all proxies (few like Exit, Base, WG support it)
291297
pc, err = h.mux.associate(cid, pxid, uid, src, selectedTarget, px.Dialer().Announce, vendor(dmx))
292298
} else {
293-
log.VV("udp: connect: #%d: attempt: %s proxy(%s) to dst(%s) for %s; mux? %t",
294-
i, cid, pxid, selectedTarget, uid, mux)
299+
if settings.Debug {
300+
log.VV("udp: connect: #%d: attempt: %s proxy(%s) to dst(%s) for %s; mux? %t",
301+
i, cid, pxid, selectedTarget, uid, mux)
302+
}
295303

296304
if settings.PortForward.Load() {
297305
boundSrc := makeAnyAddrPort(src)

‎intra/udpmux.go‎

Lines changed: 19 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -148,7 +148,9 @@ func (x *muxer) awaiters() {
148148
for {
149149
select {
150150
case c := <-x.dxconns:
151-
log.D("udp: mux: %s awaiter: watching %s => %s", c.cid, c.laddr, c.raddr)
151+
if settings.Debug {
152+
log.D("udp: mux: %s awaiter: watching %s => %s", c.cid, c.laddr, c.raddr)
153+
}
152154
x.dxconnWG.Add(1) // accept
153155
core.Gx("udpmux.vend.close", func() {
154156
<-c.closed // conn closed
@@ -165,7 +167,9 @@ func (x *muxer) awaiters() {
165167
// stop closes conns in the backlog, stops accepting new conns,
166168
// closes muxconn, and waits for demuxed conns to close.
167169
func (x *muxer) stop() error {
168-
log.D("udp: mux: %s stop", x.cid)
170+
if settings.Debug {
171+
log.D("udp: mux: %s stop", x.cid)
172+
}
169173

170174
var err error
171175
x.once.Do(func() {
@@ -187,7 +191,9 @@ func (x *muxer) drain() {
187191
defer x.rmu.Unlock()
188192

189193
defer clear(x.routes)
190-
log.D("udp: mux: %s drain: closing %d demuxed conns", x.cid, len(x.routes))
194+
if settings.Debug {
195+
log.D("udp: mux: %s drain: closing %d demuxed conns", x.cid, len(x.routes))
196+
}
191197
for _, c := range x.routes {
192198
clos(c) // will unroute as well
193199
}
@@ -225,7 +231,9 @@ func (x *muxer) readers() {
225231
if timeouterrors < maxtimeouterrors {
226232
// extend by preset (min) udp timeout
227233
x.extend(time.Now().Add(time.Second * udptimeout))
228-
log.D("udp: mux: %s read timeout(%d): %v", x.cid, timeouterrors, err)
234+
if settings.Debug {
235+
log.D("udp: mux: %s read timeout(%d): %v", x.cid, timeouterrors, err)
236+
}
229237
recycle()
230238
continue
231239
}
@@ -427,8 +435,10 @@ func (c *demuxconn) WriteTo(p []byte, to net.Addr) (int, error) {
427435

428436
// Close implements core.UDPConn.Close
429437
func (c *demuxconn) Close() error {
430-
log.D("udp: mux: %s demux %s => %s close, in: %d, over: %d",
431-
c.out.id(), c.laddr, c.raddr, len(c.inCh), len(c.overflowCh))
438+
if settings.Debug {
439+
log.D("udp: mux: %s demux %s => %s close, in: %d, over: %d",
440+
c.out.id(), c.laddr, c.raddr, len(c.inCh), len(c.overflowCh))
441+
}
432442
c.once.Do(func() {
433443
close(c.closed) // sig close
434444
defer c.wt.Stop()
@@ -511,7 +521,9 @@ func (c *demuxconn) io(out *[]byte, in *slice) (int, error) {
511521
return n, io.ErrShortWrite
512522
}
513523
} else {
514-
log.VV("udp: mux: %s demux: read: %v <= %v done(sz: %d)", id, c.laddr, c.raddr, n)
524+
if settings.Debug {
525+
log.VV("udp: mux: %s demux: read: %v <= %v done(sz: %d)", id, c.laddr, c.raddr, n)
526+
}
515527
in.fin()
516528
}
517529
return n, nil

0 commit comments

Comments
 (0)