New application logging (zerolog) & error handling

cmd/coraza-spoa/main.go

@@ -8,22 +8,33 @@ import (
 
 	"github.com/corazawaf/coraza-spoa/config"
 	"github.com/corazawaf/coraza-spoa/internal"
+	"github.com/corazawaf/coraza-spoa/log"
 )
 
 func main() {
 	cfg := flag.String("config", "", "configuration file")
+	//nolint:staticcheck // That's exactly nil check
 	if cfg == nil {
-		panic("configuration file is not set")
+		log.Fatal().Msg("configuration file is not set")
 	}
+	debug := flag.Bool("debug", false, "sets log level to debug")
+
 	flag.Parse()
+
+	log.SetDebug(*debug)
+
+	//nolint:staticcheck // Nil is checked above
 	if err := config.InitConfig(*cfg); err != nil {
-		panic(err)
+		log.Fatal().Err(err).Msg("Can't initialize configuration")
 	}
+
+	log.InitLogging(config.Global.Log.File, config.Global.Log.Level, config.Global.Log.SpoeLevel)
+
 	spoa, err := internal.New(config.Global)
 	if err != nil {
-		panic(err)
+		log.Fatal().Err(err).Msg("Can't initialize SPOA")
 	}
 	if err := spoa.Start(config.Global.Bind); err != nil {
-		panic(err)
+		log.Fatal().Err(err).Msg("Can't start SPOA")
 	}
 }

config.yaml.default

@@ -1,6 +1,14 @@
-
 # The SPOA server bind address
 bind: 0.0.0.0:9000
+log:
+  # The log level configuration, one of: debug/info/warn/error/panic/fatal
+  level: trace
+  # The log file path, /dev/stderr by default
+  file: /dev/stdout
+  # Log WAF errors as SPOA, default is false
+  waf: true
+  # The log level of underlying SPOE library (criteo/haproxy-spoe-go), one of: debug/info/warn/error/panic/fatal. Default is info.
+  spoe_level: info
 
 # Process request and response with this application if provided app name is not found.
 # You can remove or comment out this config param if you don't need "default_application" functionality.
@@ -25,7 +33,7 @@ applications:
     # The maximum number of transactions which can be cached
     transaction_active_limit: 100000
 
-    # The log level configuration, one of: debug/info/warn/error/panic/fatal
-    log_level: info
-    # The log file path
+    # Deprecated, doesn't work
+    log_level: debug
+    # Deprecated, doesn't work
     log_file: /dev/stdout

config/config.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"os"
 
+	"github.com/corazawaf/coraza-spoa/log"
 	yaml "gopkg.in/yaml.v3"
 )
 
@@ -16,14 +17,18 @@ var Global *Config
 // Config is used to configure coraza-server.
 type Config struct {
 	Bind               string                  `yaml:"bind"`
+	Log                Log                     `yaml:"log"`
 	DefaultApplication string                  `yaml:"default_application"`
 	Applications       map[string]*Application `yaml:"applications"`
 }
 
 // Application is used to manage the haproxy configuration and waf rules.
 type Application struct {
-	LogLevel        string `yaml:"log_level"`
-	LogFile         string `yaml:"log_file"`
+	// Deprecated: #70: use Config.Log.Level to set up application logging or SecDebugLogLevel to set up Coraza logging
+	LogLevel string `yaml:"log_level"`
+	// Deprecated: #70: use Config.Log.File to set up application logging or SecDebugLog to set up Coraza logging
+	LogFile string `yaml:"log_file"`
+
 	NoResponseCheck bool   `yaml:"no_response_check"`
 	Directives      string `yaml:"directives"`
 	// Deprecated: use directives instead, this will be removed in the near future.
@@ -32,6 +37,14 @@ type Application struct {
 	TransactionActiveLimit     int      `yaml:"transaction_active_limit"`
 }
 
+// Log is used to manage the SPOA logging.
+type Log struct {
+	Level     string `yaml:"level"`
+	File      string `yaml:"file"`
+	Waf       bool   `yaml:"waf"`
+	SpoeLevel string `yaml:"spoe_level"`
+}
+
 // InitConfig initializes the configuration.
 func InitConfig(file string) error {
 	f, err := os.Open(file)
@@ -54,11 +67,20 @@ func InitConfig(file string) error {
 }
 
 func validateConfig() error {
-	fmt.Printf("Loading %d applications\n", len(Global.Applications))
-	for _, app := range Global.Applications {
-		if app.LogLevel == "" {
-			app.LogLevel = "warn"
+	log.Info().Msgf("Loading %d applications", len(Global.Applications))
+
+	for name, app := range Global.Applications {
+		log.Debug().Msgf("Validating %s application config", name)
+
+		// Deprecated: #70: use Config.Log.Level to set up application logging or SecDebugLogLevel to set up Coraza logging
+		if app.LogLevel != "" {
+			log.Warn().Msg("'app.log_level' is skipped. For setting application log level use 'log.level' in the root of configuration.")
+		}
+		// Deprecated: #70: use Config.Log.File to set up application logging or SecDebugLog to set up Coraza logging
+		if app.LogFile != "" {
+			log.Warn().Msg("'app.log_level' is skipped. For setting application log file use 'log.file' in the root of configuration.")
 		}
+
 		if app.TransactionTTLMilliseconds < 0 {
 			return fmt.Errorf("SPOA transaction ttl must be greater than 0")
 		}

docker/haproxy/haproxy.cfg

@@ -26,7 +26,7 @@ frontend test_frontend
     bind *:443 ssl crt /usr/local/etc/haproxy/example.com.pem alpn h2,http/1.1
     unique-id-format %[uuid()]
     unique-id-header X-Unique-ID
-    log-format "%ci:%cp\ [%t]\ %ft\ %b/%s\ %Th/%Ti/%TR/%Tq/%Tw/%Tc/%Tr/%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r\ %ID\ spoa-error:\ %[var(txn.coraza.error)]\ waf-action:\ %[var(txn.coraza.action)]"
+    log-format "%ci:%cp\ [%t]\ %ft\ %b/%s\ %Th/%Ti/%TR/%Tq/%Tw/%Tc/%Tr/%Tt\ %ST\ %B\ %CC\ %CS\ %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r\ %ID\ waf-action:\ %[var(txn.coraza.action)]\ spoe-error:\ %[var(txn.coraza.error)]\ spoa-error:\ %[var(txn.coraza.err_code)]\ %[var(txn.coraza.err_msg)]"
 
     filter spoe engine coraza config /usr/local/etc/haproxy/coraza.cfg
 
@@ -40,10 +40,14 @@ frontend test_frontend
     http-request silent-drop if { var(txn.coraza.action) -m str drop }
     http-response silent-drop if { var(txn.coraza.action) -m str drop }
 
-    # Deny in case of an error, when processing with the Coraza SPOA
+    # Deny in case of an error, when processing with the Coraza SPOE
     http-request deny deny_status 504 if { var(txn.coraza.error) -m int gt 0 }
     http-response deny deny_status 504 if { var(txn.coraza.error) -m int gt 0 }
 
+    # Deny in case of an error, when processing with the Coraza SPOA
+    http-request deny deny_status 504 if { var(txn.coraza.err_code) -m int gt 0 }
+    http-response deny deny_status 504 if { var(txn.coraza.err_code) -m int gt 0 }
+
     # Deprecated, use action instead of fail
     #http-request deny deny_status 401 hdr waf-block "request" if { var(txn.coraza.fail) -m int eq 1 }
     #http-response deny deny_status 401 hdr waf-block "response" if { var(txn.coraza.fail) -m int eq 1 }

go.mod

@@ -7,20 +7,21 @@ require (
 	github.com/corazawaf/coraza/v3 v3.0.0
 	github.com/criteo/haproxy-spoe-go v1.0.6
 	github.com/magefile/mage v1.15.0
-	go.uber.org/zap v1.24.0
+	github.com/rs/zerolog v1.29.1
+	github.com/sirupsen/logrus v1.9.3
 	gopkg.in/yaml.v3 v3.0.1
 )
 
 require (
 	github.com/corazawaf/libinjection-go v0.1.2 // indirect
+	github.com/mattn/go-colorable v0.1.12 // indirect
+	github.com/mattn/go-isatty v0.0.14 // indirect
 	github.com/petar-dambovaliev/aho-corasick v0.0.0-20211021192214-5ab2d9280aa9 // indirect
 	github.com/pkg/errors v0.9.1 // indirect
-	github.com/sirupsen/logrus v1.9.3 // indirect
+	github.com/stretchr/testify v1.8.0 // indirect
 	github.com/tidwall/gjson v1.14.4 // indirect
 	github.com/tidwall/match v1.1.1 // indirect
 	github.com/tidwall/pretty v1.2.1 // indirect
-	go.uber.org/atomic v1.11.0 // indirect
-	go.uber.org/multierr v1.11.0 // indirect
 	golang.org/x/net v0.10.0 // indirect
 	golang.org/x/sys v0.8.0 // indirect
 	rsc.io/binaryregexp v0.2.0 // indirect

go.sum

@@ -1,17 +1,18 @@
-github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
 github.com/bluele/gcache v0.0.2 h1:WcbfdXICg7G/DGBh1PFfcirkWOQV+v077yF1pSy3DGw=
 github.com/bluele/gcache v0.0.2/go.mod h1:m15KV+ECjptwSPxKhOhQoAFQVtUFjTVkc3H8o0t/fp0=
 github.com/corazawaf/coraza/v3 v3.0.0 h1:GvTzxcgtfQ76LneYL19Nkb1/T+2E/s3BRAOEt6h2sY0=
 github.com/corazawaf/coraza/v3 v3.0.0/go.mod h1:MjV/iyO+B+JcVEWUJi4O2r1sfHeFzlF28MnvAqWfea0=
 github.com/corazawaf/libinjection-go v0.1.2 h1:oeiV9pc5rvJ+2oqOqXEAMJousPpGiup6f7Y3nZj5GoM=
 github.com/corazawaf/libinjection-go v0.1.2/go.mod h1:OP4TM7xdJ2skyXqNX1AN1wN5nNZEmJNuWbNPOItn7aw=
+github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E=
 github.com/criteo/haproxy-spoe-go v1.0.6 h1:3GDQ8hm/fIkn4wxxI/pN0OoBfKon4ROzvpU5fIriYII=
 github.com/criteo/haproxy-spoe-go v1.0.6/go.mod h1:o04s69MOZ7SvPthMtUt/tfn1hcorQQAS/nwzKPBlXQU=
 github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/foxcpp/go-mockdns v1.0.0 h1:7jBqxd3WDWwi/6WhDvacvH1XsN3rOLXyHM1uhvIx6FI=
+github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/konsorten/go-windows-terminal-sequences v1.0.3/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/pretty v0.2.1 h1:Fmg33tUaq4/8ym9TJN1x7sLJnHVwhP33CNkpYV/7rwI=
 github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
@@ -21,39 +22,44 @@ github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY=
 github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE=
 github.com/magefile/mage v1.15.0 h1:BvGheCMAsG3bWUDbZ8AyXXpCNwU9u5CB6sM+HNb9HYg=
 github.com/magefile/mage v1.15.0/go.mod h1:z5UZb/iS3GoOSn0JgWuiw7dxlurVYTu+/jHXqQg881A=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/miekg/dns v1.1.50 h1:DQUfb9uc6smULcREF09Uc+/Gd46YWqJd5DbpPE9xkcA=
 github.com/petar-dambovaliev/aho-corasick v0.0.0-20211021192214-5ab2d9280aa9 h1:lL+y4Xv20pVlCGyLzNHRC0I0rIHhIL1lTvHizoS/dU8=
 github.com/petar-dambovaliev/aho-corasick v0.0.0-20211021192214-5ab2d9280aa9/go.mod h1:EHPiTAKtiFmrMldLUNswFwfZ2eJIYBHktdaUTZxYWRw=
 github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
+github.com/rs/xid v1.4.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
+github.com/rs/zerolog v1.29.1 h1:cO+d60CHkknCbvzEWxP0S9K6KqyTjrCNUy1LdQLCGPc=
+github.com/rs/zerolog v1.29.1/go.mod h1:Le6ESbR7hc+DP6Lt1THiV8CQSdkkNrd3R0XbEgp3ZBU=
 github.com/sirupsen/logrus v1.7.0/go.mod h1:yWOB1SBYBC5VeMP7gHvWumXLIWorT60ONWic61uBYv0=
 github.com/sirupsen/logrus v1.9.3 h1:dueUQJ1C2q9oE3F7wvmSGAaVtTmUizReu6fjN8uqzbQ=
 github.com/sirupsen/logrus v1.9.3/go.mod h1:naHLuLoDiP4jHNo9R0sCBMtWGeIprob74mVsIT4qYEQ=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
+github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
+github.com/stretchr/testify v1.7.1/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg=
 github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PKk=
+github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 github.com/tidwall/gjson v1.14.4 h1:uo0p8EbA09J7RQaflQ1aBRffTR7xedD2bcIVSYxLnkM=
 github.com/tidwall/gjson v1.14.4/go.mod h1:/wbyibRr2FHMks5tjHJ5F8dMZh3AcwJEMf5vlfC0lxk=
 github.com/tidwall/match v1.1.1 h1:+Ho715JplO36QYgwN9PGYNhgZvoUSc9X2c80KVTi+GA=
 github.com/tidwall/match v1.1.1/go.mod h1:eRSPERbgtNPcGhD8UCthc6PmLEQXEWd3PRB5JTxsfmM=
 github.com/tidwall/pretty v1.2.0/go.mod h1:ITEVvHYasfjBbM0u2Pg8T2nJnzm8xPwvNhhsoaGGjNU=
 github.com/tidwall/pretty v1.2.1 h1:qjsOFOWWQl+N3RsoF5/ssm1pHmJJwhjlSbZ51I6wMl4=
 github.com/tidwall/pretty v1.2.1/go.mod h1:ITEVvHYasfjBbM0u2Pg8T2nJnzm8xPwvNhhsoaGGjNU=
-go.uber.org/atomic v1.11.0 h1:ZvwS0R+56ePWxUNi+Atn9dWONBPp/AUETXlHW0DxSjE=
-go.uber.org/atomic v1.11.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0=
-go.uber.org/goleak v1.1.11 h1:wy28qYRKZgnJTxGxvye5/wgWr1EKjmUDGYox5mGlRlI=
-go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0=
-go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y=
-go.uber.org/zap v1.24.0 h1:FiJd5l1UOLj0wCgbSE0rwwXHzEdAZS6hiiSnxJN/D60=
-go.uber.org/zap v1.24.0/go.mod h1:2kMP+WWQ8aoFoedH3T2sq6iJ2yDWpHbP0f6MQbS9Gkg=
 golang.org/x/mod v0.8.0 h1:LUYupSeNrTNCGzR/hVBk2NHZO4hXcVaW1k4Qx7rjPx8=
 golang.org/x/net v0.10.0 h1:X2//UzNDwYmtCLn7To6G58Wr6f5ahEAQgKNzv9Y951M=
 golang.org/x/net v0.10.0/go.mod h1:0qNGK6F8kojg2nk9dLZ2mShWaEBan6FAoqfSigmmuDg=
 golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20210113181707-4bcb84eeeb78/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220715151400-c0bba94af5f8/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.8.0 h1:EBmGv8NaZBZTWvrbjNoL6HVt+IVy3QDQpJs7VRIw3tU=
 golang.org/x/sys v0.8.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=

internal/request.go

@@ -4,9 +4,9 @@
 package internal
 
 import (
-	"fmt"
 	"net"
 
+	"github.com/corazawaf/coraza-spoa/log"
 	spoe "github.com/criteo/haproxy-spoe-go"
 )
 
@@ -78,22 +78,22 @@ func (req *request) init() error {
 
 	req.path, err = req.msg.getStringArg("path")
 	if err != nil {
-		fmt.Println(err.Error())
+		log.Trace().Err(err).Msg("Can't get Path from HTTP Request")
 	}
 
 	req.query, err = req.msg.getStringArg("query")
 	if err != nil {
-		fmt.Println(err.Error())
+		log.Trace().Err(err).Msg("Can't get Query from HTTP Request")
 	}
 
 	req.version, err = req.msg.getStringArg("version")
 	if err != nil {
-		fmt.Println(err.Error())
+		log.Trace().Err(err).Msg("Can't get Version from HTTP Request")
 	}
 
 	req.headers, err = req.msg.getStringArg("headers")
 	if err != nil {
-		fmt.Println(err.Error())
+		log.Trace().Err(err).Msg("Can't get Headers from HTTP Request")
 	}
 
 	req.body, _ = req.msg.getByteArrayArg("body")

internal/response.go

@@ -4,8 +4,7 @@
 package internal
 
 import (
-	"fmt"
-
+	"github.com/corazawaf/coraza-spoa/log"
 	spoe "github.com/criteo/haproxy-spoe-go"
 )
 
@@ -46,7 +45,7 @@ func (resp *response) init() error {
 
 	resp.version, err = resp.msg.getStringArg("version")
 	if err != nil {
-		fmt.Println(err.Error())
+		log.Trace().Err(err).Msg("Can't get Version from HTTP Request")
 	}
 
 	resp.status, err = resp.msg.getIntArg("status")
@@ -56,7 +55,7 @@ func (resp *response) init() error {
 
 	resp.headers, err = resp.msg.getStringArg("headers")
 	if err != nil {
-		fmt.Println(err.Error())
+		log.Trace().Err(err).Msg("Can't get Headers from HTTP Request")
 	}
 
 	resp.body, _ = resp.msg.getByteArrayArg("body")