From eb5494452e6971a3389258be2c948fd4a21d5f0f Mon Sep 17 00:00:00 2001
From: rekby <rekby@yandex-team.ru>
Date: Tue, 8 Dec 2020 09:45:51 +0300
Subject: [PATCH] Improove filter logging

---
 internal/domain_checker/chains.go  | 10 +++++++++-
 internal/domain_checker/ip_list.go |  3 ++-
 internal/domain_checker/simple.go  | 25 ++++++++++++++++++++++---
 internal/log/log.go                |  5 +++++
 4 files changed, 38 insertions(+), 5 deletions(-)

diff --git a/internal/domain_checker/chains.go b/internal/domain_checker/chains.go
index b2894230..00710259 100644
--- a/internal/domain_checker/chains.go
+++ b/internal/domain_checker/chains.go
@@ -1,7 +1,11 @@
 //nolint:golint
 package domain_checker
 
-import "context"
+import (
+	"context"
+
+	"github.com/rekby/lets-proxy2/internal/log"
+)
 
 type Any []DomainChecker
 
@@ -12,9 +16,11 @@ func (any Any) IsDomainAllowed(ctx context.Context, domain string) (bool, error)
 			return false, err
 		}
 		if res {
+			log.DebugCtx(ctx, "Allowed by 'any' rule chain: some of subrules allow domain (details in debug log)")
 			return true, nil
 		}
 	}
+	log.InfoCtx(ctx, "Deny by 'any' rule chain: nothing of subrules allow domain.")
 	return false, nil
 }
 
@@ -31,9 +37,11 @@ func (all All) IsDomainAllowed(ctx context.Context, domain string) (bool, error)
 			return false, err
 		}
 		if !res {
+			log.InfoCtx(ctx, "Deny by 'all' chain: any of subrules denied domain.")
 			return false, nil
 		}
 	}
+	log.DebugCtx(ctx, "Allow by 'all' chain: all of subrules allow domain.")
 	return true, nil
 }
 
diff --git a/internal/domain_checker/ip_list.go b/internal/domain_checker/ip_list.go
index 6b397b6e..be849f36 100644
--- a/internal/domain_checker/ip_list.go
+++ b/internal/domain_checker/ip_list.go
@@ -116,9 +116,10 @@ hostIP:
 			}
 		}
 		ip := ip
-		logger.Debug("Domain has not allowed IP address", zap.Stringer("checked_ip", &ip))
+		logger.Info("Domain has not allowed IP address", zap.Stringer("checked_ip", &ip))
 		return false, nil
 	}
+	logger.Debug("Domain allowed IP address filter")
 	return true, nil
 }
 
diff --git a/internal/domain_checker/simple.go b/internal/domain_checker/simple.go
index 20393ba0..ada722b9 100644
--- a/internal/domain_checker/simple.go
+++ b/internal/domain_checker/simple.go
@@ -4,17 +4,24 @@ package domain_checker
 import (
 	"context"
 	"regexp"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/rekby/lets-proxy2/internal/log"
 )
 
 type True struct{}
 
 func (True) IsDomainAllowed(ctx context.Context, domain string) (bool, error) {
+	log.DebugCtx(ctx, "Allow by 'true' rule")
 	return true, nil
 }
 
 type False struct{}
 
 func (False) IsDomainAllowed(ctx context.Context, domain string) (bool, error) {
+	log.InfoCtx(ctx, "Deny by 'false' rule")
 	return false, nil
 }
 
@@ -23,9 +30,15 @@ type Not struct {
 }
 
 func (n Not) IsDomainAllowed(ctx context.Context, domain string) (bool, error) {
-	res, err := n.origin.IsDomainAllowed(ctx, domain)
+	subRuleRes, err := n.origin.IsDomainAllowed(ctx, domain)
+	res := !subRuleRes
 	if err == nil {
-		return !res, nil
+		logLevel := zapcore.DebugLevel
+		if !res {
+			logLevel = zapcore.InfoLevel
+		}
+		log.LevelParamCtx(ctx, logLevel, "'Not' filter (details in debug log)", zap.Bool("result", res))
+		return res, nil
 	}
 	return false, err
 }
@@ -34,7 +47,13 @@ type Regexp regexp.Regexp
 
 func (r *Regexp) IsDomainAllowed(ctx context.Context, domain string) (bool, error) {
 	reg := (*regexp.Regexp)(r)
-	return reg.MatchString(domain), nil
+	result := reg.MatchString(domain)
+	logLevel := zapcore.DebugLevel
+	if !result {
+		logLevel = zapcore.InfoLevel
+	}
+	log.LevelParamCtx(ctx, logLevel, "Check if domain allowed by regexp", zap.String("regexp", reg.String()), zap.Bool("result", result))
+	return result, nil
 }
 
 func NewRegexp(r *regexp.Regexp) *Regexp {
diff --git a/internal/log/log.go b/internal/log/log.go
index c0377854..27bf60c8 100644
--- a/internal/log/log.go
+++ b/internal/log/log.go
@@ -80,6 +80,11 @@ func debugDpanic(logger *zap.Logger, err error, mess string, fields ...zap.Field
 	}
 }
 
+func DebugCtx(ctx context.Context, mess string, fields ...zap.Field) {
+	logger := zc.L(ctx)
+	logger.WithOptions(zap.AddCallerSkip(1)).Debug(mess, fields...)
+}
+
 func DebugFatal(logger *zap.Logger, err error, mess string, fields ...zap.Field) {
 	debugFatal(logger, err, mess, fields...)
 }