logging.go

/*
bilies-go - Bulk Insert Logs Into ElasticSearch
Copyright (C) 2016 Adirelle <adirelle@gmail.com>

This program is free software: you can redistribute it and/or modify
it under the terms of the GNU General Public License as published by
the Free Software Foundation, either version 3 of the License, or
(at your option) any later version.

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

You should have received a copy of the GNU General Public License
along with this program.  If not, see <http://www.gnu.org/licenses/>.
*/

/*
Internal logging

Internal logging (i.e. messages generated by bilies-go) is done asynchronously.
By default, messages of level NOTICE and higher are written do the standard error.

The following switches control logging:

	-d --debug [default: false]
		Enable debug logging: write messages of level DEBUG and higher.

	-v --verbose [default: false]
		Enable verbose logging: write messages of level INFO and higher.

	--log-file=STRING [default: /dev/stderr]
		Write messages into the file PATH, instead of the standard error. CRITICAL messages are still written to standard error.

Sending HUP to bilies-go causes the logfile to be reopened.
*/
package main

import (
	"fmt"
	"io"
	"os"
	"os/signal"
	"sync"
	"syscall"
	"time"

	logging "github.com/op/go-logging"
	"github.com/spf13/pflag"
)

var (
	logger    = logging.MustGetLogger("github.com/Adirelle/bilies-go")
	logFile   string
	logWriter io.Closer

	logBufferPool sync.Pool

	debug bool
)

func init() {
	pflag.BoolVarP(&debug, "debug", "d", false, "Enable debug logging")
	pflag.BoolP("verbose", "v", false, "Enable verbose logging")
	pflag.StringVar(&logFile, "log-file", "", "Write the logs into the file")
}

// StartLogging setups logging and starts the asynchronous logger.
func SetupLogging() {

	logFormat := "%{time:2006-01-02T15:04:05.000} %{level:.3s}: %{message}"
	if debug {
		logFormat += " (%{shortfile} %{shortfunc})"
	}
	logging.SetFormatter(logging.MustStringFormatter(logFormat))

	var logDest io.WriteCloser = os.Stderr
	logger.Noticef("logFile=%q", logFile)
	if logFile != "" {
		logDest = NewAsyncWriter(NewReopenableWriter(logFile))
		logWriter = logDest
	} else {
		logFile = "/dev/stderr"
	}

	stderrBackend := logging.AddModuleLevel(logging.NewLogBackend(os.Stderr, "", 0))
	logging.SetBackend(logging.NewLogBackend(NewAsyncWriter(logDest), "", 0), stderrBackend)

	logLevel := logging.NOTICE
	if debug {
		logLevel = logging.DEBUG
	} else if verbose, err := pflag.CommandLine.GetBool("verbose"); err == nil && verbose {
		logLevel = logging.INFO
	}
	logging.SetLevel(logLevel, "")
	stderrBackend.SetLevel(logging.CRITICAL, "")

	logger.Noticef("Log settings: file=%s, level=%s, debug=%t", logFile, logging.GetLevel(""), debug)
}

func StopLogging() {
	if logWriter != nil {
		logWriter.Close()
		logWriter = nil
	}
}

// ReopenableWriter is a file writer that reopen its file on SIGHUP
type ReopenableWriter struct {
	path   string
	reopen chan os.Signal
	wc     io.WriteCloser
	sync.Mutex
}

// NewReopenableWriter creates a writer that reopen on SIGHUP signal.
func NewReopenableWriter(p string) io.WriteCloser {
	rw := ReopenableWriter{path: p, reopen: make(chan os.Signal)}
	go rw.run()
	return &rw
}

func (w *ReopenableWriter) Write(buf []byte) (int, error) {
	w.Lock()
	defer w.Unlock()
	if w.wc == nil {
		return os.Stderr.Write(buf)
	}
	return w.wc.Write(buf)
}

func (w *ReopenableWriter) Close() error {
	select {
	case <-w.reopen:
	default:
		close(w.reopen)
	}
	return nil
}

func (w *ReopenableWriter) run() {
	signal.Notify(w.reopen, syscall.SIGHUP)

	for running := true; running; {
		if err := w.open(); err != nil {
			logger.Errorf("Cannot open %s for writing, trying again in 5 seconds, reason: %s", w.path, err)
			time.Sleep(5 * time.Second)
			continue
		}

		_, running = <-w.reopen
		if running {
			logger.Noticef("Received SIGHUP, reopening %q", w.path)
		}

		w.close()
	}
}

func (w *ReopenableWriter) open() (err error) {
	w.Lock()
	defer w.Unlock()

	w.wc, err = os.OpenFile(w.path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0660)
	if err != nil {
		w.wc = nil
	}
	return
}

func (w *ReopenableWriter) close() (err error) {
	w.Lock()
	defer w.Unlock()
	if w.wc == os.Stderr {
		return
	}

	err = w.wc.Close()
	w.wc = os.Stderr
	return
}

// AsyncWriter is an empty struct that implements io.Writer
type AsyncWriter struct {
	underlying io.Writer
	input      chan []byte
	done       sync.WaitGroup
}

// NewAsyncWriter creates a new asynchronous writter for the specified writer.
func NewAsyncWriter(w io.Writer) io.WriteCloser {
	aw := AsyncWriter{w, make(chan []byte, 5), sync.WaitGroup{}}
	go aw.process()
	return &aw
}

func (w *AsyncWriter) process() {
	if c, ok := w.underlying.(io.Closer); ok {
		defer c.Close()
	}
	defer w.done.Done()
	w.done.Add(1)
	for buf := range w.input {
		if _, err := w.underlying.Write(buf); err != nil {
			fmt.Fprintf(os.Stderr, "Cannot write to file: %s\n", err)
		}
		logBufferPool.Put(buf[:0])
	}
}

// Write sends a copy of the buffer to the goroutines.
func (w *AsyncWriter) Write(buf []byte) (int, error) {
	l := len(buf)
	var logBuf []byte
	if pooled := logBufferPool.Get(); pooled != nil {
		logBuf = append(pooled.([]byte), buf...)
	} else {
		logBuf = make([]byte, l)
		copy(logBuf, buf)
	}
	w.input <- logBuf
	return l, nil
}

// Close stops the processing goroutines by closing the channel and waits for its completion.
func (w *AsyncWriter) Close() (err error) {
	if w.input != nil {
		close(w.input)
		w.done.Wait()
		w.input = nil
	}
	return
}