Skip to content

ci: Improve peer logging to help identify race #93

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
Jan 30, 2022
Merged

ci: Improve peer logging to help identify race #93

Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
40d204f
ci: Improve peer logging to help identify race
kylecarbs Jan 30, 2022
8343404
Remove mutex locks
kylecarbs Jan 30, 2022
f4c9dc2
Add hash to write
kylecarbs Jan 30, 2022
f655897
Improve comment
kylecarbs Jan 30, 2022
0a9ff49
Merge branch 'main' into peerdebug
kylecarbs Jan 30, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
57 changes: 48 additions & 9 deletions peer/conn.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import (
"bytes"
"context"
"crypto/rand"
"crypto/sha256"
"io"
"sync"
"time"
Expand Down Expand Up @@ -140,15 +141,43 @@ type Conn struct {

func (c *Conn) init() error {
c.rtc.OnNegotiationNeeded(c.negotiate)
c.rtc.OnICEConnectionStateChange(func(iceConnectionState webrtc.ICEConnectionState) {
// Close must be locked here otherwise log output can appear
// after the connection has been closed.
c.closeMutex.Lock()
defer c.closeMutex.Unlock()
if c.isClosed() {
return
}

c.opts.Logger.Debug(context.Background(), "ice connection state updated",
slog.F("state", iceConnectionState))
})
c.rtc.OnICEGatheringStateChange(func(iceGatherState webrtc.ICEGathererState) {
// Close can't be locked here, because this is triggered
// when close is called. It doesn't appear this get's
// executed after close though, so it shouldn't cause
// problems.
if c.isClosed() {
return
}

c.opts.Logger.Debug(context.Background(), "ice gathering state updated",
slog.F("state", iceGatherState))
Comment on lines +165 to +166
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for adding this additional logging!

})
c.rtc.OnICECandidate(func(iceCandidate *webrtc.ICECandidate) {
if iceCandidate == nil {
return
}
c.opts.Logger.Debug(context.Background(), "adding local candidate")
json := iceCandidate.ToJSON()
c.opts.Logger.Debug(context.Background(), "writing candidate to channel",
slog.F("hash", sha256.Sum224([]byte(json.Candidate))),
slog.F("length", len(json.Candidate)),
)
select {
case <-c.closed:
break
case c.localCandidateChannel <- iceCandidate.ToJSON():
case c.localCandidateChannel <- json:
}
})
c.rtc.OnDataChannel(func(dc *webrtc.DataChannel) {
Expand All @@ -169,8 +198,7 @@ func (c *Conn) init() error {
}

c.opts.Logger.Debug(context.Background(), "rtc connection updated",
slog.F("state", pcs),
slog.F("ice", c.rtc.ICEConnectionState()))
slog.F("state", pcs))

switch pcs {
case webrtc.PeerConnectionStateDisconnected:
Expand Down Expand Up @@ -311,15 +339,22 @@ func (c *Conn) negotiate() {
c.pendingCandidatesMutex.Lock()
defer c.pendingCandidatesMutex.Unlock()
for _, pendingCandidate := range c.pendingRemoteCandidates {
c.opts.Logger.Debug(context.Background(), "flushing remote candidate")
hash := sha256.Sum224([]byte(pendingCandidate.Candidate))
c.opts.Logger.Debug(context.Background(), "flushing buffered remote candidate",
slog.F("hash", hash),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Neat idea to log this, so we can track if a particular ICE candidate made it across

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I'm concerned that somehow the ICE candidate isn't getting across the pipe, so at least now we'll know whether it does or not!

Copy link
Contributor

@bryphe-coder bryphe-coder Jan 30, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Speaking of that - we could also add logging when we set up the channels in the peer/conn_test.go, too!

			case c := <-channel1.LocalCandidate():
				_ = channel2.AddRemoteCandidate(c)

coder/peer/conn_test.go

Line 304 in f9e594f

case c := <-channel2.LocalCandidate():

And it might make sense to assert no error on that AddRemoteCandidate call? I don't think it should in the local network case (and if it does, might give us extra clues)

slog.F("length", len(pendingCandidate.Candidate)),
)
err := c.rtc.AddICECandidate(pendingCandidate)
if err != nil {
_ = c.CloseWithError(xerrors.Errorf("flush pending candidates: %w", err))
_ = c.CloseWithError(xerrors.Errorf("flush pending remote candidate: %w", err))
return
}
}
c.opts.Logger.Debug(context.Background(), "flushed buffered remote candidates",
slog.F("count", len(c.pendingRemoteCandidates)),
)
c.pendingCandidatesFlushed = true
c.opts.Logger.Debug(context.Background(), "flushed remote candidates")
c.pendingRemoteCandidates = make([]webrtc.ICECandidateInit, 0)
}

// LocalCandidate returns a channel that emits when a local candidate
Expand All @@ -332,12 +367,16 @@ func (c *Conn) LocalCandidate() <-chan webrtc.ICECandidateInit {
func (c *Conn) AddRemoteCandidate(i webrtc.ICECandidateInit) error {
c.pendingCandidatesMutex.Lock()
defer c.pendingCandidatesMutex.Unlock()
fields := []slog.Field{
slog.F("hash", sha256.Sum224([]byte(i.Candidate))),
slog.F("length", len(i.Candidate)),
}
if !c.pendingCandidatesFlushed {
c.opts.Logger.Debug(context.Background(), "adding remote candidate to buffer")
c.opts.Logger.Debug(context.Background(), "bufferring remote candidate", fields...)
c.pendingRemoteCandidates = append(c.pendingRemoteCandidates, i)
return nil
}
c.opts.Logger.Debug(context.Background(), "adding remote candidate")
c.opts.Logger.Debug(context.Background(), "adding remote candidate", fields...)
return c.rtc.AddICECandidate(i)
}

Expand Down