From 5f5bba493e86a72e451e89861ce0becb1c6f2a22 Mon Sep 17 00:00:00 2001 From: dovholuknf <46322585+dovholuknf@users.noreply.github.com> Date: Tue, 1 Dec 2020 17:18:37 -0500 Subject: [PATCH] updates to logging in case we want file name/line number later on --- service/cziti/sdk.c | 4 + service/cziti/sdk.go | 18 ++-- service/cziti/sdk.h | 2 +- service/cziti/windns.go | 1 + service/ziti-tunnel/main.go | 4 +- service/ziti-tunnel/service/ipc.go | 2 +- service/ziti-tunnel/service/state.go | 8 +- service/ziti-tunnel/util/logging/loghelper.go | 101 ++++++++++++++---- 8 files changed, 106 insertions(+), 34 deletions(-) diff --git a/service/cziti/sdk.c b/service/cziti/sdk.c index 151e4858..247cce08 100644 --- a/service/cziti/sdk.c +++ b/service/cziti/sdk.c @@ -84,3 +84,7 @@ extern void c_mapiter(model_map *map) { void ZLOG(int level, char* msg) { ZITI_LOG(level, "%s", msg); } + +bool is_null(void* anything){ + return anything == NULL; +} \ No newline at end of file diff --git a/service/cziti/sdk.go b/service/cziti/sdk.go index 01012d72..55fa7b91 100644 --- a/service/cziti/sdk.go +++ b/service/cziti/sdk.go @@ -109,6 +109,10 @@ func (c *ZIdentity) GetMetrics() (int64, int64, bool) { if c == nil { return 0, 0, false } + if C.is_null(unsafe.Pointer(&c.zctx)) { + log.Warnf("ziti context is C.NULL! %s", c.Fingerprint) + return 0, 0, false + } var up, down C.double C.ziti_get_transfer_rates(c.zctx, &up, &down) @@ -371,28 +375,28 @@ func log_writer_cb(level C.int, loc C.string, msg C.string, _ /*msglen*/ C.size_ lvl := level switch lvl { case 0: - log.Warnf("level 0 should not be logged, please report: %s", gomsg) + noFileLog.Warnf("level 0 should not be logged, please report: %s", gomsg) break case 1: - log.Errorf("SDK: %s\t%s", goline, gomsg) + noFileLog.Errorf("SDK: %s\t%s", goline, gomsg) break case 2: - log.Warnf("SDK: %s\t%s", goline, gomsg) + noFileLog.Warnf("SDK: %s\t%s", goline, gomsg) break case 3: - log.Infof("SDK: %s\t%s", goline, gomsg) + noFileLog.Infof("SDK: %s\t%s", goline, gomsg) break case 4: - log.Debugf("SDK: %s\t%s", goline, gomsg) + noFileLog.Debugf("SDK: %s\t%s", goline, gomsg) break case 5: case 6: //VERBOSE:5 //TRACE:6 - log.Tracef("SDK: %s\t%s", goline, gomsg) + noFileLog.Tracef("SDK: %s\t%s", goline, gomsg) break default: - log.Warnf("level [%d] NOT recognized: %s", level, gomsg) + noFileLog.Warnf("level [%d] NOT recognized: %s", level, gomsg) break } } \ No newline at end of file diff --git a/service/cziti/sdk.h b/service/cziti/sdk.h index 80221070..715ad693 100644 --- a/service/cziti/sdk.h +++ b/service/cziti/sdk.h @@ -57,5 +57,5 @@ extern void ziti_pq_mac_go(ziti_context ztx, char *id, ziti_pr_mac_cb response_c extern void log_writer_shim_go(int level, const char *loc, const char *msg, size_t msglen); void log_writer_cb(int level, char *loc, char *msg, size_t msglen); - +bool is_null(void* anything); #endif /* GOLANG_SDK_H */ \ No newline at end of file diff --git a/service/cziti/windns.go b/service/cziti/windns.go index b9aec737..a7881caf 100644 --- a/service/cziti/windns.go +++ b/service/cziti/windns.go @@ -28,6 +28,7 @@ import ( ) var log = logging.Logger() +var noFileLog = logging.NoFilenameLogger() func ResetDNS() { log.Info("resetting DNS server addresses") diff --git a/service/ziti-tunnel/main.go b/service/ziti-tunnel/main.go index d7b7c8f4..ec86568d 100644 --- a/service/ziti-tunnel/main.go +++ b/service/ziti-tunnel/main.go @@ -22,6 +22,7 @@ import ( "fmt" "github.com/openziti/desktop-edge-win/service/ziti-tunnel/dto" "github.com/openziti/desktop-edge-win/service/ziti-tunnel/util/logging" + "github.com/sirupsen/logrus" "golang.org/x/sys/windows/svc/debug" "golang.org/x/sys/windows/svc/eventlog" "os" @@ -39,7 +40,8 @@ func main() { Revision: Revision, BuildDate: BuildDate, } - logging.InitLogger("info") + + logging.InitLogger(logrus.InfoLevel) // passing no arguments is an indicator that this is expecting to be run 'as a service'. // using arg count instead of svc.IsAnInteractiveSession() as svc.IsAnInteractiveSession() diff --git a/service/ziti-tunnel/service/ipc.go b/service/ziti-tunnel/service/ipc.go index 3d115538..e53d157f 100644 --- a/service/ziti-tunnel/service/ipc.go +++ b/service/ziti-tunnel/service/ipc.go @@ -67,7 +67,7 @@ func SubMain(ops chan string, changes chan<- svc.Status) error { parsedLevel, cLogLevel := logging.ParseLevel(l) rts.state.LogLevel = parsedLevel.String() - logging.InitLogger(l) + logging.InitLogger(parsedLevel) _ = logging.Elog.Info(InformationEvent, SvcName+" starting. log file located at "+config.LogFile()) diff --git a/service/ziti-tunnel/service/state.go b/service/ziti-tunnel/service/state.go index c74f44c0..617b439b 100644 --- a/service/ziti-tunnel/service/state.go +++ b/service/ziti-tunnel/service/state.go @@ -219,7 +219,6 @@ func (t *RuntimeState) CreateTun(ipv4 string, ipv4mask int) (net.IP, *tun.Device } func (t *RuntimeState) LoadIdentity(id *Id) { - log.Infof("loading identity %s[%s]", id.Name, id.FingerPrint) if id.CId != nil && id.CId.Loaded { log.Warnf("id %s[%s] already connected", id.Name, id.FingerPrint) return @@ -231,11 +230,14 @@ func (t *RuntimeState) LoadIdentity(id *Id) { return } + log.Infof("loading identity %s[%s]", id.Name, id.FingerPrint) + now := time.Now() id.CId = cziti.LoadZiti(id.Path(), id.Active) - if id.CId == nil { + /*if id.CId == nil { log.Warnf("connecting to identity with fingerprint [%s] did not error but no context was returned", id.FingerPrint) return - } + }*/ + log.Infof("loading identity for %s[%s] completed taking %f seconds", id.Name, id.FingerPrint, time.Now().Sub(now).Seconds()) id.ControllerVersion = id.CId.Version id.CId.Fingerprint = id.FingerPrint diff --git a/service/ziti-tunnel/util/logging/loghelper.go b/service/ziti-tunnel/util/logging/loghelper.go index df1c3390..d062ba78 100644 --- a/service/ziti-tunnel/util/logging/loghelper.go +++ b/service/ziti-tunnel/util/logging/loghelper.go @@ -33,11 +33,11 @@ import ( ) var Elog debug.Log -var logger = logrus.New() +var withFilenameLogger = logrus.New() +var noFilenamelogger = logrus.New() var loggerInitialized = false -var tf = "2006-01-02T15:04:05.000" -var tfl = len(tf) - +var baseImportPath = "github.com/openziti/desktop-edge-win/service/" +var baseFilePath = config.ExecutablePath() func init() { /* @@ -48,19 +48,36 @@ func init() { setConsoleModeProc := kernel32DLL.NewProc("SetConsoleMode") setConsoleModeProc.Call(uintptr(handle), 0x0001|0x0002|0x0004) - f := &dateFormatter{ - timeFormat: tf, + + with := &dateFormatterNoFilename{ } - logger.SetFormatter(f) + /*with := &dateFormatterWithFilename{ + }*/ + with.dateFormatter.timeFormat = UTCFormat() + withFilenameLogger.SetFormatter(with) + + without := &dateFormatterNoFilename{ + } + without.dateFormatter.timeFormat = UTCFormat() + noFilenamelogger.SetFormatter(without) } func Logger() *logrus.Logger { - return logger + return withFilenameLogger } -func InitLogger(level string) { - l, _ := ParseLevel(level) - logger.SetLevel(l) +func NoFilenameLogger() *logrus.Logger { + return noFilenamelogger +} + +func InitLogger(level logrus.Level) { + initLogger(withFilenameLogger, level) + initLogger(noFilenamelogger, level) +} +func initLogger(logger *logrus.Logger, level logrus.Level) { + logger.SetLevel(level) + + logger.SetReportCaller(true) rl, _ := rotatelogs.New(config.LogFile() + ".%Y%m%d%H%M.log", rotatelogs.WithRotationTime(24 * time.Hour), @@ -99,7 +116,7 @@ func ParseLevel(lvl string) (logrus.Level, int) { case "verbose": return logrus.TraceLevel, 6 default: - logger.Warnf("level not recognized: [%s]. Using Info", lvl) + noFilenamelogger.Warnf("level not recognized: [%s]. Using Info", lvl) return logrus.InfoLevel, 3 } } @@ -107,25 +124,67 @@ func ParseLevel(lvl string) (logrus.Level, int) { type dateFormatter struct { timeFormat string } +type dateFormatterWithFunction struct { + dateFormatter +} +type dateFormatterWithFilename struct { + dateFormatter +} +type dateFormatterNoFilename struct { + dateFormatter +} -func (f *dateFormatter) Format(entry *logrus.Entry) ([]byte, error) { - var level string +func UTCFormat() string { + return "2006-01-02T15:04:05.000" +} + +func toLevel(entry *logrus.Entry) string { switch entry.Level { case logrus.PanicLevel: - level = panicColor + return panicColor case logrus.FatalLevel: - level = fatalColor + return fatalColor case logrus.ErrorLevel: - level = errorColor + return errorColor case logrus.WarnLevel: - level = warnColor + return warnColor case logrus.InfoLevel: - level = infoColor + return infoColor case logrus.DebugLevel: - level = debugColor + return debugColor case logrus.TraceLevel: - level = traceColor + return traceColor + default: + return infoColor } +} + +func (f *dateFormatterWithFunction) Format(entry *logrus.Entry) ([]byte, error) { + level := toLevel(entry) + + return []byte(fmt.Sprintf("[%sZ] %s\t%s:%d\t%s\n", + time.Now().UTC().Format(f.timeFormat), + level, + strings.ReplaceAll(entry.Caller.Function, baseImportPath, ""), + entry.Caller.Line, + entry.Message), + ), + nil +} +func (f *dateFormatterWithFilename) Format(entry *logrus.Entry) ([]byte, error) { + level := toLevel(entry) + + return []byte(fmt.Sprintf("[%sZ] %s\t%s:%d\t%s\n", + time.Now().UTC().Format(f.timeFormat), + level, + strings.ReplaceAll(entry.Caller.File, baseFilePath, ""), + entry.Caller.Line, + entry.Message), + ), + nil +} +func (f *dateFormatterNoFilename) Format(entry *logrus.Entry) ([]byte, error) { + level := toLevel(entry) return []byte(fmt.Sprintf("[%sZ] %s\t%s\n", time.Now().UTC().Format(f.timeFormat),