Skip to content

Commit 2a99cd7

Browse files
ignoramousignoramous
committed
ipn/wg: m logs
1 parent 9a7adb5 commit 2a99cd7

File tree

3 files changed

+31
-29
lines changed

3 files changed

+31
-29
lines changed

‎intra/ipn/rpn/yegor.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1858,7 +1858,7 @@ func newWsGw(c *WsWgConfig, h *http.Client, o x.RpnOps) (*WsClient, error) {
18581858
}
18591859

18601860
log.I("ws: gw: for %s/%s; ops: %s; from: %s until: %s",
1861-
a.Who(), c.tokenState(), a.ops, fmtUnixMillis(a.Created()), fmtUnixMillis(a.Expires()))
1861+
a.Who(), c.tokenState(), a.Ops(), fmtUnixMillis(a.Created()), fmtUnixMillis(a.Expires()))
18621862

18631863
return a, nil
18641864
}

‎intra/ipn/wg/wgconn.go‎

Lines changed: 19 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -192,15 +192,15 @@ func (e *StdNetBind) ParseEndpoint(s string) (conn.Endpoint, error) {
192192
// d.Add([]string{host}) // resolves host if needed
193193
d, err := e.pm.Load().Get(s)
194194
if err != nil || d == nil /*nilaway; can't happen*/ {
195-
log.E("wg: bind: %s parse: invalid endpoint in(%s); err: %v", e.id, s, err)
195+
log.E("wg: bind: parse: %s invalid endpoint in(%s); err: %v", e.id, s, err)
196196
return nil, err
197197
}
198198

199199
// do what tailscale does, and share a preferred endpoint regardless of "s"
200200
// github.com/tailscale/tailscale/blob/3a6d3f1a5b7/wgengine/magicsock/magicsock.go#L2568
201201
ipport := d.PreferredAddr()
202202
if !ipport.IsValid() || ipport.Addr().IsUnspecified() {
203-
log.E("wg: bind: %s parse: invalid endpoint; chosen(%v) => in(%s) => out(%s, %s)", e.id, ipport, s, d.Names(), d.Addrs())
203+
log.E("wg: bind: parse: %s invalid endpoint; chosen(%v) => in(%s) => out(%s, %s)", e.id, ipport, s, d.Names(), d.Addrs())
204204
// erroring out from here prevents PostConfig (handshake for this peer endpoint will always be zero)
205205
// github.com/WireGuard/wireguard-go/blob/12269c276173/device/uapi.go#L183
206206
return nil, errInvalidEndpoint
@@ -259,17 +259,17 @@ func (s *StdNetBind) listenNet(network string, port int) (net.PacketConn, int, e
259259

260260
conn, err := s.connect(network, saddr)
261261
if err != nil {
262-
log.E("wg: bind: %s %s: listen(%v); err: %v", s.id, network, saddr, err)
262+
log.E("wg: bind: listen: %s %s: on(%v); err: %v", s.id, network, saddr, err)
263263
return nil, 0, err
264264
}
265265
if conn == nil {
266-
log.E("wg: bind: %s %s: listen(%v); conn nil", s.id, network, saddr)
266+
log.E("wg: bind: listen: %s %s: on(%v); conn nil", s.id, network, saddr)
267267
return nil, 0, errNoListen
268268
}
269269

270270
laddr := conn.LocalAddr()
271271
if laddr == nil {
272-
log.E("wg: bind: %s %s: listen(%v); local-addr nil", s.id, network, saddr)
272+
log.E("wg: bind: listen: %s %s: on(%v); local-addr nil", s.id, network, saddr)
273273
return nil, 0, errNoLocalAddr
274274
}
275275
uaddr, err := net.ResolveUDPAddr(
@@ -283,7 +283,7 @@ func (s *StdNetBind) listenNet(network string, port int) (net.PacketConn, int, e
283283
return nil, 0, errNoLocalAddr
284284
}
285285
if settings.Debug {
286-
log.VV("wg: bind: %s %s: listen(%v)", s.id, network, laddr)
286+
log.VV("wg: bind: listen: %s %s: on(%v)", s.id, network, laddr)
287287
}
288288
// typecast is safe, because "network" is always udp[4|6]; see: Open
289289
return conn, uaddr.Port, nil
@@ -303,7 +303,7 @@ func (s *StdNetBind) Open(uport uint16) ([]conn.ReceiveFunc, uint16, error) {
303303
var tries int
304304

305305
if s.ipv4 != nil || s.ipv6 != nil {
306-
log.W("wg: bind: %s already open at :%d", s.id, uport)
306+
log.W("wg: bind: open: %s already open at :%d", s.id, uport)
307307
return nil, 0, conn.ErrBindAlreadyOpen
308308
}
309309

@@ -315,7 +315,7 @@ again:
315315

316316
ipv4, port, err = s.listenNet("udp4", port)
317317
no4 := errors.Is(err, syscall.EAFNOSUPPORT)
318-
log.D("wg: bind: %s #%d listen4(%d); no4? %t err? %v", s.id, tries, port, no4, err)
318+
log.D("wg: bind: open: %s #%d listen4(%d); no4? %t err? %v", s.id, tries, port, no4, err)
319319
if err != nil && !no4 {
320320
return nil, 0, err
321321
}
@@ -324,7 +324,7 @@ again:
324324
ipv6, port, err = s.listenNet("udp6", port)
325325
busy := errors.Is(err, syscall.EADDRINUSE)
326326
no6 := errors.Is(err, syscall.EAFNOSUPPORT)
327-
log.D("wg: bind: %s #%d listen6(%d); busy? %t no6? %t err? %v", s.id, tries, port, busy, no6, err)
327+
log.D("wg: bind: open: %s #%d listen6(%d); busy? %t no6? %t err? %v", s.id, tries, port, busy, no6, err)
328328
if uport == 0 && busy && tries < maxbindtries {
329329
clos(ipv4)
330330
tries++
@@ -345,7 +345,7 @@ again:
345345
fns = append(fns, s.makeReceiveFn(ipv6))
346346
}
347347

348-
log.I("wg: bind: %s opened port(requested %d => using %d) for v4? %t v6? %t",
348+
log.I("wg: bind: open: %s opened port(requested %d => using %d) for v4? %t v6? %t",
349349
s.id, uport, port, ipv4 != nil, ipv6 != nil)
350350
if len(fns) == 0 {
351351
return nil, 0, syscall.EAFNOSUPPORT
@@ -368,7 +368,7 @@ func (s *StdNetBind) Pause() bool {
368368

369369
// by the time resume comes about, the internal wireguard send/recv routines may have been stopped
370370
// or the keepalives blackholed for long enough that a new connection needs to be established.
371-
log.I("wg: bind: %s pausing... v4? %t v6? %t", s.id, s.ipv4 != nil, s.ipv6 != nil)
371+
log.I("wg: bind: pr: %s pausing... v4? %t v6? %t", s.id, s.ipv4 != nil, s.ipv6 != nil)
372372

373373
return true
374374
}
@@ -381,7 +381,7 @@ func (s *StdNetBind) Resume() bool {
381381
s.blackhole4 = false
382382
s.blackhole6 = false
383383

384-
log.I("wg: bind: %s resuming... v4? %t v6? %t", s.id, s.ipv4 != nil, s.ipv6 != nil)
384+
log.I("wg: bind: pr: %s resuming... v4? %t v6? %t", s.id, s.ipv4 != nil, s.ipv6 != nil)
385385

386386
return true
387387
}
@@ -418,10 +418,10 @@ func (s *StdNetBind) Close() error {
418418

419419
s.ended.Store(s.observer(Clo, nil))
420420

421-
log.I("wg: bind: %s close; addrs %s + %s; err4? %v err6? %v", s.id, addr1, addr2, err1, err2)
421+
log.I("wg: bind: close: %s addrs %v + %v; err4? %v err6? %v", s.id, addr1, addr2, err1, err2)
422422
return core.JoinErr(err1, err2)
423423
}
424-
log.W("wg: bind: %s racing close ignored", s.id)
424+
log.W("wg: bind: close: %s racing... ignored", s.id)
425425
return nil
426426
}
427427

@@ -608,7 +608,7 @@ func (s *StdNetBind) flood(c net.PacketConn, dst StdNetEndpoint, why floodkind)
608608
n += sent
609609

610610
if err != nil {
611-
log.E("wg: bind: %s flood %s %s: expected sent?(%v) / tot(%d); %v",
611+
log.E("wg: bind: flood: %s %s %s: expected sent?(%v) / tot(%d); %v",
612612
s.id, why, dst, expectedsent[:i], n, err)
613613
return n, err
614614
}
@@ -618,7 +618,7 @@ func (s *StdNetBind) flood(c net.PacketConn, dst StdNetEndpoint, why floodkind)
618618
}
619619

620620
if settings.Debug {
621-
log.D("wg: bind: %s flood %s %s: expected sent?(%v) / tot(%d)",
621+
log.D("wg: bind: flood %s %s %s: expected sent?(%v) / tot(%d)",
622622
s.id, why, dst, expectedsent, n)
623623
}
624624
return n, nil
@@ -643,7 +643,7 @@ func (s *StdNetBind) SetMark(mark uint32) (err error) {
643643
if uc4 != nil {
644644
if raw4, err = uc4.SyscallConn(); err == nil {
645645
if raw4 == nil {
646-
log.W("wg: bind: %s setmark4: raw conn nil", s.id)
646+
log.W("wg: bind: mark: %s setmark4: raw conn nil", s.id)
647647
return errNoRawConn
648648
}
649649
if err = raw4.Control(func(fd uintptr) {
@@ -656,7 +656,7 @@ func (s *StdNetBind) SetMark(mark uint32) (err error) {
656656
if err == nil && uc6 != nil {
657657
if raw6, err = uc6.SyscallConn(); err == nil {
658658
if raw6 == nil {
659-
log.W("wg: bind: %s setmark6: raw conn nil", s.id)
659+
log.W("wg: bind: mark: %s setmark6: raw conn nil", s.id)
660660
return errNoRawConn
661661
}
662662
if err = raw6.Control(func(fd uintptr) {
@@ -666,7 +666,7 @@ func (s *StdNetBind) SetMark(mark uint32) (err error) {
666666
}
667667
} // else: return err
668668
}
669-
log.I("wg: bind: %s set mark; err? %v", s.id, err)
669+
log.I("wg: bind: mark: %s err? %v", s.id, err)
670670
return nil
671671
}
672672

‎intra/ipn/wgproxy.go‎

Lines changed: 11 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -801,6 +801,7 @@ func newdevice(wgtun *wgtun, wgep wgconn) (*device.Device, error) {
801801
// started by device.NewDevice()
802802
// err = wgdev.Up()
803803
// TODO: wait for wgconn to open?
804+
log.I("proxy: wg: %s new device created %s", wgtun.tag(), core.LocStr(wgdev))
804805
return wgdev, nil
805806
}
806807

@@ -1709,7 +1710,6 @@ func (h *wgtun) listener(op wg.PktDir, err error) (ended bool) {
17091710
}
17101711
}
17111712

1712-
softrefresh := false
17131713
// s may also be TOK (for successful handshakes but not for transport data)
17141714
if age > ageThreshold.Milliseconds() && (s == TOK || s == TKO) {
17151715
lastSuccessfulRead := h.latestGoodRead.Load()
@@ -1742,17 +1742,19 @@ func (h *wgtun) listener(op wg.PktDir, err error) (ended bool) {
17421742
why = fmt.Sprintf("TZZ: r !ok? %t, w !ok? %t, rw apart? %t; overriding: %s",
17431743
readThres, writeThres, readWriteDeviation, why)
17441744
s = TNT
1745-
softrefresh = true
17461745
}
17471746
}
17481747

1749-
if s == TNT || softrefresh {
1750-
m := h.dns.Load().SoftRefresh()
1751-
if n := h.remote.Load().MaybeRefresh(); n > 0 {
1752-
log.I("wg: %s listener: %s, state: %s; refreshed %d dns / %d peers; why: %s",
1753-
h.tag(), op, pxstatus(s), m, n, why)
1754-
}
1755-
// TODO: h.redoPeers()
1748+
if s == TNT {
1749+
// listener is called from wgconn and must retrun without performing blocking ops
1750+
core.Go("wg.listener.refresh."+h.id, func() {
1751+
m := h.dns.Load().SoftRefresh()
1752+
if n := h.remote.Load().MaybeRefresh(); n > 0 {
1753+
log.I("wg: %s listener: %s, state: %s; refreshed %d dns / %d peers; why: %s",
1754+
h.tag(), op, pxstatus(s), m, n, why)
1755+
}
1756+
// TODO: h.redoPeers()
1757+
})
17561758
}
17571759
return
17581760
}

0 commit comments

Comments
 (0)