1
0
mirror of https://blitiri.com.ar/repos/chasquid synced 2026-01-26 20:35:56 +00:00

log: Replace glog with a new logging module

glog works fine and has great features, but it does not play along well
with systemd or standard log rotators (as it does the rotation itself).

So this patch replaces glog with a new logging module "log", which by
default logs to stderr, in a systemd-friendly manner.

Logging to files or syslog is still supported.
This commit is contained in:
Alberto Bertogli
2016-10-24 03:02:11 +01:00
parent 60ed30e95a
commit 60a7932bd3
19 changed files with 446 additions and 138 deletions

View File

@@ -8,7 +8,8 @@ import (
"io/ioutil"
"os"
"github.com/golang/glog"
"blitiri.com.ar/go/chasquid/internal/log"
"github.com/golang/protobuf/proto"
)
@@ -18,14 +19,14 @@ func Load(path string) (*Config, error) {
buf, err := ioutil.ReadFile(path)
if err != nil {
glog.Errorf("Failed to read config at %q", path)
glog.Errorf(" (%v)", err)
log.Errorf("Failed to read config at %q", path)
log.Errorf(" (%v)", err)
return nil, err
}
err = proto.UnmarshalText(string(buf), c)
if err != nil {
glog.Errorf("Error parsing config: %v", err)
log.Errorf("Error parsing config: %v", err)
return nil, err
}
@@ -34,7 +35,7 @@ func Load(path string) (*Config, error) {
if c.Hostname == "" {
c.Hostname, err = os.Hostname()
if err != nil {
glog.Errorf("Could not get hostname: %v", err)
log.Errorf("Could not get hostname: %v", err)
return nil, err
}
}
@@ -78,15 +79,15 @@ func Load(path string) (*Config, error) {
}
func LogConfig(c *Config) {
glog.Infof("Configuration:")
glog.Infof(" Hostname: %q", c.Hostname)
glog.Infof(" Max data size (MB): %d", c.MaxDataSizeMb)
glog.Infof(" SMTP Addresses: %v", c.SmtpAddress)
glog.Infof(" Submission Addresses: %v", c.SubmissionAddress)
glog.Infof(" Monitoring address: %s", c.MonitoringAddress)
glog.Infof(" MDA: %s %v", c.MailDeliveryAgentBin, c.MailDeliveryAgentArgs)
glog.Infof(" Data directory: %s", c.DataDir)
glog.Infof(" Suffix separators: %s", c.SuffixSeparators)
glog.Infof(" Drop characters: %s", c.DropCharacters)
glog.Infof(" Mail log: %s", c.MailLogPath)
log.Infof("Configuration:")
log.Infof(" Hostname: %q", c.Hostname)
log.Infof(" Max data size (MB): %d", c.MaxDataSizeMb)
log.Infof(" SMTP Addresses: %v", c.SmtpAddress)
log.Infof(" Submission Addresses: %v", c.SubmissionAddress)
log.Infof(" Monitoring address: %s", c.MonitoringAddress)
log.Infof(" MDA: %s %v", c.MailDeliveryAgentBin, c.MailDeliveryAgentArgs)
log.Infof(" Data directory: %s", c.DataDir)
log.Infof(" Suffix separators: %s", c.SuffixSeparators)
log.Infof(" Drop characters: %s", c.DropCharacters)
log.Infof(" Mail log: %s", c.MailLogPath)
}

View File

@@ -8,7 +8,6 @@ import (
"os"
"time"
"github.com/golang/glog"
"golang.org/x/net/idna"
"blitiri.com.ar/go/chasquid/internal/domaininfo"
@@ -48,7 +47,7 @@ func (s *SMTP) Deliver(from string, to string, data []byte) (error, bool) {
tr.Debugf("%s -> %s", from, to)
toDomain := envelope.DomainOf(to)
mx, err := lookupMX(toDomain)
mx, err := lookupMX(tr, toDomain)
if err != nil {
// Note this is considered a permanent error.
// This is in line with what other servers (Exim) do. However, the
@@ -162,7 +161,7 @@ retry:
return nil, false
}
func lookupMX(domain string) (string, error) {
func lookupMX(tr *trace.Trace, domain string) (string, error) {
if v, ok := fakeMX[domain]; ok {
return v, nil
}
@@ -175,10 +174,11 @@ func lookupMX(domain string) (string, error) {
mxs, err := net.LookupMX(domain)
if err == nil {
if len(mxs) == 0 {
glog.Infof("domain %q has no MX, falling back to A", domain)
tr.Printf("domain %q has no MX, falling back to A", domain)
return domain, nil
}
tr.Printf("MX %s", mxs[0].Host)
return mxs[0].Host, nil
}
@@ -188,6 +188,7 @@ func lookupMX(domain string) (string, error) {
// For now, if the error is permanent, we assume it's because there was no
// MX and fall back, otherwise we return.
// TODO: Find a better way to do this.
tr.Errorf("MX lookup error: %v", err)
dnsErr, ok := err.(*net.DNSError)
if !ok {
return "", err

249
internal/log/log.go Normal file
View File

@@ -0,0 +1,249 @@
// Package log implements a simple logger.
//
// It implements an API somewhat similar to "github.com/google/glog" with a
// focus towards logging to stderr, which is useful for systemd-based
// environments.
//
// There are command line flags (defined using the flag package) to control
// the behaviour of the default logger. By default, it will write to stderr
// without timestamps; this is suitable for systemd (or equivalent) logging.
package log
import (
"flag"
"fmt"
"io"
"log/syslog"
"os"
"path/filepath"
"runtime"
"strconv"
"strings"
"sync"
"time"
)
// Flags that control the default logging.
var (
vLevel = flag.Int("v", 0, "Verbosity level (1 = debug)")
logFile = flag.String("logfile", "",
"file to log to (enables logtime)")
logToSyslog = flag.String("logtosyslog", "",
"log to syslog, with the given tag")
logTime = flag.Bool("logtime", false,
"include the time when writing the log to stderr")
alsoLogToStderr = flag.Bool("alsologtostderr", false,
"also log to stderr, in addition to the file")
)
// Logging levels.
type Level int
const (
Error = Level(-1)
Info = Level(0)
Debug = Level(1)
)
var levelToLetter = map[Level]string{
Error: "E",
Info: "_",
Debug: ".",
}
// A Logger represents a logging object that writes logs to the given writer.
type Logger struct {
Level Level
LogTime bool
CallerSkip int
w io.WriteCloser
sync.Mutex
}
func New(w io.WriteCloser) *Logger {
return &Logger{
w: w,
CallerSkip: 0,
Level: Info,
LogTime: true,
}
}
func NewFile(path string) (*Logger, error) {
f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
if err != nil {
return nil, err
}
l := New(f)
l.LogTime = true
return l, nil
}
func NewSyslog(priority syslog.Priority, tag string) (*Logger, error) {
w, err := syslog.New(priority, tag)
if err != nil {
return nil, err
}
l := New(w)
l.LogTime = false
return l, nil
}
func (l *Logger) Close() {
l.w.Close()
}
func (l *Logger) V(level Level) bool {
return level <= l.Level
}
func (l *Logger) Log(level Level, skip int, format string, a ...interface{}) {
if !l.V(level) {
return
}
// Message.
msg := fmt.Sprintf(format, a...)
// Caller.
_, file, line, ok := runtime.Caller(1 + l.CallerSkip + skip)
if !ok {
file = "unknown"
}
fl := fmt.Sprintf("%s:%-4d", filepath.Base(file), line)
if len(fl) > 18 {
fl = fl[len(fl)-18:]
}
msg = fmt.Sprintf("%-18s", fl) + " " + msg
// Level.
letter, ok := levelToLetter[level]
if !ok {
letter = strconv.Itoa(int(level))
}
msg = letter + " " + msg
// Time.
if l.LogTime {
msg = time.Now().Format("20060102 15:04:05.000000 ") + msg
}
if !strings.HasSuffix(msg, "\n") {
msg += "\n"
}
l.Lock()
l.w.Write([]byte(msg))
l.Unlock()
}
func (l *Logger) Debugf(format string, a ...interface{}) {
l.Log(Debug, 1, format, a...)
}
func (l *Logger) Infof(format string, a ...interface{}) {
l.Log(Info, 1, format, a...)
}
func (l *Logger) Errorf(format string, a ...interface{}) error {
l.Log(Error, 1, format, a...)
return fmt.Errorf(format, a...)
}
func (l *Logger) Fatalf(format string, a ...interface{}) {
l.Log(-2, 1, format, a...)
// TODO: Log traceback?
os.Exit(1)
}
// The default logger, used by the top-level functions below.
var Default = &Logger{
w: os.Stderr,
CallerSkip: 1,
Level: Info,
LogTime: false,
}
// Init the default logger, based on the command-line flags.
// Must be called after flag.Parse().
func Init() {
var err error
if *logToSyslog != "" {
Default, err = NewSyslog(syslog.LOG_DAEMON|syslog.LOG_INFO, *logToSyslog)
if err != nil {
panic(err)
}
} else if *logFile != "" {
Default, err = NewFile(*logFile)
if err != nil {
panic(err)
}
*logTime = true
}
if *alsoLogToStderr && Default.w != os.Stderr {
Default.w = multiWriteCloser(Default.w, os.Stderr)
}
Default.CallerSkip = 1
Default.Level = Level(*vLevel)
Default.LogTime = *logTime
}
func V(level Level) bool {
return Default.V(level)
}
func Log(level Level, skip int, format string, a ...interface{}) {
Default.Log(level, skip, format, a...)
}
func Debugf(format string, a ...interface{}) {
Default.Debugf(format, a...)
}
func Infof(format string, a ...interface{}) {
Default.Infof(format, a...)
}
func Errorf(format string, a ...interface{}) error {
return Default.Errorf(format, a...)
}
func Fatalf(format string, a ...interface{}) {
Default.Fatalf(format, a...)
}
// multiWriteCloser creates a WriteCloser that duplicates its writes and
// closes to all the provided writers.
func multiWriteCloser(wc ...io.WriteCloser) io.WriteCloser {
return mwc(wc)
}
type mwc []io.WriteCloser
func (m mwc) Write(p []byte) (n int, err error) {
for _, w := range m {
if n, err = w.Write(p); err != nil {
return
}
}
return
}
func (m mwc) Close() error {
for _, w := range m {
if err := w.Close(); err != nil {
return err
}
}
return nil
}

104
internal/log/log_test.go Normal file
View File

@@ -0,0 +1,104 @@
package log
import (
"io/ioutil"
"os"
"regexp"
"testing"
)
func mustNewFile(t *testing.T) (string, *Logger) {
f, err := ioutil.TempFile("", "log_test-")
if err != nil {
t.Fatalf("failed to create temp file: %v", err)
}
l, err := NewFile(f.Name())
if err != nil {
t.Fatalf("failed to open new log file: %v", err)
}
return f.Name(), l
}
func checkContentsMatch(t *testing.T, name, path, expected string) {
content, err := ioutil.ReadFile(path)
if err != nil {
panic(err)
}
got := string(content)
if !regexp.MustCompile(expected).Match(content) {
t.Errorf("%s: regexp %q did not match %q",
name, expected, got)
}
}
func testLogger(t *testing.T, fname string, l *Logger) {
l.LogTime = false
l.Infof("message %d", 1)
checkContentsMatch(t, "info-no-time", fname,
"^_ log_test.go:.... message 1\n")
os.Truncate(fname, 0)
l.Infof("message %d\n", 1)
checkContentsMatch(t, "info-with-newline", fname,
"^_ log_test.go:.... message 1\n")
os.Truncate(fname, 0)
l.LogTime = true
l.Infof("message %d", 1)
checkContentsMatch(t, "info-with-time", fname,
`^\d{8} ..:..:..\.\d{6} _ log_test.go:.... message 1\n`)
os.Truncate(fname, 0)
l.LogTime = false
l.Errorf("error %d", 1)
checkContentsMatch(t, "error", fname, `^E log_test.go:.... error 1\n`)
if l.V(Debug) {
t.Fatalf("Debug level enabled by default (level: %v)", l.Level)
}
os.Truncate(fname, 0)
l.LogTime = false
l.Debugf("debug %d", 1)
checkContentsMatch(t, "debug-no-log", fname, `^$`)
os.Truncate(fname, 0)
l.Level = Debug
l.Debugf("debug %d", 1)
checkContentsMatch(t, "debug", fname, `^\. log_test.go:.... debug 1\n`)
if !l.V(Debug) {
t.Errorf("l.Level = Debug, but V(Debug) = false")
}
os.Truncate(fname, 0)
l.Level = Info
l.Log(Debug, 0, "log debug %d", 1)
l.Log(Info, 0, "log info %d", 1)
checkContentsMatch(t, "log", fname,
`^_ log_test.go:.... log info 1\n`)
}
func TestBasic(t *testing.T) {
fname, l := mustNewFile(t)
defer l.Close()
defer os.Remove(fname)
testLogger(t, fname, l)
}
func TestDefaultFile(t *testing.T) {
fname, l := mustNewFile(t)
l.Close()
defer os.Remove(fname)
*logFile = fname
Init()
testLogger(t, fname, Default)
}

View File

@@ -10,8 +10,7 @@ import (
"sync"
"time"
"github.com/golang/glog"
"blitiri.com.ar/go/chasquid/internal/log"
"blitiri.com.ar/go/chasquid/internal/trace"
)
@@ -53,8 +52,8 @@ func (l *Logger) printf(format string, args ...interface{}) {
_, err := fmt.Fprintf(l.w, format, args...)
if err != nil {
l.once.Do(func() {
glog.Errorf("failed to write to maillog: %v", err)
glog.Error("(will not report this again)")
log.Errorf("failed to write to maillog: %v", err)
log.Errorf("(will not report this again)")
})
}
}

View File

@@ -24,12 +24,12 @@ import (
"blitiri.com.ar/go/chasquid/internal/aliases"
"blitiri.com.ar/go/chasquid/internal/courier"
"blitiri.com.ar/go/chasquid/internal/envelope"
"blitiri.com.ar/go/chasquid/internal/log"
"blitiri.com.ar/go/chasquid/internal/maillog"
"blitiri.com.ar/go/chasquid/internal/protoio"
"blitiri.com.ar/go/chasquid/internal/set"
"blitiri.com.ar/go/chasquid/internal/trace"
"github.com/golang/glog"
"github.com/golang/protobuf/ptypes"
"github.com/golang/protobuf/ptypes/timestamp"
"golang.org/x/net/idna"
@@ -139,7 +139,7 @@ func (q *Queue) Load() error {
for _, fname := range files {
item, err := ItemFromFile(fname)
if err != nil {
glog.Errorf("error loading queue item from %q: %v", fname, err)
log.Errorf("error loading queue item from %q: %v", fname, err)
continue
}
@@ -197,7 +197,7 @@ func (q *Queue) Put(from string, to []string, data []byte) (string, error) {
case aliases.PIPE:
r.Type = Recipient_PIPE
default:
glog.Errorf("unknown alias type %v when resolving %q",
log.Errorf("unknown alias type %v when resolving %q",
aliasRcpt.Type, t)
return "", fmt.Errorf("internal error - unknown alias type")
}
@@ -225,7 +225,7 @@ func (q *Queue) Remove(id string) {
path := fmt.Sprintf("%s/%s%s", q.path, itemFilePrefix, id)
err := os.Remove(path)
if err != nil {
glog.Errorf("failed to remove queue file %q: %v", path, err)
log.Errorf("failed to remove queue file %q: %v", path, err)
}
q.mu.Lock()

View File

@@ -11,11 +11,11 @@ import (
"blitiri.com.ar/go/chasquid/internal/aliases"
"blitiri.com.ar/go/chasquid/internal/courier"
"blitiri.com.ar/go/chasquid/internal/domaininfo"
"blitiri.com.ar/go/chasquid/internal/log"
"blitiri.com.ar/go/chasquid/internal/maillog"
"blitiri.com.ar/go/chasquid/internal/queue"
"blitiri.com.ar/go/chasquid/internal/set"
"blitiri.com.ar/go/chasquid/internal/userdb"
"github.com/golang/glog"
)
type Server struct {
@@ -111,12 +111,12 @@ func (s *Server) InitDomainInfo(dir string) *domaininfo.DB {
var err error
s.dinfo, err = domaininfo.New(dir)
if err != nil {
glog.Fatalf("Error opening domain info database: %v", err)
log.Fatalf("Error opening domain info database: %v", err)
}
err = s.dinfo.Load()
if err != nil {
glog.Fatalf("Error loading domain info database: %v", err)
log.Fatalf("Error loading domain info database: %v", err)
}
return s.dinfo
@@ -126,7 +126,7 @@ func (s *Server) InitQueue(path string, localC, remoteC courier.Courier) {
q := queue.New(path, s.localDomains, s.aliasesR, localC, remoteC, s.Hostname)
err := q.Load()
if err != nil {
glog.Fatalf("Error loading queue: %v", err)
log.Fatalf("Error loading queue: %v", err)
}
s.queue = q
@@ -142,13 +142,13 @@ func (s *Server) periodicallyReload() {
for range time.Tick(30 * time.Second) {
err := s.aliasesR.Reload()
if err != nil {
glog.Errorf("Error reloading aliases: %v", err)
log.Errorf("Error reloading aliases: %v", err)
}
for domain, udb := range s.userDBs {
err = udb.Reload()
if err != nil {
glog.Errorf("Error reloading %q user db: %v", domain, err)
log.Errorf("Error reloading %q user db: %v", domain, err)
}
}
}
@@ -165,10 +165,10 @@ func (s *Server) ListenAndServe() {
for _, addr := range addrs {
l, err := net.Listen("tcp", addr)
if err != nil {
glog.Fatalf("Error listening: %v", err)
log.Fatalf("Error listening: %v", err)
}
glog.Infof("Server listening on %s (%v)", addr, m)
log.Infof("Server listening on %s (%v)", addr, m)
maillog.Listening(addr)
go s.serve(l, m)
}
@@ -176,7 +176,7 @@ func (s *Server) ListenAndServe() {
for m, ls := range s.listeners {
for _, l := range ls {
glog.Infof("Server listening on %s (%v, via systemd)", l.Addr(), m)
log.Infof("Server listening on %s (%v, via systemd)", l.Addr(), m)
maillog.Listening(l.Addr().String())
go s.serve(l, m)
}
@@ -193,7 +193,7 @@ func (s *Server) serve(l net.Listener, mode SocketMode) {
for {
conn, err := l.Accept()
if err != nil {
glog.Fatalf("Error accepting: %v", err)
log.Fatalf("Error accepting: %v", err)
}
sc := &Conn{

View File

@@ -20,8 +20,6 @@ import (
"blitiri.com.ar/go/chasquid/internal/aliases"
"blitiri.com.ar/go/chasquid/internal/courier"
"blitiri.com.ar/go/chasquid/internal/userdb"
"github.com/golang/glog"
)
// Flags.
@@ -414,7 +412,6 @@ func waitForServer(addr string) error {
// os.Exit(). We have to do this so we can use defer.
func realMain(m *testing.M) int {
flag.Parse()
defer glog.Flush()
if *externalSMTPAddr != "" {
smtpAddr = *externalSMTPAddr

View File

@@ -5,7 +5,8 @@ import (
"fmt"
"strconv"
"github.com/golang/glog"
"blitiri.com.ar/go/chasquid/internal/log"
nettrace "golang.org/x/net/trace"
)
@@ -28,21 +29,15 @@ func New(family, title string) *Trace {
func (t *Trace) Printf(format string, a ...interface{}) {
t.t.LazyPrintf(format, a...)
if glog.V(0) {
msg := fmt.Sprintf("%s %s: %s", t.family, t.title,
quote(fmt.Sprintf(format, a...)))
glog.InfoDepth(1, msg)
}
log.Log(log.Info, 1, "%s %s: %s", t.family, t.title,
quote(fmt.Sprintf(format, a...)))
}
func (t *Trace) Debugf(format string, a ...interface{}) {
t.t.LazyPrintf(format, a...)
if glog.V(2) {
msg := fmt.Sprintf("%s %s: %s", t.family, t.title,
quote(fmt.Sprintf(format, a...)))
glog.InfoDepth(1, msg)
}
log.Log(log.Debug, 1, "%s %s: %s",
t.family, t.title, quote(fmt.Sprintf(format, a...)))
}
func (t *Trace) SetError() {
@@ -50,15 +45,13 @@ func (t *Trace) SetError() {
}
func (t *Trace) Errorf(format string, a ...interface{}) error {
// Note we can't just call t.Error here, as it breaks caller logging.
err := fmt.Errorf(format, a...)
t.t.SetError()
t.t.LazyPrintf("error: %v", err)
if glog.V(0) {
msg := fmt.Sprintf("%s %s: error: %s", t.family, t.title,
quote(err.Error()))
glog.InfoDepth(1, msg)
}
log.Log(log.Info, 1, "%s %s: error: %s", t.family, t.title,
quote(err.Error()))
return err
}
@@ -66,11 +59,9 @@ func (t *Trace) Error(err error) error {
t.t.SetError()
t.t.LazyPrintf("error: %v", err)
if glog.V(0) {
msg := fmt.Sprintf("%s %s: error: %v", t.family, t.title,
quote(err.Error()))
glog.InfoDepth(1, msg)
}
log.Log(log.Info, 1, "%s %s: error: %s", t.family, t.title,
quote(err.Error()))
return err
}
@@ -91,32 +82,24 @@ func NewEventLog(family, title string) *EventLog {
func (e *EventLog) Printf(format string, a ...interface{}) {
e.e.Printf(format, a...)
if glog.V(0) {
msg := fmt.Sprintf("%s %s: %s", e.family, e.title,
quote(fmt.Sprintf(format, a...)))
glog.InfoDepth(1, msg)
}
log.Log(log.Info, 1, "%s %s: %s", e.family, e.title,
quote(fmt.Sprintf(format, a...)))
}
func (e *EventLog) Debugf(format string, a ...interface{}) {
e.e.Printf(format, a...)
if glog.V(2) {
msg := fmt.Sprintf("%s %s: %s", e.family, e.title,
quote(fmt.Sprintf(format, a...)))
glog.InfoDepth(1, msg)
}
log.Log(log.Debug, 1, "%s %s: %s", e.family, e.title,
quote(fmt.Sprintf(format, a...)))
}
func (e *EventLog) Errorf(format string, a ...interface{}) error {
err := fmt.Errorf(format, a...)
e.e.Errorf("error: %v", err)
if glog.V(0) {
msg := fmt.Sprintf("%s %s: error: %s", e.family, e.title,
quote(err.Error()))
glog.InfoDepth(1, msg)
}
log.Log(log.Info, 1, "%s %s: error: %s",
e.family, e.title, quote(err.Error()))
return err
}