Skip to content

Commit 5bf34dc

Browse files
coadlercoadler
authored
Refactor logging to use stderr, auth key to stdout (#23)
Separate logging to stderr to ensure normal logs don't interfere with processing output that is expected on stdout, specifically the auth key. Closes #16
1 parent 5bddd85 commit 5bf34dc

File tree

2 files changed

+51
-39
lines changed

2 files changed

+51
-39
lines changed

‎cmd/wush/serve.go

Lines changed: 24 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -11,8 +11,8 @@ import (
1111
"os"
1212
"strings"
1313
"sync"
14-
"time"
1514

15+
"github.com/mattn/go-isatty"
1616
"github.com/prometheus/client_golang/prometheus"
1717
"github.com/schollz/progressbar/v3"
1818
"github.com/spf13/afero"
@@ -51,11 +51,14 @@ func serveCmd() *serpent.Command {
5151
logSink = inv.Stderr
5252
}
5353
logger := slog.New(slog.NewTextHandler(logSink, nil))
54+
hlog := func(format string, args ...any) {
55+
fmt.Fprintf(inv.Stderr, format+"\n", args...)
56+
}
5457
dm, err := tsserver.DERPMapTailscale(ctx)
5558
if err != nil {
5659
return err
5760
}
58-
r := overlay.NewReceiveOverlay(logger, dm)
61+
r := overlay.NewReceiveOverlay(logger, hlog, dm)
5962

6063
switch overlayType {
6164
case "derp":
@@ -76,9 +79,15 @@ func serveCmd() *serpent.Command {
7679
return fmt.Errorf("unknown overlay type: %s", overlayType)
7780
}
7881

79-
fmt.Println("Your auth key is:")
80-
fmt.Println("\t>", cliui.Code(r.ClientAuth().AuthKey()))
81-
fmt.Println("Use this key to authenticate other", cliui.Code("wush"), "commands to this instance.")
82+
// Ensure we always print the auth key on stdout
83+
if isatty.IsTerminal(os.Stdout.Fd()) {
84+
hlog("Your auth key is:")
85+
fmt.Println("\t>", cliui.Code(r.ClientAuth().AuthKey()))
86+
hlog("Use this key to authenticate other " + cliui.Code("wush") + " commands to this instance.")
87+
} else {
88+
fmt.Println(cliui.Code(r.ClientAuth().AuthKey()))
89+
hlog("The auth key has been printed to stdout")
90+
}
8291

8392
s, err := tsserver.NewServer(ctx, logger, r)
8493
if err != nil {
@@ -95,7 +104,7 @@ func serveCmd() *serpent.Command {
95104
ts.Up(ctx)
96105
fs := afero.NewOsFs()
97106

98-
fmt.Println(cliui.Timestamp(time.Now()), "WireGuard is ready")
107+
hlog("WireGuard is ready")
99108

100109
closers := []io.Closer{}
101110

@@ -117,15 +126,16 @@ func serveCmd() *serpent.Command {
117126
}
118127
closers = append(closers, sshListener)
119128

120-
fmt.Println(cliui.Timestamp(time.Now()), "SSH server "+pretty.Sprint(cliui.DefaultStyles.Enabled, "enabled"))
129+
// TODO: replace these logs with all of the options in the beginning.
130+
hlog("SSH server " + pretty.Sprint(cliui.DefaultStyles.Enabled, "enabled"))
121131
go func() {
122132
err := sshSrv.Serve(sshListener)
123133
if err != nil {
124-
fmt.Println(cliui.Timestamp(time.Now()), "SSH server exited: "+err.Error())
134+
hlog("SSH server exited: " + err.Error())
125135
}
126136
}()
127137
} else {
128-
fmt.Println(cliui.Timestamp(time.Now()), "SSH server "+pretty.Sprint(cliui.DefaultStyles.Disabled, "disabled"))
138+
hlog("SSH server " + pretty.Sprint(cliui.DefaultStyles.Disabled, "disabled"))
129139
}
130140

131141
if xslices.Contains(enabled, "cp") && !xslices.Contains(disabled, "cp") {
@@ -135,23 +145,23 @@ func serveCmd() *serpent.Command {
135145
}
136146
closers = append([]io.Closer{cpListener}, closers...)
137147

138-
fmt.Println(cliui.Timestamp(time.Now()), "File transfer server "+pretty.Sprint(cliui.DefaultStyles.Enabled, "enabled"))
148+
hlog("File transfer server " + pretty.Sprint(cliui.DefaultStyles.Enabled, "enabled"))
139149
go func() {
140150
err := http.Serve(cpListener, http.HandlerFunc(cpHandler))
141151
if err != nil {
142-
fmt.Println(cliui.Timestamp(time.Now()), "File transfer server exited: "+err.Error())
152+
hlog("File transfer server exited: " + err.Error())
143153
}
144154
}()
145155
} else {
146-
fmt.Println(cliui.Timestamp(time.Now()), "File transfer server "+pretty.Sprint(cliui.DefaultStyles.Disabled, "disabled"))
156+
hlog("File transfer server " + pretty.Sprint(cliui.DefaultStyles.Disabled, "disabled"))
147157
}
148158

149159
if xslices.Contains(enabled, "port-forward") && !xslices.Contains(disabled, "port-forward") {
150160
ts.RegisterFallbackTCPHandler(func(src, dst netip.AddrPort) (handler func(net.Conn), intercept bool) {
151161
return func(src net.Conn) {
152162
dst, err := net.Dial("tcp", fmt.Sprintf("127.0.0.1:%d", dst.Port()))
153163
if err != nil {
154-
fmt.Println("failed to dial forwarded connection:", err.Error())
164+
hlog(pretty.Sprint(cliui.DefaultStyles.Warn, "Failed to dial forwarded connection:", err.Error()))
155165
src.Close()
156166
return
157167
}
@@ -160,7 +170,7 @@ func serveCmd() *serpent.Command {
160170
}, true
161171
})
162172
} else {
163-
fmt.Println(cliui.Timestamp(time.Now()), "Port-forward server "+pretty.Sprint(cliui.DefaultStyles.Disabled, "disabled"))
173+
hlog("Port-forward server " + pretty.Sprint(cliui.DefaultStyles.Disabled, "disabled"))
164174
}
165175

166176
ctx, ctxCancel := inv.SignalNotifyContext(ctx, os.Interrupt)

‎overlay/receive.go

Lines changed: 27 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -23,23 +23,28 @@ import (
2323
"tailscale.com/tailcfg"
2424
"tailscale.com/types/key"
2525

26+
"github.com/coder/pretty"
2627
"github.com/coder/wush/cliui"
2728
)
2829

29-
func NewReceiveOverlay(logger *slog.Logger, dm *tailcfg.DERPMap) *Receive {
30+
type Logf func(format string, args ...any)
31+
32+
func NewReceiveOverlay(logger *slog.Logger, hlog Logf, dm *tailcfg.DERPMap) *Receive {
3033
return &Receive{
31-
Logger: logger,
32-
DerpMap: dm,
33-
SelfPriv: key.NewNode(),
34-
PeerPriv: key.NewNode(),
35-
in: make(chan *tailcfg.Node, 8),
36-
out: make(chan *tailcfg.Node, 8),
34+
Logger: logger,
35+
HumanLogf: hlog,
36+
DerpMap: dm,
37+
SelfPriv: key.NewNode(),
38+
PeerPriv: key.NewNode(),
39+
in: make(chan *tailcfg.Node, 8),
40+
out: make(chan *tailcfg.Node, 8),
3741
}
3842
}
3943

4044
type Receive struct {
41-
Logger *slog.Logger
42-
DerpMap *tailcfg.DERPMap
45+
Logger *slog.Logger
46+
HumanLogf Logf
47+
DerpMap *tailcfg.DERPMap
4348
// SelfPriv is the private key that peers will encrypt overlay messages to.
4449
// The public key of this is sent in the auth key.
4550
SelfPriv key.NodePrivate
@@ -83,10 +88,10 @@ func (r *Receive) PickDERPHome(ctx context.Context) error {
8388
}
8489

8590
if report.PreferredDERP == 0 {
86-
fmt.Println("Failed to determine overlay DERP region, defaulting to", cliui.Code("NYC"), ".")
91+
r.HumanLogf("Failed to determine overlay DERP region, defaulting to %s.", cliui.Code("NYC"))
8792
r.derpRegionID = 1
8893
} else {
89-
fmt.Println("Picked DERP region", cliui.Code(r.DerpMap.Regions[report.PreferredDERP].RegionName), "as overlay home")
94+
r.HumanLogf("Picked DERP region %s as overlay home", cliui.Code(r.DerpMap.Regions[report.PreferredDERP].RegionName))
9095
r.derpRegionID = uint16(report.PreferredDERP)
9196
}
9297

@@ -139,7 +144,7 @@ func (r *Receive) ListenOverlaySTUN(ctx context.Context) (<-chan struct{}, error
139144
case <-restun.C:
140145
_, err = conn.WriteToUDP(m.Raw, srvAddr)
141146
if err != nil {
142-
fmt.Println(cliui.Timestamp(time.Now()), "Failed to write STUN request on overlay:", err)
147+
r.HumanLogf("%s Failed to write STUN request on overlay: %s", cliui.Timestamp(time.Now()), err)
143148
}
144149
restun.Reset(30 * time.Second)
145150
}
@@ -169,7 +174,7 @@ func (r *Receive) ListenOverlaySTUN(ctx context.Context) (<-chan struct{}, error
169174
peers.Range(func(_ key.NodePublic, addr netip.AddrPort) bool {
170175
_, err := conn.WriteToUDPAddrPort(sealed, addr)
171176
if err != nil {
172-
fmt.Println("send response over udp:", err)
177+
r.HumanLogf("%s Failed to send updated node over udp: %s", cliui.Timestamp(time.Now()), err)
173178
return false
174179
}
175180
return true
@@ -216,14 +221,11 @@ func (r *Receive) ListenOverlaySTUN(ctx context.Context) (<-chan struct{}, error
216221

217222
// our first STUN response
218223
if !r.stunIP.IsValid() {
219-
fmt.Println(cliui.Timestamp(time.Now()), "STUN address is", cliui.Code(stunAddrPort.String()))
224+
r.HumanLogf("STUN address is %s", cliui.Code(stunAddrPort.String()))
220225
}
221226

222227
if r.stunIP.IsValid() && r.stunIP.Compare(stunAddrPort) != 0 {
223-
r.Logger.Warn("STUN address changed, this may cause issues",
224-
"old_ip", r.stunIP.String(),
225-
"new_ip", stunAddrPort.String(),
226-
)
228+
r.HumanLogf(pretty.Sprintf(cliui.DefaultStyles.Warn, "STUN address changed, this may cause issues; %s->%s", r.stunIP.String(), stunAddrPort.String()))
227229
}
228230
r.stunIP = stunAddrPort
229231
closeIPChanOnce.Do(func() {
@@ -234,7 +236,7 @@ func (r *Receive) ListenOverlaySTUN(ctx context.Context) (<-chan struct{}, error
234236

235237
res, key, err := r.handleNextMessage(buf, "STUN")
236238
if err != nil {
237-
fmt.Println(cliui.Timestamp(time.Now()), "Failed to handle overlay message:", err.Error())
239+
r.HumanLogf("Failed to handle overlay message: %s", err.Error())
238240
continue
239241
}
240242

@@ -243,7 +245,7 @@ func (r *Receive) ListenOverlaySTUN(ctx context.Context) (<-chan struct{}, error
243245
if res != nil {
244246
_, err = conn.WriteToUDPAddrPort(res, addr)
245247
if err != nil {
246-
fmt.Println(cliui.Timestamp(time.Now()), "Failed to send overlay response over STUN:", err.Error())
248+
r.HumanLogf("Failed to send overlay response over STUN: %s", err.Error())
247249
return
248250
}
249251
}
@@ -285,7 +287,7 @@ func (r *Receive) ListenOverlayDERP(ctx context.Context) error {
285287
peers.Range(func(_, derpKey key.NodePublic) bool {
286288
err = c.Send(derpKey, sealed)
287289
if err != nil {
288-
fmt.Println("send response over derp:", err)
290+
r.HumanLogf("Send updated node over DERP: %s", err)
289291
return false
290292
}
291293
return true
@@ -304,7 +306,7 @@ func (r *Receive) ListenOverlayDERP(ctx context.Context) error {
304306
case derp.ReceivedPacket:
305307
res, key, err := r.handleNextMessage(msg.Data, "DERP")
306308
if err != nil {
307-
fmt.Println(cliui.Timestamp(time.Now()), "Failed to handle overlay message:", err.Error())
309+
r.HumanLogf("Failed to handle overlay message: %s", err.Error())
308310
continue
309311
}
310312

@@ -313,7 +315,7 @@ func (r *Receive) ListenOverlayDERP(ctx context.Context) error {
313315
if res != nil {
314316
err = c.Send(msg.Source, res)
315317
if err != nil {
316-
fmt.Println(cliui.Timestamp(time.Now()), "Failed to send overlay response over derp:", err.Error())
318+
r.HumanLogf("Failed to send overlay response over derp: %s", err.Error())
317319
return err
318320
}
319321
}
@@ -350,9 +352,9 @@ func (r *Receive) handleNextMessage(msg []byte, system string) (resRaw []byte, n
350352
if h := ovMsg.HostInfo.Hostname; h != "" {
351353
hostname = h
352354
}
353-
fmt.Println(cliui.Timestamp(time.Now()), "Received connection request over", system, "from", cliui.Keyword(fmt.Sprintf("%s@%s", username, hostname)))
355+
r.HumanLogf("%s Received connection request over %s from %s", cliui.Timestamp(time.Now()), system, cliui.Keyword(fmt.Sprintf("%s@%s", username, hostname)))
354356
case messageTypeNodeUpdate:
355-
fmt.Println(cliui.Timestamp(time.Now()), "Received updated node from", cliui.Code(ovMsg.Node.Key.String()))
357+
r.HumanLogf("%s Received updated node from %s", cliui.Timestamp(time.Now()), cliui.Code(ovMsg.Node.Key.String()))
356358
r.in <- &ovMsg.Node
357359
res.Typ = messageTypeNodeUpdate
358360
if lastNode := r.lastNode.Load(); lastNode != nil {

0 commit comments

Comments
 (0)