From 2eb5fb9aa58dbcd560581812d15fb975920407c6 Mon Sep 17 00:00:00 2001 From: Luca Bigliardi Date: Wed, 7 Apr 2021 03:20:52 +0200 Subject: [PATCH] add own logging and define debug flag Signed-off-by: Luca Bigliardi --- backoff.go | 9 +++--- context.go | 5 +-- fake_delayer.go | 9 +++--- format.go | 6 ++-- http.go | 14 ++++----- irc.go | 42 ++++++++++++------------- irc_server_for_test.go | 24 +++++++-------- irc_test.go | 8 ++--- logging/logging.go | 69 ++++++++++++++++++++++++++++++++++++++++++ main.go | 9 +++--- reconciler.go | 34 ++++++++++----------- 11 files changed, 151 insertions(+), 78 deletions(-) create mode 100644 logging/logging.go diff --git a/backoff.go b/backoff.go index 2d40286..7ecafe3 100644 --- a/backoff.go +++ b/backoff.go @@ -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 diff --git a/context.go b/context.go index a829201..488303e 100644 --- a/context.go +++ b/context.go @@ -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() diff --git a/fake_delayer.go b/fake_delayer.go index 19b200a..1be3bf3 100644 --- a/fake_delayer.go +++ b/fake_delayer.go @@ -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 } diff --git a/format.go b/format.go index f5558e2..8d67714 100644 --- a/format.go +++ b/format.go @@ -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() diff --git a/http.go b/http.go index 507c77a..f3f6334 100644 --- a/http.go +++ b/http.go @@ -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) } } diff --git a/irc.go b/irc.go index dc049bc..7e09b82 100644 --- a/irc.go +++ b/irc.go @@ -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") } } diff --git a/irc_server_for_test.go b/irc_server_for_test.go index 2494ddc..2975ac0 100644 --- a/irc_server_for_test.go +++ b/irc_server_for_test.go @@ -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 diff --git a/irc_test.go b/irc_test.go index 968e5bf..0641114 100644 --- a/irc_test.go +++ b/irc_test.go @@ -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 } diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 0000000..7651202 --- /dev/null +++ b/logging/logging.go @@ -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...) } diff --git a/main.go b/main.go index 46cf21b..fe4c67c 100644 --- a/main.go +++ b/main.go @@ -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() diff --git a/reconciler.go b/reconciler.go index e372da2..683664e 100644 --- a/reconciler.go +++ b/reconciler.go @@ -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}) }