logtail.go 28 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920
  1. // Copyright (c) Tailscale Inc & AUTHORS
  2. // SPDX-License-Identifier: BSD-3-Clause
  3. //go:build !ts_omit_logtail
  4. // Package logtail sends logs to log.tailscale.com.
  5. package logtail
  6. import (
  7. "bytes"
  8. "cmp"
  9. "context"
  10. "crypto/rand"
  11. "encoding/binary"
  12. "fmt"
  13. "io"
  14. "log"
  15. mrand "math/rand/v2"
  16. "net/http"
  17. "os"
  18. "runtime"
  19. "slices"
  20. "strconv"
  21. "sync"
  22. "sync/atomic"
  23. "time"
  24. "github.com/creachadair/msync/trigger"
  25. "github.com/go-json-experiment/json/jsontext"
  26. "tailscale.com/envknob"
  27. "tailscale.com/net/netmon"
  28. "tailscale.com/net/sockstats"
  29. "tailscale.com/tstime"
  30. tslogger "tailscale.com/types/logger"
  31. "tailscale.com/types/logid"
  32. "tailscale.com/util/eventbus"
  33. "tailscale.com/util/set"
  34. "tailscale.com/util/truncate"
  35. "tailscale.com/util/zstdframe"
  36. )
  37. // maxSize is the maximum size that a single log entry can be.
  38. // It is also the maximum body size that may be uploaded at a time.
  39. const maxSize = 256 << 10
  40. // maxTextSize is the maximum size for a text log message.
  41. // Note that JSON log messages can be as large as maxSize.
  42. const maxTextSize = 16 << 10
  43. // lowMemRatio reduces maxSize and maxTextSize by this ratio in lowMem mode.
  44. const lowMemRatio = 4
  45. // bufferSize is the typical buffer size to retain.
  46. // It is large enough to handle most log messages,
  47. // but not too large to be a notable waste of memory if retained forever.
  48. const bufferSize = 4 << 10
  49. func NewLogger(cfg Config, logf tslogger.Logf) *Logger {
  50. if cfg.BaseURL == "" {
  51. cfg.BaseURL = "https://" + DefaultHost
  52. }
  53. if cfg.HTTPC == nil {
  54. cfg.HTTPC = http.DefaultClient
  55. }
  56. if cfg.Clock == nil {
  57. cfg.Clock = tstime.StdClock{}
  58. }
  59. if cfg.Stderr == nil {
  60. cfg.Stderr = os.Stderr
  61. }
  62. if cfg.Buffer == nil {
  63. pendingSize := 256
  64. if cfg.LowMemory {
  65. pendingSize = 64
  66. }
  67. cfg.Buffer = NewMemoryBuffer(pendingSize)
  68. }
  69. var procID uint32
  70. if cfg.IncludeProcID {
  71. keyBytes := make([]byte, 4)
  72. rand.Read(keyBytes)
  73. procID = binary.LittleEndian.Uint32(keyBytes)
  74. if procID == 0 {
  75. // 0 is the empty/off value, assign a different (non-zero) value to
  76. // make sure we still include an ID (actual value does not matter).
  77. procID = 7
  78. }
  79. }
  80. if s := envknob.String("TS_DEBUG_LOGTAIL_FLUSHDELAY"); s != "" {
  81. if delay, err := time.ParseDuration(s); err == nil {
  82. cfg.FlushDelayFn = func() time.Duration { return delay }
  83. } else {
  84. log.Fatalf("invalid TS_DEBUG_LOGTAIL_FLUSHDELAY: %v", err)
  85. }
  86. } else if cfg.FlushDelayFn == nil && envknob.Bool("IN_TS_TEST") {
  87. cfg.FlushDelayFn = func() time.Duration { return 0 }
  88. }
  89. var urlSuffix string
  90. if !cfg.CopyPrivateID.IsZero() {
  91. urlSuffix = "?copyId=" + cfg.CopyPrivateID.String()
  92. }
  93. logger := &Logger{
  94. privateID: cfg.PrivateID,
  95. stderr: cfg.Stderr,
  96. stderrLevel: int64(cfg.StderrLevel),
  97. httpc: cfg.HTTPC,
  98. url: cfg.BaseURL + "/c/" + cfg.Collection + "/" + cfg.PrivateID.String() + urlSuffix,
  99. lowMem: cfg.LowMemory,
  100. buffer: cfg.Buffer,
  101. maxUploadSize: cfg.MaxUploadSize,
  102. skipClientTime: cfg.SkipClientTime,
  103. drainWake: make(chan struct{}, 1),
  104. sentinel: make(chan int32, 16),
  105. flushDelayFn: cfg.FlushDelayFn,
  106. clock: cfg.Clock,
  107. metricsDelta: cfg.MetricsDelta,
  108. procID: procID,
  109. includeProcSequence: cfg.IncludeProcSequence,
  110. shutdownStart: make(chan struct{}),
  111. shutdownDone: make(chan struct{}),
  112. }
  113. if cfg.Bus != nil {
  114. logger.eventClient = cfg.Bus.Client("logtail.Logger")
  115. // Subscribe to change deltas from NetMon to detect when the network comes up.
  116. eventbus.SubscribeFunc(logger.eventClient, logger.onChangeDelta)
  117. }
  118. logger.SetSockstatsLabel(sockstats.LabelLogtailLogger)
  119. logger.compressLogs = cfg.CompressLogs
  120. ctx, cancel := context.WithCancel(context.Background())
  121. logger.uploadCancel = cancel
  122. go logger.uploading(ctx)
  123. logger.Write([]byte("logtail started"))
  124. return logger
  125. }
  126. // Logger writes logs, splitting them as configured between local
  127. // logging facilities and uploading to a log server.
  128. type Logger struct {
  129. stderr io.Writer
  130. stderrLevel int64 // accessed atomically
  131. httpc *http.Client
  132. url string
  133. lowMem bool
  134. skipClientTime bool
  135. netMonitor *netmon.Monitor
  136. buffer Buffer
  137. maxUploadSize int
  138. drainWake chan struct{} // signal to speed up drain
  139. drainBuf []byte // owned by drainPending for reuse
  140. flushDelayFn func() time.Duration // negative or zero return value to upload aggressively, or >0 to batch at this delay
  141. flushPending atomic.Bool
  142. sentinel chan int32
  143. clock tstime.Clock
  144. compressLogs bool
  145. uploadCancel func()
  146. explainedRaw bool
  147. metricsDelta func() string // or nil
  148. privateID logid.PrivateID
  149. httpDoCalls atomic.Int32
  150. sockstatsLabel atomicSocktatsLabel
  151. eventClient *eventbus.Client
  152. networkIsUp trigger.Cond // set/reset by netmon.ChangeDelta events
  153. procID uint32
  154. includeProcSequence bool
  155. writeLock sync.Mutex // guards procSequence, flushTimer, buffer.Write calls
  156. procSequence uint64
  157. flushTimer tstime.TimerController // used when flushDelay is >0
  158. writeBuf [bufferSize]byte // owned by Write for reuse
  159. bytesBuf bytes.Buffer // owned by appendTextOrJSONLocked for reuse
  160. jsonDec jsontext.Decoder // owned by appendTextOrJSONLocked for reuse
  161. shutdownStartMu sync.Mutex // guards the closing of shutdownStart
  162. shutdownStart chan struct{} // closed when shutdown begins
  163. shutdownDone chan struct{} // closed when shutdown complete
  164. }
  165. type atomicSocktatsLabel struct{ p atomic.Uint32 }
  166. func (p *atomicSocktatsLabel) Load() sockstats.Label { return sockstats.Label(p.p.Load()) }
  167. func (p *atomicSocktatsLabel) Store(label sockstats.Label) { p.p.Store(uint32(label)) }
  168. // SetVerbosityLevel controls the verbosity level that should be
  169. // written to stderr. 0 is the default (not verbose). Levels 1 or higher
  170. // are increasingly verbose.
  171. func (lg *Logger) SetVerbosityLevel(level int) {
  172. atomic.StoreInt64(&lg.stderrLevel, int64(level))
  173. }
  174. // SetNetMon sets the network monitor.
  175. //
  176. // It should not be changed concurrently with log writes and should
  177. // only be set once.
  178. func (lg *Logger) SetNetMon(lm *netmon.Monitor) {
  179. lg.netMonitor = lm
  180. }
  181. // SetSockstatsLabel sets the label used in sockstat logs to identify network traffic from this logger.
  182. func (lg *Logger) SetSockstatsLabel(label sockstats.Label) {
  183. lg.sockstatsLabel.Store(label)
  184. }
  185. // PrivateID returns the logger's private log ID.
  186. //
  187. // It exists for internal use only.
  188. func (lg *Logger) PrivateID() logid.PrivateID { return lg.privateID }
  189. // Shutdown gracefully shuts down the logger while completing any
  190. // remaining uploads.
  191. //
  192. // It will block, continuing to try and upload unless the passed
  193. // context object interrupts it by being done.
  194. // If the shutdown is interrupted, an error is returned.
  195. func (lg *Logger) Shutdown(ctx context.Context) error {
  196. done := make(chan struct{})
  197. go func() {
  198. select {
  199. case <-ctx.Done():
  200. lg.uploadCancel()
  201. <-lg.shutdownDone
  202. case <-lg.shutdownDone:
  203. }
  204. close(done)
  205. lg.httpc.CloseIdleConnections()
  206. }()
  207. if lg.eventClient != nil {
  208. lg.eventClient.Close()
  209. }
  210. lg.shutdownStartMu.Lock()
  211. select {
  212. case <-lg.shutdownStart:
  213. lg.shutdownStartMu.Unlock()
  214. return nil
  215. default:
  216. }
  217. close(lg.shutdownStart)
  218. lg.shutdownStartMu.Unlock()
  219. io.WriteString(lg, "logger closing down\n")
  220. <-done
  221. return nil
  222. }
  223. // Close shuts down this logger object, the background log uploader
  224. // process, and any associated goroutines.
  225. //
  226. // Deprecated: use Shutdown
  227. func (lg *Logger) Close() {
  228. lg.Shutdown(context.Background())
  229. }
  230. // drainBlock is called by drainPending when there are no logs to drain.
  231. //
  232. // In typical operation, every call to the Write method unblocks and triggers a
  233. // buffer.TryReadline, so logs are written with very low latency.
  234. //
  235. // If the caller specified FlushInterface, drainWake is only sent to
  236. // periodically.
  237. func (lg *Logger) drainBlock() (shuttingDown bool) {
  238. select {
  239. case <-lg.shutdownStart:
  240. return true
  241. case <-lg.drainWake:
  242. }
  243. return false
  244. }
  245. // drainPending drains and encodes a batch of logs from the buffer for upload.
  246. // If no logs are available, drainPending blocks until logs are available.
  247. // The returned buffer is only valid until the next call to drainPending.
  248. func (lg *Logger) drainPending() (b []byte) {
  249. b = lg.drainBuf[:0]
  250. b = append(b, '[')
  251. defer func() {
  252. b = bytes.TrimRight(b, ",")
  253. b = append(b, ']')
  254. lg.drainBuf = b
  255. if len(b) <= len("[]") {
  256. b = nil
  257. }
  258. }()
  259. maxLen := cmp.Or(lg.maxUploadSize, maxSize)
  260. if lg.lowMem {
  261. // When operating in a low memory environment, it is better to upload
  262. // in multiple operations than it is to allocate a large body and OOM.
  263. // Even if maxLen is less than maxSize, we can still upload an entry
  264. // that is up to maxSize if we happen to encounter one.
  265. maxLen /= lowMemRatio
  266. }
  267. for len(b) < maxLen {
  268. line, err := lg.buffer.TryReadLine()
  269. switch {
  270. case err == io.EOF:
  271. return b
  272. case err != nil:
  273. b = append(b, '{')
  274. b = lg.appendMetadata(b, false, true, 0, 0, "reading ringbuffer: "+err.Error(), nil, 0)
  275. b = bytes.TrimRight(b, ",")
  276. b = append(b, '}')
  277. return b
  278. case line == nil:
  279. // If we read at least some log entries, return immediately.
  280. if len(b) > len("[") {
  281. return b
  282. }
  283. // We're about to block. If we're holding on to too much memory
  284. // in our buffer from a previous large write, let it go.
  285. if cap(b) > bufferSize {
  286. b = bytes.Clone(b)
  287. lg.drainBuf = b
  288. }
  289. if shuttingDown := lg.drainBlock(); shuttingDown {
  290. return b
  291. }
  292. continue
  293. }
  294. switch {
  295. case len(line) == 0:
  296. continue
  297. case line[0] == '{' && jsontext.Value(line).IsValid():
  298. // This is already a valid JSON object, so just append it.
  299. // This may exceed maxLen, but should be no larger than maxSize
  300. // so long as logic writing into the buffer enforces the limit.
  301. b = append(b, line...)
  302. default:
  303. // This is probably a log added to stderr by filch
  304. // outside of the logtail logger. Encode it.
  305. if !lg.explainedRaw {
  306. fmt.Fprintf(lg.stderr, "RAW-STDERR: ***\n")
  307. fmt.Fprintf(lg.stderr, "RAW-STDERR: *** Lines prefixed with RAW-STDERR below bypassed logtail and probably come from a previous run of the program\n")
  308. fmt.Fprintf(lg.stderr, "RAW-STDERR: ***\n")
  309. fmt.Fprintf(lg.stderr, "RAW-STDERR:\n")
  310. lg.explainedRaw = true
  311. }
  312. fmt.Fprintf(lg.stderr, "RAW-STDERR: %s", b)
  313. // Do not add a client time, as it could be really old.
  314. // Do not include instance key or ID either,
  315. // since this came from a different instance.
  316. b = lg.appendText(b, line, true, 0, 0, 0)
  317. }
  318. b = append(b, ',')
  319. }
  320. return b
  321. }
  322. // This is the goroutine that repeatedly uploads logs in the background.
  323. func (lg *Logger) uploading(ctx context.Context) {
  324. defer close(lg.shutdownDone)
  325. for {
  326. body := lg.drainPending()
  327. origlen := -1 // sentinel value: uncompressed
  328. // Don't attempt to compress tiny bodies; not worth the CPU cycles.
  329. if lg.compressLogs && len(body) > 256 {
  330. zbody := zstdframe.AppendEncode(nil, body,
  331. zstdframe.FastestCompression, zstdframe.LowMemory(true))
  332. // Only send it compressed if the bandwidth savings are sufficient.
  333. // Just the extra headers associated with enabling compression
  334. // are 50 bytes by themselves.
  335. if len(body)-len(zbody) > 64 {
  336. origlen = len(body)
  337. body = zbody
  338. }
  339. }
  340. var lastError string
  341. var numFailures int
  342. var firstFailure time.Time
  343. for len(body) > 0 && ctx.Err() == nil {
  344. retryAfter, err := lg.upload(ctx, body, origlen)
  345. if err != nil {
  346. numFailures++
  347. firstFailure = lg.clock.Now()
  348. if !lg.internetUp() {
  349. fmt.Fprintf(lg.stderr, "logtail: internet down; waiting\n")
  350. lg.awaitInternetUp(ctx)
  351. continue
  352. }
  353. // Only print the same message once.
  354. if currError := err.Error(); lastError != currError {
  355. fmt.Fprintf(lg.stderr, "logtail: upload: %v\n", err)
  356. lastError = currError
  357. }
  358. // Sleep for the specified retryAfter period,
  359. // otherwise default to some random value.
  360. if retryAfter <= 0 {
  361. retryAfter = mrand.N(30*time.Second) + 30*time.Second
  362. }
  363. tstime.Sleep(ctx, retryAfter)
  364. } else {
  365. // Only print a success message after recovery.
  366. if numFailures > 0 {
  367. fmt.Fprintf(lg.stderr, "logtail: upload succeeded after %d failures and %s\n", numFailures, lg.clock.Since(firstFailure).Round(time.Second))
  368. }
  369. break
  370. }
  371. }
  372. select {
  373. case <-lg.shutdownStart:
  374. return
  375. default:
  376. }
  377. }
  378. }
  379. func (lg *Logger) internetUp() bool {
  380. select {
  381. case <-lg.networkIsUp.Ready():
  382. return true
  383. default:
  384. if lg.netMonitor == nil {
  385. return true // No way to tell, so assume it is.
  386. }
  387. return lg.netMonitor.InterfaceState().AnyInterfaceUp()
  388. }
  389. }
  390. // onChangeDelta is an eventbus subscriber function that handles
  391. // [netmon.ChangeDelta] events to detect whether the Internet is expected to be
  392. // reachable.
  393. func (lg *Logger) onChangeDelta(delta *netmon.ChangeDelta) {
  394. if delta.New.AnyInterfaceUp() {
  395. fmt.Fprintf(lg.stderr, "logtail: internet back up\n")
  396. lg.networkIsUp.Set()
  397. } else {
  398. fmt.Fprintf(lg.stderr, "logtail: network changed, but is not up\n")
  399. lg.networkIsUp.Reset()
  400. }
  401. }
  402. func (lg *Logger) awaitInternetUp(ctx context.Context) {
  403. if lg.eventClient != nil {
  404. select {
  405. case <-lg.networkIsUp.Ready():
  406. case <-ctx.Done():
  407. }
  408. return
  409. }
  410. upc := make(chan bool, 1)
  411. defer lg.netMonitor.RegisterChangeCallback(func(delta *netmon.ChangeDelta) {
  412. if delta.New.AnyInterfaceUp() {
  413. select {
  414. case upc <- true:
  415. default:
  416. }
  417. }
  418. })()
  419. if lg.internetUp() {
  420. return
  421. }
  422. select {
  423. case <-upc:
  424. fmt.Fprintf(lg.stderr, "logtail: internet back up\n")
  425. case <-ctx.Done():
  426. }
  427. }
  428. // upload uploads body to the log server.
  429. // origlen indicates the pre-compression body length.
  430. // origlen of -1 indicates that the body is not compressed.
  431. func (lg *Logger) upload(ctx context.Context, body []byte, origlen int) (retryAfter time.Duration, err error) {
  432. const maxUploadTime = 45 * time.Second
  433. ctx = sockstats.WithSockStats(ctx, lg.sockstatsLabel.Load(), lg.Logf)
  434. ctx, cancel := context.WithTimeout(ctx, maxUploadTime)
  435. defer cancel()
  436. req, err := http.NewRequestWithContext(ctx, "POST", lg.url, bytes.NewReader(body))
  437. if err != nil {
  438. // I know of no conditions under which this could fail.
  439. // Report it very loudly.
  440. // TODO record logs to disk
  441. panic("logtail: cannot build http request: " + err.Error())
  442. }
  443. if origlen != -1 {
  444. req.Header.Add("Content-Encoding", "zstd")
  445. req.Header.Add("Orig-Content-Length", strconv.Itoa(origlen))
  446. }
  447. if runtime.GOOS == "js" {
  448. // We once advertised we'd accept optional client certs (for internal use)
  449. // on log.tailscale.com but then Tailscale SSH js/wasm clients prompted
  450. // users (on some browsers?) to pick a client cert. We'll fix the server's
  451. // TLS ServerHello, but we can also fix it client side for good measure.
  452. //
  453. // Corp details: https://github.com/tailscale/corp/issues/18177#issuecomment-2026598715
  454. // and https://github.com/tailscale/corp/pull/18775#issuecomment-2027505036
  455. //
  456. // See https://github.com/golang/go/wiki/WebAssembly#configuring-fetch-options-while-using-nethttp
  457. // and https://developer.mozilla.org/en-US/docs/Web/API/fetch#credentials
  458. req.Header.Set("js.fetch:credentials", "omit")
  459. }
  460. req.Header["User-Agent"] = nil // not worth writing one; save some bytes
  461. compressedNote := "not-compressed"
  462. if origlen != -1 {
  463. compressedNote = "compressed"
  464. }
  465. lg.httpDoCalls.Add(1)
  466. resp, err := lg.httpc.Do(req)
  467. if err != nil {
  468. return 0, fmt.Errorf("log upload of %d bytes %s failed: %v", len(body), compressedNote, err)
  469. }
  470. defer resp.Body.Close()
  471. if resp.StatusCode != http.StatusOK {
  472. n, _ := strconv.Atoi(resp.Header.Get("Retry-After"))
  473. b, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<10))
  474. 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))
  475. }
  476. return 0, nil
  477. }
  478. // Flush uploads all logs to the server. It blocks until complete or there is an
  479. // unrecoverable error.
  480. //
  481. // TODO(bradfitz): this apparently just returns nil, as of tailscale/corp@9c2ec35.
  482. // Finish cleaning this up.
  483. func (lg *Logger) Flush() error {
  484. return nil
  485. }
  486. // StartFlush starts a log upload, if anything is pending.
  487. //
  488. // If l is nil, StartFlush is a no-op.
  489. func (lg *Logger) StartFlush() {
  490. if lg != nil {
  491. lg.tryDrainWake()
  492. }
  493. }
  494. // logtailDisabled is whether logtail uploads to logcatcher are disabled.
  495. var logtailDisabled atomic.Bool
  496. // Disable disables logtail uploads for the lifetime of the process.
  497. func Disable() {
  498. logtailDisabled.Store(true)
  499. }
  500. var debugWakesAndUploads = envknob.RegisterBool("TS_DEBUG_LOGTAIL_WAKES")
  501. // tryDrainWake tries to send to lg.drainWake, to cause an uploading wakeup.
  502. // It does not block.
  503. func (lg *Logger) tryDrainWake() {
  504. lg.flushPending.Store(false)
  505. if debugWakesAndUploads() {
  506. // Using println instead of log.Printf here to avoid recursing back into
  507. // ourselves.
  508. println("logtail: try drain wake, numHTTP:", lg.httpDoCalls.Load())
  509. }
  510. select {
  511. case lg.drainWake <- struct{}{}:
  512. default:
  513. }
  514. }
  515. func (lg *Logger) sendLocked(jsonBlob []byte) (int, error) {
  516. tapSend(jsonBlob)
  517. if logtailDisabled.Load() {
  518. return len(jsonBlob), nil
  519. }
  520. n, err := lg.buffer.Write(jsonBlob)
  521. flushDelay := defaultFlushDelay
  522. if lg.flushDelayFn != nil {
  523. flushDelay = lg.flushDelayFn()
  524. }
  525. if flushDelay > 0 {
  526. if lg.flushPending.CompareAndSwap(false, true) {
  527. if lg.flushTimer == nil {
  528. lg.flushTimer = lg.clock.AfterFunc(flushDelay, lg.tryDrainWake)
  529. } else {
  530. lg.flushTimer.Reset(flushDelay)
  531. }
  532. }
  533. } else {
  534. lg.tryDrainWake()
  535. }
  536. return n, err
  537. }
  538. // appendMetadata appends optional "logtail", "metrics", and "v" JSON members.
  539. // This assumes dst is already within a JSON object.
  540. // Each member is comma-terminated.
  541. func (lg *Logger) appendMetadata(dst []byte, skipClientTime, skipMetrics bool, procID uint32, procSequence uint64, errDetail string, errData jsontext.Value, level int) []byte {
  542. // Append optional logtail metadata.
  543. if !skipClientTime || procID != 0 || procSequence != 0 || errDetail != "" || errData != nil {
  544. dst = append(dst, `"logtail":{`...)
  545. if !skipClientTime {
  546. dst = append(dst, `"client_time":"`...)
  547. dst = lg.clock.Now().UTC().AppendFormat(dst, time.RFC3339Nano)
  548. dst = append(dst, '"', ',')
  549. }
  550. if procID != 0 {
  551. dst = append(dst, `"proc_id":`...)
  552. dst = strconv.AppendUint(dst, uint64(procID), 10)
  553. dst = append(dst, ',')
  554. }
  555. if procSequence != 0 {
  556. dst = append(dst, `"proc_seq":`...)
  557. dst = strconv.AppendUint(dst, procSequence, 10)
  558. dst = append(dst, ',')
  559. }
  560. if errDetail != "" || errData != nil {
  561. dst = append(dst, `"error":{`...)
  562. if errDetail != "" {
  563. dst = append(dst, `"detail":`...)
  564. dst, _ = jsontext.AppendQuote(dst, errDetail)
  565. dst = append(dst, ',')
  566. }
  567. if errData != nil {
  568. dst = append(dst, `"bad_data":`...)
  569. dst = append(dst, errData...)
  570. dst = append(dst, ',')
  571. }
  572. dst = bytes.TrimRight(dst, ",")
  573. dst = append(dst, '}', ',')
  574. }
  575. dst = bytes.TrimRight(dst, ",")
  576. dst = append(dst, '}', ',')
  577. }
  578. // Append optional metrics metadata.
  579. if !skipMetrics && lg.metricsDelta != nil {
  580. if d := lg.metricsDelta(); d != "" {
  581. dst = append(dst, `"metrics":"`...)
  582. dst = append(dst, d...)
  583. dst = append(dst, '"', ',')
  584. }
  585. }
  586. // Add the optional log level, if non-zero.
  587. // Note that we only use log levels 1 and 2 currently.
  588. // It's unlikely we'll ever make it past 9.
  589. if level > 0 && level < 10 {
  590. dst = append(dst, `"v":`...)
  591. dst = append(dst, '0'+byte(level))
  592. dst = append(dst, ',')
  593. }
  594. return dst
  595. }
  596. // appendText appends a raw text message in the Tailscale JSON log entry format.
  597. func (lg *Logger) appendText(dst, src []byte, skipClientTime bool, procID uint32, procSequence uint64, level int) []byte {
  598. dst = slices.Grow(dst, len(src))
  599. dst = append(dst, '{')
  600. dst = lg.appendMetadata(dst, skipClientTime, false, procID, procSequence, "", nil, level)
  601. if len(src) == 0 {
  602. dst = bytes.TrimRight(dst, ",")
  603. return append(dst, "}\n"...)
  604. }
  605. // Append the text string, which may be truncated.
  606. // Invalid UTF-8 will be mangled with the Unicode replacement character.
  607. max := maxTextSize
  608. if lg.lowMem {
  609. max /= lowMemRatio
  610. }
  611. dst = append(dst, `"text":`...)
  612. dst = appendTruncatedString(dst, src, max)
  613. return append(dst, "}\n"...)
  614. }
  615. // appendTruncatedString appends a JSON string for src,
  616. // truncating the src to be no larger than n.
  617. func appendTruncatedString(dst, src []byte, n int) []byte {
  618. srcLen := len(src)
  619. src = truncate.String(src, n)
  620. dst, _ = jsontext.AppendQuote(dst, src) // ignore error; only occurs for invalid UTF-8
  621. if srcLen > len(src) {
  622. dst = dst[:len(dst)-len(`"`)] // trim off preceding double-quote
  623. dst = append(dst, "…+"...)
  624. dst = strconv.AppendInt(dst, int64(srcLen-len(src)), 10)
  625. dst = append(dst, '"') // re-append succeeding double-quote
  626. }
  627. return dst
  628. }
  629. // appendTextOrJSONLocked appends a raw text message or a raw JSON object
  630. // in the Tailscale JSON log format.
  631. func (lg *Logger) appendTextOrJSONLocked(dst, src []byte, level int) []byte {
  632. if lg.includeProcSequence {
  633. lg.procSequence++
  634. }
  635. if len(src) == 0 || src[0] != '{' {
  636. return lg.appendText(dst, src, lg.skipClientTime, lg.procID, lg.procSequence, level)
  637. }
  638. // Check whether the input is a valid JSON object and
  639. // whether it contains the reserved "logtail" name at the top-level.
  640. var logtailKeyOffset, logtailValOffset, logtailValLength int
  641. validJSON := func() bool {
  642. // The jsontext.NewDecoder API operates on an io.Reader, for which
  643. // bytes.Buffer provides a means to convert a []byte into an io.Reader.
  644. // However, bytes.NewBuffer normally allocates unless
  645. // we immediately shallow copy it into a pre-allocated Buffer struct.
  646. // See https://go.dev/issue/67004.
  647. lg.bytesBuf = *bytes.NewBuffer(src)
  648. defer func() { lg.bytesBuf = bytes.Buffer{} }() // avoid pinning src
  649. dec := &lg.jsonDec
  650. dec.Reset(&lg.bytesBuf)
  651. if tok, err := dec.ReadToken(); tok.Kind() != '{' || err != nil {
  652. return false
  653. }
  654. for dec.PeekKind() != '}' {
  655. keyOffset := dec.InputOffset()
  656. tok, err := dec.ReadToken()
  657. if err != nil {
  658. return false
  659. }
  660. isLogtail := tok.String() == "logtail"
  661. valOffset := dec.InputOffset()
  662. if dec.SkipValue() != nil {
  663. return false
  664. }
  665. if isLogtail {
  666. logtailKeyOffset = int(keyOffset)
  667. logtailValOffset = int(valOffset)
  668. logtailValLength = int(dec.InputOffset()) - logtailValOffset
  669. }
  670. }
  671. if tok, err := dec.ReadToken(); tok.Kind() != '}' || err != nil {
  672. return false
  673. }
  674. if _, err := dec.ReadToken(); err != io.EOF {
  675. return false // trailing junk after JSON object
  676. }
  677. return true
  678. }()
  679. // Treat invalid JSON as a raw text message.
  680. if !validJSON {
  681. return lg.appendText(dst, src, lg.skipClientTime, lg.procID, lg.procSequence, level)
  682. }
  683. // Check whether the JSON payload is too large.
  684. // Due to logtail metadata, the formatted log entry could exceed maxSize.
  685. // That's okay as the Tailscale log service limit is actually 2*maxSize.
  686. // However, so long as logging applications aim to target the maxSize limit,
  687. // there should be no trouble eventually uploading logs.
  688. maxLen := cmp.Or(lg.maxUploadSize, maxSize)
  689. if len(src) > maxLen {
  690. errDetail := fmt.Sprintf("entry too large: %d bytes", len(src))
  691. errData := appendTruncatedString(nil, src, maxLen/len(`\uffff`)) // escaping could increase size
  692. dst = append(dst, '{')
  693. dst = lg.appendMetadata(dst, lg.skipClientTime, true, lg.procID, lg.procSequence, errDetail, errData, level)
  694. dst = bytes.TrimRight(dst, ",")
  695. return append(dst, "}\n"...)
  696. }
  697. // Check whether the reserved logtail member occurs in the log data.
  698. // If so, it is moved to the the logtail/error member.
  699. const jsonSeperators = ",:" // per RFC 8259, section 2
  700. const jsonWhitespace = " \n\r\t" // per RFC 8259, section 2
  701. var errDetail string
  702. var errData jsontext.Value
  703. if logtailValLength > 0 {
  704. errDetail = "duplicate logtail member"
  705. errData = bytes.Trim(src[logtailValOffset:][:logtailValLength], jsonSeperators+jsonWhitespace)
  706. }
  707. dst = slices.Grow(dst, len(src))
  708. dst = append(dst, '{')
  709. dst = lg.appendMetadata(dst, lg.skipClientTime, true, lg.procID, lg.procSequence, errDetail, errData, level)
  710. if logtailValLength > 0 {
  711. // Exclude original logtail member from the message.
  712. dst = appendWithoutNewline(dst, src[len("{"):logtailKeyOffset])
  713. dst = bytes.TrimRight(dst, jsonSeperators+jsonWhitespace)
  714. dst = appendWithoutNewline(dst, src[logtailValOffset+logtailValLength:])
  715. } else {
  716. dst = appendWithoutNewline(dst, src[len("{"):])
  717. }
  718. dst = bytes.TrimRight(dst, jsonWhitespace)
  719. dst = dst[:len(dst)-len("}")]
  720. dst = bytes.TrimRight(dst, jsonSeperators+jsonWhitespace)
  721. return append(dst, "}\n"...)
  722. }
  723. // appendWithoutNewline appends src to dst except that it ignores newlines
  724. // since newlines are used to frame individual log entries.
  725. func appendWithoutNewline(dst, src []byte) []byte {
  726. for _, c := range src {
  727. if c != '\n' {
  728. dst = append(dst, c)
  729. }
  730. }
  731. return dst
  732. }
  733. // Logf logs to l using the provided fmt-style format and optional arguments.
  734. func (lg *Logger) Logf(format string, args ...any) {
  735. fmt.Fprintf(lg, format, args...)
  736. }
  737. // Write logs an encoded JSON blob.
  738. //
  739. // If the []byte passed to Write is not an encoded JSON blob,
  740. // then contents is fit into a JSON blob and written.
  741. //
  742. // This is intended as an interface for the stdlib "log" package.
  743. func (lg *Logger) Write(buf []byte) (int, error) {
  744. if len(buf) == 0 {
  745. return 0, nil
  746. }
  747. inLen := len(buf) // length as provided to us, before modifications to downstream writers
  748. level, buf := parseAndRemoveLogLevel(buf)
  749. if lg.stderr != nil && lg.stderr != io.Discard && int64(level) <= atomic.LoadInt64(&lg.stderrLevel) {
  750. if buf[len(buf)-1] == '\n' {
  751. lg.stderr.Write(buf)
  752. } else {
  753. // The log package always line-terminates logs,
  754. // so this is an uncommon path.
  755. withNL := append(buf[:len(buf):len(buf)], '\n')
  756. lg.stderr.Write(withNL)
  757. }
  758. }
  759. lg.writeLock.Lock()
  760. defer lg.writeLock.Unlock()
  761. b := lg.appendTextOrJSONLocked(lg.writeBuf[:0], buf, level)
  762. _, err := lg.sendLocked(b)
  763. return inLen, err
  764. }
  765. var (
  766. openBracketV = []byte("[v")
  767. v1 = []byte("[v1] ")
  768. v2 = []byte("[v2] ")
  769. vJSON = []byte("[v\x00JSON]") // precedes log level '0'-'9' byte, then JSON value
  770. )
  771. // level 0 is normal (or unknown) level; 1+ are increasingly verbose
  772. func parseAndRemoveLogLevel(buf []byte) (level int, cleanBuf []byte) {
  773. if len(buf) == 0 || buf[0] == '{' || !bytes.Contains(buf, openBracketV) {
  774. return 0, buf
  775. }
  776. if bytes.Contains(buf, v1) {
  777. return 1, bytes.ReplaceAll(buf, v1, nil)
  778. }
  779. if bytes.Contains(buf, v2) {
  780. return 2, bytes.ReplaceAll(buf, v2, nil)
  781. }
  782. if i := bytes.Index(buf, vJSON); i != -1 {
  783. rest := buf[i+len(vJSON):]
  784. if len(rest) >= 2 {
  785. v := rest[0]
  786. if v >= '0' && v <= '9' {
  787. return int(v - '0'), rest[1:]
  788. }
  789. }
  790. }
  791. return 0, buf
  792. }
  793. var (
  794. tapSetSize atomic.Int32
  795. tapMu sync.Mutex
  796. tapSet set.HandleSet[chan<- string]
  797. )
  798. // RegisterLogTap registers dst to get a copy of every log write. The caller
  799. // must call unregister when done watching.
  800. //
  801. // This would ideally be a method on Logger, but Logger isn't really available
  802. // in most places; many writes go via stderr which filch redirects to the
  803. // singleton Logger set up early. For better or worse, there's basically only
  804. // one Logger within the program. This mechanism at least works well for
  805. // tailscaled. It works less well for a binary with multiple tsnet.Servers. Oh
  806. // well. This then subscribes to all of them.
  807. func RegisterLogTap(dst chan<- string) (unregister func()) {
  808. tapMu.Lock()
  809. defer tapMu.Unlock()
  810. h := tapSet.Add(dst)
  811. tapSetSize.Store(int32(len(tapSet)))
  812. return func() {
  813. tapMu.Lock()
  814. defer tapMu.Unlock()
  815. delete(tapSet, h)
  816. tapSetSize.Store(int32(len(tapSet)))
  817. }
  818. }
  819. // tapSend relays the JSON blob to any/all registered local debug log watchers
  820. // (somebody running "tailscale debug daemon-logs").
  821. func tapSend(jsonBlob []byte) {
  822. if tapSetSize.Load() == 0 {
  823. return
  824. }
  825. s := string(jsonBlob)
  826. tapMu.Lock()
  827. defer tapMu.Unlock()
  828. for _, dst := range tapSet {
  829. select {
  830. case dst <- s:
  831. default:
  832. }
  833. }
  834. }