logpolicy, various: allow overriding log function

This allows sending logs from the "logpolicy" package (and associated
callees) to something other than the log package. The behaviour for
tailscaled remains the same, passing in log.Printf

Updates #8249

Signed-off-by: Andrew Dunham <andrew@du.nham.ca>
Change-Id: Ie1d43b75fa7281933d9225bffd388462c08a5f31
pull/8548/head
Andrew Dunham 1 year ago
parent cd313e410b
commit 60ab8089ff

@ -342,7 +342,7 @@ func run() error {
} }
sys.Set(netMon) sys.Set(netMon)
pol := logpolicy.New(logtail.CollectionNode, netMon) pol := logpolicy.New(logtail.CollectionNode, netMon, nil /* use log.Printf */)
pol.SetVerbosityLevel(args.verbose) pol.SetVerbosityLevel(args.verbose)
logPol = pol logPol = pol
defer func() { defer func() {

@ -37,7 +37,7 @@ func (s *Server) handleProxyConnectConn(w http.ResponseWriter, r *http.Request)
return return
} }
dialContext := logpolicy.MakeDialFunc(s.netMon) dialContext := logpolicy.MakeDialFunc(s.netMon, s.logf)
back, err := dialContext(ctx, "tcp", hostPort) back, err := dialContext(ctx, "tcp", hostPort)
if err != nil { if err != nil {
s.logf("error CONNECT dialing %v: %v", hostPort, err) s.logf("error CONNECT dialing %v: %v", hostPort, err)

@ -114,7 +114,7 @@ func NewLogger(logdir string, logf logger.Logf, logID logid.PublicID, netMon *ne
logger := &Logger{ logger := &Logger{
logf: logf, logf: logf,
filch: filch, filch: filch,
tr: logpolicy.NewLogtailTransport(logtail.DefaultHost, netMon), tr: logpolicy.NewLogtailTransport(logtail.DefaultHost, netMon, logf),
} }
logger.logger = logtail.NewLogger(logtail.Config{ logger.logger = logtail.NewLogger(logtail.Config{
BaseURL: logpolicy.LogURL(), BaseURL: logpolicy.LogURL(),

@ -110,6 +110,8 @@ type Policy struct {
Logtail *logtail.Logger Logtail *logtail.Logger
// PublicID is the logger's instance identifier. // PublicID is the logger's instance identifier.
PublicID logid.PublicID PublicID logid.PublicID
// Logf is where to write informational messages about this Logger.
Logf logger.Logf
} }
// NewConfig creates a Config with collection and a newly generated PrivateID. // NewConfig creates a Config with collection and a newly generated PrivateID.
@ -310,7 +312,7 @@ func winProgramDataAccessible(dir string) bool {
// log state for that command exists in dir, then the log state is // log state for that command exists in dir, then the log state is
// moved from wherever it does exist, into dir. Leftover logs state // moved from wherever it does exist, into dir. Leftover logs state
// in / and $CACHE_DIRECTORY is deleted. // in / and $CACHE_DIRECTORY is deleted.
func tryFixLogStateLocation(dir, cmdname string) { func tryFixLogStateLocation(dir, cmdname string, logf logger.Logf) {
switch runtime.GOOS { switch runtime.GOOS {
case "linux", "freebsd", "openbsd": case "linux", "freebsd", "openbsd":
// These are the OSes where we might have written stuff into // These are the OSes where we might have written stuff into
@ -320,13 +322,13 @@ func tryFixLogStateLocation(dir, cmdname string) {
return return
} }
if cmdname == "" { if cmdname == "" {
log.Printf("[unexpected] no cmdname given to tryFixLogStateLocation, please file a bug at https://github.com/tailscale/tailscale") logf("[unexpected] no cmdname given to tryFixLogStateLocation, please file a bug at https://github.com/tailscale/tailscale")
return return
} }
if dir == "/" { if dir == "/" {
// Trying to store things in / still. That's a bug, but don't // Trying to store things in / still. That's a bug, but don't
// abort hard. // abort hard.
log.Printf("[unexpected] storing logging config in /, please file a bug at https://github.com/tailscale/tailscale") logf("[unexpected] storing logging config in /, please file a bug at https://github.com/tailscale/tailscale")
return return
} }
if os.Getuid() != 0 { if os.Getuid() != 0 {
@ -383,7 +385,7 @@ func tryFixLogStateLocation(dir, cmdname string) {
existsInRoot, err := checkExists("/") existsInRoot, err := checkExists("/")
if err != nil { if err != nil {
log.Printf("checking for configs in /: %v", err) logf("checking for configs in /: %v", err)
return return
} }
existsInCache := false existsInCache := false
@ -391,12 +393,12 @@ func tryFixLogStateLocation(dir, cmdname string) {
if cacheDir != "" { if cacheDir != "" {
existsInCache, err = checkExists("/var/cache/tailscale") existsInCache, err = checkExists("/var/cache/tailscale")
if err != nil { if err != nil {
log.Printf("checking for configs in %s: %v", cacheDir, err) logf("checking for configs in %s: %v", cacheDir, err)
} }
} }
existsInDest, err := checkExists(dir) existsInDest, err := checkExists(dir)
if err != nil { if err != nil {
log.Printf("checking for configs in %s: %v", dir, err) logf("checking for configs in %s: %v", dir, err)
return return
} }
@ -411,13 +413,13 @@ func tryFixLogStateLocation(dir, cmdname string) {
// CACHE_DIRECTORY takes precedence over /, move files from // CACHE_DIRECTORY takes precedence over /, move files from
// there. // there.
if err := moveFiles(cacheDir); err != nil { if err := moveFiles(cacheDir); err != nil {
log.Print(err) logf("%v", err)
return return
} }
case existsInRoot: case existsInRoot:
// Files from root is better than nothing. // Files from root is better than nothing.
if err := moveFiles("/"); err != nil { if err := moveFiles("/"); err != nil {
log.Print(err) logf("%v", err)
return return
} }
} }
@ -439,27 +441,32 @@ func tryFixLogStateLocation(dir, cmdname string) {
if os.IsNotExist(err) { if os.IsNotExist(err) {
continue continue
} else if err != nil { } else if err != nil {
log.Printf("stat %q: %v", p, err) logf("stat %q: %v", p, err)
return return
} }
if err := os.Remove(p); err != nil { if err := os.Remove(p); err != nil {
log.Printf("rm %q: %v", p, err) logf("rm %q: %v", p, err)
} }
} }
} }
} }
// New returns a new log policy (a logger and its instance ID) for a // New returns a new log policy (a logger and its instance ID) for a given
// given collection name. // collection name.
// The netMon parameter is optional; if non-nil it's used to do faster interface lookups. //
func New(collection string, netMon *netmon.Monitor) *Policy { // The netMon parameter is optional; if non-nil it's used to do faster
return NewWithConfigPath(collection, "", "", netMon) // interface lookups.
//
// The logf parameter is optional; if non-nil, information logs (e.g. when
// migrating state) are sent to that logger, and global changes to the log
// package are avoided. If nil, logs will be printed using log.Printf.
func New(collection string, netMon *netmon.Monitor, logf logger.Logf) *Policy {
return NewWithConfigPath(collection, "", "", netMon, logf)
} }
// NewWithConfigPath is identical to New, // NewWithConfigPath is identical to New, but uses the specified directory and
// but uses the specified directory and command name. // command name. If either is empty, it derives them automatically.
// If either is empty, it derives them automatically. func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor, logf logger.Logf) *Policy {
func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor) *Policy {
var lflags int var lflags int
if term.IsTerminal(2) || runtime.GOOS == "windows" { if term.IsTerminal(2) || runtime.GOOS == "windows" {
lflags = 0 lflags = 0
@ -488,7 +495,12 @@ func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor)
if cmdName == "" { if cmdName == "" {
cmdName = version.CmdName() cmdName = version.CmdName()
} }
tryFixLogStateLocation(dir, cmdName)
useStdLogger := logf == nil
if useStdLogger {
logf = log.Printf
}
tryFixLogStateLocation(dir, cmdName, logf)
cfgPath := filepath.Join(dir, fmt.Sprintf("%s.log.conf", cmdName)) cfgPath := filepath.Join(dir, fmt.Sprintf("%s.log.conf", cmdName))
@ -556,7 +568,7 @@ func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor)
} }
return w return w
}, },
HTTPC: &http.Client{Transport: NewLogtailTransport(logtail.DefaultHost, netMon)}, HTTPC: &http.Client{Transport: NewLogtailTransport(logtail.DefaultHost, netMon, logf)},
} }
if collection == logtail.CollectionNode { if collection == logtail.CollectionNode {
conf.MetricsDelta = clientmetric.EncodeLogTailMetricsDelta conf.MetricsDelta = clientmetric.EncodeLogTailMetricsDelta
@ -565,13 +577,13 @@ func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor)
} }
if envknob.NoLogsNoSupport() || inTest() { if envknob.NoLogsNoSupport() || inTest() {
log.Println("You have disabled logging. Tailscale will not be able to provide support.") logf("You have disabled logging. Tailscale will not be able to provide support.")
conf.HTTPC = &http.Client{Transport: noopPretendSuccessTransport{}} conf.HTTPC = &http.Client{Transport: noopPretendSuccessTransport{}}
} else if val := getLogTarget(); val != "" { } else if val := getLogTarget(); val != "" {
log.Println("You have enabled a non-default log target. Doing without being told to by Tailscale staff or your network administrator will make getting support difficult.") logf("You have enabled a non-default log target. Doing without being told to by Tailscale staff or your network administrator will make getting support difficult.")
conf.BaseURL = val conf.BaseURL = val
u, _ := url.Parse(val) u, _ := url.Parse(val)
conf.HTTPC = &http.Client{Transport: NewLogtailTransport(u.Host, netMon)} conf.HTTPC = &http.Client{Transport: NewLogtailTransport(u.Host, netMon, logf)}
} }
filchOptions := filch.Options{ filchOptions := filch.Options{
@ -588,7 +600,7 @@ func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor)
filchOptions.MaxFileSize = 1 << 20 filchOptions.MaxFileSize = 1 << 20
} else { } else {
// not a fatal error, we can leave the log files on the spinning disk // not a fatal error, we can leave the log files on the spinning disk
log.Printf("Unable to create /tmp directory for log storage: %v\n", err) logf("Unable to create /tmp directory for log storage: %v\n", err)
} }
} }
@ -599,7 +611,7 @@ func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor)
conf.Stderr = filchBuf.OrigStderr conf.Stderr = filchBuf.OrigStderr
} }
} }
lw := logtail.NewLogger(conf, log.Printf) lw := logtail.NewLogger(conf, logf)
var logOutput io.Writer = lw var logOutput io.Writer = lw
@ -612,24 +624,27 @@ func NewWithConfigPath(collection, dir, cmdName string, netMon *netmon.Monitor)
} }
} }
if useStdLogger {
log.SetFlags(0) // other log flags are set on console, not here log.SetFlags(0) // other log flags are set on console, not here
log.SetOutput(logOutput) log.SetOutput(logOutput)
}
log.Printf("Program starting: v%v, Go %v: %#v", logf("Program starting: v%v, Go %v: %#v",
version.Long(), version.Long(),
goVersion(), goVersion(),
os.Args) os.Args)
log.Printf("LogID: %v", newc.PublicID) logf("LogID: %v", newc.PublicID)
if filchErr != nil { if filchErr != nil {
log.Printf("filch failed: %v", filchErr) logf("filch failed: %v", filchErr)
} }
if earlyErrBuf.Len() != 0 { if earlyErrBuf.Len() != 0 {
log.Printf("%s", earlyErrBuf.Bytes()) logf("%s", earlyErrBuf.Bytes())
} }
return &Policy{ return &Policy{
Logtail: lw, Logtail: lw,
PublicID: newc.PublicID, PublicID: newc.PublicID,
Logf: logf,
} }
} }
@ -666,7 +681,7 @@ func (p *Policy) Close() {
// log upload if it can be done before ctx is canceled. // log upload if it can be done before ctx is canceled.
func (p *Policy) Shutdown(ctx context.Context) error { func (p *Policy) Shutdown(ctx context.Context) error {
if p.Logtail != nil { if p.Logtail != nil {
log.Printf("flushing log.") p.Logf("flushing log.")
return p.Logtail.Shutdown(ctx) return p.Logtail.Shutdown(ctx)
} }
return nil return nil
@ -680,14 +695,14 @@ func (p *Policy) Shutdown(ctx context.Context) error {
// for the benefit of older OS platforms which might not include it. // for the benefit of older OS platforms which might not include it.
// //
// The netMon parameter is optional; if non-nil it's used to do faster interface lookups. // The netMon parameter is optional; if non-nil it's used to do faster interface lookups.
func MakeDialFunc(netMon *netmon.Monitor) func(ctx context.Context, netw, addr string) (net.Conn, error) { func MakeDialFunc(netMon *netmon.Monitor, logf logger.Logf) func(ctx context.Context, netw, addr string) (net.Conn, error) {
return func(ctx context.Context, netw, addr string) (net.Conn, error) { return func(ctx context.Context, netw, addr string) (net.Conn, error) {
return dialContext(ctx, netw, addr, netMon) return dialContext(ctx, netw, addr, netMon, logf)
} }
} }
func dialContext(ctx context.Context, netw, addr string, netMon *netmon.Monitor) (net.Conn, error) { func dialContext(ctx context.Context, netw, addr string, netMon *netmon.Monitor, logf logger.Logf) (net.Conn, error) {
nd := netns.FromDialer(log.Printf, netMon, &net.Dialer{ nd := netns.FromDialer(logf, netMon, &net.Dialer{
Timeout: 30 * time.Second, Timeout: 30 * time.Second,
KeepAlive: netknob.PlatformTCPKeepAlive(), KeepAlive: netknob.PlatformTCPKeepAlive(),
}) })
@ -708,7 +723,7 @@ func dialContext(ctx context.Context, netw, addr string, netMon *netmon.Monitor)
err = errors.New(res.Status) err = errors.New(res.Status)
} }
if err != nil { if err != nil {
log.Printf("logtail: CONNECT response error from tailscaled: %v", err) logf("logtail: CONNECT response error from tailscaled: %v", err)
c.Close() c.Close()
} else { } else {
dialLog.Printf("connected via tailscaled") dialLog.Printf("connected via tailscaled")
@ -718,25 +733,29 @@ func dialContext(ctx context.Context, netw, addr string, netMon *netmon.Monitor)
} }
// If we failed to dial, try again with bootstrap DNS. // If we failed to dial, try again with bootstrap DNS.
log.Printf("logtail: dial %q failed: %v (in %v), trying bootstrap...", addr, err, d) logf("logtail: dial %q failed: %v (in %v), trying bootstrap...", addr, err, d)
dnsCache := &dnscache.Resolver{ dnsCache := &dnscache.Resolver{
Forward: dnscache.Get().Forward, // use default cache's forwarder Forward: dnscache.Get().Forward, // use default cache's forwarder
UseLastGood: true, UseLastGood: true,
LookupIPFallback: dnsfallback.MakeLookupFunc(log.Printf, netMon), LookupIPFallback: dnsfallback.MakeLookupFunc(logf, netMon),
NetMon: netMon, NetMon: netMon,
} }
dialer := dnscache.Dialer(nd.DialContext, dnsCache) dialer := dnscache.Dialer(nd.DialContext, dnsCache)
c, err = dialer(ctx, netw, addr) c, err = dialer(ctx, netw, addr)
if err == nil { if err == nil {
log.Printf("logtail: bootstrap dial succeeded") logf("logtail: bootstrap dial succeeded")
} }
return c, err return c, err
} }
// NewLogtailTransport returns an HTTP Transport particularly suited to uploading // NewLogtailTransport returns an HTTP Transport particularly suited to uploading
// logs to the given host name. See DialContext for details on how it works. // logs to the given host name. See DialContext for details on how it works.
//
// The netMon parameter is optional; if non-nil it's used to do faster interface lookups. // The netMon parameter is optional; if non-nil it's used to do faster interface lookups.
func NewLogtailTransport(host string, netMon *netmon.Monitor) http.RoundTripper { //
// The logf parameter is optional; if non-nil, logs are printed using the
// provided function; if nil, log.Printf will be used instead.
func NewLogtailTransport(host string, netMon *netmon.Monitor, logf logger.Logf) http.RoundTripper {
if inTest() { if inTest() {
return noopPretendSuccessTransport{} return noopPretendSuccessTransport{}
} }
@ -752,7 +771,10 @@ func NewLogtailTransport(host string, netMon *netmon.Monitor) http.RoundTripper
tr.DisableCompression = true tr.DisableCompression = true
// Log whenever we dial: // Log whenever we dial:
tr.DialContext = MakeDialFunc(netMon) if logf == nil {
logf = log.Printf
}
tr.DialContext = MakeDialFunc(netMon, logf)
// We're contacting exactly 1 hostname, so the default's 100 // We're contacting exactly 1 hostname, so the default's 100
// max idle conns is very high for our needs. Even 2 is // max idle conns is very high for our needs. Even 2 is

@ -641,7 +641,7 @@ func (s *Server) startLogger(closePool *closeOnErrorPool) error {
} }
return w return w
}, },
HTTPC: &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost, s.netMon)}, HTTPC: &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost, s.netMon, s.logf)},
} }
s.logtail = logtail.NewLogger(c, s.logf) s.logtail = logtail.NewLogger(c, s.logf)
closePool.addFunc(func() { s.logtail.Shutdown(context.Background()) }) closePool.addFunc(func() { s.logtail.Shutdown(context.Background()) })

@ -101,7 +101,7 @@ func (nl *Logger) Startup(nodeID tailcfg.StableNodeID, nodeLogID, domainLogID lo
} }
// Startup a log stream to Tailscale's logging service. // Startup a log stream to Tailscale's logging service.
httpc := &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost, netMon)} httpc := &http.Client{Transport: logpolicy.NewLogtailTransport(logtail.DefaultHost, netMon, nl.logger.Logf)}
if testClient != nil { if testClient != nil {
httpc = testClient httpc = testClient
} }

Loading…
Cancel
Save