Skip to content

Commit 68bff0c

Browse files
ignoramousignoramous
committed
ipn/proxies: m ProxyTo debug log
1 parent 606ce8d commit 68bff0c

10 files changed

Lines changed: 76 additions & 55 deletions

File tree

‎intra/dns53/dot.go‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -318,9 +318,9 @@ func (t *dot) sendRequest(pid string, q *dns.Msg) (ans *dns.Msg, rpid string, ec
318318
return
319319
}
320320

321-
func (t *dot) chooseProxy(pids ...string) string {
321+
func (t *dot) chooseProxy(fid string, pids ...string) string {
322322
// TODO: DoT could use DTLS which is udp?
323-
return dnsx.ChooseHealthyProxyHostPort("dot: "+t.id, dnsx.NetTypeTCP, t.addrport, t.port, pids, t.proxies)
323+
return dnsx.ChooseHealthyProxyHostPort(fid+" dot."+t.id, dnsx.NetTypeTCP, t.addrport, t.port, pids, t.proxies)
324324
}
325325

326326
func (t *dot) Query(network string, q *dns.Msg, smm *x.DNSSummary) (ans *dns.Msg, err error) {
@@ -330,10 +330,10 @@ func (t *dot) Query(network string, q *dns.Msg, smm *x.DNSSummary) (ans *dns.Msg
330330
var ech bool
331331

332332
if r := t.relay; len(r) > 0 {
333-
pid = t.chooseProxy(r)
333+
pid = t.chooseProxy(smm.FID, r)
334334
} else {
335335
_, pids := xdns.Net2ProxyID(network)
336-
pid = t.chooseProxy(pids...)
336+
pid = t.chooseProxy(smm.FID, pids...)
337337
}
338338

339339
ans, rpid, ech, elapsed, qerr = t.doQuery(pid, q)

‎intra/dns53/upstream.go‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -296,18 +296,18 @@ func (t *transport) send(network, pid string, q *dns.Msg) (ans *dns.Msg, rpid st
296296
return
297297
}
298298

299-
func (t *transport) chooseProxy(pids ...string) string {
300-
return dnsx.ChooseHealthyProxyHostPort("dns53: "+t.id, dnsx.NetTypeUDP, t.addrport, t.port, pids, t.proxies)
299+
func (t *transport) chooseProxy(fid string, pids ...string) string {
300+
return dnsx.ChooseHealthyProxyHostPort(fid+" dns53."+t.id, dnsx.NetTypeUDP, t.addrport, t.port, pids, t.proxies)
301301
}
302302

303303
func (t *transport) Query(network string, q *dns.Msg, smm *x.DNSSummary) (ans *dns.Msg, err error) {
304304
var pid string
305305
proto, pids := xdns.Net2ProxyID(network)
306306

307307
if r := t.relay; len(r) > 0 {
308-
pid = t.chooseProxy(r)
308+
pid = t.chooseProxy(smm.FID, r)
309309
} else {
310-
pid = t.chooseProxy(pids...)
310+
pid = t.chooseProxy(smm.FID, pids...)
311311
}
312312

313313
ans, rpid, elapsed, qerr := t.send(proto, pid, q)

‎intra/dnscrypt/multiserver.go‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -319,16 +319,17 @@ func resolve(network string, data *dns.Msg, si *server, smm *x.DNSSummary) (ans
319319
var qerr *dnsx.QueryError
320320
var anonrelayaddr net.Addr
321321

322+
fid := smm.FID
322323
before := time.Now()
323324

324325
proto, pids := xdns.Net2ProxyID(network)
325326
useudp := proto == dnsx.NetTypeUDP
326327
pid := dnsx.NetNoProxy
327328
if si != nil {
328329
if r := si.relay; len(r) > 0 {
329-
pid = si.chooseProxy(r)
330+
pid = si.chooseProxy(fid, r)
330331
} else {
331-
pid = si.chooseProxy(pids...)
332+
pid = si.chooseProxy(fid, pids...)
332333
}
333334
}
334335

‎intra/dnscrypt/servers.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -495,8 +495,8 @@ func (s *server) dialpx(pid, proto string, addr string) (net.Conn, error) {
495495
}
496496

497497
// TODO: choose proxy w/ proto "tcp" or "udp"
498-
func (s *server) chooseProxy(pids ...string) string {
499-
return dnsx.ChooseHealthyProxy("dnscrypt: "+s.ID(), dnsx.NetTypeTCP, s.IPPorts(), pids, s.proxies)
498+
func (s *server) chooseProxy(fid string, pids ...string) string {
499+
return dnsx.ChooseHealthyProxy(fid+" dnscrypt."+s.ID(), dnsx.NetTypeTCP, s.IPPorts(), pids, s.proxies)
500500
}
501501

502502
func addr2ipp(u ...*net.UDPAddr) (ipps []netip.AddrPort) {

‎intra/dnsx/alg.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2517,7 +2517,7 @@ func ChooseHealthyProxy(who, proto string, ipps []netip.AddrPort, pids []string,
25172517
if !ipp.IsValid() {
25182518
continue
25192519
}
2520-
if p, err := px.ProxyTo(ipp, proto, protect.MyUid, pids); err == nil {
2520+
if p, err := px.ProxyTo(who, ipp, proto, protect.MyUid, pids); err == nil {
25212521
pid = proxyID(p)
25222522
foundProxy = pid != NetNoProxy
25232523
cipp = ipp

‎intra/doh/doh.go‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -825,10 +825,10 @@ func (t *transport) Type() string {
825825
return t.typ
826826
}
827827

828-
func (t *transport) chooseProxy(pids ...string) string {
828+
func (t *transport) chooseProxy(fid string, pids ...string) string {
829829
host, port := t.hostport()
830830
// TODO: doh3 is udp?
831-
return dnsx.ChooseHealthyProxyHostPort("doh: "+t.id, dnsx.NetTypeTCP, host, port, pids, t.proxies)
831+
return dnsx.ChooseHealthyProxyHostPort(fid+" doh."+t.id, dnsx.NetTypeTCP, host, port, pids, t.proxies)
832832
}
833833

834834
func (t *transport) hostport() (addr string, port uint16) {
@@ -856,10 +856,10 @@ func (t *transport) Query(network string, q *dns.Msg, smm *x.DNSSummary) (r *dns
856856
pid = dnsx.NetBaseProxy
857857
}
858858
} else if r := t.relay; len(r) > 0 {
859-
pid = t.chooseProxy(r)
859+
pid = t.chooseProxy(smm.FID, r)
860860
} else {
861861
_, pids := xdns.Net2ProxyID(network)
862-
pid = t.chooseProxy(pids...)
862+
pid = t.chooseProxy(smm.FID, pids...)
863863
}
864864

865865
if t.typ == dnsx.DOH {

‎intra/icmp.go‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -94,7 +94,7 @@ func (h *icmpHandler) Ping(msg []byte, source, target netip.AddrPort) (echoed bo
9494
return false // denied
9595
}
9696

97-
if px, err = h.prox.ProxyTo(dst, "icmp", uid, pids); err != nil || px == nil {
97+
if px, err = h.prox.ProxyTo(cid, dst, "icmp", uid, pids); err != nil || px == nil {
9898
err = log.EE("t.icmp: egress: no proxy(%s); err %v", pids, err)
9999
return false // denied
100100
}
@@ -104,8 +104,8 @@ func (h *icmpHandler) Ping(msg []byte, source, target netip.AddrPort) (echoed bo
104104
smm.Target = dst.Addr().String()
105105

106106
if h.loopDetected(smm) {
107-
log.I("t.icmp: loop: break %s => %s via %s for %s; exiting...", source, dst, pidstr(px), uid)
108-
px, err = h.prox.ProxyTo(dst, "icmp", uid, onlyExitPid)
107+
log.I("t.icmp: loop: break %s: %s => %s via %s for %s; exiting...", cid, source, dst, pidstr(px), uid)
108+
px, err = h.prox.ProxyTo(cid, dst, "icmp", uid, onlyExitPid)
109109
smm.PID = ipn.Exit
110110
smm.RPID = ""
111111
}

‎intra/ipn/proxies.go‎

Lines changed: 48 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -217,7 +217,7 @@ type ProxyProvider interface {
217217
// ProxyFor returns a transport from this multi-transport.
218218
ProxyFor(id string) (Proxy, error)
219219
// ProxyTo returns the proxy to use for ipp from given pids.
220-
ProxyTo(ipp netip.AddrPort, proto, uid string, pids []string) (Proxy, error)
220+
ProxyTo(who string, ipp netip.AddrPort, proto, uid string, pids []string) (Proxy, error)
221221
// ProxyRef returns currently reachable reference to Proxy, if any.
222222
ProxyRef(who, id string) (*core.WeakRef[Proxy], error)
223223
}
@@ -488,7 +488,7 @@ func (px *proxifier) ProxyRef(who, id string) (*core.WeakRef[Proxy], error) {
488488
// ProxyTo implements Proxies.
489489
// May return both a Proxy and an error, in which case, the error
490490
// denotes that while the Proxy is not healthy, it is still registered.
491-
func (px *proxifier) ProxyTo(ipp netip.AddrPort, proto, uid string, pids []string) (theone Proxy, err error) {
491+
func (px *proxifier) ProxyTo(who string, ipp netip.AddrPort, proto, uid string, pids []string) (theone Proxy, err error) {
492492
waitedForMissingProxy := false
493493

494494
ippstr := ipp.String()
@@ -520,26 +520,37 @@ func (px *proxifier) ProxyTo(ipp netip.AddrPort, proto, uid string, pids []strin
520520
goto retryPin
521521
}
522522
}
523-
logev(err)("proxy: pin: %s: %s+%s; pin pid0: %s (stalled? %ds / waited? %t); err? %v",
524-
proto, uid, ippstr, pids[0], stalledSec, waitedForMissingProxy, err)
523+
logev(err)("proxy: pin: single: 1 %s: %s: %s+%s; pin pid0: %s (stalled? %ds / waited? %t); err? %v",
524+
who, proto, uid, ippstr, pids[0], stalledSec, waitedForMissingProxy, err)
525525
if p != nil {
526-
if iscircular(p, ippstr) {
527-
circular = append(circular, pids[0])
526+
pid0 := p.ID()
527+
iscircle := iscircular(p, ippstr)
528+
noroute := !hasroute(p, ippstr)
529+
canth3 := uid != protect.MyUid && maybeH3(proto, ipp) && cantProxyH3(p.ID())
530+
notok := p.Status() == TNT
531+
532+
if log.Verbose {
533+
log.V("proxy: pin: single: 2 %s: %s: %s+%s; pin pid0: (%s <> %s) (stalled? %ds / waited? %t); err? %v; circular? %t; noroute? %t; canth3? %t; notok? %t",
534+
who, proto, uid, ippstr, pid0, pids[0], stalledSec, waitedForMissingProxy, err, iscircle, noroute, canth3, notok)
535+
}
536+
537+
if iscircle {
538+
circular = append(circular, pid0)
528539
px.delpin(uid, ipp)
529540
// circular route must be returned as-is (clients may check for equality)
530541
return nil, ErrCircularRoute
531542
}
532-
if !hasroute(p, ippstr) {
543+
if noroute {
533544
px.delpin(uid, ipp)
534545
return nil, e(core.JoinErr(err, errProxyRoute))
535546
} // there is only one pid to route to
536-
if uid != protect.MyUid && maybeH3(proto, ipp) && cantProxyH3(p.ID()) {
547+
if canth3 {
537548
// allow h3 like traffic from myuid, which could actually be rpn/wg on 443
538549
err = errProxyProtoH3
539550
px.delpin(uid, ipp)
540551
return nil, e(core.JoinErr(err, errProxyProtoH3))
541552
}
542-
if p.Status() == TNT { // proxy not ok
553+
if notok { // proxy not ok
543554
stalledSec = px.stall(uid + ippstr)
544555
}
545556
// wipe out err; return p, even if err is not nil
@@ -555,9 +566,10 @@ func (px *proxifier) ProxyTo(ipp netip.AddrPort, proto, uid string, pids []strin
555566
chosen := has(pids, pinnedpid)
556567
lo := local(pinnedpid)
557568

558-
log.VV("proxy: pin: %s: %s+%s; pinned: %s (ok? %t); chosen? %t / local? %t; from pids: %v",
559-
proto, uid, ippstr, pinnedpid, pinok, chosen, lo, pids)
560-
569+
if log.Verbose {
570+
log.VV("proxy: pin: %s: %s: %s+%s; pinned: %s (ok? %t); chosen? %t / local? %t; from pids: %v",
571+
who, proto, uid, ippstr, pinnedpid, pinok, chosen, lo, pids)
572+
}
561573
if !pinok { // discard pinnedpid if pin has expired
562574
pinnedpid = ""
563575
}
@@ -567,24 +579,33 @@ func (px *proxifier) ProxyTo(ipp netip.AddrPort, proto, uid string, pids []strin
567579
lopinned = pinnedpid
568580
} else if pinok && chosen {
569581
p, err := px.pinID(uid, ipp, pinnedpid) // repin & health check
570-
582+
pidc := idstr(p)
571583
hasp := core.IsNotNil(p)
584+
572585
if hasp && p != nil && err != nil {
586+
iscircle := iscircular(p, ippstr)
587+
noroute := !hasroute(p, ippstr)
588+
canth3 := uid != protect.MyUid && maybeH3(proto, ipp) && cantProxyH3(pidc)
589+
590+
if log.Verbose {
591+
log.V("proxy: pin: %s: %s: %s+%s; chosen and pinned: 1 (%s <> %s) (stalled? %ds); err? %v; circular? %t; noroute? %t; canth3? %t",
592+
who, proto, uid, ippstr, pinnedpid, pidc, stalledSec, err, iscircle, noroute, canth3)
593+
}
573594
// check for circular route before other checks
574-
if iscircular(p, ippstr) {
595+
if iscircle {
575596
circular = append(circular, pinnedpid)
576597
px.delpin(uid, ipp)
577-
} else if uid != protect.MyUid && maybeH3(proto, ipp) && cantProxyH3(p.ID()) {
598+
} else if canth3 {
578599
// allow h3 like egress from myuid, which could actually be rpn/wg on 443
579600
err = core.JoinErr(err, errProxyProtoH3)
580-
} else if hasroute(p, ippstr) {
601+
} else if !noroute { // hasroute
581602
return p, nil
582603
} else {
583604
px.delpin(uid, ipp) // del pin if no route
584605
}
585606
} // else: pinnedpid not ok (ex: END/TPU/TNT) or no route
586-
logev(err)("proxy: pin: %s: %s+%s; chosen and pinned: %s (but err? %v); hasproxy? %t (or no route)",
587-
proto, uid, ippstr, pinnedpid, err, hasp)
607+
logev(err)("proxy: pin: %s: %s: %s+%s; chosen and pinned: 2 %s <> %s (but err? %v); hasproxy? %t (or no route)",
608+
who, proto, uid, ippstr, pinnedpid, pidc, err, hasp)
588609
} else if pinok && !chosen {
589610
px.delpin(uid, ipp)
590611
}
@@ -602,8 +623,8 @@ func (px *proxifier) ProxyTo(ipp netip.AddrPort, proto, uid string, pids []strin
602623
}
603624

604625
defer func() {
605-
logev(err)("proxy: pin: %s: %s+%s; chosen? %s; stalled? %ds; local: %v; miss: %v; notok: %v; noroute: %v; paused %v; ended %v; noh3: %v; circular: %v",
606-
proto, uid, ipp, idstr(theone), stalledSec, loproxies, missproxies, notokproxies, norouteproxies, pausedproxies, endproxies, noh3proxies, circular)
626+
logev(err)("proxy: pin: %s: %s: %s+%s; chosen? %s; stalled? %ds; local: %v; miss: %v; notok: %v; noroute: %v; paused %v; ended %v; noh3: %v; circular: %v",
627+
who, proto, uid, ippstr, idstr(theone), stalledSec, loproxies, missproxies, notokproxies, norouteproxies, pausedproxies, endproxies, noh3proxies, circular)
607628
}()
608629

609630
retrySearch:
@@ -652,8 +673,7 @@ retrySearch:
652673

653674
err := px.pin(uid, ipp, p) // repin & ping if needed
654675
if err == nil {
655-
log.VV("proxy: pin: %s: %s+%s; pinned: %s; from pids: %v",
656-
proto, uid, ippstr, pid, pids)
676+
log.VV("proxy: pin: %s: %s: %s+%s; pinned: %s; from pids: %v", who, proto, uid, ippstr, pid, pids)
657677
return p, nil
658678
} // else: proxy not ok
659679
notokproxies = append(notokproxies, pid)
@@ -669,16 +689,16 @@ retrySearch:
669689
stalledSec = px.stall(uid + ippstr)
670690
if one := core.ChooseOne(notok); one != nil {
671691
if log.Verbose {
672-
log.V("proxy: pin: %s: %s+%s; pinned: %s; from notok: %v",
673-
proto, uid, ippstr, idstr(one), notokproxies)
692+
log.V("proxy: pin: %s: %s: %s+%s; pinned: %s; from notok: %v",
693+
who, proto, uid, ippstr, idstr(one), notokproxies)
674694
}
675695
return one, nil
676696
}
677697
for i, one := range noh3 {
678698
err := px.pin(uid, ipp, one) // repin & ping if needed
679699
if err != nil || log.Verbose {
680-
logev(err)("proxy: pin: %s: %s+%s; pinned: %s #%d; from noh3: %v; err? %v",
681-
proto, uid, ippstr, idstr(one), i, noh3proxies, err)
700+
logev(err)("proxy: pin: %s: %s: %s+%s; pinned: %s #%d; from noh3: %v; err? %v",
701+
who, proto, uid, ippstr, idstr(one), i, noh3proxies, err)
682702
}
683703
if err == nil {
684704
return one, nil
@@ -705,8 +725,8 @@ retrySearch:
705725
time.Sleep(time.Duration(minWaitPeriodSec-stalledSec) * time.Second)
706726
stalledSec = minWaitPeriodSec
707727
}
708-
log.W("proxy: pin: %s: %s+%s; missing: %v; notok: %v; noroute: %v; paused: %v; ended: %v; waited: %ds",
709-
proto, uid, ippstr, missproxies, notokproxies, norouteproxies, pausedproxies, endproxies, stalledSec)
728+
log.W("proxy: pin: %s: %s: %s+%s; missing: %v; notok: %v; noroute: %v; paused: %v; ended: %v; waited: %ds",
729+
who, proto, uid, ippstr, missproxies, notokproxies, norouteproxies, pausedproxies, endproxies, stalledSec)
710730
pids = missproxies
711731
missproxies = make([]string, 0)
712732
goto retrySearch

‎intra/tcp.go‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -326,7 +326,7 @@ func (h *tcpHandler) Proxy(gconn *netstack.GTCPConn, src, target netip.AddrPort)
326326
targetstr := dstipp.Addr().String()
327327

328328
var px ipn.Proxy = nil
329-
px, err = h.prox.ProxyTo(dstipp, "tcp", uid, pids)
329+
px, err = h.prox.ProxyTo(cid, dstipp, "tcp", uid, pids)
330330

331331
// TODO: wait to break circular route after going through all actualTargets?
332332
if errors.Is(err, ipn.ErrCircularRoute) {
@@ -348,8 +348,8 @@ func (h *tcpHandler) Proxy(gconn *netstack.GTCPConn, src, target netip.AddrPort)
348348
}
349349

350350
if h.loopDetected(smm) {
351-
log.I("tcp: dial: loop: break2: %s => %s via %s for %s; exiting...", src, dstipp, smm.PID, uid)
352-
px, err = h.prox.ProxyTo(dstipp, "tcp", uid, onlyExitPid)
351+
log.I("tcp: dial: loop: break2: #%d %s %s => %s via %s for %s; exiting...", i, cid, src, dstipp, smm.PID, uid)
352+
px, err = h.prox.ProxyTo(cid+"/loop", dstipp, "tcp", uid, onlyExitPid)
353353
smm.PID = ipn.Exit
354354
smm.RPID = ""
355355
}
@@ -478,7 +478,7 @@ func (h *tcpHandler) handle(px ipn.Proxy, gconn *netstack.GTCPConn, src, target
478478
}
479479
})
480480

481-
log.I("tcp: %s dialed %s proxy(%s) %s => %s [%v] (bind? %t / bindaddr? %s) for %s; rtt? %s",
481+
log.I("tcp: %s dialed %s proxy(%s) %s => %v (bind? %t / bindaddr? %s) for %s; rtt? %s",
482482
smm.ID, smm.PID, src, targetstr, dstlocal, dialbindOK, bindAddr, smm.UID, core.FmtMillis(smm.Rtt))
483483

484484
return cont, nil // handled; takes ownership of src

‎intra/udp.go‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -312,7 +312,7 @@ func (h *udpHandler) Connect(gconn *netstack.GUDPConn, src, target netip.AddrPor
312312
for i, dstipp := range actualTargets {
313313
rttstart := time.Now()
314314

315-
px, err = h.prox.ProxyTo(dstipp, "udp", uid, pids)
315+
px, err = h.prox.ProxyTo(cid, dstipp, "udp", uid, pids)
316316

317317
// TODO: wait to break circular route after going through all actualTargets?
318318
if errors.Is(err, ipn.ErrCircularRoute) {
@@ -335,8 +335,8 @@ func (h *udpHandler) Connect(gconn *netstack.GUDPConn, src, target netip.AddrPor
335335
smm.Target = selectedTarget.Addr().String() // may be invalid
336336

337337
if h.loopDetected(smm) {
338-
log.I("udp: dial: loop: break2 %s => %v via %s for %s; exiting...", src, selectedTarget, smm.PID, uid)
339-
px, err = h.prox.ProxyTo(dstipp, "udp", uid, onlyExitPid)
338+
log.I("udp: dial: loop: break2 #%d %s: %s => %v via %s for %s; exiting...", i, cid, src, selectedTarget, smm.PID, uid)
339+
px, err = h.prox.ProxyTo(cid+"/loop", dstipp, "udp", uid, onlyExitPid)
340340
smm.PID = ipn.Exit // last chosen proxy may yet emayrror out
341341
smm.RPID = ""
342342
}

0 commit comments

Comments
 (0)