add own logging and define debug flag

Signed-off-by: Luca Bigliardi <shammash@google.com>
This commit is contained in:
Luca Bigliardi 2021-04-07 03:20:52 +02:00
parent dcfa3cccf0
commit 2eb5fb9aa5
11 changed files with 151 additions and 78 deletions

View File

@ -16,10 +16,11 @@ package main
import (
"context"
"log"
"math"
"math/rand"
"time"
"github.com/google/alertmanager-irc-relay/logging"
)
type JitterFunc func(int) int
@ -107,12 +108,12 @@ func (b *Backoff) Delay() {
func (b *Backoff) DelayContext(ctx context.Context) bool {
delay := b.GetDelay()
log.Printf("Backoff for %s starts", delay)
logging.Info("Backoff for %s starts", delay)
select {
case <-b.timeTeller.After(delay):
log.Printf("Backoff for %s ends", delay)
logging.Info("Backoff for %s ends", delay)
case <-ctx.Done():
log.Printf("Backoff for %s canceled by context", delay)
logging.Info("Backoff for %s canceled by context", delay)
return false
}
return true

View File

@ -16,10 +16,11 @@ package main
import (
"context"
"log"
"os"
"os/signal"
"sync"
"github.com/google/alertmanager-irc-relay/logging"
)
func WithSignal(ctx context.Context, s ...os.Signal) (context.Context, context.CancelFunc) {
@ -29,7 +30,7 @@ func WithSignal(ctx context.Context, s ...os.Signal) (context.Context, context.C
go func() {
select {
case <-c:
log.Printf("Received %s, exiting", s)
logging.Info("Received %s, exiting", s)
cancel()
case <-ctx.Done():
cancel()

View File

@ -16,8 +16,9 @@ package main
import (
"context"
"log"
"time"
"github.com/google/alertmanager-irc-relay/logging"
)
type FakeDelayerMaker struct{}
@ -39,11 +40,11 @@ func (f *FakeDelayer) Delay() {
}
func (f *FakeDelayer) DelayContext(ctx context.Context) bool {
log.Printf("Faking Backoff")
logging.Info("Faking Backoff")
if f.DelayOnChan {
log.Printf("Waiting StopDelay signal")
logging.Info("Waiting StopDelay signal")
<-f.StopDelay
log.Printf("Received StopDelay signal")
logging.Info("Received StopDelay signal")
}
return true
}

View File

@ -17,11 +17,11 @@ package main
import (
"bytes"
"encoding/json"
"log"
"net/url"
"strings"
"text/template"
"github.com/google/alertmanager-irc-relay/logging"
promtmpl "github.com/prometheus/alertmanager/template"
)
@ -56,9 +56,9 @@ func (f *Formatter) FormatMsg(ircChannel string, data interface{}) string {
if err := f.MsgTemplate.Execute(&output, data); err != nil {
msg_bytes, _ := json.Marshal(data)
msg = string(msg_bytes)
log.Printf("Could not apply msg template on alert (%s): %s",
logging.Error("Could not apply msg template on alert (%s): %s",
err, msg)
log.Printf("Sending raw alert")
logging.Warn("Sending raw alert")
alertHandlingErrors.WithLabelValues(ircChannel, "format_msg").Inc()
} else {
msg = output.String()

14
http.go
View File

@ -18,11 +18,11 @@ import (
"encoding/json"
"io"
"io/ioutil"
"log"
"net/http"
"strconv"
"strings"
"github.com/google/alertmanager-irc-relay/logging"
"github.com/gorilla/mux"
promtmpl "github.com/prometheus/alertmanager/template"
"github.com/prometheus/client_golang/prometheus"
@ -86,19 +86,19 @@ func (s *HTTPServer) RelayAlert(w http.ResponseWriter, r *http.Request) {
body, err := ioutil.ReadAll(io.LimitReader(r.Body, 1024*1024*1024))
if err != nil {
log.Printf("Could not get body: %s", err)
logging.Error("Could not get body: %s", err)
alertHandlingErrors.WithLabelValues(ircChannel, "read_body").Inc()
return
}
var alertMessage = promtmpl.Data{}
if err := json.Unmarshal(body, &alertMessage); err != nil {
log.Printf("Could not decode request body (%s): %s", err, body)
logging.Error("Could not decode request body (%s): %s", err, body)
alertHandlingErrors.WithLabelValues(ircChannel, "decode_body").Inc()
w.Header().Set("Content-Type", "application/json; charset=UTF-8")
w.WriteHeader(422) // Unprocessable entity
if err := json.NewEncoder(w).Encode(err); err != nil {
log.Printf("Could not write decoding error: %s", err)
logging.Error("Could not write decoding error: %s", err)
return
}
return
@ -110,7 +110,7 @@ func (s *HTTPServer) RelayAlert(w http.ResponseWriter, r *http.Request) {
case s.AlertMsgs <- alertMsg:
handledAlerts.WithLabelValues(ircChannel).Inc()
default:
log.Printf("Could not send this alert to the IRC routine: %s",
logging.Error("Could not send this alert to the IRC routine: %s",
alertMsg)
alertHandlingErrors.WithLabelValues(ircChannel, "internal_comm_channel_full").Inc()
}
@ -129,8 +129,8 @@ func (s *HTTPServer) Run() {
listenAddr := strings.Join(
[]string{s.Addr, strconv.Itoa(s.Port)}, ":")
log.Printf("Starting HTTP server")
logging.Info("Starting HTTP server")
if err := s.httpListener(listenAddr, router); err != nil {
log.Printf("Could not start http server: %s", err)
logging.Error("Could not start http server: %s", err)
}
}

42
irc.go
View File

@ -17,13 +17,13 @@ package main
import (
"context"
"crypto/tls"
"log"
"strconv"
"strings"
"sync"
"time"
irc "github.com/fluffle/goirc/client"
"github.com/google/alertmanager-irc-relay/logging"
"github.com/prometheus/client_golang/prometheus"
"github.com/prometheus/client_golang/prometheus/promauto"
)
@ -54,7 +54,7 @@ var (
)
func loggerHandler(_ *irc.Conn, line *irc.Line) {
log.Printf("Received: '%s'", line.Raw)
logging.Info("Received: '%s'", line.Raw)
}
func makeGOIRCConfig(config *Config) *irc.Config {
@ -137,13 +137,13 @@ func NewIRCNotifier(config *Config, alertMsgs chan AlertMsg, delayerMaker Delaye
func (n *IRCNotifier) registerHandlers() {
n.Client.HandleFunc(irc.CONNECTED,
func(*irc.Conn, *irc.Line) {
log.Printf("Session established")
logging.Info("Session established")
n.sessionUpSignal <- true
})
n.Client.HandleFunc(irc.DISCONNECTED,
func(*irc.Conn, *irc.Line) {
log.Printf("Disconnected from IRC")
logging.Info("Disconnected from IRC")
n.sessionDownSignal <- false
})
@ -161,16 +161,16 @@ func (n *IRCNotifier) MaybeIdentifyNick() {
// so it should work here as well.
currentNick := n.Client.Me().Nick
if currentNick != n.Nick {
log.Printf("My nick is '%s', sending GHOST to NickServ to get '%s'",
logging.Info("My nick is '%s', sending GHOST to NickServ to get '%s'",
currentNick, n.Nick)
n.Client.Privmsgf("NickServ", "GHOST %s %s", n.Nick,
n.NickPassword)
time.Sleep(n.NickservDelayWait)
log.Printf("Changing nick to '%s'", n.Nick)
logging.Info("Changing nick to '%s'", n.Nick)
n.Client.Nick(n.Nick)
}
log.Printf("Sending IDENTIFY to NickServ")
logging.Info("Sending IDENTIFY to NickServ")
n.Client.Privmsgf("NickServ", "IDENTIFY %s", n.NickPassword)
time.Sleep(n.NickservDelayWait)
}
@ -186,22 +186,22 @@ func (n *IRCNotifier) ChannelJoined(ctx context.Context, channel string) bool {
case <-waitJoined:
return true
case <-n.timeTeller.After(ircJoinWaitSecs * time.Second):
log.Printf("Channel %s not joined after %d seconds, giving bad news to caller", channel, ircJoinWaitSecs)
logging.Warn("Channel %s not joined after %d seconds, giving bad news to caller", channel, ircJoinWaitSecs)
return false
case <-ctx.Done():
log.Printf("Context canceled while waiting for join on channel %s", channel)
logging.Info("Context canceled while waiting for join on channel %s", channel)
return false
}
}
func (n *IRCNotifier) SendAlertMsg(ctx context.Context, alertMsg *AlertMsg) {
if !n.sessionUp {
log.Printf("Cannot send alert to %s : IRC not connected", alertMsg.Channel)
logging.Error("Cannot send alert to %s : IRC not connected", alertMsg.Channel)
ircSendMsgErrors.WithLabelValues(alertMsg.Channel, "not_connected").Inc()
return
}
if !n.ChannelJoined(ctx, alertMsg.Channel) {
log.Printf("Cannot send alert to %s : cannot join channel", alertMsg.Channel)
logging.Error("Cannot send alert to %s : cannot join channel", alertMsg.Channel)
ircSendMsgErrors.WithLabelValues(alertMsg.Channel, "not_joined").Inc()
return
}
@ -216,18 +216,18 @@ func (n *IRCNotifier) SendAlertMsg(ctx context.Context, alertMsg *AlertMsg) {
func (n *IRCNotifier) ShutdownPhase() {
if n.sessionUp {
log.Printf("IRC client connected, quitting")
logging.Info("IRC client connected, quitting")
n.Client.Quit("see ya")
log.Printf("Wait for IRC disconnect to complete")
logging.Info("Wait for IRC disconnect to complete")
select {
case <-n.sessionDownSignal:
case <-n.timeTeller.After(n.Client.Config().Timeout):
log.Printf("Timeout while waiting for IRC disconnect to complete, stopping anyway")
logging.Warn("Timeout while waiting for IRC disconnect to complete, stopping anyway")
}
n.sessionWg.Done()
}
log.Printf("IRC shutdown complete")
logging.Info("IRC shutdown complete")
}
func (n *IRCNotifier) ConnectedPhase(ctx context.Context) {
@ -241,21 +241,21 @@ func (n *IRCNotifier) ConnectedPhase(ctx context.Context) {
n.Client.Quit("see ya")
ircConnectedGauge.Set(0)
case <-ctx.Done():
log.Printf("IRC routine asked to terminate")
logging.Info("IRC routine asked to terminate")
}
}
func (n *IRCNotifier) SetupPhase(ctx context.Context) {
if !n.Client.Connected() {
log.Printf("Connecting to IRC %s", n.Client.Config().Server)
logging.Info("Connecting to IRC %s", n.Client.Config().Server)
if ok := n.BackoffCounter.DelayContext(ctx); !ok {
return
}
if err := n.Client.ConnectContext(WithWaitGroup(ctx, &n.sessionWg)); err != nil {
log.Printf("Could not connect to IRC: %s", err)
logging.Error("Could not connect to IRC: %s", err)
return
}
log.Printf("Connected to IRC server, waiting to establish session")
logging.Info("Connected to IRC server, waiting to establish session")
}
select {
case <-n.sessionUpSignal:
@ -265,9 +265,9 @@ func (n *IRCNotifier) SetupPhase(ctx context.Context) {
n.channelReconciler.Start(ctx)
ircConnectedGauge.Set(1)
case <-n.sessionDownSignal:
log.Printf("Receiving a session down before the session is up, this is odd")
logging.Warn("Receiving a session down before the session is up, this is odd")
case <-ctx.Done():
log.Printf("IRC routine asked to terminate")
logging.Info("IRC routine asked to terminate")
}
}

View File

@ -19,13 +19,13 @@ import (
"errors"
"fmt"
"io"
"log"
"net"
"strings"
"sync"
"testing"
irc "github.com/fluffle/goirc/client"
"github.com/google/alertmanager-irc-relay/logging"
)
type LineHandlerFunc func(*bufio.ReadWriter, *irc.Line) error
@ -93,7 +93,7 @@ func (s *testServer) handleLine(conn *bufio.ReadWriter, line *irc.Line) error {
s.Log = append(s.Log, strings.Trim(line.Raw, " \r\n"))
handler := s.getHandler(line.Cmd)
if handler == nil {
log.Printf("=Server= No handler for command '%s', skipping", line.Cmd)
logging.Info("=Server= No handler for command '%s', skipping", line.Cmd)
return nil
}
return handler(conn, line)
@ -110,21 +110,21 @@ func (s *testServer) handleConnection(conn net.Conn) {
msg, err := bufConn.ReadBytes('\n')
if err != nil {
if err == io.EOF {
log.Printf("=Server= Client %s disconnected", conn.RemoteAddr().String())
logging.Info("=Server= Client %s disconnected", conn.RemoteAddr().String())
} else {
log.Printf("=Server= Could not read from %s: %s", conn.RemoteAddr().String(), err)
logging.Info("=Server= Could not read from %s: %s", conn.RemoteAddr().String(), err)
}
return
}
log.Printf("=Server= Received %s", msg)
logging.Info("=Server= Received %s", msg)
line := irc.ParseLine(string(msg))
if line == nil {
log.Printf("=Server= Could not parse received line")
logging.Error("=Server= Could not parse received line")
continue
}
err = s.handleLine(bufConn, line)
if err != nil {
log.Printf("=Server= Closing connection: %s", err)
logging.Info("=Server= Closing connection: %s", err)
return
}
bufConn.Flush()
@ -136,7 +136,7 @@ func (s *testServer) SendMsg(msg string) error {
return errors.New("Cannot write without client connected")
}
bufConn := bufio.NewWriter(s.Client)
log.Printf("=Server= sending to client: %s", msg)
logging.Info("=Server= sending to client: %s", msg)
_, err := bufConn.WriteString(msg)
bufConn.Flush()
return err
@ -154,7 +154,7 @@ func (s *testServer) handleCloseEarly(conn net.Conn) bool {
if s.closeEarlyHandler == nil {
return false
}
log.Printf("=Server= Closing connection early")
logging.Info("=Server= Closing connection early")
conn.Close()
s.closeEarlyHandler()
return true
@ -165,10 +165,10 @@ func (s *testServer) Serve() {
for {
conn, err := s.Listener.Accept()
if err != nil {
log.Printf("=Server= Stopped accepting new connections")
logging.Info("=Server= Stopped accepting new connections")
return
}
log.Printf("=Server= New client connected from %s", conn.RemoteAddr().String())
logging.Info("=Server= New client connected from %s", conn.RemoteAddr().String())
if s.handleCloseEarly(conn) {
continue
}
@ -198,7 +198,7 @@ func makeTestServer(t *testing.T) (*testServer, int) {
t.Fatalf("=Server= Could not create listener: %s", err)
}
addr = listener.Addr().(*net.TCPAddr)
log.Printf("=Server= Test server listening on %s", addr.String())
logging.Info("=Server= Test server listening on %s", addr.String())
server.Listener = listener

View File

@ -18,7 +18,6 @@ import (
"bufio"
"context"
"fmt"
"log"
"reflect"
"strings"
"sync"
@ -26,6 +25,7 @@ import (
"time"
irc "github.com/fluffle/goirc/client"
"github.com/google/alertmanager-irc-relay/logging"
)
func makeTestIRCConfig(IRCPort int) *Config {
@ -281,9 +281,9 @@ func TestSendAlertDisconnected(t *testing.T) {
testStep.Add(1)
holdUserStep.Add(1)
holdUser := func(conn *bufio.ReadWriter, line *irc.Line) error {
log.Printf("=Server= Wait before completing session")
logging.Info("=Server= Wait before completing session")
testStep.Wait()
log.Printf("=Server= Completing session")
logging.Info("=Server= Completing session")
holdUserStep.Done()
return hUSER(conn, line)
}
@ -564,7 +564,7 @@ func TestStopRunningWhenHalfConnected(t *testing.T) {
// session is not up
testStep.Add(1)
holdUser := func(conn *bufio.ReadWriter, line *irc.Line) error {
log.Printf("=Server= NOT completing session")
logging.Info("=Server= NOT completing session")
testStep.Done()
return nil
}

69
logging/logging.go Normal file
View File

@ -0,0 +1,69 @@
// Copyright 2021 Google LLC
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// https://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package logging
import (
"flag"
"fmt"
"log"
"os"
goirc_logging "github.com/fluffle/goirc/logging"
)
type Logger interface {
Debug(format string, args ...interface{})
Info(format string, args ...interface{})
Warn(format string, args ...interface{})
Error(format string, args ...interface{})
}
var logger Logger
type stdOutLogger struct {
out *log.Logger
}
var debugFlag = flag.Bool("debug", false, "Enable debug logging.")
func (l stdOutLogger) Debug(f string, a ...interface{}) {
if *debugFlag {
l.out.Output(3, fmt.Sprintf("DEBUG "+f, a...))
}
}
func (l stdOutLogger) Info(f string, a ...interface{}) {
l.out.Output(3, fmt.Sprintf("INFO "+f, a...))
}
func (l stdOutLogger) Warn(f string, a ...interface{}) {
l.out.Output(3, fmt.Sprintf("WARN "+f, a...))
}
func (l stdOutLogger) Error(f string, a ...interface{}) {
l.out.Output(3, fmt.Sprintf("ERROR "+f, a...))
}
func init() {
logger = stdOutLogger{
out: log.New(os.Stderr, "", log.Ldate|log.Lmicroseconds|log.Lshortfile),
}
goirc_logging.SetLogger(logger)
}
func Debug(f string, a ...interface{}) { logger.Debug(f, a...) }
func Info(f string, a ...interface{}) { logger.Info(f, a...) }
func Warn(f string, a ...interface{}) { logger.Warn(f, a...) }
func Error(f string, a ...interface{}) { logger.Error(f, a...) }

View File

@ -17,9 +17,10 @@ package main
import (
"context"
"flag"
"log"
"sync"
"syscall"
"github.com/google/alertmanager-irc-relay/logging"
)
func main() {
@ -33,7 +34,7 @@ func main() {
config, err := LoadConfig(*configFile)
if err != nil {
log.Printf("Could not load config: %s", err)
logging.Error("Could not load config: %s", err)
return
}
@ -42,14 +43,14 @@ func main() {
stopWg.Add(1)
ircNotifier, err := NewIRCNotifier(config, alertMsgs, &BackoffMaker{}, &RealTime{})
if err != nil {
log.Printf("Could not create IRC notifier: %s", err)
logging.Error("Could not create IRC notifier: %s", err)
return
}
go ircNotifier.Run(ctx, &stopWg)
httpServer, err := NewHTTPServer(config, alertMsgs)
if err != nil {
log.Printf("Could not create HTTP server: %s", err)
logging.Error("Could not create HTTP server: %s", err)
return
}
go httpServer.Run()

View File

@ -16,11 +16,11 @@ package main
import (
"context"
"log"
"sync"
"time"
irc "github.com/fluffle/goirc/client"
"github.com/google/alertmanager-irc-relay/logging"
)
const (
@ -70,11 +70,11 @@ func (c *channelState) SetJoined() {
defer c.mu.Unlock()
if c.joined == true {
log.Printf("Not setting JOIN state on channel %s: already set", c.channel.Name)
logging.Warn("Not setting JOIN state on channel %s: already set", c.channel.Name)
return
}
log.Printf("Setting JOIN state on channel %s", c.channel.Name)
logging.Info("Setting JOIN state on channel %s", c.channel.Name)
c.joined = true
close(c.joinDone)
}
@ -84,11 +84,11 @@ func (c *channelState) UnsetJoined() {
defer c.mu.Unlock()
if c.joined == false {
log.Printf("Not removing JOIN state on channel %s: already not set", c.channel.Name)
logging.Warn("Not removing JOIN state on channel %s: already not set", c.channel.Name)
return
}
log.Printf("Removing JOIN state on channel %s", c.channel.Name)
logging.Info("Removing JOIN state on channel %s", c.channel.Name)
c.joined = false
c.joinDone = make(chan struct{})
@ -100,30 +100,30 @@ func (c *channelState) UnsetJoined() {
}
func (c *channelState) join(ctx context.Context) {
log.Printf("Channel %s monitor: waiting to join", c.channel.Name)
logging.Info("Channel %s monitor: waiting to join", c.channel.Name)
if ok := c.delayer.DelayContext(ctx); !ok {
return
}
c.client.Join(c.channel.Name, c.channel.Password)
log.Printf("Channel %s monitor: join request sent", c.channel.Name)
logging.Info("Channel %s monitor: join request sent", c.channel.Name)
select {
case <-c.JoinDone():
log.Printf("Channel %s monitor: join succeeded", c.channel.Name)
logging.Info("Channel %s monitor: join succeeded", c.channel.Name)
case <-c.timeTeller.After(ircJoinWaitSecs * time.Second):
log.Printf("Channel %s monitor: could not join after %d seconds, will retry", c.channel.Name, ircJoinWaitSecs)
logging.Warn("Channel %s monitor: could not join after %d seconds, will retry", c.channel.Name, ircJoinWaitSecs)
case <-ctx.Done():
log.Printf("Channel %s monitor: context canceled while waiting for join", c.channel.Name)
logging.Info("Channel %s monitor: context canceled while waiting for join", c.channel.Name)
}
}
func (c *channelState) monitorJoinUnset(ctx context.Context) {
select {
case <-c.joinUnsetSignal:
log.Printf("Channel %s monitor: channel no longer joined", c.channel.Name)
logging.Info("Channel %s monitor: channel no longer joined", c.channel.Name)
case <-ctx.Done():
log.Printf("Channel %s monitor: context canceled while monitoring", c.channel.Name)
logging.Info("Channel %s monitor: context canceled while monitoring", c.channel.Name)
}
}
@ -195,11 +195,11 @@ func (r *ChannelReconciler) HandleJoin(nick string, channel string) {
// received join info for somebody else
return
}
log.Printf("Received JOIN confirmation for channel %s", channel)
logging.Info("Received JOIN confirmation for channel %s", channel)
c, ok := r.channels[channel]
if !ok {
log.Printf("Not processing JOIN for channel %s: unknown channel", channel)
logging.Warn("Not processing JOIN for channel %s: unknown channel", channel)
return
}
c.SetJoined()
@ -213,11 +213,11 @@ func (r *ChannelReconciler) HandleKick(nick string, channel string) {
// received kick info for somebody else
return
}
log.Printf("Received KICK for channel %s", channel)
logging.Info("Received KICK for channel %s", channel)
c, ok := r.channels[channel]
if !ok {
log.Printf("Not processing KICK for channel %s: unknown channel", channel)
logging.Warn("Not processing KICK for channel %s: unknown channel", channel)
return
}
c.UnsetJoined()
@ -239,7 +239,7 @@ func (r *ChannelReconciler) JoinChannel(channel string) (bool, <-chan struct{})
c, ok := r.channels[channel]
if !ok {
log.Printf("Request to JOIN new channel %s", channel)
logging.Info("Request to JOIN new channel %s", channel)
c = r.unsafeAddChannel(&IRCChannel{Name: channel})
}