diff --git a/cli/portforward.go b/cli/portforward.go index 034b14f894db7..d47a6acb2280c 100644 --- a/cli/portforward.go +++ b/cli/portforward.go @@ -98,7 +98,7 @@ func (r *RootCmd) portForward() *clibase.Cmd { return xerrors.Errorf("await agent: %w", err) } - var logger slog.Logger + logger := slog.Make() if r.verbose { logger = slog.Make(sloghuman.Sink(inv.Stdout)).Leveled(slog.LevelDebug) } @@ -131,7 +131,7 @@ func (r *RootCmd) portForward() *clibase.Cmd { defer closeAllListeners() for i, spec := range specs { - l, err := listenAndPortForward(ctx, inv, conn, wg, spec) + l, err := listenAndPortForward(ctx, inv, conn, wg, spec, logger) if err != nil { return err } @@ -185,7 +185,15 @@ func (r *RootCmd) portForward() *clibase.Cmd { return cmd } -func listenAndPortForward(ctx context.Context, inv *clibase.Invocation, conn *codersdk.WorkspaceAgentConn, wg *sync.WaitGroup, spec portForwardSpec) (net.Listener, error) { +func listenAndPortForward( + ctx context.Context, + inv *clibase.Invocation, + conn *codersdk.WorkspaceAgentConn, + wg *sync.WaitGroup, + spec portForwardSpec, + logger slog.Logger, +) (net.Listener, error) { + logger = logger.With(slog.F("network", spec.listenNetwork), slog.F("address", spec.listenAddress)) _, _ = fmt.Fprintf(inv.Stderr, "Forwarding '%v://%v' locally to '%v://%v' in the workspace\n", spec.listenNetwork, spec.listenAddress, spec.dialNetwork, spec.dialAddress) var ( @@ -218,6 +226,7 @@ func listenAndPortForward(ctx context.Context, inv *clibase.Invocation, conn *co if err != nil { return nil, xerrors.Errorf("listen '%v://%v': %w", spec.listenNetwork, spec.listenAddress, err) } + logger.Debug(ctx, "listening") wg.Add(1) go func(spec portForwardSpec) { @@ -227,12 +236,14 @@ func listenAndPortForward(ctx context.Context, inv *clibase.Invocation, conn *co if err != nil { // Silently ignore net.ErrClosed errors. if xerrors.Is(err, net.ErrClosed) { + logger.Debug(ctx, "listener closed") return } _, _ = fmt.Fprintf(inv.Stderr, "Error accepting connection from '%v://%v': %v\n", spec.listenNetwork, spec.listenAddress, err) _, _ = fmt.Fprintln(inv.Stderr, "Killing listener") return } + logger.Debug(ctx, "accepted connection", slog.F("remote_addr", netConn.RemoteAddr())) go func(netConn net.Conn) { defer netConn.Close() @@ -242,8 +253,10 @@ func listenAndPortForward(ctx context.Context, inv *clibase.Invocation, conn *co return } defer remoteConn.Close() + logger.Debug(ctx, "dialed remote", slog.F("remote_addr", netConn.RemoteAddr())) agentssh.Bicopy(ctx, netConn, remoteConn) + logger.Debug(ctx, "connection closing", slog.F("remote_addr", netConn.RemoteAddr())) }(netConn) } }(spec) diff --git a/cli/portforward_test.go b/cli/portforward_test.go index ef4d36ee05e5a..6dc6bb131d62f 100644 --- a/cli/portforward_test.go +++ b/cli/portforward_test.go @@ -140,9 +140,10 @@ func TestPortForward(t *testing.T) { for _, c := range cases { c := c - // Delay parallel tests here because setupLocal reserves + // No parallel tests here because setupLocal reserves // a free open port which is not guaranteed to be free // between the listener closing and port-forward ready. + //nolint:tparallel,paralleltest t.Run(c.name+"_OnePort", func(t *testing.T) { p1 := setupTestListener(t, c.setupRemote(t)) @@ -166,8 +167,6 @@ func TestPortForward(t *testing.T) { }() pty.ExpectMatchContext(ctx, "Ready!") - t.Parallel() // Port is reserved, enable parallel execution. - // Open two connections simultaneously and test them out of // sync. d := net.Dialer{Timeout: testutil.WaitShort} @@ -185,6 +184,10 @@ func TestPortForward(t *testing.T) { require.ErrorIs(t, err, context.Canceled) }) + // No parallel tests here because setupLocal reserves + // a free open port which is not guaranteed to be free + // between the listener closing and port-forward ready. + //nolint:tparallel,paralleltest t.Run(c.name+"_TwoPorts", func(t *testing.T) { var ( p1 = setupTestListener(t, c.setupRemote(t)) @@ -213,8 +216,6 @@ func TestPortForward(t *testing.T) { }() pty.ExpectMatchContext(ctx, "Ready!") - t.Parallel() // Port is reserved, enable parallel execution. - // Open a connection to both listener 1 and 2 simultaneously and // then test them out of order. d := net.Dialer{Timeout: testutil.WaitShort} @@ -234,6 +235,10 @@ func TestPortForward(t *testing.T) { } // Test doing TCP and UDP at the same time. + // No parallel tests here because setupLocal reserves + // a free open port which is not guaranteed to be free + // between the listener closing and port-forward ready. + //nolint:tparallel,paralleltest t.Run("All", func(t *testing.T) { var ( dials = []addr{} @@ -266,8 +271,6 @@ func TestPortForward(t *testing.T) { }() pty.ExpectMatchContext(ctx, "Ready!") - t.Parallel() // Port is reserved, enable parallel execution. - // Open connections to all items in the "dial" array. var ( d = net.Dialer{Timeout: testutil.WaitShort} diff --git a/tailnet/conn.go b/tailnet/conn.go index 358241108d147..f9c82bc753c92 100644 --- a/tailnet/conn.go +++ b/tailnet/conn.go @@ -936,10 +936,12 @@ func (c *Conn) Listen(network, addr string) (net.Listener, error) { } func (c *Conn) DialContextTCP(ctx context.Context, ipp netip.AddrPort) (*gonet.TCPConn, error) { + c.logger.Debug(ctx, "dial tcp", slog.F("addr_port", ipp)) return c.netStack.DialContextTCP(ctx, ipp) } func (c *Conn) DialContextUDP(ctx context.Context, ipp netip.AddrPort) (*gonet.UDPConn, error) { + c.logger.Debug(ctx, "dial udp", slog.F("addr_port", ipp)) return c.netStack.DialContextUDP(ctx, ipp) }