Skip to content

Commit b98909a

Browse files
mjmacmjmac
committed
Add leveled/scoped logging facility
Allow package-scoped logging at user-defined levels. Logs are at ERROR by default, for critical errors which should be handled by users. More verbose logging may be enabled via combinations of environment variables, e.g. PIONS_LOG_TRACE=ice PIONS_LOG_DEBUG=pc,dtls PIONS_LOG_INFO=all <cmd> Relates to #222
1 parent 29d004c commit b98909a

8 files changed

+422
-31
lines changed

‎pkg/ice/agent.go

+21-16
Original file line numberDiff line numberDiff line change
@@ -163,14 +163,14 @@ func (a *Agent) gatherCandidatesLocal() {
163163
for _, network := range supportedNetworks {
164164
conn, err := a.listenUDP(network, &net.UDPAddr{IP: ip, Port: 0})
165165
if err != nil {
166-
fmt.Printf("could not listen %s %s\n", network, ip)
166+
iceLog.Warningf("could not listen %s %s\n", network, ip)
167167
continue
168168
}
169169

170170
port := conn.LocalAddr().(*net.UDPAddr).Port
171171
c, err := NewCandidateHost(network, ip, port)
172172
if err != nil {
173-
fmt.Printf("Failed to create host candidate: %s %s %d: %v\n", network, ip, port, err)
173+
iceLog.Warningf("Failed to create host candidate: %s %s %d: %v\n", network, ip, port, err)
174174
continue
175175
}
176176

@@ -192,12 +192,12 @@ func (a *Agent) gatherCandidatesReflective(urls []*URL) {
192192
case SchemeTypeSTUN:
193193
laddr, xoraddr, err := allocateUDP(network, url)
194194
if err != nil {
195-
fmt.Printf("could not allocate %s %s: %v\n", network, url, err)
195+
iceLog.Warningf("could not allocate %s %s: %v\n", network, url, err)
196196
continue
197197
}
198198
conn, err := net.ListenUDP(network, laddr)
199199
if err != nil {
200-
fmt.Printf("could not listen %s %s: %v\n", network, laddr, err)
200+
iceLog.Warningf("could not listen %s %s: %v\n", network, laddr, err)
201201
}
202202

203203
ip := xoraddr.IP
@@ -206,7 +206,7 @@ func (a *Agent) gatherCandidatesReflective(urls []*URL) {
206206
relPort := laddr.Port
207207
c, err := NewCandidateServerReflexive(network, ip, port, relIP, relPort)
208208
if err != nil {
209-
fmt.Printf("Failed to create server reflexive candidate: %s %s %d: %v\n", network, ip, port, err)
209+
iceLog.Warningf("Failed to create server reflexive candidate: %s %s %d: %v\n", network, ip, port, err)
210210
continue
211211
}
212212

@@ -218,7 +218,7 @@ func (a *Agent) gatherCandidatesReflective(urls []*URL) {
218218
c.start(a, conn)
219219

220220
default:
221-
fmt.Printf("scheme %s is not implemented\n", url.Scheme.String())
221+
iceLog.Warningf("scheme %s is not implemented\n", url.Scheme)
222222
continue
223223
}
224224
}
@@ -266,6 +266,7 @@ func (a *Agent) startConnectivityChecks(isControlling bool, remoteUfrag, remoteP
266266
} else if remotePwd == "" {
267267
return errors.Errorf("remotePwd is empty")
268268
}
269+
iceLog.Debugf("Started agent: isControlling? %t, remoteUfrag: %q, remotePwd: %q", isControlling, remoteUfrag, remotePwd)
269270

270271
return a.run(func(agent *Agent) {
271272
agent.isControlling = isControlling
@@ -314,7 +315,7 @@ func (a *Agent) pingCandidate(local, remote *Candidate) {
314315
}
315316

316317
if err != nil {
317-
fmt.Println(err)
318+
iceLog.Debug(err.Error())
318319
return
319320
}
320321

@@ -335,6 +336,7 @@ func (a *Agent) updateConnectionState(newState ConnectionState) {
335336
func (a *Agent) setValidPair(local, remote *Candidate, selected bool) {
336337
// TODO: avoid duplicates
337338
p := newCandidatePair(local, remote)
339+
iceLog.Debugf("Found valid candidate pair: %s <-> %s (selected? %t)", local, remote, selected)
338340

339341
if selected {
340342
a.selectedPair = p
@@ -374,8 +376,10 @@ func (a *Agent) taskLoop() {
374376
select {
375377
case <-a.connectivityChan:
376378
if a.validateSelectedPair() {
379+
iceLog.Trace("checking keepalive")
377380
a.checkKeepalive()
378381
} else {
382+
iceLog.Trace("pinging all candidates")
379383
a.pingAllCandidates()
380384
}
381385

@@ -490,7 +494,7 @@ func (a *Agent) Close() error {
490494
for _, c := range cs {
491495
err := c.close()
492496
if err != nil {
493-
fmt.Printf("Failed to close candidate %s: %v", c, err)
497+
iceLog.Warningf("Failed to close candidate %s: %v", c, err)
494498
}
495499
}
496500
delete(agent.localCandidates, net)
@@ -499,7 +503,7 @@ func (a *Agent) Close() error {
499503
for _, c := range cs {
500504
err := c.close()
501505
if err != nil {
502-
fmt.Printf("Failed to close candidate %s: %v", c, err)
506+
iceLog.Warningf("Failed to close candidate %s: %v", c, err)
503507
}
504508
}
505509
delete(agent.remoteCandidates, net)
@@ -526,7 +530,7 @@ func (a *Agent) findRemoteCandidate(networkType NetworkType, addr net.Addr) *Can
526530
ip = a.IP
527531
port = a.Port
528532
default:
529-
fmt.Printf("unsupported address type %T", a)
533+
iceLog.Warningf("unsupported address type %T", a)
530534
return nil
531535
}
532536

@@ -555,20 +559,21 @@ func (a *Agent) sendBindingSuccess(m *stun.Message, local, remote *Candidate) {
555559
},
556560
&stun.Fingerprint{},
557561
); err != nil {
558-
fmt.Printf("Failed to handle inbound ICE from: %s to: %s error: %s", local.String(), remote.String(), err.Error())
562+
iceLog.Warningf("Failed to handle inbound ICE from: %s to: %s error: %s", local, remote, err)
559563
} else {
560564
a.sendSTUN(out, local, remote)
561565
}
562566
}
563567

564568
func (a *Agent) handleInboundControlled(m *stun.Message, localCandidate, remoteCandidate *Candidate) {
565569
if _, isControlled := m.GetOneAttribute(stun.AttrIceControlled); isControlled && !a.isControlling {
566-
fmt.Println("inbound isControlled && a.isControlling == false")
570+
iceLog.Debug("inbound isControlled && a.isControlling == false")
567571
return
568572
}
569573

570574
successResponse := m.Method == stun.MethodBinding && m.Class == stun.ClassSuccessResponse
571575
_, usepair := m.GetOneAttribute(stun.AttrUseCandidate)
576+
iceLog.Debugf("got controlled message (success? %t, usepair? %t)", successResponse, usepair)
572577
// Remember the working pair and select it when marked with usepair
573578
a.setValidPair(localCandidate, remoteCandidate, usepair)
574579

@@ -580,12 +585,13 @@ func (a *Agent) handleInboundControlled(m *stun.Message, localCandidate, remoteC
580585

581586
func (a *Agent) handleInboundControlling(m *stun.Message, localCandidate, remoteCandidate *Candidate) {
582587
if _, isControlling := m.GetOneAttribute(stun.AttrIceControlling); isControlling && a.isControlling {
583-
fmt.Println("inbound isControlling && a.isControlling == true")
588+
iceLog.Debug("inbound isControlling && a.isControlling == true")
584589
return
585590
} else if _, useCandidate := m.GetOneAttribute(stun.AttrUseCandidate); useCandidate && a.isControlling {
586-
fmt.Println("useCandidate && a.isControlling == true")
591+
iceLog.Debug("useCandidate && a.isControlling == true")
587592
return
588593
}
594+
iceLog.Debugf("got controlling message: %#v", m)
589595

590596
successResponse := m.Method == stun.MethodBinding && m.Class == stun.ClassSuccessResponse
591597
// Remember the working pair and select it when receiving a success response
@@ -604,8 +610,7 @@ func (a *Agent) handleInboundControlling(m *stun.Message, localCandidate, remote
604610
func (a *Agent) handleInbound(m *stun.Message, local *Candidate, remote net.Addr) {
605611
remoteCandidate := a.findRemoteCandidate(local.NetworkType, remote)
606612
if remoteCandidate == nil {
607-
// TODO debug
608-
// fmt.Printf("Could not find remote candidate for %s:%d ", remote.IP.String(), remote.Port)
613+
iceLog.Debugf("Could not find remote candidate for %s ", remote)
609614
return
610615
}
611616

‎pkg/ice/candidate.go

+2-2
Original file line numberDiff line numberDiff line change
@@ -89,14 +89,14 @@ func (c *Candidate) recvLoop() {
8989
if stun.IsSTUN(buffer[:n]) {
9090
m, err := stun.NewMessage(buffer[:n])
9191
if err != nil {
92-
fmt.Println(fmt.Sprintf("Failed to handle decode ICE from %s to %s: %v", c.addr(), srcAddr, err))
92+
iceLog.Warningf("Failed to handle decode ICE from %s to %s: %v", c.addr(), srcAddr, err)
9393
continue
9494
}
9595
err = c.agent.run(func(agent *Agent) {
9696
agent.handleInbound(m, c, srcAddr)
9797
})
9898
if err != nil {
99-
fmt.Println(fmt.Sprintf("Failed to handle message: %v", err))
99+
iceLog.Warningf("Failed to handle message: %v", err)
100100
}
101101

102102
continue

‎pkg/ice/candidatepair.go

+2-8
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,6 @@
11
package ice
22

33
import (
4-
"fmt"
5-
64
"github.com/pions/pkg/stun"
75
)
86

@@ -34,7 +32,7 @@ func (a *Agent) keepaliveCandidate(local, remote *Candidate) {
3432
)
3533

3634
if err != nil {
37-
fmt.Println(err)
35+
iceLog.Warning(err.Error())
3836
return
3937
}
4038

@@ -44,10 +42,6 @@ func (a *Agent) keepaliveCandidate(local, remote *Candidate) {
4442
func (a *Agent) sendSTUN(msg *stun.Message, local, remote *Candidate) {
4543
_, err := local.writeTo(msg.Pack(), remote)
4644
if err != nil {
47-
// TODO: Determine if we should always drop the err
48-
// E.g.: maybe handle for known valid pairs or to
49-
// discard pairs faster.
50-
_ = err
51-
// fmt.Printf("failed to send STUN message: %v", err)
45+
iceLog.Warningf("failed to send STUN message: %s", err)
5246
}
5347
}

‎pkg/ice/logging.go

+5
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
package ice
2+
3+
import "github.com/pions/webrtc/pkg/logging"
4+
5+
var iceLog = logging.NewScopedLogger("ice")

0 commit comments

Comments
 (0)