diff --git a/auth.go b/auth.go index 3458085f1..2db2330c0 100644 --- a/auth.go +++ b/auth.go @@ -353,7 +353,7 @@ func authenticate( params.Add("roleName", sc.cfg.Role) } - logger.WithContext(ctx).WithContext(sc.ctx).Infof("PARAMS for Auth: %v, %v, %v, %v, %v, %v", + logger.WithContext(ctx, sc.ctx).Infof("PARAMS for Auth: %v, %v, %v, %v, %v, %v", params, sc.rest.Protocol, sc.rest.Host, sc.rest.Port, sc.rest.LoginTimeout, sc.cfg.Authenticator.String()) respd, err := sc.rest.FuncPostAuth(ctx, sc.rest, sc.rest.getClientFor(sc.cfg.Authenticator), params, headers, bodyCreator, sc.rest.LoginTimeout) diff --git a/chunk_downloader.go b/chunk_downloader.go index 0a7021644..fe7d0b6da 100644 --- a/chunk_downloader.go +++ b/chunk_downloader.go @@ -175,11 +175,11 @@ func (scd *snowflakeChunkDownloader) checkErrorRetry() (err error) { }, ) scd.ChunksErrorCounter++ - logger.WithContext(scd.ctx).Warningf("chunk idx: %v, err: %v. retrying (%v/%v)...", + logger.WithContext(scd.ctx).Warn("chunk idx: %v, err: %v. retrying (%v/%v)...", errc.Index, errc.Error, scd.ChunksErrorCounter, maxChunkDownloaderErrorCounter) } else { scd.ChunksFinalErrors = append(scd.ChunksFinalErrors, errc) - logger.WithContext(scd.ctx).Warningf("chunk idx: %v, err: %v. no further retry", errc.Index, errc.Error) + logger.WithContext(scd.ctx).Warn("chunk idx: %v, err: %v. no further retry", errc.Index, errc.Error) return errc.Error } default: diff --git a/ctx_test.go b/ctx_test.go index 9422c6654..d6d7775a3 100644 --- a/ctx_test.go +++ b/ctx_test.go @@ -38,15 +38,13 @@ func TestCtxVal(t *testing.T) { } } -func TestLogEntryCtx(t *testing.T) { +func TestLogCtx(t *testing.T) { var log = logger var ctx1 = context.WithValue(context.Background(), SFSessionIDKey, "sessID1") var ctx2 = context.WithValue(context.Background(), SFSessionUserKey, "admin") - fs1 := context2Fields(ctx1) - fs2 := context2Fields(ctx2) - l1 := log.WithFields(*fs1) - l2 := log.WithFields(*fs2) - l1.Info("Hello 1") - l2.Warning("Hello 2") + l := log.WithContext(ctx1, ctx2) + l.Info("Hello 1") + l.Warn("Hello 2") + // what purpose does this test serve? ... nothing is being validated except that it compiles and runs. } diff --git a/driver_test.go b/driver_test.go index d6245653c..8e766e17b 100644 --- a/driver_test.go +++ b/driver_test.go @@ -7,6 +7,7 @@ import ( "crypto/rsa" "database/sql" "database/sql/driver" + "encoding/json" "flag" "fmt" "net/http" @@ -50,11 +51,16 @@ const ( // Optionally you may specify SNOWFLAKE_TEST_PROTOCOL, SNOWFLAKE_TEST_HOST // and SNOWFLAKE_TEST_PORT to specify the endpoint. func init() { + params := parseParameters("parameters.json", "testconnection") + // get environment variables env := func(key, defaultValue string) string { if value := os.Getenv(key); value != "" { return value } + if value, ok := params[key].(string); ok && value != "" { + return value + } return defaultValue } username = env("SNOWFLAKE_TEST_USER", "testuser") @@ -81,6 +87,29 @@ func init() { debugMode, _ = strconv.ParseBool(os.Getenv("SNOWFLAKE_TEST_DEBUG")) } +// parseParameters parses a parameters file returning the obj named objname as a map. +func parseParameters(nm string, objname string) map[string]any { + m := make(map[string]any) + b, err := os.ReadFile(nm) + if err != nil { + fmt.Printf("ignoring parameters file %s: err=%v\n", nm, err) + return m + } + err = json.Unmarshal(b, &m) + if err != nil { + fmt.Printf("invalid json in parameters file %s: err=%v\n", nm, err) + } + v, ok := m[objname] + if !ok { + return m + } + p, ok := v.(map[string]any) + if ok { + return p + } + return m +} + func createDSN(timezone string) { dsn = fmt.Sprintf("%s:%s@%s/%s/%s", username, pass, host, dbname, schemaname) diff --git a/easy_logging_test.go b/easy_logging_test.go index 70e62ef29..0b5baf968 100644 --- a/easy_logging_test.go +++ b/easy_logging_test.go @@ -149,7 +149,6 @@ func TestLogToConfiguredFile(t *testing.T) { logger.Error("Error message") logger.Warn("Warning message") - logger.Warning("Warning message") logger.Info("Info message") logger.Trace("Trace message") diff --git a/log.go b/log.go index 983319eaa..7b3d2d66c 100644 --- a/log.go +++ b/log.go @@ -10,7 +10,6 @@ import ( "path" "runtime" "strings" - "time" rlog "github.com/sirupsen/logrus" ) @@ -40,12 +39,39 @@ func RegisterLogContextHook(contextKey string, ctxExtractor ClientLogContextHook // logger.WithContext is used var LogKeys = [...]contextKey{SFSessionIDKey, SFSessionUserKey} +// fields +type fields map[string]interface{} + +type LogEntry interface { + Tracef(format string, args ...interface{}) + Debugf(format string, args ...interface{}) + Infof(format string, args ...interface{}) + Printf(format string, args ...interface{}) + Warnf(format string, args ...interface{}) + Errorf(format string, args ...interface{}) + + Trace(args ...interface{}) + Debug(args ...interface{}) + Info(args ...interface{}) + Print(args ...interface{}) + Warn(args ...interface{}) + Error(args ...interface{}) + + Traceln(args ...interface{}) + Debugln(args ...interface{}) + Infoln(args ...interface{}) + Println(args ...interface{}) + Warnln(args ...interface{}) + Errorln(args ...interface{}) +} + // SFLogger Snowflake logger interface to expose FieldLogger defined in logrus type SFLogger interface { - rlog.Ext1FieldLogger + LogEntry + WithContext(ctx ...context.Context) LogEntry + SetLogLevel(level string) error GetLogLevel() string - WithContext(ctx context.Context) *rlog.Entry SetOutput(output io.Writer) CloseFileOnLoggerReplace(file *os.File) error Replace(newLogger *SFLogger) @@ -56,6 +82,8 @@ func SFCallerPrettyfier(frame *runtime.Frame) (string, string) { return path.Base(frame.Function), fmt.Sprintf("%s:%d", path.Base(frame.File), frame.Line) } +var _ SFLogger = &defaultLogger{} + type defaultLogger struct { inner *rlog.Logger enabled bool @@ -81,7 +109,7 @@ func (log *defaultLogger) SetLogLevel(level string) error { if err != nil { return err } - log.inner.SetLevel(actualLevel) + log.inner.Level = actualLevel } return nil } @@ -91,7 +119,7 @@ func (log *defaultLogger) GetLogLevel() string { if !log.enabled { return "OFF" } - return log.inner.GetLevel().String() + return log.inner.Level.String() } // CloseFileOnLoggerReplace set a file to be closed when releasing resources occupied by the logger @@ -119,9 +147,10 @@ func closeLogFile(file *os.File) { } // WithContext return Entry to include fields in context -func (log *defaultLogger) WithContext(ctx context.Context) *rlog.Entry { - fields := context2Fields(ctx) - return log.inner.WithFields(*fields) +func (log *defaultLogger) WithContext(ctxs ...context.Context) LogEntry { + fields := context2Fields(ctxs...) + m := map[string]any(*fields) + return &entryBridge{log.inner.WithFields(m)} } // CreateDefaultLogger return a new instance of SFLogger with default config @@ -132,37 +161,15 @@ func CreateDefaultLogger() SFLogger { rLogger.SetFormatter(formatter) rLogger.SetReportCaller(true) var ret = defaultLogger{inner: rLogger, enabled: true} - return &ret //(&ret).(*SFLogger) + return &ret } -// WithField allocates a new entry and adds a field to it. -// Debug, Print, Info, Warn, Error, Fatal or Panic must be then applied to -// this new returned entry. -// If you want multiple fields, use `WithFields`. -func (log *defaultLogger) WithField(key string, value interface{}) *rlog.Entry { - return log.inner.WithField(key, value) +var _ SFLogger = &defaultLogger{} -} - -// Adds a struct of fields to the log entry. All it does is call `WithField` for -// each `Field`. -func (log *defaultLogger) WithFields(fields rlog.Fields) *rlog.Entry { - return log.inner.WithFields(fields) -} - -// Add an error as single field to the log entry. All it does is call -// `WithError` for the given `error`. -func (log *defaultLogger) WithError(err error) *rlog.Entry { - return log.inner.WithError(err) -} - -// Overrides the time of the log entry. -func (log *defaultLogger) WithTime(t time.Time) *rlog.Entry { - return log.inner.WithTime(t) -} +var _ LogEntry = &entryBridge{} -func (log *defaultLogger) Logf(level rlog.Level, format string, args ...interface{}) { - log.inner.Logf(level, format, args...) +type entryBridge struct { + *rlog.Entry } func (log *defaultLogger) Tracef(format string, args ...interface{}) { @@ -195,38 +202,12 @@ func (log *defaultLogger) Warnf(format string, args ...interface{}) { } } -func (log *defaultLogger) Warningf(format string, args ...interface{}) { - if log.enabled { - log.inner.Warningf(format, args...) - } -} - func (log *defaultLogger) Errorf(format string, args ...interface{}) { if log.enabled { log.inner.Errorf(format, args...) } } -func (log *defaultLogger) Fatalf(format string, args ...interface{}) { - if log.enabled { - log.inner.Fatalf(format, args...) - } -} - -func (log *defaultLogger) Panicf(format string, args ...interface{}) { - if log.enabled { - log.inner.Panicf(format, args...) - } -} - -func (log *defaultLogger) Log(level rlog.Level, args ...interface{}) { - log.inner.Log(level, args...) -} - -func (log *defaultLogger) LogFn(level rlog.Level, fn rlog.LogFunction) { - log.inner.LogFn(level, fn) -} - func (log *defaultLogger) Trace(args ...interface{}) { if log.enabled { log.inner.Trace(args...) @@ -257,88 +238,12 @@ func (log *defaultLogger) Warn(args ...interface{}) { } } -func (log *defaultLogger) Warning(args ...interface{}) { - if log.enabled { - log.inner.Warning(args...) - } -} - func (log *defaultLogger) Error(args ...interface{}) { if log.enabled { log.inner.Error(args...) } } -func (log *defaultLogger) Fatal(args ...interface{}) { - if log.enabled { - log.inner.Fatal(args...) - } -} - -func (log *defaultLogger) Panic(args ...interface{}) { - if log.enabled { - log.inner.Panic(args...) - } -} - -func (log *defaultLogger) TraceFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.TraceFn(fn) - } -} - -func (log *defaultLogger) DebugFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.DebugFn(fn) - } -} - -func (log *defaultLogger) InfoFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.InfoFn(fn) - } -} - -func (log *defaultLogger) PrintFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.PrintFn(fn) - } -} - -func (log *defaultLogger) WarnFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.PrintFn(fn) - } -} - -func (log *defaultLogger) WarningFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.WarningFn(fn) - } -} - -func (log *defaultLogger) ErrorFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.ErrorFn(fn) - } -} - -func (log *defaultLogger) FatalFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.FatalFn(fn) - } -} - -func (log *defaultLogger) PanicFn(fn rlog.LogFunction) { - if log.enabled { - log.inner.PanicFn(fn) - } -} - -func (log *defaultLogger) Logln(level rlog.Level, args ...interface{}) { - log.inner.Logln(level, args...) -} - func (log *defaultLogger) Traceln(args ...interface{}) { if log.enabled { log.inner.Traceln(args...) @@ -369,69 +274,17 @@ func (log *defaultLogger) Warnln(args ...interface{}) { } } -func (log *defaultLogger) Warningln(args ...interface{}) { - if log.enabled { - log.inner.Warningln(args...) - } -} - func (log *defaultLogger) Errorln(args ...interface{}) { if log.enabled { log.inner.Errorln(args...) } } -func (log *defaultLogger) Fatalln(args ...interface{}) { - if log.enabled { - log.inner.Fatalln(args...) - } -} - -func (log *defaultLogger) Panicln(args ...interface{}) { - if log.enabled { - log.inner.Panicln(args...) - } -} - -func (log *defaultLogger) Exit(code int) { - log.inner.Exit(code) -} - -// SetLevel sets the logger level. -func (log *defaultLogger) SetLevel(level rlog.Level) { - log.inner.SetLevel(level) -} - -// GetLevel returns the logger level. -func (log *defaultLogger) GetLevel() rlog.Level { - return log.inner.GetLevel() -} - -// AddHook adds a hook to the logger hooks. -func (log *defaultLogger) AddHook(hook rlog.Hook) { - log.inner.AddHook(hook) - -} - -// IsLevelEnabled checks if the log level of the logger is greater than the level param -func (log *defaultLogger) IsLevelEnabled(level rlog.Level) bool { - return log.inner.IsLevelEnabled(level) -} - -// SetFormatter sets the logger formatter. -func (log *defaultLogger) SetFormatter(formatter rlog.Formatter) { - log.inner.SetFormatter(formatter) -} - // SetOutput sets the logger output. func (log *defaultLogger) SetOutput(output io.Writer) { log.inner.SetOutput(output) } -func (log *defaultLogger) SetReportCaller(reportCaller bool) { - log.inner.SetReportCaller(reportCaller) -} - // SetLogger set a new logger of SFLogger interface for gosnowflake func SetLogger(inLogger *SFLogger) { logger = *inLogger //.(*defaultLogger) @@ -442,21 +295,25 @@ func GetLogger() SFLogger { return logger } -func context2Fields(ctx context.Context) *rlog.Fields { - var fields = rlog.Fields{} - if ctx == nil { +func context2Fields(ctxs ...context.Context) *fields { + var fields = fields{} + if len(ctxs) <= 0 { return &fields } for i := 0; i < len(LogKeys); i++ { - if ctx.Value(LogKeys[i]) != nil { - fields[string(LogKeys[i])] = ctx.Value(LogKeys[i]) + for _, ctx := range ctxs { + if ctx.Value(LogKeys[i]) != nil { + fields[string(LogKeys[i])] = ctx.Value(LogKeys[i]) + } } } for key, hook := range clientLogContextHooks { - if value := hook(ctx); value != "" { - fields[key] = value + for _, ctx := range ctxs { + if value := hook(ctx); value != "" { + fields[key] = value + } } } diff --git a/log_test.go b/log_test.go index 4efd3545a..9dd7813ad 100644 --- a/log_test.go +++ b/log_test.go @@ -5,41 +5,45 @@ package gosnowflake import ( "bytes" "context" - "errors" "fmt" "strings" "testing" - "time" rlog "github.com/sirupsen/logrus" ) -func createTestLogger() defaultLogger { +func createTestLogger() *defaultLogger { var rLogger = rlog.New() var ret = defaultLogger{inner: rLogger} - return ret + return &ret } func TestIsLevelEnabled(t *testing.T) { logger := createTestLogger() - logger.SetLevel(rlog.TraceLevel) - if !logger.IsLevelEnabled(rlog.TraceLevel) { - t.Fatalf("log level should be trace but is %v", logger.GetLevel()) + err := logger.SetLogLevel("trace") + if err != nil { + t.Fatalf("log level could not be set %v", err) + } + if logger.GetLogLevel() != "trace" { + t.Fatalf("log level should be trace but is %v", logger.GetLogLevel()) } } func TestLogFunction(t *testing.T) { logger := createTestLogger() buf := &bytes.Buffer{} - var formatter = rlog.TextFormatter{CallerPrettyfier: SFCallerPrettyfier} - logger.SetFormatter(&formatter) - logger.SetReportCaller(true) + //var formatter = rlog.TextFormatter{CallerPrettyfier: SFCallerPrettyfier} + //logger.SetFormatter(&formatter) + //logger.SetReportCaller(true) logger.SetOutput(buf) - logger.SetLevel(rlog.TraceLevel) + err := logger.SetLogLevel("trace") + if err != nil { + t.Fatalf("log level could not be set %v", err) + } - logger.Log(rlog.TraceLevel, "hello world") - logger.Logf(rlog.TraceLevel, "log %v", "format") - logger.Logln(rlog.TraceLevel, "log line") + logger.Trace("hello world") + logger.Tracef("log %v", "format") + logger.Traceln("log line") var strbuf = buf.String() if !strings.Contains(strbuf, "hello world") && @@ -86,10 +90,6 @@ func TestDefaultLogLevel(t *testing.T) { logger.Warnf("warn%v", "f") logger.Warnln("warnln") - logger.Warning("warning") - logger.Warningf("warning%v", "f") - logger.Warningln("warningln") - logger.Error("error") logger.Errorf("error%v", "f") logger.Errorln("errorln") @@ -131,9 +131,6 @@ func TestOffLogLevel(t *testing.T) { logger.Warn("warn") logger.Warnf("warn%v", "f") logger.Warnln("warnln") - logger.Warning("warning") - logger.Warningf("warning%v", "f") - logger.Warningln("warningln") logger.Error("error") logger.Errorf("error%v", "f") logger.Errorln("errorln") @@ -159,101 +156,6 @@ func TestLogSetLevel(t *testing.T) { } } -func TestLogWithError(t *testing.T) { - logger := CreateDefaultLogger() - buf := &bytes.Buffer{} - logger.SetOutput(buf) - - err := errors.New("error") - logger.WithError(err).Info("hello world") - - var strbuf = buf.String() - if !strings.Contains(strbuf, "error=error") { - t.Fatalf("unexpected output in log: %v", strbuf) - } -} - -func TestLogWithTime(t *testing.T) { - logger := createTestLogger() - buf := &bytes.Buffer{} - logger.SetOutput(buf) - - ti := time.Now() - logger.WithTime(ti).Info("hello") - time.Sleep(3 * time.Second) - - var strbuf = buf.String() - if !strings.Contains(strbuf, ti.Format(time.RFC3339)) { - t.Fatalf("unexpected string in output: %v", strbuf) - } -} - -func TestLogWithField(t *testing.T) { - logger := CreateDefaultLogger() - buf := &bytes.Buffer{} - logger.SetOutput(buf) - - logger.WithField("field", "test").Info("hello") - var strbuf = buf.String() - if !strings.Contains(strbuf, "field=test") { - t.Fatalf("unexpected string in output: %v", strbuf) - } -} - -func TestLogLevelFunctions(t *testing.T) { - logger := createTestLogger() - buf := &bytes.Buffer{} - logger.SetOutput(buf) - - logger.TraceFn(func() []interface{} { - return []interface{}{ - "trace function", - } - }) - - logger.DebugFn(func() []interface{} { - return []interface{}{ - "debug function", - } - }) - - logger.InfoFn(func() []interface{} { - return []interface{}{ - "info function", - } - }) - - logger.PrintFn(func() []interface{} { - return []interface{}{ - "print function", - } - }) - - logger.WarningFn(func() []interface{} { - return []interface{}{ - "warning function", - } - }) - - logger.ErrorFn(func() []interface{} { - return []interface{}{ - "error function", - } - }) - - // check that info, print, warning and error were outputted to the log. - var strbuf = buf.String() - - if strings.Contains(strbuf, "debug") && - strings.Contains(strbuf, "trace") && - !strings.Contains(strbuf, "info") && - !strings.Contains(strbuf, "print") && - !strings.Contains(strbuf, "warning") && - !strings.Contains(strbuf, "error") { - t.Fatalf("unexpected output in log: %v", strbuf) - } -} - type testRequestIDCtxKey struct{} func TestLogKeysDefault(t *testing.T) { diff --git a/retry.go b/retry.go index 59d2fdf60..7913a11e5 100644 --- a/retry.go +++ b/retry.go @@ -329,10 +329,10 @@ func (r *retryHTTP) execute() (res *http.Response, err error) { return res, err } if err != nil { - logger.WithContext(r.ctx).Warningf( + logger.WithContext(r.ctx).Warn( "failed http connection. err: %v. retrying...\n", err) } else { - logger.WithContext(r.ctx).Warningf( + logger.WithContext(r.ctx).Warn( "failed http connection. HTTP Status: %v. retrying...\n", res.StatusCode) res.Body.Close() } diff --git a/s3_storage_client.go b/s3_storage_client.go index 35d962bfc..7288065dc 100644 --- a/s3_storage_client.go +++ b/s3_storage_client.go @@ -84,11 +84,12 @@ func getS3CustomEndpoint(info *execResponseStageInfo) *string { } func s3LoggingFunc(classification logging.Classification, format string, v ...interface{}) { + v = append(v, "logger=S3") switch classification { case logging.Debug: - logger.WithField("logger", "S3").Debugf(format, v...) + logger.Debugf(format, v...) case logging.Warn: - logger.WithField("logger", "S3").Warnf(format, v...) + logger.Warnf(format, v...) } }