fix minor logging issues (#264)

* Silence terminal detection

* CI: debug helper for systemd units

* Fix minor logging issues

 - pre-create a file with chmod 0600, or change them if the file already exists
 - don't log fatal, panic .. twice to stderr
 - default log_mode = stdout
 - calling code from crowdsec/pkg/types would create an empty $LogDir/crowdsec.log (??),
   this dependency is removed

* fix metric parsing error

Pipfile

@@ -1,5 +1,5 @@
 [packages]
-pytest-cs = {ref = "0.7.13", git = "https://github.com/crowdsecurity/pytest-cs.git"}
+pytest-cs = {ref = "0.7.14", git = "https://github.com/crowdsecurity/pytest-cs.git"}
 pytest-dotenv = "0.5.2"
 pytest-dependency = "0.5.1"
 pexpect = "4.8.0"

Pipfile.lock

@@ -1,7 +1,7 @@
 {
     "_meta": {
         "hash": {
-            "sha256": "14be1a4d221d70c7a026430e5d5483ab0647c78fe980eea54f7e2eef80826050"
+            "sha256": "d14c7fa94d83226ad68a1e351795e589331a641dd4548e167977da2cbbea2100"
         },
         "pipfile-spec": 6,
         "requires": {
@@ -16,6 +16,14 @@
         ]
     },
     "default": {
+        "blinker": {
+            "hashes": [
+                "sha256:4afd3de66ef3a9f8067559fb7a1cbe555c17dcbe15971b05d1b625c3e7abe213",
+                "sha256:c3d739772abb7bc2860abf5f2ec284223d9ad5c76da018234f6f50d6f31ab1f0"
+            ],
+            "markers": "python_version >= '3.7'",
+            "version": "==1.6.2"
+        },
         "certifi": {
             "hashes": [
                 "sha256:35824b4c3a97115964b408844d64aa14db1cc518f6562e8d7261699d1350a9e3",
@@ -225,11 +233,11 @@
         },
         "flask": {
             "hashes": [
-                "sha256:7eb373984bf1c770023fce9db164ed0c3353cd0b53f130f4693da0ca756a2e6d",
-                "sha256:c0bec9477df1cb867e5a67c9e1ab758de9cb4a3e52dd70681f59fa40a62b3f2d"
+                "sha256:8ba2a854608fdd603b67dccd4514a46450132227fb9df40127a8d0c1de8769ec",
+                "sha256:a6059db4297106e5a64b3215fa16ae641822c1cb97ecb498573549b2478602cb"
             ],
             "index": "pypi",
-            "version": "==2.2.3"
+            "version": "==2.3.1"
         },
         "idna": {
             "hashes": [
@@ -387,7 +395,7 @@
         },
         "pytest-cs": {
             "git": "https://github.com/crowdsecurity/pytest-cs.git",
-            "ref": "bf6c63e4cdbc755fb5c7698be750671ec6864584"
+            "ref": "4bf6f42da3332104b709709202de81eb86d0f025"
         },
         "pytest-datadir": {
             "hashes": [
@@ -515,11 +523,11 @@
         },
         "werkzeug": {
             "hashes": [
-                "sha256:2e1ccc9417d4da358b9de6f174e3ac094391ea1d4fbef2d667865d819dfd0afe",
-                "sha256:56433961bc1f12533306c624f3be5e744389ac61d722175d543e1751285da612"
+                "sha256:340335057f72974d9281dbaf52c8090a9f9a59ba304ae814bf0656e6559c0020",
+                "sha256:3b6b46926d052b8ebca97c4dc73c12e47bdd07d57ab0600c039c3155450227bc"
             ],
-            "markers": "python_version >= '3.7'",
-            "version": "==2.2.3"
+            "markers": "python_version >= '3.8'",
+            "version": "==2.3.0"
         }
     },
     "develop": {

cmd/root.go

@@ -18,7 +18,6 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
 	log "github.com/sirupsen/logrus"
-	"github.com/sirupsen/logrus/hooks/writer"
 	"golang.org/x/sync/errgroup"
 
 	"github.com/crowdsecurity/cs-firewall-bouncer/pkg/backend"
@@ -142,14 +141,6 @@ func Execute() {
 		os.Exit(0)
 	}
 
-	log.AddHook(&writer.Hook{ // Send logs with level fatal to stderr
-		Writer: os.Stderr,
-		LogLevels: []log.Level{
-			log.PanicLevel,
-			log.FatalLevel,
-		},
-	})
-
 	log.Infof("crowdsec-firewall-bouncer %s", version.VersionStr())
 
 	if configPath == nil || *configPath == "" {
@@ -166,7 +157,9 @@ func Execute() {
 		log.Fatalf("unable to load configuration: %s", err)
 	}
 
-	cfg.ConfigureLogging(config)
+	if err = cfg.ConfigureLogging(config); err != nil {
+		log.Fatalf("unable to configure logging: %s", err)
+	}
 
 	if *verbose {
 		log.SetLevel(log.DebugLevel)
@@ -174,7 +167,7 @@ func Execute() {
 
 	backend, err := backend.NewBackend(config)
 	if err != nil {
-		log.Fatalf(err.Error())
+		log.Fatal(err)
 	}
 
 	if *testConfig {
@@ -183,7 +176,7 @@ func Execute() {
 	}
 
 	if err = backend.Init(); err != nil {
-		log.Fatalf(err.Error())
+		log.Fatal(err)
 	}
 	// No call to fatalf after this point
 	defer backendCleanup(backend)
@@ -196,7 +189,7 @@ func Execute() {
 	}
 	bouncer.UserAgent = fmt.Sprintf("%s/%s", name, version.VersionStr())
 	if err := bouncer.Init(); err != nil {
-		log.Errorf(err.Error())
+		log.Error(err)
 		return
 	}
 

pkg/cfg/config.go

@@ -5,11 +5,10 @@ import (
 	"io"
 
 	log "github.com/sirupsen/logrus"
-	"gopkg.in/natefinch/lumberjack.v2"
 	"gopkg.in/yaml.v2"
 
-	"github.com/crowdsecurity/crowdsec/pkg/types"
 	"github.com/crowdsecurity/crowdsec/pkg/yamlpatch"
+	"github.com/crowdsecurity/cs-firewall-bouncer/pkg/types"
 )
 
 type PrometheusConfig struct {
@@ -34,25 +33,25 @@ const (
 )
 
 type BouncerConfig struct {
-	Mode            string    `yaml:"mode"` // ipset,iptables,tc
-	PidDir          string    `yaml:"pid_dir"`
-	UpdateFrequency string    `yaml:"update_frequency"`
-	Daemon          bool      `yaml:"daemonize"`
-	LogMode         string    `yaml:"log_mode"`
-	LogDir          string    `yaml:"log_dir"`
-	LogLevel        log.Level `yaml:"log_level"`
-	CompressLogs    *bool     `yaml:"compress_logs,omitempty"`
-	LogMaxSize      int       `yaml:"log_max_size,omitempty"`
-	LogMaxFiles     int       `yaml:"log_max_files,omitempty"`
-	LogMaxAge       int       `yaml:"log_max_age,omitempty"`
-	DisableIPV6     bool      `yaml:"disable_ipv6"`
-	DenyAction      string    `yaml:"deny_action"`
-	DenyLog         bool      `yaml:"deny_log"`
-	DenyLogPrefix   string    `yaml:"deny_log_prefix"`
-	BlacklistsIpv4  string    `yaml:"blacklists_ipv4"`
-	BlacklistsIpv6  string    `yaml:"blacklists_ipv6"`
-	SetType         string    `yaml:"ipset_type"`
-	SetSize         int       `yaml:"ipset_size"`
+	Mode            string     `yaml:"mode"` // ipset,iptables,tc
+	PidDir          string     `yaml:"pid_dir"`
+	UpdateFrequency string     `yaml:"update_frequency"`
+	Daemon          bool       `yaml:"daemonize"`
+	LogMode         string     `yaml:"log_mode"`
+	LogDir          string     `yaml:"log_dir"`
+	LogLevel        *log.Level `yaml:"log_level"`
+	CompressLogs    *bool      `yaml:"compress_logs,omitempty"`
+	LogMaxSize      int        `yaml:"log_max_size,omitempty"`
+	LogMaxFiles     int        `yaml:"log_max_files,omitempty"`
+	LogMaxAge       int        `yaml:"log_max_age,omitempty"`
+	DisableIPV6     bool       `yaml:"disable_ipv6"`
+	DenyAction      string     `yaml:"deny_action"`
+	DenyLog         bool       `yaml:"deny_log"`
+	DenyLogPrefix   string     `yaml:"deny_log_prefix"`
+	BlacklistsIpv4  string     `yaml:"blacklists_ipv4"`
+	BlacklistsIpv6  string     `yaml:"blacklists_ipv6"`
+	SetType         string     `yaml:"ipset_type"`
+	SetSize         int        `yaml:"ipset_size"`
 
 	// specific to iptables, following https://github.com/crowdsecurity/cs-firewall-bouncer/issues/19
 	IptablesChains          []string `yaml:"iptables_chains"`
@@ -78,7 +77,6 @@ func MergedConfig(configPath string) ([]byte, error) {
 		return nil, err
 	}
 	return data, nil
-
 }
 
 func NewConfig(reader io.Reader) (*BouncerConfig, error) {
@@ -197,62 +195,16 @@ func nftablesConfig(config *BouncerConfig) error {
 	return nil
 }
 
-func ConfigureLogging(config *BouncerConfig) {
-	var LogOutput *lumberjack.Logger // io.Writer
-
-	/* Configure logging */
-	if err := types.SetDefaultLoggerConfig(config.LogMode, config.LogDir, config.LogLevel, config.LogMaxSize,
-		config.LogMaxFiles, config.LogMaxAge, config.CompressLogs, false); err != nil {
-		log.Fatal(err.Error())
-	}
-
-	if config.LogMode == "file" {
-		if config.LogDir == "" {
-			config.LogDir = "/var/log/"
-		}
-
-		_maxsize := 500
-
-		if config.LogMaxSize != 0 {
-			_maxsize = config.LogMaxSize
-		}
-
-		_maxfiles := 3
-
-		if config.LogMaxFiles != 0 {
-			_maxfiles = config.LogMaxFiles
-		}
-
-		_maxage := 30
-
-		if config.LogMaxAge != 0 {
-			_maxage = config.LogMaxAge
-		}
-
-		_compress := true
-
-		if config.CompressLogs != nil {
-			_compress = *config.CompressLogs
-		}
-
-		LogOutput = &lumberjack.Logger{
-			Filename:   config.LogDir + "/crowdsec-firewall-bouncer.log",
-			MaxSize:    _maxsize, // megabytes
-			MaxBackups: _maxfiles,
-			MaxAge:     _maxage,   // days
-			Compress:   _compress, // disabled by default
-		}
-		log.SetOutput(LogOutput)
-		log.SetFormatter(&log.TextFormatter{TimestampFormat: "02-01-2006 15:04:05", FullTimestamp: true})
-	}
-}
-
 func validateConfig(config BouncerConfig) error {
-	if config.Mode == "" || config.LogMode == "" {
-		return fmt.Errorf("config does not contain mode and log mode")
+	if config.Mode == "" {
+		return fmt.Errorf("config does not contain 'mode'")
 	}
 
-	if config.LogMode != "stdout" && config.LogMode != "file" {
+	switch config.LogMode {
+	case "":
+		config.LogMode = "stdout"
+	case "stdout", "file":
+	default:
 		return fmt.Errorf("log mode '%s' unknown, expecting 'file' or 'stdout'", config.LogMode)
 	}
 

pkg/cfg/fileperms.go

@@ -0,0 +1,44 @@
+package cfg
+
+import (
+	"fmt"
+	"os"
+	"path/filepath"
+)
+
+// setLogFilePermissions sets the permissions of the log file to 0600.
+// If the file does not exist, it will be created.
+// lumberjack will then respect our permissions.
+// https://github.com/natefinch/lumberjack/issues/82
+func setLogFilePermissions(logDir string, logFile string) (string, error) {
+	err := os.MkdirAll(logDir, 0755)
+	if err != nil {
+		return "", fmt.Errorf("failed to create log directory: %w", err)
+	}
+
+	logPath := filepath.Join(logDir, logFile)
+
+	st, err := os.Stat(logPath)
+	if err != nil {
+		if !os.IsNotExist(err) {
+			return "", fmt.Errorf("failed to check file existence: %w", err)
+		}
+		file, err := os.OpenFile(logPath, os.O_CREATE|os.O_WRONLY, 0600)
+		if err != nil {
+			return "", fmt.Errorf("failed to create file: %w", err)
+		}
+		file.Close()
+		return logPath, nil
+	}
+
+	if st.IsDir() {
+		return "", fmt.Errorf("expected a file, found a directory: %s", logPath)
+	}
+
+	err = os.Chmod(logPath, 0600)
+	if err != nil {
+		return "", fmt.Errorf("failed to change file permissions: %w", err)
+	}
+
+	return logPath, nil
+}

pkg/cfg/logging.go

@@ -0,0 +1,103 @@
+package cfg
+
+import (
+	"os"
+
+	log "github.com/sirupsen/logrus"
+	"github.com/sirupsen/logrus/hooks/writer"
+
+	"gopkg.in/natefinch/lumberjack.v2"
+)
+
+func removeStderrHook(logger *log.Logger) {
+	// remove the fallback stderr hook
+	newHooks := make(log.LevelHooks)
+	for level, hooks := range logger.Hooks {
+		newHooks[level] = make([]log.Hook, 0, len(hooks))
+		for i, h := range hooks {
+			if hook, ok := h.(*writer.Hook); ok {
+				if hook.Writer != os.Stderr {
+					newHooks[level] = append(newHooks[level], hooks[i])
+				}
+			}
+		}
+	}
+	logger.ReplaceHooks(newHooks)
+}
+
+func ConfigureLogging(config *BouncerConfig) error {
+	var LogOutput *lumberjack.Logger // io.Writer
+
+	if config.LogMode == "" {
+		config.LogMode = "stdout"
+	}
+
+	if config.LogMode == "file" {
+		if config.LogDir == "" {
+			config.LogDir = "/var/log/"
+		}
+
+		_maxsize := 500
+
+		if config.LogMaxSize != 0 {
+			_maxsize = config.LogMaxSize
+		}
+
+		_maxfiles := 3
+
+		if config.LogMaxFiles != 0 {
+			_maxfiles = config.LogMaxFiles
+		}
+
+		_maxage := 30
+
+		if config.LogMaxAge != 0 {
+			_maxage = config.LogMaxAge
+		}
+
+		_compress := true
+
+		if config.CompressLogs != nil {
+			_compress = *config.CompressLogs
+		}
+
+		logPath, err := setLogFilePermissions(config.LogDir, "crowdsec-firewall-bouncer.log")
+		if err != nil {
+			return err
+		}
+
+		LogOutput = &lumberjack.Logger{
+			Filename:   logPath,
+			MaxSize:    _maxsize, // megabytes
+			MaxBackups: _maxfiles,
+			MaxAge:     _maxage,   // days
+			Compress:   _compress, // disabled by default
+		}
+		log.SetOutput(LogOutput)
+		log.SetFormatter(&log.TextFormatter{TimestampFormat: "02-01-2006 15:04:05", FullTimestamp: true})
+
+		// keep stderr for panic/fatal, otherwise process failures
+		// won't be visible enough
+		log.AddHook(&writer.Hook{
+			Writer: os.Stderr,
+			LogLevels: []log.Level{
+				log.PanicLevel,
+				log.FatalLevel,
+			},
+		})
+	}
+
+	if config.LogMode == "stdout" {
+		// avoid duplicate logs on stderr
+		removeStderrHook(log.StandardLogger())
+	}
+
+	logLevel := log.InfoLevel
+	if config.LogLevel != nil {
+		logLevel = *config.LogLevel
+	}
+
+	log.SetLevel(logLevel)
+
+	return nil
+}

pkg/iptables/metrics.go

@@ -76,9 +76,12 @@ func (ipt *iptables) CollectMetrics() {
 		var newCount float64 = 0
 		for _, ipset := range ipsets.Ipset {
 			if ipset.Name == ipt.v4.SetName || (ipt.v6 != nil && ipset.Name == ipt.v6.SetName) {
+				if ipset.Header.Numentries == "" {
+					continue
+				}
 				count, err := strconv.ParseFloat(ipset.Header.Numentries, 64)
 				if err != nil {
-					log.Error("error while parsing  Numentries from ipsets", err)
+					log.Errorf("error while parsing  Numentries from ipsets: %s", err)
 					continue
 				}
 				newCount += count

pkg/types/types.go

@@ -12,3 +12,7 @@ type Backend interface {
 	Commit() error
 	CollectMetrics()
 }
+
+func BoolPtr(b bool) *bool {
+	return &b
+}

pytest.ini

@@ -7,6 +7,7 @@ addopts =
 markers:
     deb: mark tests related to deb packaging
     rpm: mark tests related to rpm packaging
+    systemd_debug: dump systemd status and journal on test failure
 env_files =
     .env
     default.env

scripts/_bouncer.sh

@@ -23,7 +23,7 @@ if [ ! -t 0 ]; then
     FG_YELLOW=""
     FG_CYAN=""
     RESET=""
-elif tput sgr0 >/dev/null; then
+elif tput sgr0 >/dev/null 2>&1; then
     # terminfo
     FG_RED=$(tput setaf 1)
     FG_GREEN=$(tput setaf 2)

test/bouncer/test_firewall_bouncer.py

@@ -5,7 +5,7 @@ def test_partial_config(crowdsec, bouncer, fw_cfg_factory):
     with bouncer(cfg) as fw:
         fw.wait_for_lines_fnmatch([
             # XXX: improve this message
-            "*unable to load configuration: config does not contain mode and log mode*",
+            "*unable to load configuration: config does not contain 'mode'*",
         ])
         fw.proc.wait(timeout=0.2)
         assert not fw.proc.is_running()

test/conftest.py

@@ -2,6 +2,10 @@ import contextlib
 
 import pytest
 
+from pytest_cs import plugin
+
+pytest_exception_interact = plugin.pytest_exception_interact
+
 
 # provide the name of the bouncer binary to test
 @pytest.fixture(scope='session')
@@ -42,7 +46,6 @@ def bouncer_with_lapi(bouncer, crowdsec, fw_cfg_factory, api_key_factory, tmp_pa
 
 
 _default_config = {
-    'log_mode': 'stdout',
     'log_level': 'info',
 }
 

test/install/with_crowdsec/test_crowdsec_scripts.py

@@ -6,11 +6,11 @@ import yaml
 import pytest
 from pytest_cs.lib import cscli, text
 
-
 BOUNCER = "crowdsec-firewall-bouncer"
 CONFIG = f"/etc/crowdsec/bouncers/{BOUNCER}.yaml"
 
 
+@pytest.mark.systemd_debug(BOUNCER)
 @pytest.mark.dependency()
 def test_install_crowdsec(project_repo, bouncer_binary, must_be_root):
     c = pexpect.spawn(