diff --git a/internal/kv/field.go b/internal/kv/field.go new file mode 100644 index 000000000..b3f0c4a06 --- /dev/null +++ b/internal/kv/field.go @@ -0,0 +1,404 @@ +package kv + +import ( + "encoding/json" + "fmt" + "reflect" + "strconv" + "time" + + "github.com/ydb-platform/ydb-go-sdk/v3/internal/version" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/xstring" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +const nilPtr = "" + +// KeyValue represents typed log field (a key-value pair). Adapters should determine +// KeyValue's type based on Type and use the corresponding getter method to retrieve +// the value: +// +// switch f.Type() { +// case logs.IntType: +// var i int = f.Int() +// // handle int value +// case logs.StringType: +// var s string = f.String() +// // handle string value +// //... +// } +// +// Getter methods must not be called on fields with wrong Type (e.g. calling String() +// on fields with Type != StringType). +// KeyValue must not be initialized directly as a struct literal. +type KeyValue struct { + ftype FieldType + key string + + vint int64 + vstr string + vany interface{} +} + +func (f KeyValue) Type() FieldType { + return f.ftype +} + +func (f KeyValue) Key() string { + return f.key +} + +// StringValue is a value getter for fields with StringType type +func (f KeyValue) StringValue() string { + f.checkType(StringType) + + return f.vstr +} + +// IntValue is a value getter for fields with IntType type +func (f KeyValue) IntValue() int { + f.checkType(IntType) + + return int(f.vint) +} + +// Int64Value is a value getter for fields with Int64Type type +func (f KeyValue) Int64Value() int64 { + f.checkType(Int64Type) + + return f.vint +} + +// BoolValue is a value getter for fields with BoolType type +func (f KeyValue) BoolValue() bool { + f.checkType(BoolType) + + return f.vint != 0 +} + +// DurationValue is a value getter for fields with DurationType type +func (f KeyValue) DurationValue() time.Duration { + f.checkType(DurationType) + + return time.Nanosecond * time.Duration(f.vint) +} + +// StringsValue is a value getter for fields with StringsType type +func (f KeyValue) StringsValue() []string { + f.checkType(StringsType) + if f.vany == nil { + return nil + } + val, ok := f.vany.([]string) + if !ok { + panic(fmt.Sprintf("unsupported type conversion from %T to []string", val)) + } + + return val +} + +// ErrorValue is a value getter for fields with ErrorType type +func (f KeyValue) ErrorValue() error { + f.checkType(ErrorType) + if f.vany == nil { + return nil + } + val, ok := f.vany.(error) + if !ok { + panic(fmt.Sprintf("unsupported type conversion from %T to error", val)) + } + + return val +} + +// AnyValue is a value getter for fields with AnyType type +func (f KeyValue) AnyValue() interface{} { + switch f.ftype { + case AnyType: + return f.vany + case IntType: + return f.IntValue() + case Int64Type: + return f.Int64Value() + case StringType: + return f.StringValue() + case BoolType: + return f.BoolValue() + case DurationType: + return f.DurationValue() + case StringsType: + return f.StringsValue() + case ErrorType: + return f.ErrorValue() + case StringerType: + return f.Stringer() + default: + panic(fmt.Sprintf("unknown FieldType %d", f.ftype)) + } +} + +// Stringer is a value getter for fields with StringerType type +func (f KeyValue) Stringer() fmt.Stringer { + f.checkType(StringerType) + if f.vany == nil { + return nil + } + val, ok := f.vany.(fmt.Stringer) + if !ok { + panic(fmt.Sprintf("unsupported type conversion from %T to fmt.Stringer", val)) + } + + return val +} + +// Panics on type mismatch +func (f KeyValue) checkType(want FieldType) { + if f.ftype != want { + panic(fmt.Sprintf("bad type. have: %s, want: %s", f.ftype, want)) + } +} + +// Returns default string representation of KeyValue value. +// It should be used by adapters that don't support f.Type directly. +func (f KeyValue) String() string { + switch f.ftype { + case IntType, Int64Type: + return strconv.FormatInt(f.vint, 10) + case StringType: + return f.vstr + case BoolType: + return strconv.FormatBool(f.BoolValue()) + case DurationType: + return f.DurationValue().String() + case StringsType: + return fmt.Sprintf("%v", f.StringsValue()) + case ErrorType: + if f.vany == nil { + return nilPtr + } + + val, ok := f.vany.(error) + if !ok { + panic(fmt.Sprintf("unsupported type conversion from %T to fmt.Stringer", val)) + } + + if val == nil { + return "" + } + + return f.ErrorValue().Error() + case AnyType: + if f.vany == nil { + return nilPtr + } + if v := reflect.ValueOf(f.vany); v.Type().Kind() == reflect.Ptr { + if v.IsNil() { + return nilPtr + } + + return v.Type().String() + "(" + fmt.Sprint(v.Elem()) + ")" + } + + return fmt.Sprint(f.vany) + case StringerType: + return f.Stringer().String() + default: + panic(fmt.Sprintf("unknown FieldType %d", f.ftype)) + } +} + +// String constructs KeyValue with StringType +func String(k, v string) KeyValue { + return KeyValue{ + ftype: StringType, + key: k, + vstr: v, + } +} + +// Int constructs KeyValue with IntType +func Int(k string, v int) KeyValue { + return KeyValue{ + ftype: IntType, + key: k, + vint: int64(v), + } +} + +func Int64(k string, v int64) KeyValue { + return KeyValue{ + ftype: Int64Type, + key: k, + vint: v, + } +} + +// Bool constructs KeyValue with BoolType +func Bool(key string, value bool) KeyValue { + var vint int64 + if value { + vint = 1 + } else { + vint = 0 + } + + return KeyValue{ + ftype: BoolType, + key: key, + vint: vint, + } +} + +// Duration constructs KeyValue with DurationType +func Duration(key string, value time.Duration) KeyValue { + return KeyValue{ + ftype: DurationType, + key: key, + vint: value.Nanoseconds(), + } +} + +// Strings constructs KeyValue with StringsType +func Strings(key string, value []string) KeyValue { + return KeyValue{ + ftype: StringsType, + key: key, + vany: value, + } +} + +// NamedError constructs KeyValue with ErrorType +func NamedError(key string, value error) KeyValue { + return KeyValue{ + ftype: ErrorType, + key: key, + vany: value, + } +} + +// Error is the same as NamedError("error", value) +func Error(value error) KeyValue { + return NamedError("error", value) +} + +// Any constructs untyped KeyValue. +func Any(key string, value interface{}) KeyValue { + return KeyValue{ + ftype: AnyType, + key: key, + vany: value, + } +} + +// Stringer constructs KeyValue with StringerType. If value is nil, +// resulting KeyValue will be of AnyType instead of StringerType. +func Stringer(key string, value fmt.Stringer) KeyValue { + if value == nil { + return Any(key, nil) + } + + return KeyValue{ + ftype: StringerType, + key: key, + vany: value, + } +} + +// FieldType indicates type info about the KeyValue. This enum might be extended in future releases. +// Adapters that don't support some FieldType value should use KeyValue.Fallback() for marshaling. +type FieldType int + +const ( + // InvalidType indicates that KeyValue was not initialized correctly. Adapters + // should either ignore such field or issue an error. No value getters should + // be called on field with such type. + InvalidType FieldType = iota + + IntType + Int64Type + StringType + BoolType + DurationType + + // StringsType corresponds to []string + StringsType + + ErrorType + // AnyType indicates that the KeyValue is untyped. Adapters should use + // reflection-based approached to marshal this field. + AnyType + + // StringerType corresponds to fmt.Stringer + StringerType + + endType +) + +func (ft FieldType) String() (typeName string) { + switch ft { + case InvalidType: + typeName = "invalid" + case IntType: + typeName = "int" + case Int64Type: + typeName = "int64" + case StringType: + typeName = "string" + case BoolType: + typeName = "bool" + case DurationType: + typeName = "time.Duration" + case StringsType: + typeName = "[]string" + case ErrorType: + typeName = "error" + case AnyType: + typeName = "any" + case StringerType: + typeName = "stringer" + case endType: + typeName = "endtype" + default: + panic("not implemented") + } + + return typeName +} + +// Latency creates KeyValue "latency": time.Since(start) +func Latency(start time.Time) KeyValue { + return Duration("latency", time.Since(start)) +} + +// Version creates KeyValue "version": version.Version +func Version() KeyValue { + return String("version", version.Version) +} + +type Endpoints []trace.EndpointInfo + +func (ee Endpoints) String() string { + b := xstring.Buffer() + defer b.Free() + b.WriteByte('[') + for i, e := range ee { + if i != 0 { + b.WriteByte(',') + } + b.WriteString(e.String()) + } + b.WriteByte(']') + + return b.String() +} + +type Metadata map[string][]string + +func (m Metadata) String() string { + b, err := json.Marshal(m) + if err != nil { + return fmt.Sprintf("error:%s", err) + } + + return xstring.FromBytes(b) +} diff --git a/log/field_test.go b/internal/kv/field_test.go similarity index 97% rename from log/field_test.go rename to internal/kv/field_test.go index af2dfb217..3dd9e0f58 100644 --- a/log/field_test.go +++ b/internal/kv/field_test.go @@ -1,4 +1,4 @@ -package log +package kv import ( "errors" @@ -16,7 +16,7 @@ func (s stringerTest) String() string { func TestField_String(t *testing.T) { for _, tt := range []struct { - f Field + f KeyValue want string panic bool fail bool @@ -42,7 +42,7 @@ func TestField_String(t *testing.T) { {f: Any("any_string_ptr", func(v string) *string { return &v }("string pointer")), want: "*string(string pointer)"}, //nolint:lll {f: Any("any_string_nil", (*string)(nil)), want: ""}, {f: Stringer("stringer", stringerTest("stringerTest")), want: "stringerTest"}, - {f: Field{ftype: InvalidType, key: "invalid"}, want: "", panic: true}, + {f: KeyValue{ftype: InvalidType, key: "invalid"}, want: "", panic: true}, } { t.Run(tt.f.key, func(t *testing.T) { // Known fieldType, but String() panics with it. @@ -65,7 +65,7 @@ func TestField_String(t *testing.T) { func TestField_AnyValue(t *testing.T) { for _, tt := range []struct { name string - f Field + f KeyValue want interface{} }{ {name: "int", f: Int("any", 1), want: 1}, diff --git a/log/coordination.go b/log/coordination.go index ef1a15001..00cf2883d 100644 --- a/log/coordination.go +++ b/log/coordination.go @@ -5,6 +5,7 @@ import ( "strconv" "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/trace" ) @@ -29,8 +30,8 @@ func internalCoordination( return func(info trace.CoordinationNewDoneInfo) { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } }, @@ -40,19 +41,19 @@ func internalCoordination( } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "create") l.Log(ctx, "start", - String("path", info.Path), + kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationCreateNodeDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "fail", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } @@ -63,19 +64,19 @@ func internalCoordination( } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "alter") l.Log(ctx, "start", - String("path", info.Path), + kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationAlterNodeDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "fail", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } @@ -86,19 +87,19 @@ func internalCoordination( } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "drop") l.Log(ctx, "start", - String("path", info.Path), + kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationDropNodeDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "fail", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } @@ -109,19 +110,19 @@ func internalCoordination( } ctx := with(*info.Context, TRACE, "ydb", "coordination", "node", "describe") l.Log(ctx, "start", - String("path", info.Path), + kv.String("path", info.Path), ) start := time.Now() return func(info trace.CoordinationDescribeNodeDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "fail", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } @@ -137,12 +138,12 @@ func internalCoordination( return func(info trace.CoordinationSessionDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "fail", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } @@ -158,12 +159,12 @@ func internalCoordination( return func(info trace.CoordinationCloseDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "fail", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } @@ -182,9 +183,9 @@ func internalCoordination( return func(info trace.CoordinationStreamNewDoneInfo) { l.Log(ctx, "done", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } }, @@ -194,8 +195,8 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "started") l.Log(ctx, "", - String("sessionID", strconv.FormatUint(info.SessionID, 10)), - String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)), + kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)), + kv.String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)), ) }, OnSessionStartTimeout: func(info trace.CoordinationSessionStartTimeoutInfo) { @@ -204,7 +205,7 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "start", "timeout") l.Log(ctx, "", - Stringer("timeout", info.Timeout), + kv.Stringer("timeout", info.Timeout), ) }, OnSessionKeepAliveTimeout: func(info trace.CoordinationSessionKeepAliveTimeoutInfo) { @@ -213,8 +214,8 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "keepAlive", "timeout") l.Log(ctx, "", - Stringer("timeout", info.Timeout), - Stringer("lastGoodResponseTime", info.LastGoodResponseTime), + kv.Stringer("timeout", info.Timeout), + kv.Stringer("lastGoodResponseTime", info.LastGoodResponseTime), ) }, OnSessionStopped: func(info trace.CoordinationSessionStoppedInfo) { @@ -223,8 +224,8 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stopped") l.Log(ctx, "", - String("sessionID", strconv.FormatUint(info.SessionID, 10)), - String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)), + kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)), + kv.String("expectedSessionID", strconv.FormatUint(info.SessionID, 10)), ) }, OnSessionStopTimeout: func(info trace.CoordinationSessionStopTimeoutInfo) { @@ -233,7 +234,7 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stop", "timeout") l.Log(ctx, "", - Stringer("timeout", info.Timeout), + kv.Stringer("timeout", info.Timeout), ) }, OnSessionClientTimeout: func(info trace.CoordinationSessionClientTimeoutInfo) { @@ -242,8 +243,8 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "client", "timeout") l.Log(ctx, "", - Stringer("timeout", info.Timeout), - Stringer("lastGoodResponseTime", info.LastGoodResponseTime), + kv.Stringer("timeout", info.Timeout), + kv.Stringer("lastGoodResponseTime", info.LastGoodResponseTime), ) }, OnSessionServerExpire: func(info trace.CoordinationSessionServerExpireInfo) { @@ -252,7 +253,7 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "server", "expire") l.Log(ctx, "", - Stringer("failure", info.Failure), + kv.Stringer("failure", info.Failure), ) }, OnSessionServerError: func(info trace.CoordinationSessionServerErrorInfo) { @@ -261,7 +262,7 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "server", "error") l.Log(ctx, "", - Stringer("failure", info.Failure), + kv.Stringer("failure", info.Failure), ) }, OnSessionReceive: func( @@ -278,10 +279,10 @@ func internalCoordination( return func(info trace.CoordinationSessionReceiveDoneInfo) { l.Log(ctx, "done", - latencyField(start), - Error(info.Error), - Stringer("response", info.Response), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Stringer("response", info.Response), + kv.Version(), ) } }, @@ -291,7 +292,7 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "receive", "unexpected") l.Log(ctx, "", - Stringer("response", info.Response), + kv.Stringer("response", info.Response), ) }, OnSessionStop: func(info trace.CoordinationSessionStopInfo) { @@ -300,7 +301,7 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "stop") l.Log(ctx, "", - String("sessionID", strconv.FormatUint(info.SessionID, 10)), + kv.String("sessionID", strconv.FormatUint(info.SessionID, 10)), ) }, OnSessionStart: func( @@ -317,9 +318,9 @@ func internalCoordination( return func(info trace.CoordinationSessionStartDoneInfo) { l.Log(ctx, "done", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } }, @@ -333,15 +334,15 @@ func internalCoordination( } ctx := with(context.Background(), TRACE, "ydb", "coordination", "session", "send") l.Log(ctx, "start", - Stringer("request", info.Request), + kv.Stringer("request", info.Request), ) start := time.Now() return func(info trace.CoordinationSessionSendDoneInfo) { l.Log(ctx, "done", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } }, diff --git a/log/discovery.go b/log/discovery.go index 452c61876..24c382687 100644 --- a/log/discovery.go +++ b/log/discovery.go @@ -3,6 +3,7 @@ package log import ( "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/trace" ) @@ -18,22 +19,22 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) { } ctx := with(*info.Context, DEBUG, "ydb", "discovery", "list", "endpoints") l.Log(ctx, "start", - String("address", info.Address), - String("database", info.Database), + kv.String("address", info.Address), + kv.String("database", info.Database), ) start := time.Now() return func(info trace.DiscoveryDiscoverDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), - Stringer("endpoints", endpoints(info.Endpoints)), + kv.Latency(start), + kv.Stringer("endpoints", kv.Endpoints(info.Endpoints)), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -49,15 +50,15 @@ func internalDiscovery(l Logger, d trace.Detailer) (t trace.Discovery) { return func(info trace.DiscoveryWhoAmIDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("user", info.User), - Strings("groups", info.Groups), + kv.Latency(start), + kv.String("user", info.User), + kv.Strings("groups", info.Groups), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } diff --git a/log/driver.go b/log/driver.go index 45363a64a..c6848f0a3 100644 --- a/log/driver.go +++ b/log/driver.go @@ -4,6 +4,7 @@ import ( "context" "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/internal/secret" "github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors" "github.com/ydb-platform/ydb-go-sdk/v3/trace" @@ -29,22 +30,22 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { target := info.Target addresses := info.Resolved l.Log(ctx, "start", - String("target", target), - Strings("resolved", addresses), + kv.String("target", target), + kv.Strings("resolved", addresses), ) return func(info trace.DriverResolveDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - String("target", target), - Strings("resolved", addresses), + kv.String("target", target), + kv.Strings("resolved", addresses), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - String("target", target), - Strings("resolved", addresses), - versionField(), + kv.Error(info.Error), + kv.String("target", target), + kv.Strings("resolved", addresses), + kv.Version(), ) } } @@ -58,28 +59,28 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { secure := info.Secure ctx := with(*info.Context, DEBUG, "ydb", "driver", "resolver", "init") l.Log(ctx, "start", - String("endpoint", endpoint), - String("database", database), - Bool("secure", secure), + kv.String("endpoint", endpoint), + kv.String("database", database), + kv.Bool("secure", secure), ) start := time.Now() return func(info trace.DriverInitDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - String("endpoint", endpoint), - String("database", database), - Bool("secure", secure), - latencyField(start), + kv.String("endpoint", endpoint), + kv.String("database", database), + kv.Bool("secure", secure), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - String("endpoint", endpoint), - String("database", database), - Bool("secure", secure), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.String("endpoint", endpoint), + kv.String("database", database), + kv.Bool("secure", secure), + kv.Latency(start), + kv.Version(), ) } } @@ -95,13 +96,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -113,22 +114,22 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "dial") endpoint := info.Endpoint l.Log(ctx, "start", - Stringer("endpoint", endpoint), + kv.Stringer("endpoint", endpoint), ) start := time.Now() return func(info trace.DriverConnDialDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - Stringer("endpoint", endpoint), - latencyField(start), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - Stringer("endpoint", endpoint), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), + kv.Version(), ) } } @@ -140,16 +141,16 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(context.Background(), TRACE, "ydb", "driver", "conn", "state", "change") endpoint := info.Endpoint l.Log(ctx, "start", - Stringer("endpoint", endpoint), - Stringer("state", info.State), + kv.Stringer("endpoint", endpoint), + kv.Stringer("state", info.State), ) start := time.Now() return func(info trace.DriverConnStateChangeDoneInfo) { l.Log(ctx, "done", - Stringer("endpoint", endpoint), - latencyField(start), - Stringer("state", info.State), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), + kv.Stringer("state", info.State), ) } }, @@ -160,22 +161,22 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "close") endpoint := info.Endpoint l.Log(ctx, "start", - Stringer("endpoint", endpoint), + kv.Stringer("endpoint", endpoint), ) start := time.Now() return func(info trace.DriverConnCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - Stringer("endpoint", endpoint), - latencyField(start), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - Stringer("endpoint", endpoint), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), + kv.Version(), ) } } @@ -188,27 +189,27 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { endpoint := info.Endpoint method := string(info.Method) l.Log(ctx, "start", - Stringer("endpoint", endpoint), - String("method", method), + kv.Stringer("endpoint", endpoint), + kv.String("method", method), ) start := time.Now() return func(info trace.DriverConnInvokeDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - Stringer("endpoint", endpoint), - String("method", method), - latencyField(start), - Stringer("metadata", metadata(info.Metadata)), + kv.Stringer("endpoint", endpoint), + kv.String("method", method), + kv.Latency(start), + kv.Stringer("metadata", kv.Metadata(info.Metadata)), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - Stringer("endpoint", endpoint), - String("method", method), - latencyField(start), - Stringer("metadata", metadata(info.Metadata)), - versionField(), + kv.Error(info.Error), + kv.Stringer("endpoint", endpoint), + kv.String("method", method), + kv.Latency(start), + kv.Stringer("metadata", kv.Metadata(info.Metadata)), + kv.Version(), ) } } @@ -225,25 +226,25 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { endpoint := info.Endpoint method := string(info.Method) l.Log(ctx, "start", - Stringer("endpoint", endpoint), - String("method", method), + kv.Stringer("endpoint", endpoint), + kv.String("method", method), ) start := time.Now() return func(info trace.DriverConnNewStreamDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - Stringer("endpoint", endpoint), - String("method", method), - latencyField(start), + kv.Stringer("endpoint", endpoint), + kv.String("method", method), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - Stringer("endpoint", endpoint), - String("method", method), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Stringer("endpoint", endpoint), + kv.String("method", method), + kv.Latency(start), + kv.Version(), ) } } @@ -261,13 +262,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverConnStreamCloseSendDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -283,13 +284,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverConnStreamSendMsgDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -305,13 +306,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverConnStreamRecvMsgDoneInfo) { if xerrors.HideEOF(info.Error) == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -324,18 +325,18 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { endpoint := info.Endpoint cause := info.Cause l.Log(ctx, "start", - Stringer("endpoint", endpoint), - NamedError("cause", cause), + kv.Stringer("endpoint", endpoint), + kv.NamedError("cause", cause), ) start := time.Now() return func(info trace.DriverConnBanDoneInfo) { l.Log(WithLevel(ctx, WARN), "done", - Stringer("endpoint", endpoint), - latencyField(start), - Stringer("state", info.State), - NamedError("cause", cause), - versionField(), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), + kv.Stringer("state", info.State), + kv.NamedError("cause", cause), + kv.Version(), ) } }, @@ -346,15 +347,15 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { ctx := with(*info.Context, TRACE, "ydb", "driver", "conn", "allow") endpoint := info.Endpoint l.Log(ctx, "start", - Stringer("endpoint", endpoint), + kv.Stringer("endpoint", endpoint), ) start := time.Now() return func(info trace.DriverConnAllowDoneInfo) { l.Log(ctx, "done", - Stringer("endpoint", endpoint), - latencyField(start), - Stringer("state", info.State), + kv.Stringer("endpoint", endpoint), + kv.Latency(start), + kv.Stringer("state", info.State), ) } }, @@ -366,25 +367,25 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { name := info.Name event := info.Event l.Log(ctx, "start", - String("name", name), - String("event", event), + kv.String("name", name), + kv.String("event", event), ) start := time.Now() return func(info trace.DriverRepeaterWakeUpDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - String("name", name), - String("event", event), - latencyField(start), + kv.String("name", name), + kv.String("event", event), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - String("name", name), - String("event", event), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.String("name", name), + kv.String("event", event), + kv.Latency(start), + kv.Version(), ) } } @@ -399,7 +400,7 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverBalancerInitDoneInfo) { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } }, @@ -414,13 +415,13 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverBalancerCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -440,14 +441,14 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverBalancerChooseEndpointDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Stringer("endpoint", info.Endpoint), + kv.Latency(start), + kv.Stringer("endpoint", info.Endpoint), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -462,17 +463,17 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { } ctx := with(*info.Context, TRACE, "ydb", "driver", "balancer", "update") l.Log(ctx, "start", - Bool("needLocalDC", info.NeedLocalDC), + kv.Bool("needLocalDC", info.NeedLocalDC), ) start := time.Now() return func(info trace.DriverBalancerUpdateDoneInfo) { l.Log(ctx, "done", - latencyField(start), - Stringer("endpoints", endpoints(info.Endpoints)), - Stringer("added", endpoints(info.Added)), - Stringer("dropped", endpoints(info.Dropped)), - String("detectedLocalDC", info.LocalDC), + kv.Latency(start), + kv.Stringer("endpoints", kv.Endpoints(info.Endpoints)), + kv.Stringer("added", kv.Endpoints(info.Added)), + kv.Stringer("dropped", kv.Endpoints(info.Dropped)), + kv.String("detectedLocalDC", info.LocalDC), ) } }, @@ -487,15 +488,15 @@ func internalDriver(l Logger, d trace.Detailer) trace.Driver { return func(info trace.DriverGetCredentialsDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("token", secret.Token(info.Token)), + kv.Latency(start), + kv.String("token", secret.Token(info.Token)), ) } else { l.Log(WithLevel(ctx, ERROR), "done", - Error(info.Error), - latencyField(start), - String("token", secret.Token(info.Token)), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.String("token", secret.Token(info.Token)), + kv.Version(), ) } } diff --git a/log/field.go b/log/field.go index 17479d3c6..3caab871d 100644 --- a/log/field.go +++ b/log/field.go @@ -1,408 +1,25 @@ package log import ( - "encoding/json" - "fmt" - "reflect" - "strconv" - "time" - - "github.com/ydb-platform/ydb-go-sdk/v3/internal/version" - "github.com/ydb-platform/ydb-go-sdk/v3/internal/xstring" - "github.com/ydb-platform/ydb-go-sdk/v3/trace" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" ) -const nilPtr = "" - -// Field represents typed log field (a key-value pair). Adapters should determine -// Field's type based on Type and use the corresponding getter method to retrieve -// the value: -// -// switch f.Type() { -// case logs.IntType: -// var i int = f.Int() -// // handle int value -// case logs.StringType: -// var s string = f.String() -// // handle string value -// //... -// } -// -// Getter methods must not be called on fields with wrong Type (e.g. calling String() -// on fields with Type != StringType). -// Field must not be initialized directly as a struct literal. -type Field struct { - ftype FieldType - key string - - vint int64 - vstr string - vany interface{} -} - -func (f Field) Type() FieldType { - return f.ftype -} - -func (f Field) Key() string { - return f.key -} - -// StringValue is a value getter for fields with StringType type -func (f Field) StringValue() string { - f.checkType(StringType) - - return f.vstr -} - -// IntValue is a value getter for fields with IntType type -func (f Field) IntValue() int { - f.checkType(IntType) - - return int(f.vint) -} - -// Int64Value is a value getter for fields with Int64Type type -func (f Field) Int64Value() int64 { - f.checkType(Int64Type) - - return f.vint -} - -// BoolValue is a value getter for fields with BoolType type -func (f Field) BoolValue() bool { - f.checkType(BoolType) - - return f.vint != 0 -} - -// DurationValue is a value getter for fields with DurationType type -func (f Field) DurationValue() time.Duration { - f.checkType(DurationType) - - return time.Nanosecond * time.Duration(f.vint) -} - -// StringsValue is a value getter for fields with StringsType type -func (f Field) StringsValue() []string { - f.checkType(StringsType) - if f.vany == nil { - return nil - } - val, ok := f.vany.([]string) - if !ok { - panic(fmt.Sprintf("unsupported type conversion from %T to []string", val)) - } - - return val -} - -// ErrorValue is a value getter for fields with ErrorType type -func (f Field) ErrorValue() error { - f.checkType(ErrorType) - if f.vany == nil { - return nil - } - val, ok := f.vany.(error) - if !ok { - panic(fmt.Sprintf("unsupported type conversion from %T to error", val)) - } - - return val -} - -// AnyValue is a value getter for fields with AnyType type -func (f Field) AnyValue() interface{} { - switch f.ftype { - case AnyType: - return f.vany - case IntType: - return f.IntValue() - case Int64Type: - return f.Int64Value() - case StringType: - return f.StringValue() - case BoolType: - return f.BoolValue() - case DurationType: - return f.DurationValue() - case StringsType: - return f.StringsValue() - case ErrorType: - return f.ErrorValue() - case StringerType: - return f.Stringer() - default: - panic(fmt.Sprintf("unknown FieldType %d", f.ftype)) - } -} - -// Stringer is a value getter for fields with StringerType type -func (f Field) Stringer() fmt.Stringer { - f.checkType(StringerType) - if f.vany == nil { - return nil - } - val, ok := f.vany.(fmt.Stringer) - if !ok { - panic(fmt.Sprintf("unsupported type conversion from %T to fmt.Stringer", val)) - } - - return val -} - -// Panics on type mismatch -func (f Field) checkType(want FieldType) { - if f.ftype != want { - panic(fmt.Sprintf("bad type. have: %s, want: %s", f.ftype, want)) - } -} - -// Returns default string representation of Field value. -// It should be used by adapters that don't support f.Type directly. -func (f Field) String() string { - switch f.ftype { - case IntType, Int64Type: - return strconv.FormatInt(f.vint, 10) - case StringType: - return f.vstr - case BoolType: - return strconv.FormatBool(f.BoolValue()) - case DurationType: - return f.DurationValue().String() - case StringsType: - return fmt.Sprintf("%v", f.StringsValue()) - case ErrorType: - if f.vany == nil { - return nilPtr - } - - val, ok := f.vany.(error) - if !ok { - panic(fmt.Sprintf("unsupported type conversion from %T to fmt.Stringer", val)) - } - - if val == nil { - return "" - } - - return f.ErrorValue().Error() - case AnyType: - if f.vany == nil { - return nilPtr - } - if v := reflect.ValueOf(f.vany); v.Type().Kind() == reflect.Ptr { - if v.IsNil() { - return nilPtr - } - - return v.Type().String() + "(" + fmt.Sprint(v.Elem()) + ")" - } - - return fmt.Sprint(f.vany) - case StringerType: - return f.Stringer().String() - default: - panic(fmt.Sprintf("unknown FieldType %d", f.ftype)) - } -} - -// String constructs Field with StringType -func String(k, v string) Field { - return Field{ - ftype: StringType, - key: k, - vstr: v, - } -} - -// Int constructs Field with IntType -func Int(k string, v int) Field { - return Field{ - ftype: IntType, - key: k, - vint: int64(v), - } -} - -func Int64(k string, v int64) Field { - return Field{ - ftype: Int64Type, - key: k, - vint: v, - } -} - -// Bool constructs Field with BoolType -func Bool(key string, value bool) Field { - var vint int64 - if value { - vint = 1 - } else { - vint = 0 - } - - return Field{ - ftype: BoolType, - key: key, - vint: vint, - } -} - -// Duration constructs Field with DurationType -func Duration(key string, value time.Duration) Field { - return Field{ - ftype: DurationType, - key: key, - vint: value.Nanoseconds(), - } -} - -// Strings constructs Field with StringsType -func Strings(key string, value []string) Field { - return Field{ - ftype: StringsType, - key: key, - vany: value, - } -} - -// NamedError constructs Field with ErrorType -func NamedError(key string, value error) Field { - return Field{ - ftype: ErrorType, - key: key, - vany: value, - } -} - -// Error is the same as NamedError("error", value) -func Error(value error) Field { - return NamedError("error", value) -} - -// Any constructs untyped Field. -func Any(key string, value interface{}) Field { - return Field{ - ftype: AnyType, - key: key, - vany: value, - } -} - -// Stringer constructs Field with StringerType. If value is nil, -// resulting Field will be of AnyType instead of StringerType. -func Stringer(key string, value fmt.Stringer) Field { - if value == nil { - return Any(key, nil) - } - - return Field{ - ftype: StringerType, - key: key, - vany: value, - } -} - -// FieldType indicates type info about the Field. This enum might be extended in future releases. -// Adapters that don't support some FieldType value should use Field.Fallback() for marshaling. -type FieldType int +type ( + Field = kv.KeyValue +) const ( - // InvalidType indicates that Field was not initialized correctly. Adapters - // should either ignore such field or issue an error. No value getters should - // be called on field with such type. - InvalidType FieldType = iota - - IntType - Int64Type - StringType - BoolType - DurationType - - // StringsType corresponds to []string - StringsType - - ErrorType - // AnyType indicates that the Field is untyped. Adapters should use - // reflection-based approached to marshal this field. - AnyType - - // StringerType corresponds to fmt.Stringer - StringerType - - endType + IntType = kv.IntType + Int64Type = kv.Int64Type + StringType = kv.StringType + BoolType = kv.BoolType + DurationType = kv.DurationType + StringsType = kv.StringsType + ErrorType = kv.ErrorType + AnyType = kv.AnyType + StringerType = kv.StringerType ) -func (ft FieldType) String() (typeName string) { - switch ft { - case InvalidType: - typeName = "invalid" - case IntType: - typeName = "int" - case Int64Type: - typeName = "int64" - case StringType: - typeName = "string" - case BoolType: - typeName = "bool" - case DurationType: - typeName = "time.Duration" - case StringsType: - typeName = "[]string" - case ErrorType: - typeName = "error" - case AnyType: - typeName = "any" - case StringerType: - typeName = "stringer" - case endType: - typeName = "endtype" - default: - panic("not implemented") - } - - return typeName -} - -// latencyField creates Field "latency": time.Since(start) -func latencyField(start time.Time) Field { - return Duration("latency", time.Since(start)) -} - -// versionField creates Field "version": version.Version -func versionField() Field { - return String("version", version.Version) -} - -type endpoints []trace.EndpointInfo - -func (ee endpoints) String() string { - b := xstring.Buffer() - defer b.Free() - b.WriteByte('[') - for i, e := range ee { - if i != 0 { - b.WriteByte(',') - } - b.WriteString(e.String()) - } - b.WriteByte(']') - - return b.String() -} - -type metadata map[string][]string - -func (m metadata) String() string { - b, err := json.Marshal(m) - if err != nil { - return fmt.Sprintf("error:%s", err) - } - - return xstring.FromBytes(b) -} - func appendFieldByCondition(condition bool, ifTrueField Field, fields ...Field) []Field { if condition { fields = append(fields, ifTrueField) diff --git a/log/query.go b/log/query.go index ec60dbffb..1a3c4e296 100644 --- a/log/query.go +++ b/log/query.go @@ -3,6 +3,7 @@ package log import ( "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors" "github.com/ydb-platform/ydb-go-sdk/v3/trace" ) @@ -28,7 +29,7 @@ func internalQuery( return func(info trace.QueryNewDoneInfo) { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } }, @@ -43,7 +44,7 @@ func internalQuery( return func(info trace.QueryCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -51,9 +52,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -68,8 +69,8 @@ func internalQuery( return func(info trace.QueryPoolNewDoneInfo) { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), - Int("Limit", info.Limit), + kv.Latency(start), + kv.Int("Limit", info.Limit), ) } }, @@ -84,7 +85,7 @@ func internalQuery( return func(info trace.QueryPoolCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -92,9 +93,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -110,7 +111,7 @@ func internalQuery( return func(info trace.QueryPoolTryDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -118,9 +119,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -136,8 +137,8 @@ func internalQuery( return func(info trace.QueryPoolWithDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Int("Attempts", info.Attempts), + kv.Latency(start), + kv.Int("Attempts", info.Attempts), ) } else { lvl := ERROR @@ -145,10 +146,10 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - Int("Attempts", info.Attempts), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Int("Attempts", info.Attempts), + kv.Version(), ) } } @@ -164,7 +165,7 @@ func internalQuery( return func(info trace.QueryPoolPutDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -172,9 +173,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -190,7 +191,7 @@ func internalQuery( return func(info trace.QueryPoolGetDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -198,9 +199,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -216,8 +217,8 @@ func internalQuery( return func(info trace.QueryDoDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Int("attempts", info.Attempts), + kv.Latency(start), + kv.Int("attempts", info.Attempts), ) } else { lvl := ERROR @@ -225,10 +226,10 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - Int("attempts", info.Attempts), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Int("attempts", info.Attempts), + kv.Version(), ) } } @@ -244,8 +245,8 @@ func internalQuery( return func(info trace.QueryDoTxDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Int("attempts", info.Attempts), + kv.Latency(start), + kv.Int("attempts", info.Attempts), ) } else { lvl := ERROR @@ -253,10 +254,10 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - Int("attempts", info.Attempts), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Int("attempts", info.Attempts), + kv.Version(), ) } } @@ -272,7 +273,7 @@ func internalQuery( return func(info trace.QueryExecDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := ERROR @@ -280,9 +281,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -298,7 +299,7 @@ func internalQuery( return func(info trace.QueryQueryDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := ERROR @@ -306,9 +307,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -324,7 +325,7 @@ func internalQuery( return func(info trace.QueryQueryRowDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := ERROR @@ -332,9 +333,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -350,7 +351,7 @@ func internalQuery( return func(info trace.QueryQueryResultSetDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := ERROR @@ -358,9 +359,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -376,9 +377,9 @@ func internalQuery( return func(info trace.QuerySessionCreateDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("session_id", info.Session.ID()), - String("session_status", info.Session.Status()), + kv.Latency(start), + kv.String("session_id", info.Session.ID()), + kv.String("session_status", info.Session.Status()), ) } else { lvl := WARN @@ -386,9 +387,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "done", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -399,15 +400,15 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "attach") l.Log(ctx, "start", - String("session_id", info.Session.ID()), - String("session_status", info.Session.Status()), + kv.String("session_id", info.Session.ID()), + kv.String("session_status", info.Session.Status()), ) start := time.Now() return func(info trace.QuerySessionAttachDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -415,9 +416,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -428,15 +429,15 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "delete") l.Log(ctx, "start", - String("session_id", info.Session.ID()), - String("session_status", info.Session.Status()), + kv.String("session_id", info.Session.ID()), + kv.String("session_status", info.Session.Status()), ) start := time.Now() return func(info trace.QuerySessionDeleteDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -444,9 +445,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -457,16 +458,16 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "exec") l.Log(ctx, "start", - String("SessionID", info.Session.ID()), - String("SessionStatus", info.Session.Status()), - String("Query", info.Query), + kv.String("SessionID", info.Session.ID()), + kv.String("SessionStatus", info.Session.Status()), + kv.String("Query", info.Query), ) start := time.Now() return func(info trace.QuerySessionExecDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -474,9 +475,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -487,16 +488,16 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "query") l.Log(ctx, "start", - String("SessionID", info.Session.ID()), - String("SessionStatus", info.Session.Status()), - String("Query", info.Query), + kv.String("SessionID", info.Session.ID()), + kv.String("SessionStatus", info.Session.Status()), + kv.String("Query", info.Query), ) start := time.Now() return func(info trace.QuerySessionQueryDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -504,9 +505,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -517,16 +518,16 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "session", "begin") l.Log(ctx, "start", - String("SessionID", info.Session.ID()), - String("SessionStatus", info.Session.Status()), + kv.String("SessionID", info.Session.ID()), + kv.String("SessionStatus", info.Session.Status()), ) start := time.Now() return func(info trace.QuerySessionBeginDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, DEBUG), "done", - latencyField(start), - String("TransactionID", info.Tx.ID()), + kv.Latency(start), + kv.String("TransactionID", info.Tx.ID()), ) } else { lvl := WARN @@ -534,9 +535,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -547,16 +548,16 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "transaction", "exec") l.Log(ctx, "start", - String("SessionID", info.Session.ID()), - String("TransactionID", info.Tx.ID()), - String("SessionStatus", info.Session.Status()), + kv.String("SessionID", info.Session.ID()), + kv.String("TransactionID", info.Tx.ID()), + kv.String("SessionStatus", info.Session.Status()), ) start := time.Now() return func(info trace.QueryTxExecDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, DEBUG), "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -564,9 +565,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -577,16 +578,16 @@ func internalQuery( } ctx := with(*info.Context, TRACE, "ydb", "query", "transaction", "query") l.Log(ctx, "start", - String("SessionID", info.Session.ID()), - String("TransactionID", info.Tx.ID()), - String("SessionStatus", info.Session.Status()), + kv.String("SessionID", info.Session.ID()), + kv.String("TransactionID", info.Tx.ID()), + kv.String("SessionStatus", info.Session.Status()), ) start := time.Now() return func(info trace.QueryTxQueryDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, DEBUG), "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -594,9 +595,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -612,7 +613,7 @@ func internalQuery( return func(info trace.QueryResultNewDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -620,9 +621,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -638,8 +639,8 @@ func internalQuery( return func(info trace.QueryResultNextPartDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - Stringer("stats", info.Stats), - latencyField(start), + kv.Stringer("stats", info.Stats), + kv.Latency(start), ) } else { lvl := WARN @@ -647,9 +648,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -669,7 +670,7 @@ func internalQuery( return func(info trace.QueryResultNextResultSetDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -677,9 +678,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -695,7 +696,7 @@ func internalQuery( return func(info trace.QueryResultCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { lvl := WARN @@ -703,9 +704,9 @@ func internalQuery( lvl = DEBUG } l.Log(WithLevel(ctx, lvl), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } diff --git a/log/retry.go b/log/retry.go index df772bdb3..76bd713ed 100644 --- a/log/retry.go +++ b/log/retry.go @@ -3,6 +3,7 @@ package log import ( "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors" "github.com/ydb-platform/ydb-go-sdk/v3/retry" "github.com/ydb-platform/ydb-go-sdk/v3/trace" @@ -22,17 +23,17 @@ func internalRetry(l Logger, d trace.Detailer) (t trace.Retry) { label := info.Label idempotent := info.Idempotent l.Log(ctx, "start", - String("label", label), - Bool("idempotent", idempotent), + kv.String("label", label), + kv.Bool("idempotent", idempotent), ) start := time.Now() return func(info trace.RetryLoopDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - String("label", label), - latencyField(start), - Int("attempts", info.Attempts), + kv.String("label", label), + kv.Latency(start), + kv.Int("attempts", info.Attempts), ) } else { lvl := ERROR @@ -41,14 +42,14 @@ func internalRetry(l Logger, d trace.Detailer) (t trace.Retry) { } m := retry.Check(info.Error) l.Log(WithLevel(ctx, lvl), "failed", - Error(info.Error), - String("label", label), - latencyField(start), - Int("attempts", info.Attempts), - Bool("retryable", m.MustRetry(idempotent)), - Int64("code", m.StatusCode()), - Bool("deleteSession", m.IsRetryObjectValid()), - versionField(), + kv.Error(info.Error), + kv.String("label", label), + kv.Latency(start), + kv.Int("attempts", info.Attempts), + kv.Bool("retryable", m.MustRetry(idempotent)), + kv.Int64("code", m.StatusCode()), + kv.Bool("deleteSession", m.IsRetryObjectValid()), + kv.Version(), ) } } diff --git a/log/scripting.go b/log/scripting.go index fc2d16009..10611c2dd 100644 --- a/log/scripting.go +++ b/log/scripting.go @@ -3,6 +3,7 @@ package log import ( "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/trace" ) @@ -24,15 +25,15 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return func(info trace.ScriptingExecuteDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Int("resultSetCount", info.Result.ResultSetCount()), - NamedError("resultSetError", info.Result.Err()), + kv.Latency(start), + kv.Int("resultSetCount", info.Result.ResultSetCount()), + kv.NamedError("resultSetError", info.Result.Err()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -48,14 +49,14 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return func(info trace.ScriptingExplainDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("plan", info.Plan), + kv.Latency(start), + kv.String("plan", info.Plan), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -74,7 +75,7 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { query := info.Query l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", query), + kv.String("query", query), )..., ) start := time.Now() @@ -88,8 +89,8 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { l.Log(ctx, "intermediate") } else { l.Log(WithLevel(ctx, WARN), "intermediate failed", - Error(info.Error), - versionField(), + kv.Error(info.Error), + kv.Version(), ) } @@ -97,17 +98,17 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { if info.Error == nil { l.Log(ctx, "done", appendFieldByCondition(l.logQuery, - String("query", query), - latencyField(start), + kv.String("query", query), + kv.Latency(start), )..., ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Error(info.Error), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), )..., ) } @@ -125,13 +126,13 @@ func internalScripting(l *wrapper, d trace.Detailer) (t trace.Scripting) { return func(info trace.ScriptingCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } diff --git a/log/sql.go b/log/sql.go index 70a87be49..6d13a8ea9 100644 --- a/log/sql.go +++ b/log/sql.go @@ -4,6 +4,7 @@ import ( "context" "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/retry" "github.com/ydb-platform/ydb-go-sdk/v3/trace" ) @@ -30,15 +31,15 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnectorConnectDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, DEBUG), "connected", - latencyField(start), - String("session_id", info.Session.ID()), - String("session_status", info.Session.Status()), + kv.Latency(start), + kv.String("session_id", info.Session.ID()), + kv.String("session_status", info.Session.Status()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -55,13 +56,13 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnPingDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -77,13 +78,13 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -99,13 +100,13 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnBeginDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -117,7 +118,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "prepare", "stmt") l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", info.Query), + kv.String("query", info.Query), )..., ) query := info.Query @@ -126,15 +127,15 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnPrepareDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Error(info.Error), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), )..., ) } @@ -147,7 +148,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "exec") l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", info.Query), + kv.String("query", info.Query), )..., ) query := info.Query @@ -157,19 +158,19 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnExecDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { m := retry.Check(info.Error) l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Bool("retryable", m.MustRetry(idempotent)), - Int64("code", m.StatusCode()), - Bool("deleteSession", m.IsRetryObjectValid()), - Error(info.Error), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Bool("retryable", m.MustRetry(idempotent)), + kv.Int64("code", m.StatusCode()), + kv.Bool("deleteSession", m.IsRetryObjectValid()), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), )..., ) } @@ -182,7 +183,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "conn", "query") l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", info.Query), + kv.String("query", info.Query), )..., ) query := info.Query @@ -192,19 +193,19 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLConnQueryDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { m := retry.Check(info.Error) l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Bool("retryable", m.MustRetry(idempotent)), - Int64("code", m.StatusCode()), - Bool("deleteSession", m.IsRetryObjectValid()), - Error(info.Error), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Bool("retryable", m.MustRetry(idempotent)), + kv.Int64("code", m.StatusCode()), + kv.Bool("deleteSession", m.IsRetryObjectValid()), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), )..., ) } @@ -221,13 +222,13 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLTxCommitDoneInfo) { if info.Error == nil { l.Log(ctx, "committed", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -243,13 +244,13 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLTxRollbackDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -265,13 +266,13 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLStmtCloseDoneInfo) { if info.Error == nil { l.Log(ctx, "closed", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "close failed", - Error(info.Error), - latencyField(start), - versionField(), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -283,7 +284,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "stmt", "exec") l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", info.Query), + kv.String("query", info.Query), )..., ) query := info.Query @@ -292,16 +293,16 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLStmtExecDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - Error(info.Error), - latencyField(start), + kv.Error(info.Error), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Error(info.Error), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), )..., ) } @@ -314,7 +315,7 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { ctx := with(*info.Context, TRACE, "ydb", "database", "sql", "stmt", "query") l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", info.Query), + kv.String("query", info.Query), )..., ) query := info.Query @@ -323,15 +324,15 @@ func internalDatabaseSQL(l *wrapper, d trace.Detailer) (t trace.DatabaseSQL) { return func(info trace.DatabaseSQLStmtQueryDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Error(info.Error), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Error(info.Error), + kv.Latency(start), + kv.Version(), )..., ) } diff --git a/log/table.go b/log/table.go index 11a19f1c7..d84e09451 100644 --- a/log/table.go +++ b/log/table.go @@ -4,6 +4,7 @@ import ( "context" "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors" "github.com/ydb-platform/ydb-go-sdk/v3/retry" "github.com/ydb-platform/ydb-go-sdk/v3/trace" @@ -27,8 +28,8 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableInitDoneInfo) { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), - Int("size_max", info.Limit), + kv.Latency(start), + kv.Int("size_max", info.Limit), ) } }, @@ -43,13 +44,13 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableCloseDoneInfo) { if info.Error == nil { l.Log(WithLevel(ctx, INFO), "done", - latencyField(start), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -66,18 +67,18 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { idempotent := info.Idempotent label := info.Label l.Log(ctx, "start", - Bool("idempotent", idempotent), - String("label", label), + kv.Bool("idempotent", idempotent), + kv.String("label", label), ) start := time.Now() return func(info trace.TableDoDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Bool("idempotent", idempotent), - String("label", label), - Int("attempts", info.Attempts), + kv.Latency(start), + kv.Bool("idempotent", idempotent), + kv.String("label", label), + kv.Int("attempts", info.Attempts), ) } else { lvl := ERROR @@ -86,15 +87,15 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } m := retry.Check(info.Error) l.Log(WithLevel(ctx, lvl), "done", - latencyField(start), - Bool("idempotent", idempotent), - String("label", label), - Int("attempts", info.Attempts), - Error(info.Error), - Bool("retryable", m.MustRetry(idempotent)), - Int64("code", m.StatusCode()), - Bool("deleteSession", m.IsRetryObjectValid()), - versionField(), + kv.Latency(start), + kv.Bool("idempotent", idempotent), + kv.String("label", label), + kv.Int("attempts", info.Attempts), + kv.Error(info.Error), + kv.Bool("retryable", m.MustRetry(idempotent)), + kv.Int64("code", m.StatusCode()), + kv.Bool("deleteSession", m.IsRetryObjectValid()), + kv.Version(), ) } } @@ -111,18 +112,18 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { idempotent := info.Idempotent label := info.Label l.Log(ctx, "start", - Bool("idempotent", idempotent), - String("label", label), + kv.Bool("idempotent", idempotent), + kv.String("label", label), ) start := time.Now() return func(info trace.TableDoTxDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Bool("idempotent", idempotent), - String("label", label), - Int("attempts", info.Attempts), + kv.Latency(start), + kv.Bool("idempotent", idempotent), + kv.String("label", label), + kv.Int("attempts", info.Attempts), ) } else { lvl := WARN @@ -131,15 +132,15 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } m := retry.Check(info.Error) l.Log(WithLevel(ctx, lvl), "done", - latencyField(start), - Bool("idempotent", idempotent), - String("label", label), - Int("attempts", info.Attempts), - Error(info.Error), - Bool("retryable", m.MustRetry(idempotent)), - Int64("code", m.StatusCode()), - Bool("deleteSession", m.IsRetryObjectValid()), - versionField(), + kv.Latency(start), + kv.Bool("idempotent", idempotent), + kv.String("label", label), + kv.Int("attempts", info.Attempts), + kv.Error(info.Error), + kv.Bool("retryable", m.MustRetry(idempotent)), + kv.Int64("code", m.StatusCode()), + kv.Bool("deleteSession", m.IsRetryObjectValid()), + kv.Version(), ) } } @@ -159,17 +160,17 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { return func(info trace.TableCreateSessionDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - Int("attempts", info.Attempts), - String("session_id", info.Session.ID()), - String("session_status", info.Session.Status()), + kv.Latency(start), + kv.Int("attempts", info.Attempts), + kv.String("session_id", info.Session.ID()), + kv.String("session_status", info.Session.Status()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - latencyField(start), - Int("attempts", info.Attempts), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Int("attempts", info.Attempts), + kv.Error(info.Error), + kv.Version(), ) } } @@ -186,20 +187,20 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { if info.Error == nil { if info.Session != nil { l.Log(ctx, "done", - latencyField(start), - String("id", info.Session.ID()), + kv.Latency(start), + kv.String("id", info.Session.ID()), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - latencyField(start), - versionField(), + kv.Latency(start), + kv.Version(), ) } } else { l.Log(WithLevel(ctx, WARN), "failed", - latencyField(start), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Error(info.Error), + kv.Version(), ) } } @@ -211,25 +212,25 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "delete") session := info.Session l.Log(ctx, "start", - String("id", info.Session.ID()), - String("status", info.Session.Status()), + kv.String("id", info.Session.ID()), + kv.String("status", info.Session.Status()), ) start := time.Now() return func(info trace.TableSessionDeleteDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -241,25 +242,25 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "keep", "alive") session := info.Session l.Log(ctx, "start", - String("id", session.ID()), - String("status", session.Status()), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) start := time.Now() return func(info trace.TableKeepAliveDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -277,9 +278,9 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { query := info.Query l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - String("query", info.Query), - String("id", session.ID()), - String("status", session.Status()), + kv.String("query", info.Query), + kv.String("id", session.ID()), + kv.String("status", session.Status()), )..., ) start := time.Now() @@ -288,24 +289,24 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { if info.Error == nil { l.Log(ctx, "done", appendFieldByCondition(l.logQuery, - Stringer("result", info.Result), + kv.Stringer("result", info.Result), appendFieldByCondition(l.logQuery, - String("query", query), - String("id", session.ID()), - String("status", session.Status()), - latencyField(start), + kv.String("query", query), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Latency(start), )..., )..., ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - String("query", query), - Error(info.Error), - String("id", session.ID()), - String("status", session.Status()), - latencyField(start), - versionField(), + kv.String("query", query), + kv.Error(info.Error), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Latency(start), + kv.Version(), )..., ) } @@ -324,9 +325,9 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { query := info.Query l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - Stringer("query", info.Query), - String("id", session.ID()), - String("status", session.Status()), + kv.Stringer("query", info.Query), + kv.String("id", session.ID()), + kv.String("status", session.Status()), )..., ) start := time.Now() @@ -336,25 +337,25 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { tx := info.Tx l.Log(ctx, "done", appendFieldByCondition(l.logQuery, - Stringer("query", query), - String("id", session.ID()), - String("tx", tx.ID()), - String("status", session.Status()), - Bool("prepared", info.Prepared), - NamedError("result_err", info.Result.Err()), - latencyField(start), + kv.Stringer("query", query), + kv.String("id", session.ID()), + kv.String("tx", tx.ID()), + kv.String("status", session.Status()), + kv.Bool("prepared", info.Prepared), + kv.NamedError("result_err", info.Result.Err()), + kv.Latency(start), )..., ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - Stringer("query", query), - Error(info.Error), - String("id", session.ID()), - String("status", session.Status()), - Bool("prepared", info.Prepared), - latencyField(start), - versionField(), + kv.Stringer("query", query), + kv.Error(info.Error), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Bool("prepared", info.Prepared), + kv.Latency(start), + kv.Version(), )..., ) } @@ -373,9 +374,9 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { query := info.Query l.Log(ctx, "start", appendFieldByCondition(l.logQuery, - Stringer("query", info.Query), - String("id", session.ID()), - String("status", session.Status()), + kv.Stringer("query", info.Query), + kv.String("id", session.ID()), + kv.String("status", session.Status()), )..., ) start := time.Now() @@ -384,22 +385,22 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { if info.Error == nil { l.Log(ctx, "done", appendFieldByCondition(l.logQuery, - Stringer("query", query), - Error(info.Error), - String("id", session.ID()), - String("status", session.Status()), - latencyField(start), + kv.Stringer("query", query), + kv.Error(info.Error), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Latency(start), )..., ) } else { l.Log(WithLevel(ctx, ERROR), "failed", appendFieldByCondition(l.logQuery, - Stringer("query", query), - Error(info.Error), - String("id", session.ID()), - String("status", session.Status()), - latencyField(start), - versionField(), + kv.Stringer("query", query), + kv.Error(info.Error), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Latency(start), + kv.Version(), )..., ) } @@ -416,25 +417,25 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "query", "stream", "read") session := info.Session l.Log(ctx, "start", - String("id", session.ID()), - String("status", session.Status()), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) start := time.Now() return func(info trace.TableSessionQueryStreamReadDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -450,26 +451,26 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "session", "tx", "begin") session := info.Session l.Log(ctx, "start", - String("id", session.ID()), - String("status", session.Status()), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) start := time.Now() return func(info trace.TableTxBeginDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - String("tx", info.Tx.ID()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", info.Tx.ID()), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -482,28 +483,28 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { session := info.Session tx := info.Tx l.Log(ctx, "start", - String("id", session.ID()), - String("status", session.Status()), - String("tx", info.Tx.ID()), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", info.Tx.ID()), ) start := time.Now() return func(info trace.TableTxCommitDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - String("tx", tx.ID()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", tx.ID()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - String("tx", tx.ID()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", tx.ID()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -520,28 +521,28 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { session := info.Session tx := info.Tx l.Log(ctx, "start", - String("id", session.ID()), - String("status", session.Status()), - String("tx", tx.ID()), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", tx.ID()), ) start := time.Now() return func(info trace.TableTxRollbackDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - String("tx", tx.ID()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", tx.ID()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - String("tx", tx.ID()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.String("tx", tx.ID()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -553,25 +554,25 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { ctx := with(*info.Context, TRACE, "ydb", "table", "pool", "put") session := info.Session l.Log(ctx, "start", - String("id", session.ID()), - String("status", session.Status()), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) start := time.Now() return func(info trace.TablePoolPutDoneInfo) { if info.Error == nil { l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), ) } else { l.Log(WithLevel(ctx, ERROR), "failed", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Error(info.Error), + kv.Version(), ) } } @@ -588,17 +589,17 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { if info.Error == nil { session := info.Session l.Log(ctx, "done", - latencyField(start), - String("id", session.ID()), - String("status", session.Status()), - Int("attempts", info.Attempts), + kv.Latency(start), + kv.String("id", session.ID()), + kv.String("status", session.Status()), + kv.Int("attempts", info.Attempts), ) } else { l.Log(WithLevel(ctx, WARN), "failed", - latencyField(start), - Int("attempts", info.Attempts), - Error(info.Error), - versionField(), + kv.Latency(start), + kv.Int("attempts", info.Attempts), + kv.Error(info.Error), + kv.Version(), ) } } @@ -609,11 +610,11 @@ func internalTable(l *wrapper, d trace.Detailer) (t trace.Table) { } ctx := with(context.Background(), TRACE, "ydb", "table", "pool", "state", "change") l.Log(WithLevel(ctx, DEBUG), "", - Int("limit", info.Limit), - Int("index", info.Index), - Int("idle", info.Idle), - Int("wait", info.Wait), - Int("create_in_progress", info.CreateInProgress), + kv.Int("limit", info.Limit), + kv.Int("index", info.Index), + kv.Int("idle", info.Idle), + kv.Int("wait", info.Wait), + kv.Int("create_in_progress", info.CreateInProgress), ) }, OnSessionBulkUpsert: nil, diff --git a/log/topic.go b/log/topic.go index 8e2d0d198..f8d420114 100644 --- a/log/topic.go +++ b/log/topic.go @@ -4,6 +4,7 @@ import ( "context" "time" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" "github.com/ydb-platform/ydb-go-sdk/v3/trace" ) @@ -26,8 +27,8 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderReconnectDoneInfo) { l.Log(WithLevel(ctx, INFO), "reconnected", - NamedError("reason", info.Reason), - latencyField(start), + kv.NamedError("reason", info.Reason), + kv.Latency(start), ) } } @@ -37,8 +38,8 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "reconnect", "request") l.Log(ctx, "start", - NamedError("reason", info.Reason), - Bool("was_sent", info.WasSent), + kv.NamedError("reason", info.Reason), + kv.Bool("was_sent", info.WasSent), ) } t.OnReaderPartitionReadStartResponse = func( @@ -50,28 +51,28 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "partition", "read", "start", "response") start := time.Now() l.Log(ctx, "start", - String("topic", info.Topic), - String("reader_connection_id", info.ReaderConnectionID), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), + kv.String("topic", info.Topic), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), ) return func(doneInfo trace.TopicReaderPartitionReadStartResponseDoneInfo) { fields := []Field{ - String("topic", info.Topic), - String("reader_connection_id", info.ReaderConnectionID), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), - latencyField(start), + kv.String("topic", info.Topic), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), + kv.Latency(start), } if doneInfo.CommitOffset != nil { fields = append(fields, - Int64("commit_offset", *doneInfo.CommitOffset), + kv.Int64("commit_offset", *doneInfo.CommitOffset), ) } if doneInfo.ReadOffset != nil { fields = append(fields, - Int64("read_offset", *doneInfo.ReadOffset), + kv.Int64("read_offset", *doneInfo.ReadOffset), ) } if doneInfo.Error == nil { @@ -79,8 +80,8 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } else { l.Log(WithLevel(ctx, WARN), "read partition response completed", append(fields, - Error(doneInfo.Error), - versionField(), + kv.Error(doneInfo.Error), + kv.Version(), )..., ) } @@ -95,30 +96,30 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "partition", "read", "stop", "response") start := time.Now() l.Log(ctx, "start", - String("reader_connection_id", info.ReaderConnectionID), - String("topic", info.Topic), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), - Int64("committed_offset", info.CommittedOffset), - Bool("graceful", info.Graceful)) + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.String("topic", info.Topic), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), + kv.Int64("committed_offset", info.CommittedOffset), + kv.Bool("graceful", info.Graceful)) return func(doneInfo trace.TopicReaderPartitionReadStopResponseDoneInfo) { fields := []Field{ - String("reader_connection_id", info.ReaderConnectionID), - String("topic", info.Topic), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), - Int64("committed_offset", info.CommittedOffset), - Bool("graceful", info.Graceful), - latencyField(start), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.String("topic", info.Topic), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), + kv.Int64("committed_offset", info.CommittedOffset), + kv.Bool("graceful", info.Graceful), + kv.Latency(start), } if doneInfo.Error == nil { l.Log(WithLevel(ctx, INFO), "reader partition stopped", fields...) } else { l.Log(WithLevel(ctx, WARN), "reader partition stopped", append(fields, - Error(doneInfo.Error), - versionField(), + kv.Error(doneInfo.Error), + kv.Version(), )..., ) } @@ -131,29 +132,29 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "commit") start := time.Now() l.Log(ctx, "start", - String("topic", info.Topic), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), - Int64("commit_start_offset", info.StartOffset), - Int64("commit_end_offset", info.EndOffset), + kv.String("topic", info.Topic), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), + kv.Int64("commit_start_offset", info.StartOffset), + kv.Int64("commit_end_offset", info.EndOffset), ) return func(doneInfo trace.TopicReaderCommitDoneInfo) { fields := []Field{ - String("topic", info.Topic), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), - Int64("commit_start_offset", info.StartOffset), - Int64("commit_end_offset", info.EndOffset), - latencyField(start), + kv.String("topic", info.Topic), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), + kv.Int64("commit_start_offset", info.StartOffset), + kv.Int64("commit_end_offset", info.EndOffset), + kv.Latency(start), } if doneInfo.Error == nil { l.Log(ctx, "committed", fields...) } else { l.Log(WithLevel(ctx, WARN), "committed", append(fields, - Error(doneInfo.Error), - versionField(), + kv.Error(doneInfo.Error), + kv.Version(), )..., ) } @@ -171,31 +172,31 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { commitInfo := info.CommitsInfo.GetCommitsInfo() for i := range commitInfo { l.Log(ctx, "start", - String("topic", commitInfo[i].Topic), - Int64("partitions_id", commitInfo[i].PartitionID), - Int64("partitions_session_id", commitInfo[i].PartitionSessionID), - Int64("commit_start_offset", commitInfo[i].StartOffset), - Int64("commit_end_offset", commitInfo[i].EndOffset), + kv.String("topic", commitInfo[i].Topic), + kv.Int64("partitions_id", commitInfo[i].PartitionID), + kv.Int64("partitions_session_id", commitInfo[i].PartitionSessionID), + kv.Int64("commit_start_offset", commitInfo[i].StartOffset), + kv.Int64("commit_end_offset", commitInfo[i].EndOffset), ) } return func(doneInfo trace.TopicReaderSendCommitMessageDoneInfo) { for i := range commitInfo { fields := []Field{ - String("topic", commitInfo[i].Topic), - Int64("partitions_id", commitInfo[i].PartitionID), - Int64("partitions_session_id", commitInfo[i].PartitionSessionID), - Int64("commit_start_offset", commitInfo[i].StartOffset), - Int64("commit_end_offset", commitInfo[i].EndOffset), - latencyField(start), + kv.String("topic", commitInfo[i].Topic), + kv.Int64("partitions_id", commitInfo[i].PartitionID), + kv.Int64("partitions_session_id", commitInfo[i].PartitionSessionID), + kv.Int64("commit_start_offset", commitInfo[i].StartOffset), + kv.Int64("commit_end_offset", commitInfo[i].EndOffset), + kv.Latency(start), } if doneInfo.Error == nil { l.Log(ctx, "done", fields...) } else { l.Log(WithLevel(ctx, WARN), "commit message sent", append(fields, - Error(doneInfo.Error), - versionField(), + kv.Error(doneInfo.Error), + kv.Version(), )..., ) } @@ -208,11 +209,11 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "committed", "notify") l.Log(ctx, "ack", - String("reader_connection_id", info.ReaderConnectionID), - String("topic", info.Topic), - Int64("partition_id", info.PartitionID), - Int64("partition_session_id", info.PartitionSessionID), - Int64("committed_offset", info.CommittedOffset), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.String("topic", info.Topic), + kv.Int64("partition_id", info.PartitionID), + kv.Int64("partition_session_id", info.PartitionSessionID), + kv.Int64("committed_offset", info.CommittedOffset), ) } t.OnReaderClose = func(info trace.TopicReaderCloseStartInfo) func(doneInfo trace.TopicReaderCloseDoneInfo) { @@ -222,22 +223,22 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "close") start := time.Now() l.Log(ctx, "done", - String("reader_connection_id", info.ReaderConnectionID), - NamedError("close_reason", info.CloseReason), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.NamedError("close_reason", info.CloseReason), ) return func(doneInfo trace.TopicReaderCloseDoneInfo) { fields := []Field{ - String("reader_connection_id", info.ReaderConnectionID), - latencyField(start), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Latency(start), } if doneInfo.CloseError == nil { l.Log(ctx, "closed", fields...) } else { l.Log(WithLevel(ctx, WARN), "closed", append(fields, - Error(doneInfo.CloseError), - versionField(), + kv.Error(doneInfo.CloseError), + kv.Version(), )..., ) } @@ -251,25 +252,25 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "init") start := time.Now() l.Log(ctx, "start", - String("pre_init_reader_connection_id", info.PreInitReaderConnectionID), - String("consumer", info.InitRequestInfo.GetConsumer()), - Strings("topics", info.InitRequestInfo.GetTopics()), + kv.String("pre_init_reader_connection_id", info.PreInitReaderConnectionID), + kv.String("consumer", info.InitRequestInfo.GetConsumer()), + kv.Strings("topics", info.InitRequestInfo.GetTopics()), ) return func(doneInfo trace.TopicReaderInitDoneInfo) { fields := []Field{ - String("pre_init_reader_connection_id", info.PreInitReaderConnectionID), - String("consumer", info.InitRequestInfo.GetConsumer()), - Strings("topics", info.InitRequestInfo.GetTopics()), - latencyField(start), + kv.String("pre_init_reader_connection_id", info.PreInitReaderConnectionID), + kv.String("consumer", info.InitRequestInfo.GetConsumer()), + kv.Strings("topics", info.InitRequestInfo.GetTopics()), + kv.Latency(start), } if doneInfo.Error == nil { l.Log(ctx, "topic reader stream initialized", fields...) } else { l.Log(WithLevel(ctx, WARN), "topic reader stream initialized", append(fields, - Error(doneInfo.Error), - versionField(), + kv.Error(doneInfo.Error), + kv.Version(), )..., ) } @@ -281,9 +282,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "error") l.Log(WithLevel(ctx, INFO), "stream error", - Error(info.Error), - String("reader_connection_id", info.ReaderConnectionID), - versionField(), + kv.Error(info.Error), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Version(), ) } t.OnReaderUpdateToken = func( @@ -297,7 +298,7 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "update", "token") start := time.Now() l.Log(ctx, "token updating...", - String("reader_connection_id", info.ReaderConnectionID), + kv.String("reader_connection_id", info.ReaderConnectionID), ) return func( @@ -305,34 +306,34 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ) func(doneInfo trace.OnReadStreamUpdateTokenDoneInfo) { if updateTokenInfo.Error == nil { l.Log(ctx, "got token", - String("reader_connection_id", info.ReaderConnectionID), - Int("token_len", updateTokenInfo.TokenLen), - latencyField(start), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("token_len", updateTokenInfo.TokenLen), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "got token", - Error(updateTokenInfo.Error), - String("reader_connection_id", info.ReaderConnectionID), - Int("token_len", updateTokenInfo.TokenLen), - latencyField(start), - versionField(), + kv.Error(updateTokenInfo.Error), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("token_len", updateTokenInfo.TokenLen), + kv.Latency(start), + kv.Version(), ) } return func(doneInfo trace.OnReadStreamUpdateTokenDoneInfo) { if doneInfo.Error == nil { l.Log(ctx, "token updated on stream", - String("reader_connection_id", info.ReaderConnectionID), - Int("token_len", updateTokenInfo.TokenLen), - latencyField(start), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("token_len", updateTokenInfo.TokenLen), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "token updated on stream", - Error(doneInfo.Error), - String("reader_connection_id", info.ReaderConnectionID), - Int("token_len", updateTokenInfo.TokenLen), - latencyField(start), - versionField(), + kv.Error(doneInfo.Error), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("token_len", updateTokenInfo.TokenLen), + kv.Latency(start), + kv.Version(), ) } } @@ -344,9 +345,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "sent", "data", "request") l.Log(ctx, "sent data request", - String("reader_connection_id", info.ReaderConnectionID), - Int("request_bytes", info.RequestBytes), - Int("local_capacity", info.LocalBufferSizeAfterSent), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("request_bytes", info.RequestBytes), + kv.Int("local_capacity", info.LocalBufferSizeAfterSent), ) } t.OnReaderReceiveDataResponse = func( @@ -359,36 +360,36 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() partitionsCount, batchesCount, messagesCount := info.DataResponse.GetPartitionBatchMessagesCounts() l.Log(ctx, "data response received, process starting...", - String("reader_connection_id", info.ReaderConnectionID), - Int("received_bytes", info.DataResponse.GetBytesSize()), - Int("local_capacity", info.LocalBufferSizeAfterReceive), - Int("partitions_count", partitionsCount), - Int("batches_count", batchesCount), - Int("messages_count", messagesCount), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("received_bytes", info.DataResponse.GetBytesSize()), + kv.Int("local_capacity", info.LocalBufferSizeAfterReceive), + kv.Int("partitions_count", partitionsCount), + kv.Int("batches_count", batchesCount), + kv.Int("messages_count", messagesCount), ) return func(doneInfo trace.TopicReaderReceiveDataResponseDoneInfo) { if doneInfo.Error == nil { l.Log(ctx, "data response received and processed", - String("reader_connection_id", info.ReaderConnectionID), - Int("received_bytes", info.DataResponse.GetBytesSize()), - Int("local_capacity", info.LocalBufferSizeAfterReceive), - Int("partitions_count", partitionsCount), - Int("batches_count", batchesCount), - Int("messages_count", messagesCount), - latencyField(start), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("received_bytes", info.DataResponse.GetBytesSize()), + kv.Int("local_capacity", info.LocalBufferSizeAfterReceive), + kv.Int("partitions_count", partitionsCount), + kv.Int("batches_count", batchesCount), + kv.Int("messages_count", messagesCount), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "data response received and processed", - Error(doneInfo.Error), - String("reader_connection_id", info.ReaderConnectionID), - Int("received_bytes", info.DataResponse.GetBytesSize()), - Int("local_capacity", info.LocalBufferSizeAfterReceive), - Int("partitions_count", partitionsCount), - Int("batches_count", batchesCount), - Int("messages_count", messagesCount), - latencyField(start), - versionField(), + kv.Error(doneInfo.Error), + kv.String("reader_connection_id", info.ReaderConnectionID), + kv.Int("received_bytes", info.DataResponse.GetBytesSize()), + kv.Int("local_capacity", info.LocalBufferSizeAfterReceive), + kv.Int("partitions_count", partitionsCount), + kv.Int("batches_count", batchesCount), + kv.Int("messages_count", messagesCount), + kv.Latency(start), + kv.Version(), ) } } @@ -402,27 +403,27 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "read", "messages") start := time.Now() l.Log(ctx, "read messages called, waiting...", - Int("min_count", info.MinCount), - Int("max_count", info.MaxCount), - Int("local_capacity_before", info.FreeBufferCapacity), + kv.Int("min_count", info.MinCount), + kv.Int("max_count", info.MaxCount), + kv.Int("local_capacity_before", info.FreeBufferCapacity), ) return func(doneInfo trace.TopicReaderReadMessagesDoneInfo) { if doneInfo.Error == nil { l.Log(ctx, "read messages returned", - Int("min_count", info.MinCount), - Int("max_count", info.MaxCount), - Int("local_capacity_before", info.FreeBufferCapacity), - latencyField(start), + kv.Int("min_count", info.MinCount), + kv.Int("max_count", info.MaxCount), + kv.Int("local_capacity_before", info.FreeBufferCapacity), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "read messages returned", - Error(doneInfo.Error), - Int("min_count", info.MinCount), - Int("max_count", info.MaxCount), - Int("local_capacity_before", info.FreeBufferCapacity), - latencyField(start), - versionField(), + kv.Error(doneInfo.Error), + kv.Int("min_count", info.MinCount), + kv.Int("max_count", info.MaxCount), + kv.Int("local_capacity_before", info.FreeBufferCapacity), + kv.Latency(start), + kv.Version(), ) } } @@ -433,8 +434,8 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), TRACE, "ydb", "topic", "reader", "unknown", "grpc", "message") l.Log(WithLevel(ctx, INFO), "received unknown message", - Error(info.Error), - String("reader_connection_id", info.ReaderConnectionID), + kv.Error(info.Error), + kv.String("reader_connection_id", info.ReaderConnectionID), ) } @@ -448,33 +449,33 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "customer", "popbatchtx") l.Log(WithLevel(ctx, TRACE), "starting pop batch tx", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), ) return func(doneInfo trace.TopicReaderPopBatchTxDoneInfo) { if doneInfo.Error == nil { l.Log( WithLevel(ctx, DEBUG), "pop batch done", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - Int("messaged_count", doneInfo.MessagesCount), - Int64("start_offset", doneInfo.StartOffset), - Int64("end_offset", doneInfo.EndOffset), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Int("messaged_count", doneInfo.MessagesCount), + kv.Int64("start_offset", doneInfo.StartOffset), + kv.Int64("end_offset", doneInfo.EndOffset), + kv.Latency(start), + kv.Version(), ) } else { l.Log( WithLevel(ctx, WARN), "pop batch failed", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - Error(doneInfo.Error), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Error(doneInfo.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -492,32 +493,32 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "popbatchtx_on_stream") l.Log(WithLevel(ctx, TRACE), "starting pop batch tx", - Int64("reader_id", startInfo.ReaderID), - String("reader_connection_id", startInfo.ReaderConnectionID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("reader_connection_id", startInfo.ReaderConnectionID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Version(), ) return func(doneInfo trace.TopicReaderStreamPopBatchTxDoneInfo) { if doneInfo.Error == nil { l.Log( WithLevel(ctx, DEBUG), "pop batch on stream done", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Latency(start), + kv.Version(), ) } else { l.Log( WithLevel(ctx, WARN), "pop batch on stream failed", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - Error(doneInfo.Error), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Error(doneInfo.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -535,32 +536,32 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "update_offsets") l.Log(WithLevel(ctx, TRACE), "starting update offsets in transaction", - Int64("reader_id", startInfo.ReaderID), - String("reader_connection_id", startInfo.ReaderConnectionID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("reader_connection_id", startInfo.ReaderConnectionID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Version(), ) return func(doneInfo trace.TopicReaderOnUpdateOffsetsInTransactionDoneInfo) { if doneInfo.Error == nil { l.Log( WithLevel(ctx, DEBUG), "pop batch on stream done", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Latency(start), + kv.Version(), ) } else { l.Log( WithLevel(ctx, WARN), "pop batch on stream failed", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - Error(doneInfo.Error), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Error(doneInfo.Error), + kv.Latency(start), + kv.Version(), ) } } @@ -578,32 +579,32 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { start := time.Now() ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "update_offsets") l.Log(WithLevel(ctx, TRACE), "starting update offsets in transaction", - Int64("reader_id", startInfo.ReaderID), - String("reader_connection_id", startInfo.ReaderConnectionID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("reader_connection_id", startInfo.ReaderConnectionID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Version(), ) return func(doneInfo trace.TopicReaderTransactionRollbackDoneInfo) { if doneInfo.RollbackError == nil { l.Log( WithLevel(ctx, DEBUG), "pop batch on stream done", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Latency(start), + kv.Version(), ) } else { l.Log( WithLevel(ctx, WARN), "pop batch on stream failed", - Int64("reader_id", startInfo.ReaderID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - Error(doneInfo.RollbackError), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Error(doneInfo.RollbackError), + kv.Latency(start), + kv.Version(), ) } } @@ -624,12 +625,12 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicReaderTransactionCompletedDoneInfo) { ctx := with(*startInfo.Context, TRACE, "ydb", "topic", "reader", "transaction", "update_offsets") l.Log(WithLevel(ctx, TRACE), "starting update offsets in transaction", - Int64("reader_id", startInfo.ReaderID), - String("reader_connection_id", startInfo.ReaderConnectionID), - String("transaction_session_id", startInfo.TransactionSessionID), - String("transaction_id", startInfo.Tx.ID()), - latencyField(start), - versionField(), + kv.Int64("reader_id", startInfo.ReaderID), + kv.String("reader_connection_id", startInfo.ReaderConnectionID), + kv.String("transaction_session_id", startInfo.TransactionSessionID), + kv.String("transaction_id", startInfo.Tx.ID()), + kv.Latency(start), + kv.Version(), ) } } @@ -646,29 +647,29 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "reconnect") start := time.Now() l.Log(ctx, "connect to topic writer stream starting...", - String("topic", info.Topic), - String("producer_id", info.ProducerID), - String("writer_instance_id", info.WriterInstanceID), - Int("attempt", info.Attempt), + kv.String("topic", info.Topic), + kv.String("producer_id", info.ProducerID), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.Int("attempt", info.Attempt), ) return func(doneInfo trace.TopicWriterReconnectDoneInfo) { if doneInfo.Error == nil { l.Log(WithLevel(ctx, DEBUG), "connect to topic writer stream completed", - String("topic", info.Topic), - String("producer_id", info.ProducerID), - String("writer_instance_id", info.WriterInstanceID), - Int("attempt", info.Attempt), - latencyField(start), + kv.String("topic", info.Topic), + kv.String("producer_id", info.ProducerID), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.Int("attempt", info.Attempt), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "connect to topic writer stream completed", - Error(doneInfo.Error), - String("topic", info.Topic), - String("producer_id", info.ProducerID), - String("writer_instance_id", info.WriterInstanceID), - Int("attempt", info.Attempt), - latencyField(start), + kv.Error(doneInfo.Error), + kv.String("topic", info.Topic), + kv.String("producer_id", info.ProducerID), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.Int("attempt", info.Attempt), + kv.Latency(start), ) } } @@ -682,29 +683,29 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "stream", "init") start := time.Now() l.Log(ctx, "start", - String("topic", info.Topic), - String("producer_id", info.ProducerID), - String("writer_instance_id", info.WriterInstanceID), + kv.String("topic", info.Topic), + kv.String("producer_id", info.ProducerID), + kv.String("writer_instance_id", info.WriterInstanceID), ) return func(doneInfo trace.TopicWriterInitStreamDoneInfo) { if doneInfo.Error == nil { l.Log(WithLevel(ctx, DEBUG), "init stream completed", - Error(doneInfo.Error), - String("topic", info.Topic), - String("producer_id", info.ProducerID), - String("writer_instance_id", info.WriterInstanceID), - latencyField(start), - String("session_id", doneInfo.SessionID), + kv.Error(doneInfo.Error), + kv.String("topic", info.Topic), + kv.String("producer_id", info.ProducerID), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.Latency(start), + kv.String("session_id", doneInfo.SessionID), ) } else { l.Log(WithLevel(ctx, WARN), "init stream completed", - Error(doneInfo.Error), - String("topic", info.Topic), - String("producer_id", info.ProducerID), - String("writer_instance_id", info.WriterInstanceID), - latencyField(start), - String("session_id", doneInfo.SessionID), + kv.Error(doneInfo.Error), + kv.String("topic", info.Topic), + kv.String("producer_id", info.ProducerID), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.Latency(start), + kv.String("session_id", doneInfo.SessionID), ) } } @@ -721,11 +722,11 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicOnWriterBeforeCommitTransactionDoneInfo) { ctx := with(*info.Ctx, TRACE, "ydb", "topic", "writer", "beforecommit") l.Log(ctx, "wait of flush messages before commit transaction", - String("kqp_session_id", info.KqpSessionID), - String("topic_session_id_start", info.TopicSessionID), - String("topic_session_id_finish", doneInfo.TopicSessionID), - String("tx_id", info.TransactionID), - latencyField(start), + kv.String("kqp_session_id", info.KqpSessionID), + kv.String("topic_session_id_start", info.TopicSessionID), + kv.String("topic_session_id_finish", doneInfo.TopicSessionID), + kv.String("tx_id", info.TransactionID), + kv.Latency(start), ) } } @@ -737,9 +738,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { return func(doneInfo trace.TopicOnWriterAfterFinishTransactionDoneInfo) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "beforecommit") l.Log(ctx, "close writer after transaction finished", - String("kqp_session_id", info.SessionID), - String("tx_id", info.TransactionID), - latencyField(start), + kv.String("kqp_session_id", info.SessionID), + kv.String("tx_id", info.TransactionID), + kv.Latency(start), ) } } @@ -750,24 +751,24 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "close") start := time.Now() l.Log(ctx, "start", - String("writer_instance_id", info.WriterInstanceID), - NamedError("reason", info.Reason), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.NamedError("reason", info.Reason), ) return func(doneInfo trace.TopicWriterCloseDoneInfo) { if doneInfo.Error == nil { l.Log(WithLevel(ctx, DEBUG), "close topic writer completed", - Error(doneInfo.Error), - String("writer_instance_id", info.WriterInstanceID), - NamedError("reason", info.Reason), - latencyField(start), + kv.Error(doneInfo.Error), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.NamedError("reason", info.Reason), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "close topic writer completed", - Error(doneInfo.Error), - String("writer_instance_id", info.WriterInstanceID), - NamedError("reason", info.Reason), - latencyField(start), + kv.Error(doneInfo.Error), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.NamedError("reason", info.Reason), + kv.Latency(start), ) } } @@ -781,36 +782,36 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "compress", "messages") start := time.Now() l.Log(ctx, "start", - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Any("reason", info.Reason), - Any("codec", info.Codec), - Int("messages_count", info.MessagesCount), - Int64("first_seqno", info.FirstSeqNo), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Any("reason", info.Reason), + kv.Any("codec", info.Codec), + kv.Int("messages_count", info.MessagesCount), + kv.Int64("first_seqno", info.FirstSeqNo), ) return func(doneInfo trace.TopicWriterCompressMessagesDoneInfo) { if doneInfo.Error == nil { l.Log(ctx, "compress message completed", - Error(doneInfo.Error), - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Any("reason", info.Reason), - Any("codec", info.Codec), - Int("messages_count", info.MessagesCount), - Int64("first_seqno", info.FirstSeqNo), - latencyField(start), + kv.Error(doneInfo.Error), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Any("reason", info.Reason), + kv.Any("codec", info.Codec), + kv.Int("messages_count", info.MessagesCount), + kv.Int64("first_seqno", info.FirstSeqNo), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, ERROR), "compress message completed", - Error(doneInfo.Error), - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Any("reason", info.Reason), - Any("codec", info.Codec), - Int("messages_count", info.MessagesCount), - Int64("first_seqno", info.FirstSeqNo), - latencyField(start), + kv.Error(doneInfo.Error), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Any("reason", info.Reason), + kv.Any("codec", info.Codec), + kv.Int("messages_count", info.MessagesCount), + kv.Int64("first_seqno", info.FirstSeqNo), + kv.Latency(start), ) } } @@ -824,32 +825,32 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { ctx := with(context.Background(), TRACE, "ydb", "topic", "writer", "send", "messages") start := time.Now() l.Log(ctx, "start", - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Any("codec", info.Codec), - Int("messages_count", info.MessagesCount), - Int64("first_seqno", info.FirstSeqNo), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Any("codec", info.Codec), + kv.Int("messages_count", info.MessagesCount), + kv.Int64("first_seqno", info.FirstSeqNo), ) return func(doneInfo trace.TopicWriterSendMessagesDoneInfo) { if doneInfo.Error == nil { l.Log(ctx, "writing messages to grpc buffer completed", - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Any("codec", info.Codec), - Int("messages_count", info.MessagesCount), - Int64("first_seqno", info.FirstSeqNo), - latencyField(start), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Any("codec", info.Codec), + kv.Int("messages_count", info.MessagesCount), + kv.Int64("first_seqno", info.FirstSeqNo), + kv.Latency(start), ) } else { l.Log(WithLevel(ctx, WARN), "writing messages to grpc buffer completed", - Error(doneInfo.Error), - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Any("codec", info.Codec), - Int("messages_count", info.MessagesCount), - Int64("first_seqno", info.FirstSeqNo), - latencyField(start), + kv.Error(doneInfo.Error), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Any("codec", info.Codec), + kv.Int("messages_count", info.MessagesCount), + kv.Int64("first_seqno", info.FirstSeqNo), + kv.Latency(start), ) } } @@ -861,17 +862,17 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { acks := info.Acks.GetAcks() ctx := with(context.Background(), DEBUG, "ydb", "topic", "writer", "receive", "result") l.Log(ctx, "topic writer receive result from server", - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), - Int("acks_count", acks.AcksCount), - Int64("seq_no_min", acks.SeqNoMin), - Int64("seq_no_max", acks.SeqNoMax), - Int64("written_offset_min", acks.WrittenOffsetMin), - Int64("written_offset_max", acks.WrittenOffsetMax), - Int("written_offset_count", acks.WrittenCount), - Int("written_in_tx_count", acks.WrittenInTxCount), - Int("skip_count", acks.SkipCount), - versionField(), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), + kv.Int("acks_count", acks.AcksCount), + kv.Int64("seq_no_min", acks.SeqNoMin), + kv.Int64("seq_no_max", acks.SeqNoMax), + kv.Int64("written_offset_min", acks.WrittenOffsetMin), + kv.Int64("written_offset_max", acks.WrittenOffsetMax), + kv.Int("written_offset_count", acks.WrittenCount), + kv.Int("written_in_tx_count", acks.WrittenInTxCount), + kv.Int("skip_count", acks.SkipCount), + kv.Version(), ) } t.OnWriterReadUnknownGrpcMessage = func(info trace.TopicOnWriterReadUnknownGrpcMessageInfo) { @@ -880,9 +881,9 @@ func internalTopic(l Logger, d trace.Detailer) (t trace.Topic) { } ctx := with(context.Background(), DEBUG, "ydb", "topic", "writer", "read", "unknown", "grpc", "message") l.Log(ctx, "topic writer receive unknown message from server", - Error(info.Error), - String("writer_instance_id", info.WriterInstanceID), - String("session_id", info.SessionID), + kv.Error(info.Error), + kv.String("writer_instance_id", info.WriterInstanceID), + kv.String("session_id", info.SessionID), ) } diff --git a/otel/config.go b/otel/config.go new file mode 100644 index 000000000..0bf6c9af9 --- /dev/null +++ b/otel/config.go @@ -0,0 +1,97 @@ +package otel + +import ( + "context" + + "github.com/ydb-platform/ydb-go-sdk/v3" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/internal/xerrors" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +type ( + KeyValue = kv.KeyValue + Span interface { + TraceID() string + + Msg(msg string, attributes ...KeyValue) + + End(attributes ...KeyValue) + } + Config interface { + trace.Detailer + + SpanFromContext(ctx context.Context) Span + Start(ctx context.Context, operationName string, attributes ...KeyValue) (context.Context, Span) + } +) + +func childSpanWithReplaceCtx( + cfg Config, + ctx *context.Context, + operationName string, + fields ...KeyValue, +) (s Span) { + *ctx, s = childSpan(cfg, *ctx, operationName, fields...) + + return s +} + +func childSpan( + cfg Config, + ctx context.Context, //nolint:revive + operationName string, + fields ...KeyValue, +) (context.Context, Span) { + return cfg.Start(ctx, + operationName, + fields..., + ) +} + +func finish( + s Span, + err error, + fields ...KeyValue, +) { + if err != nil { + s.Msg(err.Error(), kv.Error(err)) + } + s.End(fields...) +} + +func logError( + s Span, + err error, + fields ...KeyValue, +) { + var ydbErr ydb.Error + if xerrors.As(err, &ydbErr) { + fields = append(fields, + kv.Error(err), + kv.Int("error.ydb.code", int(ydbErr.Code())), + kv.String("error.ydb.name", ydbErr.Name()), + ) + } + s.Msg(err.Error(), fields...) +} + +func logToParentSpan( + cfg Config, + ctx context.Context, //nolint:revive + msg string, + fields ...KeyValue, //nolint:unparam +) { + parent := cfg.SpanFromContext(ctx) + parent.Msg(msg, fields...) +} + +func logToParentSpanError( + cfg Config, + ctx context.Context, //nolint:revive + err error, + fields ...KeyValue, //nolint:unparam +) { + parent := cfg.SpanFromContext(ctx) + logError(parent, err, fields...) +} diff --git a/otel/coordination.go b/otel/coordination.go new file mode 100644 index 000000000..1f5abd5c8 --- /dev/null +++ b/otel/coordination.go @@ -0,0 +1,9 @@ +package otel + +import ( + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +func coordination(cfg Config) (t trace.Coordination) { + return t +} diff --git a/otel/discovery.go b/otel/discovery.go new file mode 100644 index 000000000..1f585834d --- /dev/null +++ b/otel/discovery.go @@ -0,0 +1,36 @@ +package otel + +import ( + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +func discovery(cfg Config) (t trace.Discovery) { + t.OnDiscover = func(info trace.DiscoveryDiscoverStartInfo) func(discovery trace.DiscoveryDiscoverDoneInfo) { + if cfg.Details()&trace.DiscoveryEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("address", info.Address), + kv.String("database", info.Database), + ) + + return func(info trace.DiscoveryDiscoverDoneInfo) { + endpoints := make([]string, len(info.Endpoints)) + for i, e := range info.Endpoints { + endpoints[i] = e.String() + } + finish( + start, + info.Error, + kv.Strings("endpoints", endpoints), + ) + } + } + + return nil + } + + return t +} diff --git a/otel/driver.go b/otel/driver.go new file mode 100644 index 000000000..5a55e1c7d --- /dev/null +++ b/otel/driver.go @@ -0,0 +1,440 @@ +package otel + +import ( + "bytes" + "context" + "fmt" + "hash/crc32" + "sync/atomic" + + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/meta" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +// driver makes driver with publishing traces +func driver(cfg Config) trace.Driver { //nolint:gocyclo,funlen + return trace.Driver{ + OnRepeaterWakeUp: func(info trace.DriverRepeaterWakeUpStartInfo) func(trace.DriverRepeaterWakeUpDoneInfo) { + if cfg.Details()&trace.DriverRepeaterEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DriverRepeaterWakeUpDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnConnDial: func(info trace.DriverConnDialStartInfo) func(trace.DriverConnDialDoneInfo) { + if cfg.Details()&trace.DriverConnEvents == 0 { + return nil + } + *info.Context = meta.WithTraceParent(*info.Context, + cfg.SpanFromContext(*info.Context).TraceID(), + ) + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DriverConnDialDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnConnInvoke: func(info trace.DriverConnInvokeStartInfo) func(trace.DriverConnInvokeDoneInfo) { + if cfg.Details()&trace.DriverConnEvents == 0 { + return nil + } + *info.Context = meta.WithTraceParent(*info.Context, + cfg.SpanFromContext(*info.Context).TraceID(), + ) + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("address", safeAddress(info.Endpoint)), + kv.String("method", string(info.Method)), + ) + + return func(info trace.DriverConnInvokeDoneInfo) { + fields := []KeyValue{ + kv.String("opID", info.OpID), + kv.String("state", safeStringer(info.State)), + } + if len(info.Issues) > 0 { + issues := make([]string, len(info.Issues)) + for i, issue := range info.Issues { + issues[i] = fmt.Sprintf("%+v", issue) + } + fields = append(fields, + kv.Strings("issues", issues), + ) + } + finish( + start, + info.Error, + fields..., + ) + } + }, + OnConnNewStream: func(info trace.DriverConnNewStreamStartInfo) func(trace.DriverConnNewStreamDoneInfo) { + if cfg.Details()&trace.DriverConnStreamEvents == 0 { + return nil + } + *info.Context = withGrpcStreamMsgCounters(*info.Context) + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("address", safeAddress(info.Endpoint)), + kv.String("method", string(info.Method)), + ) + *info.Context = meta.WithTraceParent(*info.Context, + start.TraceID(), + ) + + return func(info trace.DriverConnNewStreamDoneInfo) { + finish(start, info.Error, + kv.String("state", safeStringer(info.State)), + ) + } + }, + OnConnStreamRecvMsg: func(info trace.DriverConnStreamRecvMsgStartInfo) func(trace.DriverConnStreamRecvMsgDoneInfo) { + if cfg.Details()&trace.DriverConnStreamEvents == 0 { + return nil + } + start := cfg.SpanFromContext(*info.Context) + counters := grpcStreamMsgCountersFromContext(*info.Context) + if counters != nil { + counters.updateReceivedMessages() + } + + return func(info trace.DriverConnStreamRecvMsgDoneInfo) { + if skipEOF(info.Error) != nil { + logError(start, info.Error) + } + } + }, + OnConnStreamSendMsg: func(info trace.DriverConnStreamSendMsgStartInfo) func(trace.DriverConnStreamSendMsgDoneInfo) { + if cfg.Details()&trace.DriverConnStreamEvents == 0 { + return nil + } + start := cfg.SpanFromContext(*info.Context) + counters := grpcStreamMsgCountersFromContext(*info.Context) + if counters != nil { + counters.updateSentMessages() + } + + return func(info trace.DriverConnStreamSendMsgDoneInfo) { + if info.Error != nil { + logError(start, info.Error) + } + } + }, + OnConnStreamCloseSend: func(info trace.DriverConnStreamCloseSendStartInfo) func( + trace.DriverConnStreamCloseSendDoneInfo, + ) { + if cfg.Details()&trace.DriverConnStreamEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DriverConnStreamCloseSendDoneInfo) { + finish(start, info.Error) + } + }, + OnConnStreamFinish: func(info trace.DriverConnStreamFinishInfo) { + if cfg.Details()&trace.DriverConnStreamEvents == 0 { + return + } + start := childSpanWithReplaceCtx( + cfg, + &info.Context, + info.Call.FunctionID(), + ) + counters := grpcStreamMsgCountersFromContext(info.Context) + + attributes := make([]kv.KeyValue, 0, 2) + if counters != nil { + attributes = append(attributes, + kv.Int64("received_messages", counters.receivedMessages()), + kv.Int64("sent_messages", counters.sentMessages()), + ) + } + finish(start, info.Error, attributes...) + }, + OnConnPark: func(info trace.DriverConnParkStartInfo) func(trace.DriverConnParkDoneInfo) { + if cfg.Details()&trace.DriverConnEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("address", safeAddress(info.Endpoint)), + ) + + return func(info trace.DriverConnParkDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnConnClose: func(info trace.DriverConnCloseStartInfo) func(trace.DriverConnCloseDoneInfo) { + if cfg.Details()&trace.DriverConnEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("address", safeAddress(info.Endpoint)), + ) + + return func(info trace.DriverConnCloseDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnConnBan: func(info trace.DriverConnBanStartInfo) func(trace.DriverConnBanDoneInfo) { + if cfg.Details()&trace.DriverConnEvents == 0 { + return nil + } + s := cfg.SpanFromContext(*info.Context) + s.Msg(info.Call.FunctionID(), + kv.String("cause", safeError(info.Cause)), + ) + + return nil + }, + OnConnStateChange: func(info trace.DriverConnStateChangeStartInfo) func(trace.DriverConnStateChangeDoneInfo) { + if cfg.Details()&trace.DriverConnEvents == 0 { + return nil + } + s := cfg.SpanFromContext(*info.Context) + oldState := safeStringer(info.State) + functionID := info.Call.FunctionID() + + return func(info trace.DriverConnStateChangeDoneInfo) { + s.Msg(functionID, + kv.String("old state", oldState), + kv.String("new state", safeStringer(info.State)), + ) + } + }, + OnBalancerInit: func(info trace.DriverBalancerInitStartInfo) func(trace.DriverBalancerInitDoneInfo) { + if cfg.Details()&trace.DriverBalancerEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("name", info.Name), + ) + + return func(info trace.DriverBalancerInitDoneInfo) { + finish(start, info.Error) + } + }, + OnBalancerClusterDiscoveryAttempt: func(info trace.DriverBalancerClusterDiscoveryAttemptStartInfo) func( + trace.DriverBalancerClusterDiscoveryAttemptDoneInfo, + ) { + if cfg.Details()&trace.DriverBalancerEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DriverBalancerClusterDiscoveryAttemptDoneInfo) { + finish(start, info.Error) + } + }, + OnBalancerUpdate: func(info trace.DriverBalancerUpdateStartInfo) func(trace.DriverBalancerUpdateDoneInfo) { + if cfg.Details()&trace.DriverBalancerEvents == 0 { + return nil + } + needLocalDC := info.NeedLocalDC + functionID := info.Call.FunctionID() + s := cfg.SpanFromContext(*info.Context) + + return func(info trace.DriverBalancerUpdateDoneInfo) { + var ( + endpoints = make([]string, len(info.Endpoints)) + added = make([]string, len(info.Added)) + dropped = make([]string, len(info.Dropped)) + ) + for i, e := range info.Endpoints { + endpoints[i] = e.String() + } + for i, e := range info.Added { + added[i] = e.String() + } + for i, e := range info.Dropped { + dropped[i] = e.String() + } + s.Msg(functionID, + kv.String("local_dc", info.LocalDC), + kv.Strings("endpoints", endpoints), + kv.Strings("added", added), + kv.Strings("dropped", dropped), + kv.Bool("need_local_dc", needLocalDC), + ) + } + }, + OnBalancerChooseEndpoint: func( + info trace.DriverBalancerChooseEndpointStartInfo, + ) func( + trace.DriverBalancerChooseEndpointDoneInfo, + ) { + if cfg.Details()&trace.DriverBalancerEvents == 0 { + return nil + } + parent := cfg.SpanFromContext(*info.Context) + functionID := info.Call.FunctionID() + + return func(info trace.DriverBalancerChooseEndpointDoneInfo) { + if info.Error != nil { + parent.Msg(functionID, + kv.Error(info.Error), + ) + } else { + parent.Msg(functionID, + kv.String("address", safeAddress(info.Endpoint)), + kv.String("nodeID", safeNodeID(info.Endpoint)), + ) + } + } + }, + OnGetCredentials: func(info trace.DriverGetCredentialsStartInfo) func(trace.DriverGetCredentialsDoneInfo) { + if cfg.Details()&trace.DriverCredentialsEvents == 0 { + return nil + } + parent := cfg.SpanFromContext(*info.Context) + functionID := info.Call.FunctionID() + + return func(info trace.DriverGetCredentialsDoneInfo) { + if info.Error != nil { + parent.Msg(functionID, + kv.Error(info.Error), + ) + } else { + var mask bytes.Buffer + if len(info.Token) > 16 { + mask.WriteString(info.Token[:4]) + mask.WriteString("****") + mask.WriteString(info.Token[len(info.Token)-4:]) + } else { + mask.WriteString("****") + } + mask.WriteString(fmt.Sprintf("(CRC-32c: %08X)", crc32.Checksum([]byte(info.Token), crc32.IEEETable))) + parent.Msg(functionID, + kv.String("token", mask.String()), + ) + } + } + }, + OnInit: func(info trace.DriverInitStartInfo) func(trace.DriverInitDoneInfo) { + if cfg.Details()&trace.DriverEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("endpoint", info.Endpoint), + kv.String("database", info.Database), + kv.Bool("secure", info.Secure), + ) + + return func(info trace.DriverInitDoneInfo) { + finish(start, info.Error) + } + }, + OnClose: func(info trace.DriverCloseStartInfo) func(trace.DriverCloseDoneInfo) { + if cfg.Details()&trace.DriverEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DriverCloseDoneInfo) { + finish(start, info.Error) + } + }, + OnPoolNew: func(info trace.DriverConnPoolNewStartInfo) func(trace.DriverConnPoolNewDoneInfo) { + if cfg.Details()&trace.DriverEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DriverConnPoolNewDoneInfo) { + start.End() + } + }, + } +} + +type grpcStreamMsgCountersKey struct{} + +func withGrpcStreamMsgCounters(ctx context.Context) context.Context { + return context.WithValue(ctx, grpcStreamMsgCountersKey{}, &grpcStreamMsgCounters{}) +} + +func grpcStreamMsgCountersFromContext(ctx context.Context) *grpcStreamMsgCounters { + value, ok := ctx.Value(grpcStreamMsgCountersKey{}).(*grpcStreamMsgCounters) + if !ok { + return nil + } + + return value +} + +type grpcStreamMsgCounters struct { + sent atomic.Int64 + received atomic.Int64 +} + +func (c *grpcStreamMsgCounters) updateSentMessages() { + c.sent.Add(1) +} + +func (c *grpcStreamMsgCounters) updateReceivedMessages() { + c.received.Add(1) +} + +func (c *grpcStreamMsgCounters) sentMessages() int64 { + return c.sent.Load() +} + +func (c *grpcStreamMsgCounters) receivedMessages() int64 { + return c.received.Load() +} diff --git a/otel/errors.go b/otel/errors.go new file mode 100644 index 000000000..fb45be868 --- /dev/null +++ b/otel/errors.go @@ -0,0 +1,16 @@ +package otel + +import ( + "errors" + "io" +) + +var errNestedCall = errors.New("") + +func skipEOF(err error) error { + if err == nil || errors.Is(err, io.EOF) { + return nil + } + + return err +} diff --git a/otel/query.go b/otel/query.go new file mode 100644 index 000000000..5a190a226 --- /dev/null +++ b/otel/query.go @@ -0,0 +1,553 @@ +package otel + +import ( + "errors" + "io" + "strings" + + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +//nolint:funlen,gocyclo +func query(cfg Config) trace.Query { + nodeID := func(session interface{ NodeID() uint32 }) int64 { + if session != nil { + return int64(session.NodeID()) + } + + return 0 + } + + return trace.Query{ + OnNew: func(info trace.QueryNewStartInfo) func(info trace.QueryNewDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryNewDoneInfo) { + start.End() + } + }, + OnClose: func(info trace.QueryCloseStartInfo) func(info trace.QueryCloseDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryCloseDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnPoolNew: func(info trace.QueryPoolNewStartInfo) func(trace.QueryPoolNewDoneInfo) { + if cfg.Details()&trace.QueryPoolEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryPoolNewDoneInfo) { + start.End( + kv.Int("Limit", info.Limit), + ) + } + }, + OnPoolClose: func(info trace.QueryPoolCloseStartInfo) func(trace.QueryPoolCloseDoneInfo) { + if cfg.Details()&trace.QueryPoolEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryPoolCloseDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnPoolTry: func(info trace.QueryPoolTryStartInfo) func(trace.QueryPoolTryDoneInfo) { + if cfg.Details()&trace.QueryPoolEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryPoolTryDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnPoolWith: func(info trace.QueryPoolWithStartInfo) func(trace.QueryPoolWithDoneInfo) { + if cfg.Details()&trace.QueryPoolEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryPoolWithDoneInfo) { + finish( + start, + info.Error, + kv.Int("Attempts", info.Attempts), + ) + } + }, + OnPoolPut: func(info trace.QueryPoolPutStartInfo) func(trace.QueryPoolPutDoneInfo) { + if cfg.Details()&trace.QueryPoolEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryPoolPutDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnPoolGet: func(info trace.QueryPoolGetStartInfo) func(trace.QueryPoolGetDoneInfo) { + if cfg.Details()&trace.QueryPoolEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryPoolGetDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnDo: func(info trace.QueryDoStartInfo) func(trace.QueryDoDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryDoDoneInfo) { + finish( + start, + info.Error, + kv.Int("Attempts", info.Attempts), + ) + } + }, + OnDoTx: func(info trace.QueryDoTxStartInfo) func(trace.QueryDoTxDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QueryDoTxDoneInfo) { + finish( + start, + info.Error, + kv.Int("Attempts", info.Attempts), + ) + } + }, + OnExec: func(info trace.QueryExecStartInfo) func(info trace.QueryExecDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryExecDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnQuery: func(info trace.QueryQueryStartInfo) func(info trace.QueryQueryDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryQueryDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnQueryResultSet: func(info trace.QueryQueryResultSetStartInfo) func(info trace.QueryQueryResultSetDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryQueryResultSetDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnQueryRow: func(info trace.QueryQueryRowStartInfo) func(info trace.QueryQueryRowDoneInfo) { + if cfg.Details()&trace.QueryEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryQueryRowDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnSessionCreate: func(info trace.QuerySessionCreateStartInfo) func(info trace.QuerySessionCreateDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QuerySessionCreateDoneInfo) { + finish( + start, + info.Error, + kv.String("SessionID", safeID(info.Session)), + kv.String("SessionStatus", safeStatus(info.Session)), + kv.Int64("NodeID", nodeID(info.Session)), + ) + } + }, + OnSessionAttach: func(info trace.QuerySessionAttachStartInfo) func(info trace.QuerySessionAttachDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + + ctx := *info.Context + call := info.Call.FunctionID() + + return func(info trace.QuerySessionAttachDoneInfo) { + if info.Error == nil { + logToParentSpan(cfg, ctx, call) + } else if errors.Is(info.Error, io.EOF) { + logToParentSpan(cfg, ctx, call+" => io.EOF") + } else { + logToParentSpanError(cfg, ctx, info.Error) + } + } + }, + OnSessionDelete: func(info trace.QuerySessionDeleteStartInfo) func(info trace.QuerySessionDeleteDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QuerySessionDeleteDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnSessionExec: func(info trace.QuerySessionExecStartInfo) func(info trace.QuerySessionExecDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QuerySessionExecDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnSessionQuery: func(info trace.QuerySessionQueryStartInfo) func(info trace.QuerySessionQueryDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QuerySessionQueryDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnSessionQueryResultSet: func( + info trace.QuerySessionQueryResultSetStartInfo, + ) func(info trace.QuerySessionQueryResultSetDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QuerySessionQueryResultSetDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnSessionQueryRow: func(info trace.QuerySessionQueryRowStartInfo) func(info trace.QuerySessionQueryRowDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QuerySessionQueryRowDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnSessionBegin: func(info trace.QuerySessionBeginStartInfo) func(info trace.QuerySessionBeginDoneInfo) { + if cfg.Details()&trace.QuerySessionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.QuerySessionBeginDoneInfo) { + finish( + start, + info.Error, + kv.String("TransactionID", safeID(info.Tx)), + ) + } + }, + OnResultNew: func(info trace.QueryResultNewStartInfo) func(info trace.QueryResultNewDoneInfo) { + if cfg.Details()&trace.QueryResultEvents == 0 { + return nil + } + + ctx := *info.Context + call := info.Call.FunctionID() + + return func(info trace.QueryResultNewDoneInfo) { + if info.Error == nil { + logToParentSpan(cfg, ctx, call) + } else { + logToParentSpanError(cfg, ctx, info.Error) + } + } + }, + OnResultNextPart: func(info trace.QueryResultNextPartStartInfo) func(info trace.QueryResultNextPartDoneInfo) { + if cfg.Details()&trace.QueryResultEvents == 0 { + return nil + } + + ctx := *info.Context + call := info.Call.FunctionID() + + return func(info trace.QueryResultNextPartDoneInfo) { + if info.Error == nil { + logToParentSpan(cfg, ctx, call) + } else if errors.Is(info.Error, io.EOF) { + logToParentSpan(cfg, ctx, call+" => io.EOF") + } else { + logToParentSpanError(cfg, ctx, info.Error) + } + } + }, + OnResultNextResultSet: func(info trace.QueryResultNextResultSetStartInfo) func( + info trace.QueryResultNextResultSetDoneInfo) { + if cfg.Details()&trace.QueryResultEvents == 0 { + return nil + } + + ctx := *info.Context + call := info.Call.FunctionID() + + return func(info trace.QueryResultNextResultSetDoneInfo) { + if info.Error == nil { + logToParentSpan(cfg, ctx, call) + } else if errors.Is(info.Error, io.EOF) { + logToParentSpan(cfg, ctx, call+" => io.EOF") + } else { + logToParentSpanError(cfg, ctx, info.Error) + } + } + }, + OnResultClose: func(info trace.QueryResultCloseStartInfo) func(info trace.QueryResultCloseDoneInfo) { + if cfg.Details()&trace.QueryResultEvents == 0 { + return nil + } + + ctx := *info.Context + call := info.Call.FunctionID() + + return func(info trace.QueryResultCloseDoneInfo) { + if info.Error == nil { + logToParentSpan(cfg, ctx, call) + } else { + logToParentSpanError(cfg, ctx, info.Error) + } + } + }, + OnTxExec: func(info trace.QueryTxExecStartInfo) func(info trace.QueryTxExecDoneInfo) { + if cfg.Details()&trace.QueryTransactionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryTxExecDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnTxQuery: func(info trace.QueryTxQueryStartInfo) func(info trace.QueryTxQueryDoneInfo) { + if cfg.Details()&trace.QueryTransactionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryTxQueryDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnTxQueryResultSet: func(info trace.QueryTxQueryResultSetStartInfo) func(info trace.QueryTxQueryResultSetDoneInfo) { + if cfg.Details()&trace.QueryTransactionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryTxQueryResultSetDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + OnTxQueryRow: func(info trace.QueryTxQueryRowStartInfo) func(info trace.QueryTxQueryRowDoneInfo) { + if cfg.Details()&trace.QueryTransactionEvents == 0 { + return nil + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("Query", strings.TrimSpace(info.Query)), + ) + + return func(info trace.QueryTxQueryRowDoneInfo) { + finish( + start, + info.Error, + ) + } + }, + } +} diff --git a/otel/ratelimiter.go b/otel/ratelimiter.go new file mode 100644 index 000000000..2c0efb25b --- /dev/null +++ b/otel/ratelimiter.go @@ -0,0 +1,9 @@ +package otel + +import ( + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +func ratelimiter(cfg Config) (t trace.Ratelimiter) { + return t +} diff --git a/otel/retry.go b/otel/retry.go new file mode 100644 index 000000000..6cd0aa690 --- /dev/null +++ b/otel/retry.go @@ -0,0 +1,100 @@ +package otel + +import ( + "context" + + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +type ( + ctxRetryFunctionIDKey struct{} + ctxRetryFieldsKey struct{} + ctxNoTraceRetryKey struct{} + fieldsStore struct { + fields []kv.KeyValue + } +) + +func withFunctionID(ctx context.Context, functionID string) context.Context { + return context.WithValue(ctx, ctxRetryFunctionIDKey{}, functionID) +} + +func functionID(ctx context.Context) string { + if functionID, has := ctx.Value(ctxRetryFunctionIDKey{}).(string); has { + return functionID + } + + return "" +} + +func noTraceRetry(ctx context.Context) context.Context { + return context.WithValue(ctx, ctxNoTraceRetryKey{}, true) +} + +func isTraceRetry(ctx context.Context) bool { + if noTrace, has := ctx.Value(ctxNoTraceRetryKey{}).(bool); has { + return !noTrace + } + + return true +} + +func fieldsStoreFromContext(ctx *context.Context) *fieldsStore { + if store, has := (*ctx).Value(ctxRetryFieldsKey{}).(*fieldsStore); has { + return store + } + store := &fieldsStore{} + *ctx = context.WithValue(*ctx, ctxRetryFieldsKey{}, store) + + return store +} + +func fieldsFromStore(ctx context.Context) []kv.KeyValue { + if holder, has := ctx.Value(ctxRetryFieldsKey{}).(*fieldsStore); has { + return holder.fields + } + + return nil +} + +func retry(cfg Config) (t trace.Retry) { + t.OnRetry = func(info trace.RetryLoopStartInfo) func(trace.RetryLoopDoneInfo) { + if cfg.Details()&trace.RetryEvents != 0 && isTraceRetry(*info.Context) { //nolint:nestif + operationName := info.Label + if operationName == "" { + operationName = info.Call.FunctionID() + } + if functionID := functionID(*info.Context); functionID != "" { + operationName = functionID + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + operationName, + kv.Bool("idempotent", info.Idempotent), + ) + if info.NestedCall { + start.Msg("nested call", kv.Error(errNestedCall)) + } + ctx := *info.Context + + return func(info trace.RetryLoopDoneInfo) { + fields := []KeyValue{ + kv.Int("attempts", info.Attempts), + } + if fieldsFromStore := fieldsFromStore(ctx); len(fieldsFromStore) > 0 { + fields = append(fields, fieldsFromStore...) + } + if info.Error != nil { + fields = append(fields, kv.Error(info.Error)) + } + start.End(fields...) + } + } + + return nil + } + + return t +} diff --git a/otel/safe.go b/otel/safe.go new file mode 100644 index 000000000..30fb0a8c2 --- /dev/null +++ b/otel/safe.go @@ -0,0 +1,62 @@ +package otel + +import ( + "fmt" + "strconv" +) + +func safeAddress(a interface{ Address() string }) string { + if a == nil { + return "" + } + + return a.Address() +} + +func safeNodeID(n interface{ NodeID() uint32 }) string { + if n == nil { + return "0" + } + + return strconv.FormatUint(uint64(n.NodeID()), 10) +} + +func safeID(id interface{ ID() string }) string { + if id == nil { + return "" + } + + return id.ID() +} + +func safeStatus(s interface{ Status() string }) string { + if s == nil { + return "" + } + + return s.Status() +} + +func safeStringer(s fmt.Stringer) string { + if s == nil { + return "" + } + + return s.String() +} + +func safeError(err error) string { + if err == nil { + return "" + } + + return err.Error() +} + +func safeErr(err interface{ Err() error }) error { + if err == nil { + return nil + } + + return err.Err() +} diff --git a/otel/scheme.go b/otel/scheme.go new file mode 100644 index 000000000..e790f7ff9 --- /dev/null +++ b/otel/scheme.go @@ -0,0 +1,35 @@ +package otel + +import ( + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +func scheme(_ Config) (t trace.Scheme) { + t.OnListDirectory = func(info trace.SchemeListDirectoryStartInfo) func(trace.SchemeListDirectoryDoneInfo) { + *info.Context = withFunctionID(*info.Context, info.Call.FunctionID()) + + return nil + } + t.OnDescribePath = func(info trace.SchemeDescribePathStartInfo) func(trace.SchemeDescribePathDoneInfo) { + *info.Context = withFunctionID(*info.Context, info.Call.FunctionID()) + + return nil + } + t.OnModifyPermissions = func(info trace.SchemeModifyPermissionsStartInfo) func(trace.SchemeModifyPermissionsDoneInfo) { + *info.Context = withFunctionID(*info.Context, info.Call.FunctionID()) + + return nil + } + t.OnMakeDirectory = func(info trace.SchemeMakeDirectoryStartInfo) func(trace.SchemeMakeDirectoryDoneInfo) { + *info.Context = withFunctionID(*info.Context, info.Call.FunctionID()) + + return nil + } + t.OnRemoveDirectory = func(info trace.SchemeRemoveDirectoryStartInfo) func(trace.SchemeRemoveDirectoryDoneInfo) { + *info.Context = withFunctionID(*info.Context, info.Call.FunctionID()) + + return nil + } + + return t +} diff --git a/otel/scripting.go b/otel/scripting.go new file mode 100644 index 000000000..9e3bca342 --- /dev/null +++ b/otel/scripting.go @@ -0,0 +1,106 @@ +package otel + +import ( + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +//nolint:funlen +func scripting(cfg Config) (t trace.Scripting) { + t.OnExecute = func(info trace.ScriptingExecuteStartInfo) func(trace.ScriptingExecuteDoneInfo) { + if cfg.Details()&trace.ScriptingEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("params", safeStringer(info.Parameters)), + ) + + return func(info trace.ScriptingExecuteDoneInfo) { + if info.Error == nil { + finish( + start, + safeErr(info.Result), + ) + } else { + finish( + start, + info.Error, + ) + } + } + } + + return nil + } + t.OnStreamExecute = func( + info trace.ScriptingStreamExecuteStartInfo, + ) func( + trace.ScriptingStreamExecuteIntermediateInfo, + ) func( + trace.ScriptingStreamExecuteDoneInfo, + ) { + if cfg.Details()&trace.ScriptingEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("params", safeStringer(info.Parameters)), + ) + + return func( + info trace.ScriptingStreamExecuteIntermediateInfo, + ) func( + trace.ScriptingStreamExecuteDoneInfo, + ) { + start.Msg("", kv.Error(info.Error)) + + return func(info trace.ScriptingStreamExecuteDoneInfo) { + start.Msg("") + if info.Error != nil { + start.End(kv.Error(info.Error)) + } else { + start.End() + } + } + } + } + + return nil + } + t.OnExplain = func(info trace.ScriptingExplainStartInfo) func(trace.ScriptingExplainDoneInfo) { + if cfg.Details()&trace.ScriptingEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + ) + + return func(info trace.ScriptingExplainDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnClose = func(info trace.ScriptingCloseStartInfo) func(trace.ScriptingCloseDoneInfo) { + if cfg.Details()&trace.ScriptingEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.ScriptingCloseDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + + return t +} diff --git a/otel/sql.go b/otel/sql.go new file mode 100644 index 000000000..f046df726 --- /dev/null +++ b/otel/sql.go @@ -0,0 +1,315 @@ +package otel + +import ( + "context" + + otelTrace "go.opentelemetry.io/otel/trace" + + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +type ctxStmtCallKey struct{} + +func markStmtCall(ctx context.Context) context.Context { + return context.WithValue(ctx, ctxStmtCallKey{}, true) +} + +func isStmtCall(ctx context.Context) bool { + if txStmt, has := ctx.Value(ctxStmtCallKey{}).(bool); has { + return txStmt + } + + return false +} + +// databaseSQL makes trace.DatabaseSQL with logging events from details +// +//nolint:funlen +func databaseSQL(cfg Config) (t trace.DatabaseSQL) { + childSpanWithReplaceCtx := func( + ctx *context.Context, + operationName string, + fields ...kv.KeyValue, + ) (s Span) { + return childSpanWithReplaceCtx(cfg, ctx, operationName, fields...) + } + t.OnConnectorConnect = func( + info trace.DatabaseSQLConnectorConnectStartInfo, + ) func( + trace.DatabaseSQLConnectorConnectDoneInfo, + ) { + if cfg.Details()&trace.DatabaseSQLConnectorEvents != 0 { + start := childSpanWithReplaceCtx(info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DatabaseSQLConnectorConnectDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnConnPing = func(info trace.DatabaseSQLConnPingStartInfo) func(trace.DatabaseSQLConnPingDoneInfo) { + if cfg.Details()&trace.DatabaseSQLConnEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DatabaseSQLConnPingDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnConnPrepare = func(info trace.DatabaseSQLConnPrepareStartInfo) func(trace.DatabaseSQLConnPrepareDoneInfo) { + if cfg.Details()&trace.DatabaseSQLConnEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + ) + + return func(info trace.DatabaseSQLConnPrepareDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnConnExec = func(info trace.DatabaseSQLConnExecStartInfo) func(trace.DatabaseSQLConnExecDoneInfo) { + if cfg.Details()&trace.DatabaseSQLConnEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("query_mode", info.Mode), + kv.Bool("idempotent", info.Idempotent), + ) + + return func(info trace.DatabaseSQLConnExecDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnConnQuery = func(info trace.DatabaseSQLConnQueryStartInfo) func(trace.DatabaseSQLConnQueryDoneInfo) { + if cfg.Details()&trace.DatabaseSQLConnEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("query_mode", info.Mode), + kv.Bool("idempotent", info.Idempotent), + ) + + return func(info trace.DatabaseSQLConnQueryDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnConnIsTableExists = func(info trace.DatabaseSQLConnIsTableExistsStartInfo) func( + trace.DatabaseSQLConnIsTableExistsDoneInfo, + ) { + if cfg.Details()&trace.DatabaseSQLConnEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("table_name", info.TableName), + ) + + return func(info trace.DatabaseSQLConnIsTableExistsDoneInfo) { + finish( + start, + info.Error, + kv.Bool("exists", info.Exists), + ) + } + } + + return nil + } + t.OnConnBegin = func(info trace.DatabaseSQLConnBeginStartInfo) func(trace.DatabaseSQLConnBeginDoneInfo) { + if cfg.Details()&trace.DatabaseSQLTxEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.DatabaseSQLConnBeginDoneInfo) { + finish( + start, + info.Error, + kv.String("transaction_id", safeID(info.Tx)), + ) + } + } + + return nil + } + t.OnTxRollback = func(info trace.DatabaseSQLTxRollbackStartInfo) func(trace.DatabaseSQLTxRollbackDoneInfo) { + if cfg.Details()&trace.DatabaseSQLTxEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.DatabaseSQLTxRollbackDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnTxCommit = func(info trace.DatabaseSQLTxCommitStartInfo) func(trace.DatabaseSQLTxCommitDoneInfo) { + if cfg.Details()&trace.DatabaseSQLTxEvents != 0 { + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.DatabaseSQLTxCommitDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnTxExec = func(info trace.DatabaseSQLTxExecStartInfo) func(trace.DatabaseSQLTxExecDoneInfo) { + if cfg.Details()&trace.DatabaseSQLTxEvents != 0 { + if !isStmtCall(*info.Context) { + *info.Context = otelTrace.ContextWithSpan(*info.Context, otelTrace.SpanFromContext(info.TxContext)) + } + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.DatabaseSQLTxExecDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnTxQuery = func(info trace.DatabaseSQLTxQueryStartInfo) func(trace.DatabaseSQLTxQueryDoneInfo) { + if cfg.Details()&trace.DatabaseSQLTxEvents != 0 { + if !isStmtCall(*info.Context) { + *info.Context = otelTrace.ContextWithSpan(*info.Context, otelTrace.SpanFromContext(info.TxContext)) + } + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.DatabaseSQLTxQueryDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnTxPrepare = func(info trace.DatabaseSQLTxPrepareStartInfo) func(trace.DatabaseSQLTxPrepareDoneInfo) { + if cfg.Details()&trace.DatabaseSQLTxEvents != 0 { + *info.Context = otelTrace.ContextWithSpan(*info.Context, otelTrace.SpanFromContext(info.TxContext)) + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.DatabaseSQLTxPrepareDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnStmtExec = func(info trace.DatabaseSQLStmtExecStartInfo) func(trace.DatabaseSQLStmtExecDoneInfo) { + if cfg.Details()&trace.DatabaseSQLStmtEvents != 0 { + *info.Context = markStmtCall( + otelTrace.ContextWithSpan(*info.Context, otelTrace.SpanFromContext(info.StmtContext)), + ) + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + ) + + return func(info trace.DatabaseSQLStmtExecDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + t.OnStmtQuery = func(info trace.DatabaseSQLStmtQueryStartInfo) func(trace.DatabaseSQLStmtQueryDoneInfo) { + if cfg.Details()&trace.DatabaseSQLStmtEvents != 0 { + *info.Context = markStmtCall( + otelTrace.ContextWithSpan(*info.Context, otelTrace.SpanFromContext(info.StmtContext)), + ) + start := childSpanWithReplaceCtx( + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + ) + + return func(info trace.DatabaseSQLStmtQueryDoneInfo) { + finish( + start, + info.Error, + ) + } + } + + return nil + } + + return t +} diff --git a/otel/table.go b/otel/table.go new file mode 100644 index 000000000..16796299b --- /dev/null +++ b/otel/table.go @@ -0,0 +1,458 @@ +package otel + +import ( + "net/url" + + "github.com/ydb-platform/ydb-go-sdk/v3/internal/kv" + "github.com/ydb-platform/ydb-go-sdk/v3/trace" +) + +// table makes table.ClientTrace with solomon metrics publishing +// +//nolint:funlen +func table(cfg Config) (t trace.Table) { //nolint:gocyclo + nodeID := func(sessionID string) string { + u, err := url.Parse(sessionID) + if err != nil { + return "" + } + + return u.Query().Get("node_id") + } + t.OnCreateSession = func(info trace.TableCreateSessionStartInfo) func(trace.TableCreateSessionDoneInfo) { + if cfg.Details()&trace.TableEvents != 0 { + fieldsStore := fieldsStoreFromContext(info.Context) + *info.Context = withFunctionID(*info.Context, info.Call.FunctionID()) + + return func(info trace.TableCreateSessionDoneInfo) { + if info.Error == nil { + fieldsStore.fields = append(fieldsStore.fields, + kv.String("session_id", safeID(info.Session)), + kv.String("session_status", safeStatus(info.Session)), + kv.String("node_id", nodeID(safeID(info.Session))), + ) + } + } + } + + return nil + } + t.OnDo = func(info trace.TableDoStartInfo) func(trace.TableDoDoneInfo) { + if cfg.Details()&trace.TableEvents != 0 { + *info.Context = noTraceRetry(*info.Context) + operationName := info.Label + if operationName == "" { + operationName = info.Call.FunctionID() + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + operationName, + kv.Bool("idempotent", info.Idempotent), + ) + if info.NestedCall { + start.Msg("nested call", kv.Error(errNestedCall)) + } + + return func(info trace.TableDoDoneInfo) { + fields := []KeyValue{ + kv.Int("attempts", info.Attempts), + } + if info.Error != nil { + fields = append(fields, kv.Error(info.Error)) + } + start.End(fields...) + } + } + + return nil + } + t.OnDoTx = func(info trace.TableDoTxStartInfo) func(trace.TableDoTxDoneInfo) { + if cfg.Details()&trace.TableEvents != 0 { + *info.Context = noTraceRetry(*info.Context) + operationName := info.Label + if operationName == "" { + operationName = info.Call.FunctionID() + } + start := childSpanWithReplaceCtx( + cfg, + info.Context, + operationName, + kv.Bool("idempotent", info.Idempotent), + ) + if info.NestedCall { + start.Msg("nested call", kv.Error(errNestedCall)) + } + + return func(info trace.TableDoTxDoneInfo) { + fields := []KeyValue{ + kv.Int("attempts", info.Attempts), + } + if info.Error != nil { + fields = append(fields, kv.Error(info.Error)) + } + start.End(fields...) + } + } + + return nil + } + t.OnSessionNew = func(info trace.TableSessionNewStartInfo) func(trace.TableSessionNewDoneInfo) { + if cfg.Details()&trace.TableSessionLifeCycleEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.TableSessionNewDoneInfo) { + finish( + start, + info.Error, + kv.String("status", safeStatus(info.Session)), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + } + } + + return nil + } + t.OnSessionDelete = func(info trace.TableSessionDeleteStartInfo) func(trace.TableSessionDeleteDoneInfo) { + if cfg.Details()&trace.TableSessionLifeCycleEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TableSessionDeleteDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnSessionKeepAlive = func(info trace.TableKeepAliveStartInfo) func(trace.TableKeepAliveDoneInfo) { + if cfg.Details()&trace.TableSessionLifeCycleEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TableKeepAliveDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnSessionBulkUpsert = func(info trace.TableSessionBulkUpsertStartInfo) func(trace.TableSessionBulkUpsertDoneInfo) { + if cfg.Details()&trace.TableSessionQueryEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TableSessionBulkUpsertDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnSessionQueryPrepare = func( + info trace.TablePrepareDataQueryStartInfo, + ) func( + trace.TablePrepareDataQueryDoneInfo, + ) { + if cfg.Details()&trace.TableSessionQueryInvokeEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("query", info.Query), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TablePrepareDataQueryDoneInfo) { + finish( + start, + info.Error, + kv.String("result", safeStringer(info.Result)), + ) + } + } + + return nil + } + t.OnSessionQueryExecute = func( + info trace.TableExecuteDataQueryStartInfo, + ) func( + trace.TableExecuteDataQueryDoneInfo, + ) { + if cfg.Details()&trace.TableSessionQueryInvokeEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + kv.String("query", safeStringer(info.Query)), + kv.Bool("keep_in_cache", info.KeepInCache), + ) + + return func(info trace.TableExecuteDataQueryDoneInfo) { + if info.Error == nil { + finish( + start, + safeErr(info.Result), + kv.Bool("prepared", info.Prepared), + kv.String("transaction_id", safeID(info.Tx)), + ) + } else { + finish( + start, + info.Error, + ) + } + } + } + + return nil + } + t.OnSessionQueryStreamExecute = func( + info trace.TableSessionQueryStreamExecuteStartInfo, + ) func( + trace.TableSessionQueryStreamExecuteDoneInfo, + ) { + if cfg.Details()&trace.TableSessionQueryStreamEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("query", safeStringer(info.Query)), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TableSessionQueryStreamExecuteDoneInfo) { + if info.Error != nil { + start.End(kv.Error(info.Error)) + } else { + start.End() + } + } + } + + return nil + } + t.OnSessionQueryStreamRead = func( + info trace.TableSessionQueryStreamReadStartInfo, + ) func( + trace.TableSessionQueryStreamReadDoneInfo, + ) { + if cfg.Details()&trace.TableSessionQueryStreamEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TableSessionQueryStreamReadDoneInfo) { + if info.Error != nil { + start.End(kv.Error(info.Error)) + } else { + start.End() + } + } + } + + return nil + } + t.OnTxBegin = func(info trace.TableTxBeginStartInfo) func(trace.TableTxBeginDoneInfo) { + if cfg.Details()&trace.TableSessionTransactionEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TableTxBeginDoneInfo) { + finish( + start, + info.Error, + kv.String("transaction_id", safeID(info.Tx)), + ) + } + } + + return nil + } + t.OnTxCommit = func(info trace.TableTxCommitStartInfo) func(trace.TableTxCommitDoneInfo) { + if cfg.Details()&trace.TableSessionTransactionEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.TableTxCommitDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnTxRollback = func(info trace.TableTxRollbackStartInfo) func(trace.TableTxRollbackDoneInfo) { + if cfg.Details()&trace.TableSessionTransactionEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + kv.String("transaction_id", safeID(info.Tx)), + ) + + return func(info trace.TableTxRollbackDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnTxExecute = func(info trace.TableTransactionExecuteStartInfo) func(trace.TableTransactionExecuteDoneInfo) { + if cfg.Details()&trace.TableSessionTransactionEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + kv.String("transaction_id", safeID(info.Tx)), + kv.String("query", safeStringer(info.Query)), + ) + + return func(info trace.TableTransactionExecuteDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnTxExecuteStatement = func( + info trace.TableTransactionExecuteStatementStartInfo, + ) func( + info trace.TableTransactionExecuteStatementDoneInfo, + ) { + if cfg.Details()&trace.TableSessionTransactionEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + kv.String("transaction_id", safeID(info.Tx)), + kv.String("query", safeStringer(info.StatementQuery)), + ) + + return func(info trace.TableTransactionExecuteStatementDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnInit = func(info trace.TableInitStartInfo) func(trace.TableInitDoneInfo) { + if cfg.Details()&trace.TableEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.TableInitDoneInfo) { + finish( + start, + nil, + kv.Int("limit", info.Limit), + ) + } + } + + return nil + } + t.OnClose = func(info trace.TableCloseStartInfo) func(trace.TableCloseDoneInfo) { + if cfg.Details()&trace.TableEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.TableCloseDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnPoolPut = func(info trace.TablePoolPutStartInfo) func(trace.TablePoolPutDoneInfo) { + if cfg.Details()&trace.TablePoolAPIEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + + return func(info trace.TablePoolPutDoneInfo) { + finish(start, info.Error) + } + } + + return nil + } + t.OnPoolGet = func(info trace.TablePoolGetStartInfo) func(trace.TablePoolGetDoneInfo) { + if cfg.Details()&trace.TablePoolAPIEvents != 0 { + start := childSpanWithReplaceCtx( + cfg, + info.Context, + info.Call.FunctionID(), + ) + + return func(info trace.TablePoolGetDoneInfo) { + finish( + start, + info.Error, + kv.Int("attempts", info.Attempts), + kv.String("status", safeStatus(info.Session)), + kv.String("node_id", nodeID(safeID(info.Session))), + kv.String("session_id", safeID(info.Session)), + ) + } + } + + return nil + } + + return t +} diff --git a/otel/traces.go b/otel/traces.go new file mode 100644 index 000000000..22431dcf6 --- /dev/null +++ b/otel/traces.go @@ -0,0 +1,24 @@ +package otel + +import ( + "github.com/ydb-platform/ydb-go-sdk/v3" +) + +func WithTraces(config Config) ydb.Option { + if config == nil { + return nil + } + + return ydb.MergeOptions( + ydb.WithTraceDriver(driver(config)), + ydb.WithTraceTable(table(config)), + ydb.WithTraceQuery(query(config)), + ydb.WithTraceScripting(scripting(config)), + ydb.WithTraceScheme(scheme(config)), + ydb.WithTraceCoordination(coordination(config)), + ydb.WithTraceRatelimiter(ratelimiter(config)), + ydb.WithTraceDiscovery(discovery(config)), + ydb.WithTraceDatabaseSQL(databaseSQL(config)), + ydb.WithTraceRetry(retry(config)), + ) +}