Skip to content

Commit 76f5dfa

Browse files
omid-officialomid-official
authored
Merge branch 'n2' into fix-typos
2 parents 47db8c3 + 61187f8 commit 76f5dfa

6 files changed

Lines changed: 94 additions & 52 deletions

File tree

‎intra/backend/ipn_proxies.go‎

Lines changed: 8 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -238,14 +238,18 @@ type RouterStats struct {
238238
Rx int64
239239
// bytes transmitted
240240
Tx int64
241-
// receive errors
241+
// receive error count
242242
ErrRx int64
243-
// transmit errors
243+
// transmit error count
244244
ErrTx int64
245245
// last (most recent) receive in millis
246-
LastRx int64
247-
// last (most recent) transmit in millis
248246
LastTx int64
247+
// last (most recent) transmit in millis
248+
LastRx int64
249+
// last successful receive in millis
250+
LastGoodRx int64
251+
// last successful transmit in millis
252+
LastGoodTx int64
249253
// last (most recent) handshake or ping or connect millis
250254
LastOK int64
251255
// last refresh time in millis

‎intra/ipn/proxies.go‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1139,8 +1139,10 @@ func accStats(a, b *x.RouterStats) (c *x.RouterStats) {
11391139
c.ErrRx = a.ErrRx + b.ErrRx
11401140
c.ErrTx = a.ErrTx + b.ErrTx
11411141
c.LastOK = max(a.LastOK, b.LastOK)
1142-
c.LastRx = max(a.LastRx, b.LastRx)
11431142
c.LastTx = max(a.LastTx, b.LastTx)
1143+
c.LastRx = max(a.LastRx, b.LastRx)
1144+
c.LastGoodRx = max(a.LastGoodRx, b.LastGoodRx)
1145+
c.LastGoodTx = max(a.LastGoodTx, b.LastGoodTx)
11441146
c.LastRefresh = max(a.LastRefresh, b.LastRefresh)
11451147
// todo: a.Since or b.Since may be zero
11461148
c.Since = min(a.Since, b.Since)

‎intra/ipn/proxy.go‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -181,11 +181,11 @@ func (pxr *proxifier) addProxy(id, txt string) (p Proxy, err error) {
181181
if wgp, ok := p.(WgProxy); ok && wgp.update(id, txt) {
182182
newcfg, readd := wgp.OnProtoChange(lp)
183183
if readd || len(newcfg) > 0 {
184-
log.W("proxy: cannot update wg(%s); readd it!", id)
184+
log.W("proxy: add: cannot update wg(%s); readd it!", id)
185185
return nil, errProxyReadd
186186
}
187187

188-
log.I("proxy: updated wg %s/%s/%s", id, lp, p.GetAddr())
188+
log.I("proxy: add: updated wg %s/%s/%s", id, lp, p.GetAddr())
189189
return
190190
} // else: recreate
191191
} // else: new
@@ -219,18 +219,18 @@ func (pxr *proxifier) addProxy(id, txt string) (p Proxy, err error) {
219219
}
220220

221221
if err != nil {
222-
log.P("proxy: add %s failed; cfg: %v", id, txt)
223-
log.W("proxy: add %s failed; err: %v", id, err)
222+
log.P("proxy: add: %s failed; cfg: %v", id, txt)
223+
log.W("proxy: add: %s failed; err: %v", id, err)
224224
return nil, err
225225
} else if p == nil {
226-
log.P("proxy: add %s nil; cfg: %v", id, txt)
227-
log.W("proxy: add %s nil; txt: %d", id, len(txt))
226+
log.P("proxy: add: %s nil; cfg: %v", id, txt)
227+
log.W("proxy: add: %s nil; txt: %d", id, len(txt))
228228
return nil, errAddProxy
229229
} else if ok := pxr.add(p); !ok {
230230
return nil, errAddProxy
231231
}
232232

233-
log.I("proxy: added %s/%s/%s", p.ID(), p.Type(), p.GetAddr())
233+
log.I("proxy: add: done %s/%s/%s", p.ID(), p.Type(), p.GetAddr())
234234
return
235235
}
236236

‎intra/ipn/wg/stats.go‎

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ import (
2222

2323
"github.com/celzero/firestack/intra/core"
2424
"github.com/celzero/firestack/intra/log"
25+
"github.com/celzero/firestack/intra/settings"
2526
)
2627

2728
// from: github.com/WireGuard/wireguard-android/blob/4ba87947ae/tunnel/src/main/java/com/wireguard/android/backend/Statistics.java
@@ -75,7 +76,9 @@ func newStats(owner string) *ifstats {
7576

7677
// add adds a new peer's statistics to the map.
7778
func (s *ifstats) add(key string, rx, tx, latestHandshake int64) bool {
78-
log.VV("wg: ReadStats: %s: add %s, %d, %d, %d", s.o, key, rx, tx, latestHandshake)
79+
if settings.Debug {
80+
log.VV("wg: ReadStats: %s: add %s, %d, %d, %d", s.o, key, rx, tx, latestHandshake)
81+
}
7982
s.stats[key] = peerstats{RxBytes: rx, TxBytes: tx, LatestHandshakeEpochMillis: latestHandshake}
8083
return latestHandshake > 0
8184
}
@@ -125,8 +128,10 @@ func (s *ifstats) LatestRecentHandshake() int64 {
125128
for _, stats := range s.stats {
126129
least = max(least, stats.LatestHandshakeEpochMillis)
127130
}
128-
log.VV("wg: ReadStats: %s: LatestRecentHandshake: %s, Peers: %d",
129-
s.o, core.FmtUnixMillisAsPeriod(least), len(s.stats))
131+
if settings.Debug {
132+
log.VV("wg: ReadStats: %s: LatestRecentHandshake: %s, Peers: %d",
133+
s.o, core.FmtUnixMillisAsPeriod(least), len(s.stats))
134+
}
130135
return least
131136
}
132137

@@ -196,8 +201,9 @@ func readStats(who, config string) (*ifstats, error) {
196201
}
197202
stats.lastTouched = time.Now()
198203

199-
log.V("wg: ReadStats: %s: %d peers, %d lines, any OK? %t", who, k, n, anyStatOK)
200-
204+
if settings.Debug {
205+
log.V("wg: ReadStats: %s: %d peers, %d lines, any OK? %t", who, k, n, anyStatOK)
206+
}
201207
if !anyStatOK {
202208
return stats, errAllStatsNotOK // negative ttl on barrier
203209
}

‎intra/ipn/wg/wgconn.go‎

Lines changed: 10 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -412,10 +412,10 @@ func (s *StdNetBind) makeReceiveFn(uc net.PacketConn) conn.ReceiveFunc {
412412
}
413413

414414
if err != nil && !timedout(err) {
415-
log.E("wg: bind: %s recvFrom(%v): %d / ov? %t<=%t / trans? %t / err? %v",
415+
log.E("wg: bind: recv: %s recvfrom(%v): %d / ov? %t<=%t / trans? %t / err? %v",
416416
s.id, addr, n, usingamz, overwritten, anyTransportTyp, err)
417417
} else if settings.Debug {
418-
log.V("wg: bind: %s recvFrom(%v): %d / ov? %t<=%t / trans? %t / err? %v",
418+
log.V("wg: bind: recv: %s recvfrom(%v): %d / ov? %t<=%t / trans? %t / err? %v",
419419
s.id, addr, n, usingamz, overwritten, anyTransportTyp, err)
420420
}
421421
return numMsgs, err
@@ -662,15 +662,19 @@ func clos(c io.Closer) {
662662
core.CloseOp(c, core.CopRW)
663663
}
664664

665-
// transportType reports whether unobs is a transport message.
666-
// "unobs" must be free of Amnezia-like obfuscations.
667665
func transportType(unobs []byte) (y bool) {
666+
return messageType(unobs, device.MessageTransportType)
667+
}
668+
669+
// messageType reports whether unobs is of type t message.
670+
// "unobs" must be free of Amnezia-like obfuscations.
671+
func messageType(unobs []byte, t uint32) (y bool) {
668672
var typ uint32
669673
n := len(unobs)
670674

671675
defer func() {
672676
if settings.Debug && !y {
673-
log.V("wg: bind: transportType: len(%d) type(%d) => trans? %t", n, typ, y)
677+
log.V("wg: bind: messageType: len(%d) msgt(%d) == t(%d)? %t", n, typ, t, y)
674678
}
675679
}()
676680

@@ -679,6 +683,6 @@ func transportType(unobs []byte) (y bool) {
679683
}
680684

681685
typ = binary.LittleEndian.Uint32(unobs)
682-
y = typ == device.MessageTransportType
686+
y = typ == t
683687
return
684688
}

‎intra/ipn/wgproxy.go‎

Lines changed: 55 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -142,8 +142,10 @@ type wgtun struct {
142142
status *core.Volatile[int] // status of this interface
143143
latestRefresh atomic.Int64 // last refresh time in unix millis
144144
latestPing atomic.Int64 // last ping time in unix millis
145-
latestRx atomic.Int64 // last rx time in unix millis
146-
latestTx atomic.Int64 // last tx time in unix millis
145+
latestGoodRx atomic.Int64 // last successful rx time in unix millis
146+
latestGoodTx atomic.Int64 // last successful tx time in unix millis
147+
latestRx atomic.Int64 // last (successful or not) rx time in unix millis
148+
latestTx atomic.Int64 // last (successful or not) tx time in unix millis
147149
errRx atomic.Int64 // rx error count
148150
errTx atomic.Int64 // tx error count
149151
}
@@ -1141,12 +1143,19 @@ func (w *wgproxy) Stat() (out *x.RouterStats) {
11411143
out.ErrTx = w.errTx.Load()
11421144
out.LastRx = w.latestRx.Load()
11431145
out.LastTx = w.latestTx.Load()
1146+
out.LastGoodRx = w.latestGoodRx.Load()
1147+
out.LastGoodTx = w.latestGoodTx.Load()
11441148
out.LastRefresh = w.latestRefresh.Load()
11451149
out.Since = w.since
11461150
out.Status = pxstatus(w.status.Load()).String()
11471151

1148-
log.VV("proxy: wg: %s stats: rx: %d, tx: %d, lastok: %s",
1149-
w.tag(), out.Rx, out.Tx, core.FmtUnixMillisAsPeriod(out.LastOK))
1152+
if settings.Debug {
1153+
log.VV("proxy: wg: %s stats: rx: %d, tx: %d, r: %s (good: %s), w: %s (good: %s), lastok: %s",
1154+
w.tag(), out.Rx, out.Tx,
1155+
core.FmtUnixMillisAsPeriod(out.LastRx), core.FmtUnixMillisAsPeriod(out.LastGoodRx),
1156+
core.FmtUnixMillisAsPeriod(out.LastTx), core.FmtUnixMillisAsPeriod(out.LastGoodTx),
1157+
core.FmtUnixMillisAsPeriod(out.LastOK))
1158+
}
11501159
return out
11511160
}
11521161

@@ -1531,11 +1540,12 @@ func (h *wgtun) listener(op wg.PktDir, err error) {
15311540
defer func() {
15321541
cur := h.status.Load()
15331542
stoppedOrPaused := cur == END || cur == TPU
1534-
logeif(stoppedOrPaused)("wg: %s listener: %s; status %s => %s; ignoring2? %t, why: %s",
1535-
h.tag(), op, pxstatus(cur), pxstatus(s), stoppedOrPaused, why)
1543+
updated := false
15361544
if !stoppedOrPaused {
1537-
h.status.Cas(cur, s)
1545+
updated = h.status.Cas(cur, s)
15381546
}
1547+
logeif(!updated)("wg: %s listener: %s; status %s => %s; end/pause? %t, ignored? %t, why: %s",
1548+
h.tag(), op, pxstatus(cur), pxstatus(s), stoppedOrPaused, !updated, why)
15391549
}()
15401550

15411551
now := now()
@@ -1546,18 +1556,28 @@ func (h *wgtun) listener(op wg.PktDir, err error) {
15461556
why = "TNT: could not open conn"
15471557
} else if op == wg.Rcv && timedout(err) {
15481558
s = TZZ // writes and reads have succeeded in the recent past
1549-
why = "TZZ: timeout"
1559+
why = "TZZ: read timeout"
15501560
} else {
15511561
s = TKO
15521562
why = "TKO: " + err.Error()
15531563
}
1564+
1565+
if op == wg.Rcv && !timedout(err) { // read error
1566+
h.errRx.Add(1)
1567+
h.latestRx.Store(now)
1568+
} else if op == wg.Snd { // write error
1569+
h.errTx.Add(1)
1570+
h.latestTx.Store(now)
1571+
}
15541572
} else { // ok
15551573
s = TOK
15561574
why = "TOK: ok"
15571575
if op == wg.Rcv { // read ok
1576+
h.latestGoodRx.Store(now)
15581577
h.latestRx.Store(now)
15591578
why = "TOK: read ok"
15601579
} else if op == wg.Snd { // write ok
1580+
h.latestGoodTx.Store(now)
15611581
h.latestTx.Store(now)
15621582
why = "TOK: write ok"
15631583
} // else: not a transport message
@@ -1566,30 +1586,36 @@ func (h *wgtun) listener(op wg.PktDir, err error) {
15661586
const tenSecMillis = 10 * 1000
15671587
// s may also be TOK (for successful handshakes but not for transport data)
15681588
if age > tenSecMillis && (s == TOK || s == TKO) {
1569-
lastSuccessfulRead := h.latestRx.Load()
1570-
lastSuccessfulWrite := h.latestTx.Load()
1571-
writeElapsedMs := lastSuccessfulWrite - lastSuccessfulRead // may be negative
1572-
1573-
// if no reads since last write, mark as unresponsive
1574-
// if status is "up" but writes (Snd) have not yet happened
1589+
lastSuccessfulRead := h.latestGoodRx.Load()
1590+
lastSuccessfulWrite := h.latestGoodTx.Load()
1591+
lastRead := h.latestRx.Load()
1592+
lastWrite := h.latestTx.Load()
1593+
1594+
deviationMs := (max(lastSuccessfulWrite, lastSuccessfulRead) -
1595+
min(lastSuccessfulWrite, lastSuccessfulRead))
1596+
readElapsedMs := lastRead - lastSuccessfulRead // never negative
1597+
writeElapsedMs := lastWrite - lastSuccessfulWrite // never negative
1598+
1599+
hasNewWrites := lastWrite > age
1600+
hasNewReads := lastRead > age
1601+
1602+
// too much time since last good write and good reads
1603+
readWriteDeviation := (hasNewReads || hasNewWrites) && deviationMs > markTNTAfterMillis
1604+
// too much time since last attempted read was good
1605+
readThres := hasNewReads && readElapsedMs > markTNTAfterMillis
1606+
// too much time since last attempted write was good
1607+
writeThres := hasNewWrites && writeElapsedMs > markTNTAfterMillis
1608+
1609+
// if status is !ok (TKO), no reads since last write, mark as unresponsive
1610+
// if status is ok (TOK) but writes have not yet happened
15751611
// then reads (Rcv) are expected to timeout; so ignore them
1576-
if lastSuccessfulRead <= age && lastSuccessfulWrite <= age {
1612+
if !hasNewReads && !hasNewWrites {
15771613
why = "TZZ: idling after start/refresh"
15781614
s = TZZ // possibly idling
1579-
} else if (s == TKO && lastSuccessfulRead <= age && lastSuccessfulWrite > age) ||
1580-
(s == TOK && writeElapsedMs > markTNTAfterMillis) {
1581-
why = fmt.Sprintf("TNT: [w ok, r !ok] (if %d == -1) OR [w !ok, no r] (if %d == -2); %s",
1582-
s, s, pxstatus(s))
1583-
s = TNT // writes succeeded; but reads have never or not in the past 20s
1584-
}
1585-
}
1586-
1587-
if s != TOK {
1588-
switch op {
1589-
case wg.Rcv:
1590-
h.errRx.Add(1)
1591-
case wg.Snd:
1592-
h.errTx.Add(1)
1615+
} else if readThres || writeThres || readWriteDeviation {
1616+
why = fmt.Sprintf("TNT: r !ok? %t, w !ok? %t, rw apart? %t; overriding: %s",
1617+
readThres, writeThres, readWriteDeviation, why)
1618+
s = TNT
15931619
}
15941620
}
15951621

0 commit comments

Comments
 (0)