From 59e55ea0ff831c3285e98f380141d08f1d800c12 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Bj=C3=B8rn?= <bso@lunarway.com>
Date: Wed, 12 Feb 2020 16:08:04 +0100
Subject: [PATCH] Add additional logging (#18)

Should help us debug unnamed ikeSAs and all the connects and disconnects that
our metrics indicate.
---
 internal/strongswan/strongswan.go  | 9 +++++++--
 internal/tcpchecker/logreporter.go | 8 ++++----
 internal/tcpchecker/tcpchecker.go  | 4 ++--
 3 files changed, 13 insertions(+), 8 deletions(-)

diff --git a/internal/strongswan/strongswan.go b/internal/strongswan/strongswan.go
index c56c0ab..5d6fb21 100644
--- a/internal/strongswan/strongswan.go
+++ b/internal/strongswan/strongswan.go
@@ -54,7 +54,6 @@ func collectSasStats(configs []map[string]vici.IKEConf, sas []map[string]vici.Ik
 		}
 	}
 
-	log.Infof("Sas: %d", len(sas))
 	for _, sa := range sas {
 		for ikeName, ikeSa := range sa {
 			conf, ok := expectedConnections[ikeName]
@@ -62,12 +61,18 @@ func collectSasStats(configs []map[string]vici.IKEConf, sas []map[string]vici.Ik
 				log.Errorf("Unexpected SA: %s: %#v", ikeName, ikeSa)
 				continue
 			}
-			log.Infof("  ikeName: %s: sa: %#v", ikeName, ikeSa)
+			log.With("conf", conf).
+				With("sa", ikeSa).
+				With("ikeName", ikeName).
+				Infof("Reporting on ike name '%s'", ikeName)
 			reporter.IKESAStatus(ikeName, conf, &ikeSa)
 			delete(expectedConnections, ikeName)
 		}
 	}
 	for ikeName, conf := range expectedConnections {
+		log.With("conf", conf).
+			With("ikeName", ikeName).
+			Infof("Reporting config without active SAs on '%s'", ikeName)
 		reporter.IKESAStatus(ikeName, conf, nil)
 	}
 }
diff --git a/internal/tcpchecker/logreporter.go b/internal/tcpchecker/logreporter.go
index 9323e62..98cfe5c 100644
--- a/internal/tcpchecker/logreporter.go
+++ b/internal/tcpchecker/logreporter.go
@@ -13,6 +13,7 @@ type logReporter struct {
 }
 
 func (r *logReporter) ReportPortCheck(report Report) {
+	l := r.Logger.With("report", report)
 	switch {
 	case report.Open && r.lastOpen:
 		// Port is still open - great
@@ -20,23 +21,22 @@ func (r *logReporter) ReportPortCheck(report Report) {
 		// Port closed
 		r.lastReport = time.Now()
 		r.lastOpen = report.Open
-		r.Logger.
+		l.
 			With("status", "closed").
 			Infof("TCP connection to %s closed", report.Name)
 	case report.Open && !r.lastOpen:
 		// Port opened
 		r.lastReport = time.Now()
 		r.lastOpen = report.Open
-		r.Logger.
+		l.
 			With("status", "opened").
-			With("content", report.Content).
 			Infof("TCP connection to %s opened", report.Name)
 	case !report.Open && !r.lastOpen:
 		// Port still closed
 		if time.Since(r.lastReport) > 5*time.Minute {
 			r.lastReport = time.Now()
 			r.lastOpen = report.Open
-			r.Logger.
+			l.
 				With("status", "closed").
 				Infof("TCP connection to %s is still closed", report.Name)
 		}
diff --git a/internal/tcpchecker/tcpchecker.go b/internal/tcpchecker/tcpchecker.go
index 7b02368..88b8739 100644
--- a/internal/tcpchecker/tcpchecker.go
+++ b/internal/tcpchecker/tcpchecker.go
@@ -53,7 +53,7 @@ func Check(name string, address string, port int, reporter Reporter) {
 				Address: address,
 				Port:    port,
 				Open:    true,
-				Status:  "Open",
+				Status:  "Open (closed by us)",
 				Error:   nil,
 				Content: output.String(),
 			})
@@ -75,7 +75,7 @@ func Check(name string, address string, port int, reporter Reporter) {
 		Address: address,
 		Port:    port,
 		Open:    true,
-		Status:  "Open",
+		Status:  "Open (closed by peer)",
 		Error:   nil,
 		Content: output.String(),
 	})