From 0bc73824d5404419de1ba397e7ab42f277140d55 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 6 Jan 2025 11:59:37 -0800 Subject: [PATCH 01/16] SNOW-625282: Make logrus dependency optional or drop it all together --- auth.go | 2 +- chunk_downloader.go | 4 +- ctx_test.go | 12 +-- driver_test.go | 29 +++++ easy_logging_test.go | 1 - log.go | 249 +++++++++---------------------------------- log_test.go | 134 ++++------------------- retry.go | 4 +- s3_storage_client.go | 5 +- 9 files changed, 113 insertions(+), 327 deletions(-) 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...) } } From 9501757089b2766576803c5f4ac55ccf266e337c Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Tue, 7 Jan 2025 09:39:57 -0800 Subject: [PATCH 02/16] minor cleanup --- log.go | 6 ++---- log_test.go | 3 --- 2 files changed, 2 insertions(+), 7 deletions(-) diff --git a/log.go b/log.go index 7b3d2d66c..583fdec97 100644 --- a/log.go +++ b/log.go @@ -82,7 +82,7 @@ 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{} +var _ SFLogger = &defaultLogger{} // ensure defaultLogger isa SFLogger. type defaultLogger struct { inner *rlog.Logger @@ -164,9 +164,7 @@ func CreateDefaultLogger() SFLogger { return &ret } -var _ SFLogger = &defaultLogger{} - -var _ LogEntry = &entryBridge{} +var _ LogEntry = &entryBridge{} // ensure entryBridge isa LogEntry. type entryBridge struct { *rlog.Entry diff --git a/log_test.go b/log_test.go index 9dd7813ad..e55e0b5b3 100644 --- a/log_test.go +++ b/log_test.go @@ -32,9 +32,6 @@ func TestIsLevelEnabled(t *testing.T) { func TestLogFunction(t *testing.T) { logger := createTestLogger() buf := &bytes.Buffer{} - //var formatter = rlog.TextFormatter{CallerPrettyfier: SFCallerPrettyfier} - //logger.SetFormatter(&formatter) - //logger.SetReportCaller(true) logger.SetOutput(buf) err := logger.SetLogLevel("trace") if err != nil { From d6562e6ada99a631be08dfa5b8b0f45f0f93e580 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 13 Jan 2025 12:50:24 -0800 Subject: [PATCH 03/16] add some rm methods back --- log.go | 105 ++++++++++++++++++++++++++++++++++++++++++++++++---- log_test.go | 87 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 185 insertions(+), 7 deletions(-) diff --git a/log.go b/log.go index 583fdec97..fe539d527 100644 --- a/log.go +++ b/log.go @@ -10,6 +10,7 @@ import ( "path" "runtime" "strings" + "time" rlog "github.com/sirupsen/logrus" ) @@ -39,8 +40,8 @@ func RegisterLogContextHook(contextKey string, ctxExtractor ClientLogContextHook // logger.WithContext is used var LogKeys = [...]contextKey{SFSessionIDKey, SFSessionUserKey} -// fields -type fields map[string]interface{} +// Fields +type Fields map[string]any type LogEntry interface { Tracef(format string, args ...interface{}) @@ -48,30 +49,43 @@ type LogEntry interface { Infof(format string, args ...interface{}) Printf(format string, args ...interface{}) Warnf(format string, args ...interface{}) + Warningf(format string, args ...interface{}) Errorf(format string, args ...interface{}) + Fatalf(format string, args ...interface{}) + Panicf(format string, args ...interface{}) Trace(args ...interface{}) Debug(args ...interface{}) Info(args ...interface{}) Print(args ...interface{}) Warn(args ...interface{}) + Warning(args ...interface{}) Error(args ...interface{}) + Fatal(args ...interface{}) + Panic(args ...interface{}) Traceln(args ...interface{}) Debugln(args ...interface{}) Infoln(args ...interface{}) Println(args ...interface{}) Warnln(args ...interface{}) + Warningln(args ...interface{}) Errorln(args ...interface{}) + Fatalln(args ...interface{}) + Panicln(args ...interface{}) } // SFLogger Snowflake logger interface to expose FieldLogger defined in logrus type SFLogger interface { LogEntry - WithContext(ctx ...context.Context) LogEntry + WithField(key string, value interface{}) LogEntry + WithFields(fields Fields) LogEntry + WithError(err error) LogEntry + WithTime(t time.Time) LogEntry SetLogLevel(level string) error GetLogLevel() string + WithContext(ctx ...context.Context) LogEntry SetOutput(output io.Writer) CloseFileOnLoggerReplace(file *os.File) error Replace(newLogger *SFLogger) @@ -148,9 +162,11 @@ func closeLogFile(file *os.File) { // WithContext return Entry to include fields in context func (log *defaultLogger) WithContext(ctxs ...context.Context) LogEntry { + if !log.enabled { + return log + } fields := context2Fields(ctxs...) - m := map[string]any(*fields) - return &entryBridge{log.inner.WithFields(m)} + return log.WithFields(*fields) } // CreateDefaultLogger return a new instance of SFLogger with default config @@ -170,6 +186,27 @@ type entryBridge struct { *rlog.Entry } +// WithTime overrides the time of the log entry. +func (log *defaultLogger) WithTime(t time.Time) LogEntry { + return &entryBridge{log.inner.WithTime(t)} +} + +// WithError overrides the error of the log entry. +func (log *defaultLogger) WithError(err error) LogEntry { + return &entryBridge{log.inner.WithError(err)} +} + +// WithFields add a map of fields to the log entry. +func (log *defaultLogger) WithFields(fields Fields) LogEntry { + m := map[string]any(fields) + return &entryBridge{log.inner.WithFields(m)} +} + +// WithField adds a single key/value pair to the log entry. +func (log *defaultLogger) WithField(key string, value interface{}) LogEntry { + return &entryBridge{log.inner.WithField(key, value)} +} + func (log *defaultLogger) Tracef(format string, args ...interface{}) { if log.enabled { log.inner.Tracef(format, args...) @@ -200,12 +237,30 @@ 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) Trace(args ...interface{}) { if log.enabled { log.inner.Trace(args...) @@ -236,12 +291,30 @@ 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) Traceln(args ...interface{}) { if log.enabled { log.inner.Traceln(args...) @@ -272,12 +345,30 @@ 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...) + } +} + // SetOutput sets the logger output. func (log *defaultLogger) SetOutput(output io.Writer) { log.inner.SetOutput(output) @@ -293,8 +384,8 @@ func GetLogger() SFLogger { return logger } -func context2Fields(ctxs ...context.Context) *fields { - var fields = fields{} +func context2Fields(ctxs ...context.Context) *Fields { + var fields = Fields{} if len(ctxs) <= 0 { return &fields } diff --git a/log_test.go b/log_test.go index e55e0b5b3..d44616361 100644 --- a/log_test.go +++ b/log_test.go @@ -87,6 +87,10 @@ 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") @@ -128,6 +132,9 @@ 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") @@ -153,6 +160,86 @@ 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 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) { From 1670ee46b18aafe029cf374fd3c50a7475161317 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 13 Jan 2025 12:58:23 -0800 Subject: [PATCH 04/16] fixups to make diff cleaner --- log.go | 38 ++++++++++++++++--------------- log_test.go | 65 ++++++++++++----------------------------------------- 2 files changed, 34 insertions(+), 69 deletions(-) diff --git a/log.go b/log.go index fe539d527..d61fd3c60 100644 --- a/log.go +++ b/log.go @@ -162,9 +162,6 @@ func closeLogFile(file *os.File) { // WithContext return Entry to include fields in context func (log *defaultLogger) WithContext(ctxs ...context.Context) LogEntry { - if !log.enabled { - return log - } fields := context2Fields(ctxs...) return log.WithFields(*fields) } @@ -180,31 +177,36 @@ func CreateDefaultLogger() SFLogger { return &ret } -var _ LogEntry = &entryBridge{} // ensure entryBridge isa LogEntry. - -type entryBridge struct { - *rlog.Entry +// 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{}) LogEntry { + return &entryBridge{log.inner.WithField(key, value)} } -// WithTime overrides the time of the log entry. -func (log *defaultLogger) WithTime(t time.Time) LogEntry { - return &entryBridge{log.inner.WithTime(t)} +// Adds a struct of fields to the log entry. All it does is call `WithField` for +// each `Field`. +func (log *defaultLogger) WithFields(fields Fields) LogEntry { + m := map[string]any(fields) + return &entryBridge{log.inner.WithFields(m)} } -// WithError overrides the error of the log entry. +// 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) LogEntry { return &entryBridge{log.inner.WithError(err)} } -// WithFields add a map of fields to the log entry. -func (log *defaultLogger) WithFields(fields Fields) LogEntry { - m := map[string]any(fields) - return &entryBridge{log.inner.WithFields(m)} +// WithTime overrides the time of the log entry. +func (log *defaultLogger) WithTime(t time.Time) LogEntry { + return &entryBridge{log.inner.WithTime(t)} } -// WithField adds a single key/value pair to the log entry. -func (log *defaultLogger) WithField(key string, value interface{}) LogEntry { - return &entryBridge{log.inner.WithField(key, value)} +var _ LogEntry = &entryBridge{} // ensure entryBridge isa LogEntry. + +type entryBridge struct { + *rlog.Entry } func (log *defaultLogger) Tracef(format string, args ...interface{}) { diff --git a/log_test.go b/log_test.go index d44616361..7b8a56cda 100644 --- a/log_test.go +++ b/log_test.go @@ -5,9 +5,11 @@ package gosnowflake import ( "bytes" "context" + "errors" "fmt" "strings" "testing" + "time" rlog "github.com/sirupsen/logrus" ) @@ -174,69 +176,30 @@ func TestLogWithError(t *testing.T) { } } -func TestLogWithField(t *testing.T) { - logger := CreateDefaultLogger() +func TestLogWithTime(t *testing.T) { + logger := createTestLogger() buf := &bytes.Buffer{} logger.SetOutput(buf) - logger.WithField("field", "test").Info("hello") + ti := time.Now() + logger.WithTime(ti).Info("hello") + time.Sleep(3 * time.Second) + var strbuf = buf.String() - if !strings.Contains(strbuf, "field=test") { + if !strings.Contains(strbuf, ti.Format(time.RFC3339)) { t.Fatalf("unexpected string in output: %v", strbuf) } } -func TestLogLevelFunctions(t *testing.T) { - logger := createTestLogger() +func TestLogWithField(t *testing.T) { + logger := CreateDefaultLogger() 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. + logger.WithField("field", "test").Info("hello") 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) + if !strings.Contains(strbuf, "field=test") { + t.Fatalf("unexpected string in output: %v", strbuf) } } From 87f99ed40f4e9841acde156c13280ee1c7d855a8 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 13 Jan 2025 13:14:04 -0800 Subject: [PATCH 05/16] undo --- driver_test.go | 29 ----------------------------- 1 file changed, 29 deletions(-) diff --git a/driver_test.go b/driver_test.go index 8e766e17b..d6245653c 100644 --- a/driver_test.go +++ b/driver_test.go @@ -7,7 +7,6 @@ import ( "crypto/rsa" "database/sql" "database/sql/driver" - "encoding/json" "flag" "fmt" "net/http" @@ -51,16 +50,11 @@ 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") @@ -87,29 +81,6 @@ 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) From 10f841928a4baf929c6cccc7ba409445030d557a Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 13 Jan 2025 13:14:36 -0800 Subject: [PATCH 06/16] undo --- chunk_downloader.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/chunk_downloader.go b/chunk_downloader.go index fe7d0b6da..0a7021644 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).Warn("chunk idx: %v, err: %v. retrying (%v/%v)...", + logger.WithContext(scd.ctx).Warningf("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).Warn("chunk idx: %v, err: %v. no further retry", errc.Index, errc.Error) + logger.WithContext(scd.ctx).Warningf("chunk idx: %v, err: %v. no further retry", errc.Index, errc.Error) return errc.Error } default: From d18ddb25bb8826a2964cb0f5b8a6f3e02a163bec Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 13 Jan 2025 13:15:37 -0800 Subject: [PATCH 07/16] undo --- easy_logging_test.go | 1 + retry.go | 4 ++-- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/easy_logging_test.go b/easy_logging_test.go index 0b5baf968..70e62ef29 100644 --- a/easy_logging_test.go +++ b/easy_logging_test.go @@ -149,6 +149,7 @@ 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/retry.go b/retry.go index 7913a11e5..59d2fdf60 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).Warn( + logger.WithContext(r.ctx).Warningf( "failed http connection. err: %v. retrying...\n", err) } else { - logger.WithContext(r.ctx).Warn( + logger.WithContext(r.ctx).Warningf( "failed http connection. HTTP Status: %v. retrying...\n", res.StatusCode) res.Body.Close() } From f91df81cda4edd6f36c4e9ea7053f2dc2068006f Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Mon, 13 Jan 2025 13:23:02 -0800 Subject: [PATCH 08/16] undo --- s3_storage_client.go | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/s3_storage_client.go b/s3_storage_client.go index 7288065dc..35d962bfc 100644 --- a/s3_storage_client.go +++ b/s3_storage_client.go @@ -84,12 +84,11 @@ 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.Debugf(format, v...) + logger.WithField("logger", "S3").Debugf(format, v...) case logging.Warn: - logger.Warnf(format, v...) + logger.WithField("logger", "S3").Warnf(format, v...) } } From 6df823d54c9ffb35f7c2d63410386dd0f5a63f21 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 12:30:09 -0800 Subject: [PATCH 09/16] fix test --- ctx_test.go | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) diff --git a/ctx_test.go b/ctx_test.go index d6d7775a3..68b114620 100644 --- a/ctx_test.go +++ b/ctx_test.go @@ -3,8 +3,10 @@ package gosnowflake import ( + "bytes" "context" "fmt" + "strings" "testing" ) @@ -43,8 +45,23 @@ func TestLogCtx(t *testing.T) { var ctx1 = context.WithValue(context.Background(), SFSessionIDKey, "sessID1") var ctx2 = context.WithValue(context.Background(), SFSessionUserKey, "admin") + var b bytes.Buffer + logger.SetOutput(&b) + err := logger.SetLogLevel("trace") + if err != nil { + t.Error("could not set log level") + } 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. + s := b.String() + if len(s) <= 0 { + t.Error("nothing written") + } + if !strings.Contains(s, "LOG_SESSION_ID=sessID1") { + t.Error("context ctx1 keys/values not logged") + } + if !strings.Contains(s, "LOG_USER=admin") { + t.Error("context ctx2 keys/values not logged") + } } From 8f24481b149dcda203cbae9f648136367bd857f5 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:02:49 -0800 Subject: [PATCH 10/16] higher level of backwards compat --- async_test.go | 2 ++ ctx_test.go | 4 ++-- log.go | 48 +++++++++++++++++++++++++++++++++++++++++++++++- log_test.go | 19 +++++++++++++++++++ 4 files changed, 70 insertions(+), 3 deletions(-) diff --git a/async_test.go b/async_test.go index c209c3893..d713efe24 100644 --- a/async_test.go +++ b/async_test.go @@ -163,6 +163,7 @@ func retrieveRows(rows *sql.Rows, ch chan string) { } func TestLongRunningAsyncQuery(t *testing.T) { + t.Skip() conn := openConn(t) defer conn.Close() @@ -198,6 +199,7 @@ func TestLongRunningAsyncQuery(t *testing.T) { } func TestLongRunningAsyncQueryFetchResultByID(t *testing.T) { + t.Skip() runDBTest(t, func(dbt *DBTest) { queryIDChan := make(chan string, 1) ctx := WithAsyncMode(context.Background()) diff --git a/ctx_test.go b/ctx_test.go index 68b114620..c87b1e90f 100644 --- a/ctx_test.go +++ b/ctx_test.go @@ -46,8 +46,8 @@ func TestLogCtx(t *testing.T) { var ctx2 = context.WithValue(context.Background(), SFSessionUserKey, "admin") var b bytes.Buffer - logger.SetOutput(&b) - err := logger.SetLogLevel("trace") + log.SetOutput(&b) + err := log.SetLogLevel("trace") if err != nil { t.Error("could not set log level") } diff --git a/log.go b/log.go index d61fd3c60..a2d6eb960 100644 --- a/log.go +++ b/log.go @@ -43,6 +43,13 @@ var LogKeys = [...]contextKey{SFSessionIDKey, SFSessionUserKey} // Fields type Fields map[string]any +// ConvertibleEntry returns the underlying logrus Entry struct. +type ConvertibleEntry interface { + ToEntry() *rlog.Entry +} + +// LogEntry allows for logging using a snapshot of field values, similar to logrus.Entry. +// No references to logrus or other implementat specific logging should be placed into this interface. type LogEntry interface { Tracef(format string, args ...interface{}) Debugf(format string, args ...interface{}) @@ -75,7 +82,8 @@ type LogEntry interface { Panicln(args ...interface{}) } -// SFLogger Snowflake logger interface to expose FieldLogger defined in logrus +// SFLogger Snowflake logger interface which abstracts away the underlying logging mechanism. +// No references to logrus or other implementat specific logging should be placed into this interface. type SFLogger interface { LogEntry WithField(key string, value interface{}) LogEntry @@ -204,11 +212,16 @@ func (log *defaultLogger) WithTime(t time.Time) LogEntry { } var _ LogEntry = &entryBridge{} // ensure entryBridge isa LogEntry. +var _ ConvertibleEntry = &entryBridge{} type entryBridge struct { *rlog.Entry } +func (entry *entryBridge) ToEntry() *rlog.Entry { + return entry.Entry +} + func (log *defaultLogger) Tracef(format string, args ...interface{}) { if log.enabled { log.inner.Tracef(format, args...) @@ -371,11 +384,44 @@ func (log *defaultLogger) Panicln(args ...interface{}) { } } +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) diff --git a/log_test.go b/log_test.go index 7b8a56cda..8d9007f9a 100644 --- a/log_test.go +++ b/log_test.go @@ -34,6 +34,9 @@ func TestIsLevelEnabled(t *testing.T) { func TestLogFunction(t *testing.T) { logger := createTestLogger() buf := &bytes.Buffer{} + var formatter = rlog.TextFormatter{CallerPrettyfier: SFCallerPrettyfier} + logger.SetFormatter(&formatter) + logger.SetReportCaller(true) logger.SetOutput(buf) err := logger.SetLogLevel("trace") if err != nil { @@ -289,3 +292,19 @@ func TestLogMaskSecrets(t *testing.T) { t.Fatalf("expected that password would be masked. WithContext was used, but got: %v", strbuf) } } + +func TestLogEntryConversion(t *testing.T) { + log := createTestLogger() + e := log.WithField("k", 1) + l, ok := e.(ConvertibleEntry) + if !ok { + t.Fatalf("expected a ConvertibleEntry") + } + v, ok := l.ToEntry().Data["k"] + if !ok { + t.Fatalf("should be able to access the underlying rlog.Entry") + } + if v.(int) != 1 { + t.Fatalf("expected value to be 1") + } +} From 5f8b1fd557acc2ebe5c5fa1814594c4f1d2b65ec Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:12:15 -0800 Subject: [PATCH 11/16] even less changes --- async_test.go | 2 -- driver_test.go | 29 +++++++++++++++++++++++++++++ log.go | 4 ++-- log_test.go | 20 +++++++++++++------- 4 files changed, 44 insertions(+), 11 deletions(-) diff --git a/async_test.go b/async_test.go index d713efe24..c209c3893 100644 --- a/async_test.go +++ b/async_test.go @@ -163,7 +163,6 @@ func retrieveRows(rows *sql.Rows, ch chan string) { } func TestLongRunningAsyncQuery(t *testing.T) { - t.Skip() conn := openConn(t) defer conn.Close() @@ -199,7 +198,6 @@ func TestLongRunningAsyncQuery(t *testing.T) { } func TestLongRunningAsyncQueryFetchResultByID(t *testing.T) { - t.Skip() runDBTest(t, func(dbt *DBTest) { queryIDChan := make(chan string, 1) ctx := WithAsyncMode(context.Background()) diff --git a/driver_test.go b/driver_test.go index ba465dd5a..f5d42f9d4 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/log.go b/log.go index a2d6eb960..1e251b04e 100644 --- a/log.go +++ b/log.go @@ -131,7 +131,7 @@ func (log *defaultLogger) SetLogLevel(level string) error { if err != nil { return err } - log.inner.Level = actualLevel + log.inner.SetLevel(actualLevel) } return nil } @@ -141,7 +141,7 @@ func (log *defaultLogger) GetLogLevel() string { if !log.enabled { return "OFF" } - return log.inner.Level.String() + return log.inner.GetLevel().String() } // CloseFileOnLoggerReplace set a file to be closed when releasing resources occupied by the logger diff --git a/log_test.go b/log_test.go index 8d9007f9a..e39f3cdab 100644 --- a/log_test.go +++ b/log_test.go @@ -22,12 +22,21 @@ func createTestLogger() *defaultLogger { func TestIsLevelEnabled(t *testing.T) { logger := createTestLogger() - err := logger.SetLogLevel("trace") + logger.SetLevel(rlog.TraceLevel) + if !logger.IsLevelEnabled(rlog.TraceLevel) { + t.Fatalf("log level should be trace but is %v", logger.GetLevel()) + } +} + +func TestLogLevelEnabled(t *testing.T) { + var log SFLogger + log = createTestLogger() + err := log.SetLogLevel("info") 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()) + if log.GetLogLevel() != "info" { + t.Fatalf("log level should be trace but is %v", log.GetLogLevel()) } } @@ -38,10 +47,7 @@ func TestLogFunction(t *testing.T) { logger.SetFormatter(&formatter) logger.SetReportCaller(true) logger.SetOutput(buf) - err := logger.SetLogLevel("trace") - if err != nil { - t.Fatalf("log level could not be set %v", err) - } + logger.SetLevel(rlog.TraceLevel) logger.Trace("hello world") logger.Tracef("log %v", "format") From cbd4cd7a2f10d6859a6fcf67ff6b9d5528802434 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:16:21 -0800 Subject: [PATCH 12/16] more cleanup --- driver_test.go | 29 ----------------------------- log.go | 12 ++++++++++++ log_test.go | 6 +++--- 3 files changed, 15 insertions(+), 32 deletions(-) diff --git a/driver_test.go b/driver_test.go index f5d42f9d4..ba465dd5a 100644 --- a/driver_test.go +++ b/driver_test.go @@ -7,7 +7,6 @@ import ( "crypto/rsa" "database/sql" "database/sql/driver" - "encoding/json" "flag" "fmt" "net/http" @@ -51,16 +50,11 @@ 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") @@ -87,29 +81,6 @@ 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/log.go b/log.go index 1e251b04e..924517d38 100644 --- a/log.go +++ b/log.go @@ -211,6 +211,10 @@ func (log *defaultLogger) WithTime(t time.Time) LogEntry { return &entryBridge{log.inner.WithTime(t)} } +func (log *defaultLogger) Logf(level rlog.Level, format string, args ...interface{}) { + log.inner.Logf(level, format, args...) +} + var _ LogEntry = &entryBridge{} // ensure entryBridge isa LogEntry. var _ ConvertibleEntry = &entryBridge{} @@ -276,6 +280,14 @@ func (log *defaultLogger) Panicf(format string, args ...interface{}) { } } +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...) diff --git a/log_test.go b/log_test.go index e39f3cdab..30e15e17f 100644 --- a/log_test.go +++ b/log_test.go @@ -49,9 +49,9 @@ func TestLogFunction(t *testing.T) { logger.SetOutput(buf) logger.SetLevel(rlog.TraceLevel) - logger.Trace("hello world") - logger.Tracef("log %v", "format") - logger.Traceln("log line") + logger.Log(rlog.TraceLevel, "hello world") + logger.Logf(rlog.TraceLevel, "log %v", "format") + logger.Logln(rlog.TraceLevel, "log line") var strbuf = buf.String() if !strings.Contains(strbuf, "hello world") && From ee9f8f35e8cd9c4fae73ff665fd9caf92ecd1c67 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:20:27 -0800 Subject: [PATCH 13/16] undo --- log.go | 4 ++-- log_test.go | 54 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 56 insertions(+), 2 deletions(-) diff --git a/log.go b/log.go index 924517d38..4637416c0 100644 --- a/log.go +++ b/log.go @@ -284,8 +284,8 @@ 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) Logln(level rlog.Level, args ...interface{}) { + log.inner.Logln(level, args...) } func (log *defaultLogger) Trace(args ...interface{}) { diff --git a/log_test.go b/log_test.go index 30e15e17f..26918df1e 100644 --- a/log_test.go +++ b/log_test.go @@ -212,6 +212,60 @@ func TestLogWithField(t *testing.T) { } } +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) { From 3975959ad2833d3852c7948acb38904ca71acce2 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:23:11 -0800 Subject: [PATCH 14/16] clean diff --- log.go | 8 ++++---- log_test.go | 54 ----------------------------------------------------- 2 files changed, 4 insertions(+), 58 deletions(-) diff --git a/log.go b/log.go index 4637416c0..08a963446 100644 --- a/log.go +++ b/log.go @@ -284,10 +284,6 @@ func (log *defaultLogger) Log(level rlog.Level, args ...interface{}) { log.inner.Log(level, args...) } -func (log *defaultLogger) Logln(level rlog.Level, args ...interface{}) { - log.inner.Logln(level, args...) -} - func (log *defaultLogger) Trace(args ...interface{}) { if log.enabled { log.inner.Trace(args...) @@ -342,6 +338,10 @@ func (log *defaultLogger) Panic(args ...interface{}) { } } +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...) diff --git a/log_test.go b/log_test.go index 26918df1e..30e15e17f 100644 --- a/log_test.go +++ b/log_test.go @@ -212,60 +212,6 @@ func TestLogWithField(t *testing.T) { } } -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) { From 2dcc0ac77d37e5e7a33ff9b286f6573d3c96a987 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:34:36 -0800 Subject: [PATCH 15/16] more cleanup --- log.go | 1 - log_test.go | 5 ++--- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/log.go b/log.go index 08a963446..94f266fe5 100644 --- a/log.go +++ b/log.go @@ -89,7 +89,6 @@ type SFLogger interface { WithField(key string, value interface{}) LogEntry WithFields(fields Fields) LogEntry WithError(err error) LogEntry - WithTime(t time.Time) LogEntry SetLogLevel(level string) error GetLogLevel() string diff --git a/log_test.go b/log_test.go index 30e15e17f..9b024bf86 100644 --- a/log_test.go +++ b/log_test.go @@ -29,8 +29,7 @@ func TestIsLevelEnabled(t *testing.T) { } func TestLogLevelEnabled(t *testing.T) { - var log SFLogger - log = createTestLogger() + log := CreateDefaultLogger() // via the SFLogger interface. err := log.SetLogLevel("info") if err != nil { t.Fatalf("log level could not be set %v", err) @@ -300,7 +299,7 @@ func TestLogMaskSecrets(t *testing.T) { } func TestLogEntryConversion(t *testing.T) { - log := createTestLogger() + log := CreateDefaultLogger() e := log.WithField("k", 1) l, ok := e.(ConvertibleEntry) if !ok { From 45f7c8542364dad978c3fd5c678ab6fde770fc01 Mon Sep 17 00:00:00 2001 From: Rick Reitmaier Date: Fri, 17 Jan 2025 13:41:05 -0800 Subject: [PATCH 16/16] put function logging back in --- log.go | 58 +++++++++++++++++++++++++++++++++++++++++++++++++++++ log_test.go | 54 +++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 112 insertions(+) diff --git a/log.go b/log.go index 94f266fe5..81b15db67 100644 --- a/log.go +++ b/log.go @@ -283,6 +283,10 @@ 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...) @@ -337,6 +341,60 @@ func (log *defaultLogger) Panic(args ...interface{}) { } } +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...) } diff --git a/log_test.go b/log_test.go index 9b024bf86..011cc2379 100644 --- a/log_test.go +++ b/log_test.go @@ -211,6 +211,60 @@ func TestLogWithField(t *testing.T) { } } +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) {