968 lines
30 KiB
Go
968 lines
30 KiB
Go
// Copyright (c) Tailscale Inc & AUTHORS
|
|
// SPDX-License-Identifier: BSD-3-Clause
|
|
|
|
// Package logtail sends logs to log.tailscale.io.
|
|
package logtail
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"crypto/rand"
|
|
"encoding/binary"
|
|
"fmt"
|
|
"io"
|
|
"log"
|
|
mrand "math/rand"
|
|
"net/http"
|
|
"net/netip"
|
|
"os"
|
|
"regexp"
|
|
"runtime"
|
|
"slices"
|
|
"strconv"
|
|
"sync"
|
|
"sync/atomic"
|
|
"time"
|
|
|
|
"github.com/go-json-experiment/json/jsontext"
|
|
"tailscale.com/envknob"
|
|
"tailscale.com/net/netmon"
|
|
"tailscale.com/net/sockstats"
|
|
"tailscale.com/net/tsaddr"
|
|
"tailscale.com/tstime"
|
|
tslogger "tailscale.com/types/logger"
|
|
"tailscale.com/types/logid"
|
|
"tailscale.com/util/set"
|
|
"tailscale.com/util/truncate"
|
|
"tailscale.com/util/zstdframe"
|
|
)
|
|
|
|
// maxSize is the maximum size that a single log entry can be.
|
|
// It is also the maximum body size that may be uploaded at a time.
|
|
const maxSize = 256 << 10
|
|
|
|
// maxTextSize is the maximum size for a text log message.
|
|
// Note that JSON log messages can be as large as maxSize.
|
|
const maxTextSize = 16 << 10
|
|
|
|
// lowMemRatio reduces maxSize and maxTextSize by this ratio in lowMem mode.
|
|
const lowMemRatio = 4
|
|
|
|
// bufferSize is the typical buffer size to retain.
|
|
// It is large enough to handle most log messages,
|
|
// but not too large to be a notable waste of memory if retained forever.
|
|
const bufferSize = 4 << 10
|
|
|
|
// DefaultHost is the default host name to upload logs to when
|
|
// Config.BaseURL isn't provided.
|
|
const DefaultHost = "log.tailscale.io"
|
|
|
|
const defaultFlushDelay = 2 * time.Second
|
|
|
|
const (
|
|
// CollectionNode is the name of a logtail Config.Collection
|
|
// for tailscaled (or equivalent: IPNExtension, Android app).
|
|
CollectionNode = "tailnode.log.tailscale.io"
|
|
)
|
|
|
|
type Config struct {
|
|
Collection string // collection name, a domain name
|
|
PrivateID logid.PrivateID // private ID for the primary log stream
|
|
CopyPrivateID logid.PrivateID // private ID for a log stream that is a superset of this log stream
|
|
BaseURL string // if empty defaults to "https://log.tailscale.io"
|
|
HTTPC *http.Client // if empty defaults to http.DefaultClient
|
|
SkipClientTime bool // if true, client_time is not written to logs
|
|
LowMemory bool // if true, logtail minimizes memory use
|
|
Clock tstime.Clock // if set, Clock.Now substitutes uses of time.Now
|
|
Stderr io.Writer // if set, logs are sent here instead of os.Stderr
|
|
StderrLevel int // max verbosity level to write to stderr; 0 means the non-verbose messages only
|
|
Buffer Buffer // temp storage, if nil a MemoryBuffer
|
|
CompressLogs bool // whether to compress the log uploads
|
|
|
|
// MetricsDelta, if non-nil, is a func that returns an encoding
|
|
// delta in clientmetrics to upload alongside existing logs.
|
|
// It can return either an empty string (for nothing) or a string
|
|
// that's safe to embed in a JSON string literal without further escaping.
|
|
MetricsDelta func() string
|
|
|
|
// FlushDelayFn, if non-nil is a func that returns how long to wait to
|
|
// accumulate logs before uploading them. 0 or negative means to upload
|
|
// immediately.
|
|
//
|
|
// If nil, a default value is used. (currently 2 seconds)
|
|
FlushDelayFn func() time.Duration
|
|
|
|
// IncludeProcID, if true, results in an ephemeral process identifier being
|
|
// included in logs. The ID is random and not guaranteed to be globally
|
|
// unique, but it can be used to distinguish between different instances
|
|
// running with same PrivateID.
|
|
IncludeProcID bool
|
|
|
|
// IncludeProcSequence, if true, results in an ephemeral sequence number
|
|
// being included in the logs. The sequence number is incremented for each
|
|
// log message sent, but is not persisted across process restarts.
|
|
IncludeProcSequence bool
|
|
}
|
|
|
|
func NewLogger(cfg Config, logf tslogger.Logf) *Logger {
|
|
if cfg.BaseURL == "" {
|
|
cfg.BaseURL = "https://" + DefaultHost
|
|
}
|
|
if cfg.HTTPC == nil {
|
|
cfg.HTTPC = http.DefaultClient
|
|
}
|
|
if cfg.Clock == nil {
|
|
cfg.Clock = tstime.StdClock{}
|
|
}
|
|
if cfg.Stderr == nil {
|
|
cfg.Stderr = os.Stderr
|
|
}
|
|
if cfg.Buffer == nil {
|
|
pendingSize := 256
|
|
if cfg.LowMemory {
|
|
pendingSize = 64
|
|
}
|
|
cfg.Buffer = NewMemoryBuffer(pendingSize)
|
|
}
|
|
var procID uint32
|
|
if cfg.IncludeProcID {
|
|
keyBytes := make([]byte, 4)
|
|
rand.Read(keyBytes)
|
|
procID = binary.LittleEndian.Uint32(keyBytes)
|
|
if procID == 0 {
|
|
// 0 is the empty/off value, assign a different (non-zero) value to
|
|
// make sure we still include an ID (actual value does not matter).
|
|
procID = 7
|
|
}
|
|
}
|
|
if s := envknob.String("TS_DEBUG_LOGTAIL_FLUSHDELAY"); s != "" {
|
|
if delay, err := time.ParseDuration(s); err == nil {
|
|
cfg.FlushDelayFn = func() time.Duration { return delay }
|
|
} else {
|
|
log.Fatalf("invalid TS_DEBUG_LOGTAIL_FLUSHDELAY: %v", err)
|
|
}
|
|
} else if cfg.FlushDelayFn == nil && envknob.Bool("IN_TS_TEST") {
|
|
cfg.FlushDelayFn = func() time.Duration { return 0 }
|
|
}
|
|
|
|
var urlSuffix string
|
|
if !cfg.CopyPrivateID.IsZero() {
|
|
urlSuffix = "?copyId=" + cfg.CopyPrivateID.String()
|
|
}
|
|
l := &Logger{
|
|
privateID: cfg.PrivateID,
|
|
stderr: cfg.Stderr,
|
|
stderrLevel: int64(cfg.StderrLevel),
|
|
httpc: cfg.HTTPC,
|
|
url: cfg.BaseURL + "/c/" + cfg.Collection + "/" + cfg.PrivateID.String() + urlSuffix,
|
|
lowMem: cfg.LowMemory,
|
|
buffer: cfg.Buffer,
|
|
skipClientTime: cfg.SkipClientTime,
|
|
drainWake: make(chan struct{}, 1),
|
|
sentinel: make(chan int32, 16),
|
|
flushDelayFn: cfg.FlushDelayFn,
|
|
clock: cfg.Clock,
|
|
metricsDelta: cfg.MetricsDelta,
|
|
|
|
procID: procID,
|
|
includeProcSequence: cfg.IncludeProcSequence,
|
|
|
|
shutdownStart: make(chan struct{}),
|
|
shutdownDone: make(chan struct{}),
|
|
}
|
|
l.SetSockstatsLabel(sockstats.LabelLogtailLogger)
|
|
l.compressLogs = cfg.CompressLogs
|
|
|
|
ctx, cancel := context.WithCancel(context.Background())
|
|
l.uploadCancel = cancel
|
|
|
|
go l.uploading(ctx)
|
|
l.Write([]byte("logtail started"))
|
|
return l
|
|
}
|
|
|
|
// Logger writes logs, splitting them as configured between local
|
|
// logging facilities and uploading to a log server.
|
|
type Logger struct {
|
|
stderr io.Writer
|
|
stderrLevel int64 // accessed atomically
|
|
httpc *http.Client
|
|
url string
|
|
lowMem bool
|
|
skipClientTime bool
|
|
netMonitor *netmon.Monitor
|
|
buffer Buffer
|
|
drainWake chan struct{} // signal to speed up drain
|
|
drainBuf []byte // owned by drainPending for reuse
|
|
flushDelayFn func() time.Duration // negative or zero return value to upload aggressively, or >0 to batch at this delay
|
|
flushPending atomic.Bool
|
|
sentinel chan int32
|
|
clock tstime.Clock
|
|
compressLogs bool
|
|
uploadCancel func()
|
|
explainedRaw bool
|
|
metricsDelta func() string // or nil
|
|
privateID logid.PrivateID
|
|
httpDoCalls atomic.Int32
|
|
sockstatsLabel atomicSocktatsLabel
|
|
|
|
procID uint32
|
|
includeProcSequence bool
|
|
|
|
writeLock sync.Mutex // guards procSequence, flushTimer, buffer.Write calls
|
|
procSequence uint64
|
|
flushTimer tstime.TimerController // used when flushDelay is >0
|
|
writeBuf [bufferSize]byte // owned by Write for reuse
|
|
jsonDec jsontext.Decoder // owned by appendTextOrJSONLocked for reuse
|
|
|
|
shutdownStartMu sync.Mutex // guards the closing of shutdownStart
|
|
shutdownStart chan struct{} // closed when shutdown begins
|
|
shutdownDone chan struct{} // closed when shutdown complete
|
|
}
|
|
|
|
type atomicSocktatsLabel struct{ p atomic.Uint32 }
|
|
|
|
func (p *atomicSocktatsLabel) Load() sockstats.Label { return sockstats.Label(p.p.Load()) }
|
|
func (p *atomicSocktatsLabel) Store(label sockstats.Label) { p.p.Store(uint32(label)) }
|
|
|
|
// SetVerbosityLevel controls the verbosity level that should be
|
|
// written to stderr. 0 is the default (not verbose). Levels 1 or higher
|
|
// are increasingly verbose.
|
|
func (l *Logger) SetVerbosityLevel(level int) {
|
|
atomic.StoreInt64(&l.stderrLevel, int64(level))
|
|
}
|
|
|
|
// SetNetMon sets the network monitor.
|
|
//
|
|
// It should not be changed concurrently with log writes and should
|
|
// only be set once.
|
|
func (l *Logger) SetNetMon(lm *netmon.Monitor) {
|
|
l.netMonitor = lm
|
|
}
|
|
|
|
// SetSockstatsLabel sets the label used in sockstat logs to identify network traffic from this logger.
|
|
func (l *Logger) SetSockstatsLabel(label sockstats.Label) {
|
|
l.sockstatsLabel.Store(label)
|
|
}
|
|
|
|
// PrivateID returns the logger's private log ID.
|
|
//
|
|
// It exists for internal use only.
|
|
func (l *Logger) PrivateID() logid.PrivateID { return l.privateID }
|
|
|
|
// Shutdown gracefully shuts down the logger while completing any
|
|
// remaining uploads.
|
|
//
|
|
// It will block, continuing to try and upload unless the passed
|
|
// context object interrupts it by being done.
|
|
// If the shutdown is interrupted, an error is returned.
|
|
func (l *Logger) Shutdown(ctx context.Context) error {
|
|
done := make(chan struct{})
|
|
go func() {
|
|
select {
|
|
case <-ctx.Done():
|
|
l.uploadCancel()
|
|
<-l.shutdownDone
|
|
case <-l.shutdownDone:
|
|
}
|
|
close(done)
|
|
}()
|
|
|
|
l.shutdownStartMu.Lock()
|
|
select {
|
|
case <-l.shutdownStart:
|
|
l.shutdownStartMu.Unlock()
|
|
return nil
|
|
default:
|
|
}
|
|
close(l.shutdownStart)
|
|
l.shutdownStartMu.Unlock()
|
|
|
|
io.WriteString(l, "logger closing down\n")
|
|
<-done
|
|
|
|
return nil
|
|
}
|
|
|
|
// Close shuts down this logger object, the background log uploader
|
|
// process, and any associated goroutines.
|
|
//
|
|
// Deprecated: use Shutdown
|
|
func (l *Logger) Close() {
|
|
l.Shutdown(context.Background())
|
|
}
|
|
|
|
// drainBlock is called by drainPending when there are no logs to drain.
|
|
//
|
|
// In typical operation, every call to the Write method unblocks and triggers a
|
|
// buffer.TryReadline, so logs are written with very low latency.
|
|
//
|
|
// If the caller specified FlushInterface, drainWake is only sent to
|
|
// periodically.
|
|
func (l *Logger) drainBlock() (shuttingDown bool) {
|
|
select {
|
|
case <-l.shutdownStart:
|
|
return true
|
|
case <-l.drainWake:
|
|
}
|
|
return false
|
|
}
|
|
|
|
// drainPending drains and encodes a batch of logs from the buffer for upload.
|
|
// If no logs are available, drainPending blocks until logs are available.
|
|
// The returned buffer is only valid until the next call to drainPending.
|
|
func (l *Logger) drainPending() (b []byte) {
|
|
b = l.drainBuf[:0]
|
|
b = append(b, '[')
|
|
defer func() {
|
|
b = bytes.TrimRight(b, ",")
|
|
b = append(b, ']')
|
|
l.drainBuf = b
|
|
if len(b) <= len("[]") {
|
|
b = nil
|
|
}
|
|
}()
|
|
|
|
maxLen := maxSize
|
|
if l.lowMem {
|
|
// When operating in a low memory environment, it is better to upload
|
|
// in multiple operations than it is to allocate a large body and OOM.
|
|
// Even if maxLen is less than maxSize, we can still upload an entry
|
|
// that is up to maxSize if we happen to encounter one.
|
|
maxLen /= lowMemRatio
|
|
}
|
|
for len(b) < maxLen {
|
|
line, err := l.buffer.TryReadLine()
|
|
switch {
|
|
case err == io.EOF:
|
|
return b
|
|
case err != nil:
|
|
b = append(b, '{')
|
|
b = l.appendMetadata(b, false, true, 0, 0, "reading ringbuffer: "+err.Error(), nil, 0)
|
|
b = bytes.TrimRight(b, ",")
|
|
b = append(b, '}')
|
|
return b
|
|
case line == nil:
|
|
// If we read at least some log entries, return immediately.
|
|
if len(b) > len("[") {
|
|
return b
|
|
}
|
|
|
|
// We're about to block. If we're holding on to too much memory
|
|
// in our buffer from a previous large write, let it go.
|
|
if cap(b) > bufferSize {
|
|
b = bytes.Clone(b)
|
|
l.drainBuf = b
|
|
}
|
|
|
|
if shuttingDown := l.drainBlock(); shuttingDown {
|
|
return b
|
|
}
|
|
continue
|
|
}
|
|
|
|
switch {
|
|
case len(line) == 0:
|
|
continue
|
|
case line[0] == '{' && jsontext.Value(line).IsValid():
|
|
// This is already a valid JSON object, so just append it.
|
|
// This may exceed maxLen, but should be no larger than maxSize
|
|
// so long as logic writing into the buffer enforces the limit.
|
|
b = append(b, line...)
|
|
default:
|
|
// This is probably a log added to stderr by filch
|
|
// outside of the logtail logger. Encode it.
|
|
if !l.explainedRaw {
|
|
fmt.Fprintf(l.stderr, "RAW-STDERR: ***\n")
|
|
fmt.Fprintf(l.stderr, "RAW-STDERR: *** Lines prefixed with RAW-STDERR below bypassed logtail and probably come from a previous run of the program\n")
|
|
fmt.Fprintf(l.stderr, "RAW-STDERR: ***\n")
|
|
fmt.Fprintf(l.stderr, "RAW-STDERR:\n")
|
|
l.explainedRaw = true
|
|
}
|
|
fmt.Fprintf(l.stderr, "RAW-STDERR: %s", b)
|
|
// Do not add a client time, as it could be really old.
|
|
// Do not include instance key or ID either,
|
|
// since this came from a different instance.
|
|
b = l.appendText(b, line, true, 0, 0, 0)
|
|
}
|
|
b = append(b, ',')
|
|
}
|
|
return b
|
|
}
|
|
|
|
// This is the goroutine that repeatedly uploads logs in the background.
|
|
func (l *Logger) uploading(ctx context.Context) {
|
|
defer close(l.shutdownDone)
|
|
|
|
for {
|
|
body := l.drainPending()
|
|
origlen := -1 // sentinel value: uncompressed
|
|
// Don't attempt to compress tiny bodies; not worth the CPU cycles.
|
|
if l.compressLogs && len(body) > 256 {
|
|
zbody := zstdframe.AppendEncode(nil, body,
|
|
zstdframe.FastestCompression, zstdframe.LowMemory(true))
|
|
|
|
// Only send it compressed if the bandwidth savings are sufficient.
|
|
// Just the extra headers associated with enabling compression
|
|
// are 50 bytes by themselves.
|
|
if len(body)-len(zbody) > 64 {
|
|
origlen = len(body)
|
|
body = zbody
|
|
}
|
|
}
|
|
|
|
var lastError string
|
|
var numFailures int
|
|
var firstFailure time.Time
|
|
for len(body) > 0 && ctx.Err() == nil {
|
|
retryAfter, err := l.upload(ctx, body, origlen)
|
|
if err != nil {
|
|
numFailures++
|
|
firstFailure = l.clock.Now()
|
|
|
|
if !l.internetUp() {
|
|
fmt.Fprintf(l.stderr, "logtail: internet down; waiting\n")
|
|
l.awaitInternetUp(ctx)
|
|
continue
|
|
}
|
|
|
|
// Only print the same message once.
|
|
if currError := err.Error(); lastError != currError {
|
|
fmt.Fprintf(l.stderr, "logtail: upload: %v\n", err)
|
|
lastError = currError
|
|
}
|
|
|
|
// Sleep for the specified retryAfter period,
|
|
// otherwise default to some random value.
|
|
if retryAfter <= 0 {
|
|
retryAfter = time.Duration(30+mrand.Intn(30)) * time.Second
|
|
}
|
|
tstime.Sleep(ctx, retryAfter)
|
|
} else {
|
|
// Only print a success message after recovery.
|
|
if numFailures > 0 {
|
|
fmt.Fprintf(l.stderr, "logtail: upload succeeded after %d failures and %s\n", numFailures, l.clock.Since(firstFailure).Round(time.Second))
|
|
}
|
|
break
|
|
}
|
|
}
|
|
|
|
select {
|
|
case <-l.shutdownStart:
|
|
return
|
|
default:
|
|
}
|
|
}
|
|
}
|
|
|
|
func (l *Logger) internetUp() bool {
|
|
if l.netMonitor == nil {
|
|
// No way to tell, so assume it is.
|
|
return true
|
|
}
|
|
return l.netMonitor.InterfaceState().AnyInterfaceUp()
|
|
}
|
|
|
|
func (l *Logger) awaitInternetUp(ctx context.Context) {
|
|
upc := make(chan bool, 1)
|
|
defer l.netMonitor.RegisterChangeCallback(func(delta *netmon.ChangeDelta) {
|
|
if delta.New.AnyInterfaceUp() {
|
|
select {
|
|
case upc <- true:
|
|
default:
|
|
}
|
|
}
|
|
})()
|
|
if l.internetUp() {
|
|
return
|
|
}
|
|
select {
|
|
case <-upc:
|
|
fmt.Fprintf(l.stderr, "logtail: internet back up\n")
|
|
case <-ctx.Done():
|
|
}
|
|
}
|
|
|
|
// upload uploads body to the log server.
|
|
// origlen indicates the pre-compression body length.
|
|
// origlen of -1 indicates that the body is not compressed.
|
|
func (l *Logger) upload(ctx context.Context, body []byte, origlen int) (retryAfter time.Duration, err error) {
|
|
const maxUploadTime = 45 * time.Second
|
|
ctx = sockstats.WithSockStats(ctx, l.sockstatsLabel.Load(), l.Logf)
|
|
ctx, cancel := context.WithTimeout(ctx, maxUploadTime)
|
|
defer cancel()
|
|
|
|
req, err := http.NewRequestWithContext(ctx, "POST", l.url, bytes.NewReader(body))
|
|
if err != nil {
|
|
// I know of no conditions under which this could fail.
|
|
// Report it very loudly.
|
|
// TODO record logs to disk
|
|
panic("logtail: cannot build http request: " + err.Error())
|
|
}
|
|
if origlen != -1 {
|
|
req.Header.Add("Content-Encoding", "zstd")
|
|
req.Header.Add("Orig-Content-Length", strconv.Itoa(origlen))
|
|
}
|
|
if runtime.GOOS == "js" {
|
|
// We once advertised we'd accept optional client certs (for internal use)
|
|
// on log.tailscale.io but then Tailscale SSH js/wasm clients prompted
|
|
// users (on some browsers?) to pick a client cert. We'll fix the server's
|
|
// TLS ServerHello, but we can also fix it client side for good measure.
|
|
//
|
|
// Corp details: https://github.com/tailscale/corp/issues/18177#issuecomment-2026598715
|
|
// and https://github.com/tailscale/corp/pull/18775#issuecomment-2027505036
|
|
//
|
|
// See https://github.com/golang/go/wiki/WebAssembly#configuring-fetch-options-while-using-nethttp
|
|
// and https://developer.mozilla.org/en-US/docs/Web/API/fetch#credentials
|
|
req.Header.Set("js.fetch:credentials", "omit")
|
|
}
|
|
req.Header["User-Agent"] = nil // not worth writing one; save some bytes
|
|
|
|
compressedNote := "not-compressed"
|
|
if origlen != -1 {
|
|
compressedNote = "compressed"
|
|
}
|
|
|
|
l.httpDoCalls.Add(1)
|
|
resp, err := l.httpc.Do(req)
|
|
if err != nil {
|
|
return 0, fmt.Errorf("log upload of %d bytes %s failed: %v", len(body), compressedNote, err)
|
|
}
|
|
defer resp.Body.Close()
|
|
|
|
if resp.StatusCode != http.StatusOK {
|
|
n, _ := strconv.Atoi(resp.Header.Get("Retry-After"))
|
|
b, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<10))
|
|
return time.Duration(n) * time.Second, fmt.Errorf("log upload of %d bytes %s failed %d: %s", len(body), compressedNote, resp.StatusCode, bytes.TrimSpace(b))
|
|
}
|
|
return 0, nil
|
|
}
|
|
|
|
// Flush uploads all logs to the server. It blocks until complete or there is an
|
|
// unrecoverable error.
|
|
//
|
|
// TODO(bradfitz): this apparently just returns nil, as of tailscale/corp@9c2ec35.
|
|
// Finish cleaning this up.
|
|
func (l *Logger) Flush() error {
|
|
return nil
|
|
}
|
|
|
|
// StartFlush starts a log upload, if anything is pending.
|
|
//
|
|
// If l is nil, StartFlush is a no-op.
|
|
func (l *Logger) StartFlush() {
|
|
if l != nil {
|
|
l.tryDrainWake()
|
|
}
|
|
}
|
|
|
|
// logtailDisabled is whether logtail uploads to logcatcher are disabled.
|
|
var logtailDisabled atomic.Bool
|
|
|
|
// Disable disables logtail uploads for the lifetime of the process.
|
|
func Disable() {
|
|
logtailDisabled.Store(true)
|
|
}
|
|
|
|
var debugWakesAndUploads = envknob.RegisterBool("TS_DEBUG_LOGTAIL_WAKES")
|
|
|
|
// tryDrainWake tries to send to lg.drainWake, to cause an uploading wakeup.
|
|
// It does not block.
|
|
func (l *Logger) tryDrainWake() {
|
|
l.flushPending.Store(false)
|
|
if debugWakesAndUploads() {
|
|
// Using println instead of log.Printf here to avoid recursing back into
|
|
// ourselves.
|
|
println("logtail: try drain wake, numHTTP:", l.httpDoCalls.Load())
|
|
}
|
|
select {
|
|
case l.drainWake <- struct{}{}:
|
|
default:
|
|
}
|
|
}
|
|
|
|
func (l *Logger) sendLocked(jsonBlob []byte) (int, error) {
|
|
tapSend(jsonBlob)
|
|
if logtailDisabled.Load() {
|
|
return len(jsonBlob), nil
|
|
}
|
|
|
|
n, err := l.buffer.Write(jsonBlob)
|
|
|
|
flushDelay := defaultFlushDelay
|
|
if l.flushDelayFn != nil {
|
|
flushDelay = l.flushDelayFn()
|
|
}
|
|
if flushDelay > 0 {
|
|
if l.flushPending.CompareAndSwap(false, true) {
|
|
if l.flushTimer == nil {
|
|
l.flushTimer = l.clock.AfterFunc(flushDelay, l.tryDrainWake)
|
|
} else {
|
|
l.flushTimer.Reset(flushDelay)
|
|
}
|
|
}
|
|
} else {
|
|
l.tryDrainWake()
|
|
}
|
|
return n, err
|
|
}
|
|
|
|
// appendMetadata appends optional "logtail", "metrics", and "v" JSON members.
|
|
// This assumes dst is already within a JSON object.
|
|
// Each member is comma-terminated.
|
|
func (l *Logger) appendMetadata(dst []byte, skipClientTime, skipMetrics bool, procID uint32, procSequence uint64, errDetail string, errData jsontext.Value, level int) []byte {
|
|
// Append optional logtail metadata.
|
|
if !skipClientTime || procID != 0 || procSequence != 0 || errDetail != "" || errData != nil {
|
|
dst = append(dst, `"logtail":{`...)
|
|
if !skipClientTime {
|
|
dst = append(dst, `"client_time":"`...)
|
|
dst = l.clock.Now().UTC().AppendFormat(dst, time.RFC3339Nano)
|
|
dst = append(dst, '"', ',')
|
|
}
|
|
if procID != 0 {
|
|
dst = append(dst, `"proc_id":`...)
|
|
dst = strconv.AppendUint(dst, uint64(procID), 10)
|
|
dst = append(dst, ',')
|
|
}
|
|
if procSequence != 0 {
|
|
dst = append(dst, `"proc_seq":`...)
|
|
dst = strconv.AppendUint(dst, procSequence, 10)
|
|
dst = append(dst, ',')
|
|
}
|
|
if errDetail != "" || errData != nil {
|
|
dst = append(dst, `"error":{`...)
|
|
if errDetail != "" {
|
|
dst = append(dst, `"detail":`...)
|
|
dst, _ = jsontext.AppendQuote(dst, errDetail)
|
|
dst = append(dst, ',')
|
|
}
|
|
if errData != nil {
|
|
dst = append(dst, `"bad_data":`...)
|
|
dst = append(dst, errData...)
|
|
dst = append(dst, ',')
|
|
}
|
|
dst = bytes.TrimRight(dst, ",")
|
|
dst = append(dst, '}', ',')
|
|
}
|
|
dst = bytes.TrimRight(dst, ",")
|
|
dst = append(dst, '}', ',')
|
|
}
|
|
|
|
// Append optional metrics metadata.
|
|
if !skipMetrics && l.metricsDelta != nil {
|
|
if d := l.metricsDelta(); d != "" {
|
|
dst = append(dst, `"metrics":"`...)
|
|
dst = append(dst, d...)
|
|
dst = append(dst, '"', ',')
|
|
}
|
|
}
|
|
|
|
// Add the optional log level, if non-zero.
|
|
// Note that we only use log levels 1 and 2 currently.
|
|
// It's unlikely we'll ever make it past 9.
|
|
if level > 0 && level < 10 {
|
|
dst = append(dst, `"v":`...)
|
|
dst = append(dst, '0'+byte(level))
|
|
dst = append(dst, ',')
|
|
}
|
|
|
|
return dst
|
|
}
|
|
|
|
// appendText appends a raw text message in the Tailscale JSON log entry format.
|
|
func (l *Logger) appendText(dst, src []byte, skipClientTime bool, procID uint32, procSequence uint64, level int) []byte {
|
|
dst = slices.Grow(dst, len(src))
|
|
dst = append(dst, '{')
|
|
dst = l.appendMetadata(dst, skipClientTime, false, procID, procSequence, "", nil, level)
|
|
if len(src) == 0 {
|
|
dst = bytes.TrimRight(dst, ",")
|
|
return append(dst, "}\n"...)
|
|
}
|
|
|
|
// Append the text string, which may be truncated.
|
|
// Invalid UTF-8 will be mangled with the Unicode replacement character.
|
|
max := maxTextSize
|
|
if l.lowMem {
|
|
max /= lowMemRatio
|
|
}
|
|
dst = append(dst, `"text":`...)
|
|
dst = appendTruncatedString(dst, src, max)
|
|
return append(dst, "}\n"...)
|
|
}
|
|
|
|
// appendTruncatedString appends a JSON string for src,
|
|
// truncating the src to be no larger than n.
|
|
func appendTruncatedString(dst, src []byte, n int) []byte {
|
|
srcLen := len(src)
|
|
src = truncate.String(src, n)
|
|
dst, _ = jsontext.AppendQuote(dst, src) // ignore error; only occurs for invalid UTF-8
|
|
if srcLen > len(src) {
|
|
dst = dst[:len(dst)-len(`"`)] // trim off preceding double-quote
|
|
dst = append(dst, "…+"...)
|
|
dst = strconv.AppendInt(dst, int64(srcLen-len(src)), 10)
|
|
dst = append(dst, '"') // re-append succeeding double-quote
|
|
}
|
|
return dst
|
|
}
|
|
|
|
func (l *Logger) AppendTextOrJSONLocked(dst, src []byte) []byte {
|
|
l.clock = tstime.StdClock{}
|
|
return l.appendTextOrJSONLocked(dst, src, 0)
|
|
}
|
|
|
|
// appendTextOrJSONLocked appends a raw text message or a raw JSON object
|
|
// in the Tailscale JSON log format.
|
|
func (l *Logger) appendTextOrJSONLocked(dst, src []byte, level int) []byte {
|
|
if l.includeProcSequence {
|
|
l.procSequence++
|
|
}
|
|
if len(src) == 0 || src[0] != '{' {
|
|
return l.appendText(dst, src, l.skipClientTime, l.procID, l.procSequence, level)
|
|
}
|
|
|
|
// Check whether the input is a valid JSON object and
|
|
// whether it contains the reserved "logtail" name at the top-level.
|
|
var logtailKeyOffset, logtailValOffset, logtailValLength int
|
|
validJSON := func() bool {
|
|
// TODO(dsnet): Avoid allocation of bytes.Buffer struct.
|
|
dec := &l.jsonDec
|
|
dec.Reset(bytes.NewBuffer(src))
|
|
if tok, err := dec.ReadToken(); tok.Kind() != '{' || err != nil {
|
|
return false
|
|
}
|
|
for dec.PeekKind() != '}' {
|
|
keyOffset := dec.InputOffset()
|
|
tok, err := dec.ReadToken()
|
|
if err != nil {
|
|
return false
|
|
}
|
|
isLogtail := tok.String() == "logtail"
|
|
valOffset := dec.InputOffset()
|
|
if dec.SkipValue() != nil {
|
|
return false
|
|
}
|
|
if isLogtail {
|
|
logtailKeyOffset = int(keyOffset)
|
|
logtailValOffset = int(valOffset)
|
|
logtailValLength = int(dec.InputOffset()) - logtailValOffset
|
|
}
|
|
}
|
|
if tok, err := dec.ReadToken(); tok.Kind() != '}' || err != nil {
|
|
return false
|
|
}
|
|
if _, err := dec.ReadToken(); err != io.EOF {
|
|
return false // trailing junk after JSON object
|
|
}
|
|
return true
|
|
}()
|
|
|
|
// Treat invalid JSON as a raw text message.
|
|
if !validJSON {
|
|
return l.appendText(dst, src, l.skipClientTime, l.procID, l.procSequence, level)
|
|
}
|
|
|
|
// Check whether the JSON payload is too large.
|
|
// Due to logtail metadata, the formatted log entry could exceed maxSize.
|
|
// That's okay as the Tailscale log service limit is actually 2*maxSize.
|
|
// However, so long as logging applications aim to target the maxSize limit,
|
|
// there should be no trouble eventually uploading logs.
|
|
if len(src) > maxSize {
|
|
errDetail := fmt.Sprintf("entry too large: %d bytes", len(src))
|
|
errData := appendTruncatedString(nil, src, maxSize/len(`\uffff`)) // escaping could increase size
|
|
|
|
dst = append(dst, '{')
|
|
dst = l.appendMetadata(dst, l.skipClientTime, true, l.procID, l.procSequence, errDetail, errData, level)
|
|
dst = bytes.TrimRight(dst, ",")
|
|
return append(dst, "}\n"...)
|
|
}
|
|
|
|
// Check whether the reserved logtail member occurs in the log data.
|
|
// If so, it is moved to the the logtail/error member.
|
|
const jsonSeperators = ",:" // per RFC 8259, section 2
|
|
const jsonWhitespace = " \n\r\t" // per RFC 8259, section 2
|
|
var errDetail string
|
|
var errData jsontext.Value
|
|
if logtailValLength > 0 {
|
|
errDetail = "duplicate logtail member"
|
|
errData = bytes.Trim(src[logtailValOffset:][:logtailValLength], jsonSeperators+jsonWhitespace)
|
|
}
|
|
dst = slices.Grow(dst, len(src))
|
|
dst = append(dst, '{')
|
|
dst = l.appendMetadata(dst, l.skipClientTime, true, l.procID, l.procSequence, errDetail, errData, level)
|
|
if logtailValLength > 0 {
|
|
// Exclude original logtail member from the message.
|
|
dst = appendWithoutNewline(dst, src[len("{"):logtailKeyOffset])
|
|
dst = bytes.TrimRight(dst, jsonSeperators+jsonWhitespace)
|
|
dst = appendWithoutNewline(dst, src[logtailValOffset+logtailValLength:])
|
|
} else {
|
|
dst = appendWithoutNewline(dst, src[len("{"):])
|
|
}
|
|
dst = bytes.TrimRight(dst, jsonWhitespace)
|
|
dst = dst[:len(dst)-len("}")]
|
|
dst = bytes.TrimRight(dst, jsonSeperators+jsonWhitespace)
|
|
return append(dst, "}\n"...)
|
|
}
|
|
|
|
// appendWithoutNewline appends src to dst except that it ignores newlines
|
|
// since newlines are used to frame individual log entries.
|
|
func appendWithoutNewline(dst, src []byte) []byte {
|
|
for _, c := range src {
|
|
if c != '\n' {
|
|
dst = append(dst, c)
|
|
}
|
|
}
|
|
return dst
|
|
}
|
|
|
|
// Logf logs to l using the provided fmt-style format and optional arguments.
|
|
func (l *Logger) Logf(format string, args ...any) {
|
|
fmt.Fprintf(l, format, args...)
|
|
}
|
|
|
|
var obscureIPs = envknob.RegisterBool("TS_OBSCURE_LOGGED_IPS")
|
|
|
|
// Write logs an encoded JSON blob.
|
|
//
|
|
// If the []byte passed to Write is not an encoded JSON blob,
|
|
// then contents is fit into a JSON blob and written.
|
|
//
|
|
// This is intended as an interface for the stdlib "log" package.
|
|
func (l *Logger) Write(buf []byte) (int, error) {
|
|
if len(buf) == 0 {
|
|
return 0, nil
|
|
}
|
|
inLen := len(buf) // length as provided to us, before modifications to downstream writers
|
|
|
|
level, buf := parseAndRemoveLogLevel(buf)
|
|
if l.stderr != nil && l.stderr != io.Discard && int64(level) <= atomic.LoadInt64(&l.stderrLevel) {
|
|
if buf[len(buf)-1] == '\n' {
|
|
l.stderr.Write(buf)
|
|
} else {
|
|
// The log package always line-terminates logs,
|
|
// so this is an uncommon path.
|
|
withNL := append(buf[:len(buf):len(buf)], '\n')
|
|
l.stderr.Write(withNL)
|
|
}
|
|
}
|
|
|
|
if obscureIPs() {
|
|
buf = redactIPs(buf)
|
|
}
|
|
|
|
l.writeLock.Lock()
|
|
defer l.writeLock.Unlock()
|
|
|
|
b := l.appendTextOrJSONLocked(l.writeBuf[:0], buf, level)
|
|
_, err := l.sendLocked(b)
|
|
return inLen, err
|
|
}
|
|
|
|
var (
|
|
regexMatchesIPv6 = regexp.MustCompile(`([0-9a-fA-F]{1,4}):([0-9a-fA-F]{1,4}):([0-9a-fA-F:]{1,4})*`)
|
|
regexMatchesIPv4 = regexp.MustCompile(`(\d{1,3})\.(\d{1,3})\.\d{1,3}\.\d{1,3}`)
|
|
)
|
|
|
|
// redactIPs is a helper function used in Write() to redact IPs (other than tailscale IPs).
|
|
// This function takes a log line as a byte slice and
|
|
// uses regex matching to parse and find IP addresses. Based on if the IP address is IPv4 or
|
|
// IPv6, it parses and replaces the end of the addresses with an "x". This function returns the
|
|
// log line with the IPs redacted.
|
|
func redactIPs(buf []byte) []byte {
|
|
out := regexMatchesIPv6.ReplaceAllFunc(buf, func(b []byte) []byte {
|
|
ip, err := netip.ParseAddr(string(b))
|
|
if err != nil || tsaddr.IsTailscaleIP(ip) {
|
|
return b // don't change this one
|
|
}
|
|
|
|
prefix := bytes.Split(b, []byte(":"))
|
|
return bytes.Join(append(prefix[:2], []byte("x")), []byte(":"))
|
|
})
|
|
|
|
out = regexMatchesIPv4.ReplaceAllFunc(out, func(b []byte) []byte {
|
|
ip, err := netip.ParseAddr(string(b))
|
|
if err != nil || tsaddr.IsTailscaleIP(ip) {
|
|
return b // don't change this one
|
|
}
|
|
|
|
prefix := bytes.Split(b, []byte("."))
|
|
return bytes.Join(append(prefix[:2], []byte("x.x")), []byte("."))
|
|
})
|
|
|
|
return []byte(out)
|
|
}
|
|
|
|
var (
|
|
openBracketV = []byte("[v")
|
|
v1 = []byte("[v1] ")
|
|
v2 = []byte("[v2] ")
|
|
vJSON = []byte("[v\x00JSON]") // precedes log level '0'-'9' byte, then JSON value
|
|
)
|
|
|
|
// level 0 is normal (or unknown) level; 1+ are increasingly verbose
|
|
func parseAndRemoveLogLevel(buf []byte) (level int, cleanBuf []byte) {
|
|
if len(buf) == 0 || buf[0] == '{' || !bytes.Contains(buf, openBracketV) {
|
|
return 0, buf
|
|
}
|
|
if bytes.Contains(buf, v1) {
|
|
return 1, bytes.ReplaceAll(buf, v1, nil)
|
|
}
|
|
if bytes.Contains(buf, v2) {
|
|
return 2, bytes.ReplaceAll(buf, v2, nil)
|
|
}
|
|
if i := bytes.Index(buf, vJSON); i != -1 {
|
|
rest := buf[i+len(vJSON):]
|
|
if len(rest) >= 2 {
|
|
v := rest[0]
|
|
if v >= '0' && v <= '9' {
|
|
return int(v - '0'), rest[1:]
|
|
}
|
|
}
|
|
}
|
|
return 0, buf
|
|
}
|
|
|
|
var (
|
|
tapSetSize atomic.Int32
|
|
tapMu sync.Mutex
|
|
tapSet set.HandleSet[chan<- string]
|
|
)
|
|
|
|
// RegisterLogTap registers dst to get a copy of every log write. The caller
|
|
// must call unregister when done watching.
|
|
//
|
|
// This would ideally be a method on Logger, but Logger isn't really available
|
|
// in most places; many writes go via stderr which filch redirects to the
|
|
// singleton Logger set up early. For better or worse, there's basically only
|
|
// one Logger within the program. This mechanism at least works well for
|
|
// tailscaled. It works less well for a binary with multiple tsnet.Servers. Oh
|
|
// well. This then subscribes to all of them.
|
|
func RegisterLogTap(dst chan<- string) (unregister func()) {
|
|
tapMu.Lock()
|
|
defer tapMu.Unlock()
|
|
h := tapSet.Add(dst)
|
|
tapSetSize.Store(int32(len(tapSet)))
|
|
return func() {
|
|
tapMu.Lock()
|
|
defer tapMu.Unlock()
|
|
delete(tapSet, h)
|
|
tapSetSize.Store(int32(len(tapSet)))
|
|
}
|
|
}
|
|
|
|
// tapSend relays the JSON blob to any/all registered local debug log watchers
|
|
// (somebody running "tailscale debug daemon-logs").
|
|
func tapSend(jsonBlob []byte) {
|
|
if tapSetSize.Load() == 0 {
|
|
return
|
|
}
|
|
s := string(jsonBlob)
|
|
tapMu.Lock()
|
|
defer tapMu.Unlock()
|
|
for _, dst := range tapSet {
|
|
select {
|
|
case dst <- s:
|
|
default:
|
|
}
|
|
}
|
|
}
|