Skip to content

Commit 844a982

Browse files
ignoramousignoramous
committed
ipn/wg: gso / batch mode debug logs
1 parent ed14de7 commit 844a982

File tree

2 files changed

+40
-28
lines changed

2 files changed

+40
-28
lines changed

‎intra/ipn/wg/wgconn.go‎

Lines changed: 15 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -399,8 +399,13 @@ func (s *StdNetBind) makeReceiveFn(uc net.PacketConn) conn.ReceiveFunc {
399399
eps[i] = s.asEndpoint(addr)
400400
}
401401

402-
logeif(err != nil && !timedout(err))("wg: bind: %s recvFrom(%v): %d / ov? %t<=%t / err? %v",
403-
s.id, addr, n, usingamz, overwritten, err)
402+
if err != nil && !timedout(err) {
403+
log.E("wg: bind: %s recvFrom(%v): %d / ov? %t<=%t / err? %v",
404+
s.id, addr, n, usingamz, overwritten, err)
405+
} else if settings.Debug {
406+
log.V("wg: bind: %s recvFrom(%v): %d / ov? %t<=%t / err? %v",
407+
s.id, addr, n, usingamz, overwritten, err)
408+
}
404409
return numMsgs, err
405410
}
406411
}
@@ -480,8 +485,14 @@ func (s *StdNetBind) Send(buf [][]byte, peer conn.Endpoint) (err error) {
480485

481486
s.sendAddr.Store(dstIpp)
482487

483-
loge(errs)("wg: bind: send: %s addr(%v) parcels(%d) tx(%d) (exp? %t / flood? %t / overw? %t); err? %v",
484-
s.id, dstIpp, len(buf), nn, experimentalWg, flooded, overwritten, errs)
488+
if errs != nil {
489+
log.E("wg: bind: send: %s addr(%v) parcels(%d) tx(%d) (exp? %t / flood? %t / overw? %t); err? %v",
490+
s.id, dstIpp, len(buf), nn, experimentalWg, flooded, overwritten, errs)
491+
} else if settings.Debug {
492+
log.V("wg: bind: send: %s addr(%v) parcels(%d) tx(%d) (exp? %t / flood? %t / overw? %t); err? %v",
493+
s.id, dstIpp, len(buf), nn, experimentalWg, flooded, overwritten, errs)
494+
}
495+
485496
return errs
486497
}
487498

@@ -622,13 +633,6 @@ func loge(err error) log.LogFn {
622633
return l
623634
}
624635

625-
func logeif(cond bool) log.LogFn {
626-
if cond {
627-
return log.E
628-
}
629-
return log.V
630-
}
631-
632636
func extend(c core.MinConn, t time.Duration) {
633637
if c != nil && core.IsNotNil(c) {
634638
_ = c.SetDeadline(time.Now().Add(t))

‎intra/ipn/wg/wgconn2.go‎

Lines changed: 25 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -115,7 +115,7 @@ var (
115115
var errSplitOverflow = errors.New("wg: splitting coalesced packet resulted in overflow")
116116

117117
func (e ErrUDPGSODisabled) Error() string {
118-
return fmt.Sprintf("disabled UDP GSO on %s, NIC(s) may not support checksum offload", e.onLaddr)
118+
return fmt.Sprintf("disabled udp gso on %s, NIC(s) may not support checksum offload", e.onLaddr)
119119
}
120120

121121
func (e ErrUDPGSODisabled) Unwrap() error {
@@ -368,34 +368,36 @@ func (s *StdNetBind2) receiveIP(
368368
msg.OOB = msg.OOB[:cap(msg.OOB)]
369369
}
370370

371+
batch := false
371372
var numMsgs int
372373
if br != nil {
373374
if rxOffload {
374375
readAt := len(*msgs) - (IdealBatchSize / udpSegmentMaxDatagrams)
375376
numMsgs, err = br.ReadBatch((*msgs)[readAt:], 0)
376377
waddr := msgAddr(msgs)
377-
loge(err)("wg: bind2: %s GRO: readAt(%d) addr(%v) numMsgs(%d) err(%v)", s.id, readAt, waddr, numMsgs, err)
378378
if err != nil {
379+
log.E("wg: bind2: %s GRO: readAt(%d) addr(%v) numMsgs(%d) err(%v)", s.id, readAt, waddr, numMsgs, err)
379380
return 0, err
380381
}
381382

382383
numMsgs, err = splitCoalescedMessages(*msgs, readAt, getGSOSize)
383-
loge(err)("wg: bind2: %s GRO: splitCoalescedMessages(at: %d; from: %v) numMsgs(%d) err(%v)", s.id, readAt, waddr, numMsgs, err)
384384
if err != nil {
385+
log.E("wg: bind2: %s GRO: splitCoalescedMessages(at: %d; from: %v) numMsgs(%d) err(%v)", s.id, readAt, waddr, numMsgs, err)
385386
return 0, err
386387
}
387388
} else {
389+
batch = true
388390
numMsgs, err = br.ReadBatch(*msgs, 0)
389-
loge(err)("wg: bind2: %s ReadBatch(sz: %d; from: %s) numMsgs(%d) err(%v)", s.id, len(*msgs), msgAddr(msgs), numMsgs, err)
390391
if err != nil {
392+
log.E("wg: bind2: %s ReadBatch(sz: %d; from: %s) numMsgs(%d) err(%v)", s.id, len(*msgs), msgAddr(msgs), numMsgs, err)
391393
return 0, err
392394
}
393395
}
394396
} else {
395397
msg := &(*msgs)[0]
396398
msg.N, msg.NN, _, msg.Addr, err = conn.ReadMsgUDP(msg.Buffers[0], msg.OOB)
397-
loge(err)("wg: bind2: %s ReadMsgUDP(sz: %d; from: %v) err(%v)", s.id, msg.N, msg.Addr, err)
398399
if err != nil {
400+
log.E("wg: bind2: %s ReadMsgUDP(sz: %d; from: %v) err(%v)", s.id, msg.N, msg.Addr, err)
399401
return 0, err
400402
}
401403
numMsgs = 1
@@ -404,7 +406,7 @@ func (s *StdNetBind2) receiveIP(
404406
for i := 0; i < numMsgs; i++ {
405407
msg := &(*msgs)[i]
406408
sizes[i] = msg.N
407-
if sizes[i] == 0 {
409+
if sizes[i] == 0 && settings.Debug {
408410
log.V("wg: bind2: %s zero-sized message from %v", s.id, msg.Addr)
409411
continue
410412
}
@@ -418,7 +420,7 @@ func (s *StdNetBind2) receiveIP(
418420
eps[i] = ep
419421
}
420422
if settings.Debug {
421-
log.VV("wg: bind2: %s received %d messages", s.id, numMsgs)
423+
log.VV("wg: bind2: %s received (batch? %t, offload? %t) %d messages", s.id, batch, rxOffload, numMsgs)
422424
}
423425
return numMsgs, nil
424426
}
@@ -598,8 +600,9 @@ retry:
598600
if offload {
599601
n := coalesceMessages(ua, ep, bufs, *msgs, setGSOSize)
600602
// send coalesced msgs; ie, len(*msgs) <= len(bufs)
601-
err = s.send(c, br, (*msgs)[:n])
602-
loge(err)("wg: bind2: %s GSO: send(%d/%d) to %s; err(%v)", s.id, n, len(bufs), ua, err)
603+
if err = s.send(c, br, (*msgs)[:n], "gso"); err != nil {
604+
log.E("wg: bind2: %s gso: send(%d/%d) to %s; err(%v)", s.id, n, len(bufs), ua, err)
605+
}
603606

604607
if shouldDisableUDPGSOOnError(err) { // err may be nil
605608
offload = false
@@ -611,7 +614,7 @@ retry:
611614
}
612615
s.mu.Unlock()
613616
retried = true
614-
log.E("wg: bind2: %s GSO: disabled on %s / v4? %t; err %v", s.id, ua, !is6, err)
617+
log.E("wg: bind2: %s gso: disabled on %s / v4? %t; err %v", s.id, ua, !is6, err)
615618
goto retry
616619
}
617620
} else {
@@ -623,21 +626,22 @@ retry:
623626
setSrcControl(&msg.OOB, ep) // no-op on Android
624627
}
625628
// send all msgs
626-
err = s.send(c, br, (*msgs)[:len(bufs)])
627-
loge(err)("wg: bind2: %s GSO: send(%d) to %s (retry? %t); err(%v)", s.id, len(bufs), ua, retried, err)
629+
if err = s.send(c, br, (*msgs)[:len(bufs)], "batch"); err != nil {
630+
log.E("wg: bind2: %s gso: send(%d) to %s (retry? %t); err(%v)", s.id, len(bufs), ua, retried, err)
631+
}
628632
}
629633
if retried {
630634
x := zeroaddr
631635
if a := c.LocalAddr(); a != nil {
632636
x = a
633637
}
634-
log.W("wg: bind2: %s disabled UDP GSO on %s; err %v", s.id, x, err)
638+
log.W("wg: bind2: %s disabled udp gso on %s; err %v", s.id, x, err)
635639
return ErrUDPGSODisabled{onLaddr: x.String(), RetryErr: err}
636640
}
637641
return err
638642
}
639643

640-
func (s *StdNetBind2) send(conn *net.UDPConn, pc batchWriter, msgs []ipv6.Message) (err error) {
644+
func (s *StdNetBind2) send(conn *net.UDPConn, pc batchWriter, msgs []ipv6.Message, who string) (err error) {
641645
var n, start int
642646

643647
batch := pc != nil && core.IsNotNil(pc)
@@ -653,18 +657,22 @@ func (s *StdNetBind2) send(conn *net.UDPConn, pc batchWriter, msgs []ipv6.Messag
653657
for _, msg := range msgs {
654658
addr, ok := msg.Addr.(*net.UDPAddr)
655659
if !ok { // unlikely
656-
log.E("wg: bind2: %s wrong addr type %s %T", s.id, msg.Addr, msg.Addr)
660+
log.E("wg: bind2: %s send: %s wrong addr type %s %T", s.id, who, msg.Addr, msg.Addr)
657661
continue
658662
}
659663
_, _, err = conn.WriteMsgUDP(msg.Buffers[0], msg.OOB, addr)
660664
if err != nil {
661-
log.E("wg: bind2: %s send: to %v; err %v", s.id, addr, err)
665+
log.E("wg: bind2: %s send: %s to %v; err %v", s.id, who, addr, err)
662666
break
663667
}
664668
n += 1
665669
}
666670
}
667-
loge(err)("wg: bind2: %s send: batch? %t; n(%d); err? %v", s.id, batch, n, err)
671+
if err != nil {
672+
log.E("wg: bind2: %s send: %s batch? %t; n(%d); err? %v", s.id, who, batch, n, err)
673+
} else {
674+
log.V("wg: bind2: %s send: %s batch? %t; n(%d); err? %v", s.id, who, batch, n, err)
675+
}
668676
return err
669677
}
670678

0 commit comments

Comments
 (0)