Skip to content

fix: lock log sink against concurrent write and close #10668

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.

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 1 commit into from
Nov 14, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
38 changes: 38 additions & 0 deletions cli/cliutil/sink.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,38 @@
package cliutil

import (
"io"
"sync"
)

type discardAfterClose struct {
sync.Mutex
wc io.WriteCloser
closed bool
}

// DiscardAfterClose is an io.WriteCloser that discards writes after it is closed without errors.
// It is useful as a target for a slog.Sink such that an underlying WriteCloser, like a file, can
// be cleaned up without race conditions from still-active loggers.
func DiscardAfterClose(wc io.WriteCloser) io.WriteCloser {
return &discardAfterClose{wc: wc}
}

func (d *discardAfterClose) Write(p []byte) (n int, err error) {
d.Lock()
defer d.Unlock()
if d.closed {
return len(p), nil
}
return d.wc.Write(p)
}

func (d *discardAfterClose) Close() error {
d.Lock()
defer d.Unlock()
if d.closed {
return nil
}
d.closed = true
return d.wc.Close()
}
54 changes: 54 additions & 0 deletions cli/cliutil/sink_test.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,54 @@
package cliutil_test

import (
"errors"
"testing"

"github.com/stretchr/testify/require"

"github.com/coder/coder/v2/cli/cliutil"
)

func TestDiscardAfterClose(t *testing.T) {
t.Parallel()
exErr := errors.New("test")
fwc := &fakeWriteCloser{err: exErr}
uut := cliutil.DiscardAfterClose(fwc)

n, err := uut.Write([]byte("one"))
require.Equal(t, 3, n)
require.NoError(t, err)

n, err = uut.Write([]byte("two"))
require.Equal(t, 3, n)
require.NoError(t, err)

err = uut.Close()
require.Equal(t, exErr, err)

n, err = uut.Write([]byte("three"))
require.Equal(t, 5, n)
require.NoError(t, err)

require.Len(t, fwc.writes, 2)
require.EqualValues(t, "one", fwc.writes[0])
require.EqualValues(t, "two", fwc.writes[1])
}

type fakeWriteCloser struct {
writes [][]byte
closed bool
err error
}

func (f *fakeWriteCloser) Write(p []byte) (n int, err error) {
q := make([]byte, len(p))
copy(q, p)
f.writes = append(f.writes, q)
return len(p), nil
}

func (f *fakeWriteCloser) Close() error {
f.closed = true
return f.err
}
6 changes: 4 additions & 2 deletions cli/ssh.go
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ import (

"github.com/coder/coder/v2/cli/clibase"
"github.com/coder/coder/v2/cli/cliui"
"github.com/coder/coder/v2/cli/cliutil"
"github.com/coder/coder/v2/coderd/autobuild/notify"
"github.com/coder/coder/v2/coderd/util/ptr"
"github.com/coder/coder/v2/codersdk"
Expand Down Expand Up @@ -114,12 +115,13 @@ func (r *RootCmd) ssh() *clibase.Cmd {
if err != nil {
return xerrors.Errorf("error opening %s for logging: %w", logDirPath, err)
}
dc := cliutil.DiscardAfterClose(logFile)
go func() {
wg.Wait()
_ = logFile.Close()
_ = dc.Close()
}()

logger = slog.Make(sloghuman.Sink(logFile))
logger = logger.AppendSinks(sloghuman.Sink(dc))
if r.verbose {
logger = logger.Leveled(slog.LevelDebug)
}
Expand Down
8 changes: 5 additions & 3 deletions cli/vscodessh.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@ import (
"cdr.dev/slog/sloggers/sloghuman"

"github.com/coder/coder/v2/cli/clibase"
"github.com/coder/coder/v2/cli/cliutil"
"github.com/coder/coder/v2/codersdk"
)

Expand Down Expand Up @@ -137,15 +138,16 @@ func (r *RootCmd) vscodeSSH() *clibase.Cmd {
// command via the ProxyCommand SSH option.
pid := os.Getppid()

var logger slog.Logger
logger := slog.Make()
Comment on lines -140 to +141
Copy link
Member

Choose a reason for hiding this comment

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

I'm assuming the zero value of a logger is fundamentally unsafe given exit func(int) may be nil.

Should this be a linter rule?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Actually, it's fine. https://github.com/coder/slog/blob/f0c466fabe10641afdbcc629938df29f941b3d18/slog.go#L148

But, I still like using the constructor for consistency, and in the stacked PR I set it to something else anyway.

if logDir != "" {
logFilePath := filepath.Join(logDir, fmt.Sprintf("%d.log", pid))
logFile, err := fs.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY, 0o600)
if err != nil {
return xerrors.Errorf("open log file %q: %w", logFilePath, err)
}
defer logFile.Close()
logger = slog.Make(sloghuman.Sink(logFile)).Leveled(slog.LevelDebug)
dc := cliutil.DiscardAfterClose(logFile)
defer dc.Close()
logger = logger.AppendSinks(sloghuman.Sink(dc)).Leveled(slog.LevelDebug)
}
if r.disableDirect {
logger.Info(ctx, "direct connections disabled")
Expand Down