1 package log 2 3 import ( 4 "bytes" 5 "reflect" 6 "time" 7 8 "github.com/Microsoft/hcsshim/internal/logfields" 9 "github.com/sirupsen/logrus" 10 "go.opencensus.io/trace" 11 ) 12 13 const nullString = "null" 14 15 // Hook intercepts and formats a [logrus.Entry] before it logged. 16 // 17 // The shim either outputs the logs through an ETW hook, discarding the (formatted) output 18 // or logs output to a pipe for logging binaries to consume. 19 // The Linux GCS outputs logrus entries over stdout, which is then consumed and re-output 20 // by the shim. 21 type Hook struct { 22 // EncodeAsJSON formats structs, maps, arrays, slices, and [bytes.Buffer] as JSON. 23 // Variables of [bytes.Buffer] will be converted to []byte. 24 // 25 // Default is false. 26 EncodeAsJSON bool 27 28 // FormatTime specifies the format for [time.Time] variables. 29 // An empty string disables formatting. 30 // When disabled, the fall back will the JSON encoding, if enabled. 31 // 32 // Default is [TimeFormat]. 33 TimeFormat string 34 35 // Duration format converts a [time.Duration] fields to an appropriate encoding. 36 // nil disables formatting. 37 // When disabled, the fall back will the JSON encoding, if enabled. 38 // 39 // Default is [DurationFormatString], which appends a duration unit after the value. 40 DurationFormat DurationFormat 41 42 // AddSpanContext adds [logfields.TraceID] and [logfields.SpanID] fields to 43 // the entry from the span context stored in [logrus.Entry.Context], if it exists. 44 AddSpanContext bool 45 } 46 47 var _ logrus.Hook = &Hook{} 48 49 func NewHook() *Hook { 50 return &Hook{ 51 TimeFormat: TimeFormat, 52 DurationFormat: DurationFormatString, 53 AddSpanContext: true, 54 } 55 } 56 57 func (h *Hook) Levels() []logrus.Level { 58 return logrus.AllLevels 59 } 60 61 func (h *Hook) Fire(e *logrus.Entry) (err error) { 62 // JSON encode, if necessary, then add span information 63 h.encode(e) 64 h.addSpanContext(e) 65 66 return nil 67 } 68 69 // encode loops through all the fields in the [logrus.Entry] and encodes them according to 70 // the settings in [Hook]. 71 // If [Hook.TimeFormat] is non-empty, it will be passed to [time.Time.Format] for 72 // fields of type [time.Time]. 73 // 74 // If [Hook.EncodeAsJSON] is true, then fields that are not numeric, boolean, strings, or 75 // errors will be encoded via a [json.Marshal] (with HTML escaping disabled). 76 // Chanel- and function-typed fields, as well as unsafe pointers are left alone and not encoded. 77 // 78 // If [Hook.TimeFormat] and [Hook.DurationFormat] are empty and [Hook.EncodeAsJSON] is false, 79 // then this is a no-op. 80 func (h *Hook) encode(e *logrus.Entry) { 81 d := e.Data 82 83 formatTime := h.TimeFormat != "" 84 formatDuration := h.DurationFormat != nil 85 if !(h.EncodeAsJSON || formatTime || formatDuration) { 86 return 87 } 88 89 for k, v := range d { 90 // encode types with dedicated formatting options first 91 92 if vv, ok := v.(time.Time); formatTime && ok { 93 d[k] = vv.Format(h.TimeFormat) 94 continue 95 } 96 97 if vv, ok := v.(time.Duration); formatDuration && ok { 98 d[k] = h.DurationFormat(vv) 99 continue 100 } 101 102 // general case JSON encoding 103 104 if !h.EncodeAsJSON { 105 continue 106 } 107 108 switch vv := v.(type) { 109 // built in types 110 // "json" marshals errors as "{}", so leave alone here 111 case bool, string, error, uintptr, 112 int8, int16, int32, int64, int, 113 uint8, uint32, uint64, uint, 114 float32, float64: 115 continue 116 117 // Rather than setting d[k] = vv.String(), JSON encode []byte value, since it 118 // may be a binary payload and not representable as a string. 119 // `case bytes.Buffer,*bytes.Buffer:` resolves `vv` to `interface{}`, 120 // so cannot use `vv.Bytes`. 121 // Could move to below the `reflect.Indirect()` call below, but 122 // that would require additional typematching and dereferencing. 123 // Easier to keep these duplicate branches here. 124 case bytes.Buffer: 125 v = vv.Bytes() 126 case *bytes.Buffer: 127 v = vv.Bytes() 128 } 129 130 // dereference pointer or interface variables 131 rv := reflect.Indirect(reflect.ValueOf(v)) 132 // check if `v` is a null pointer 133 if !rv.IsValid() { 134 d[k] = nullString 135 continue 136 } 137 138 switch rv.Kind() { 139 case reflect.Map, reflect.Struct, reflect.Array, reflect.Slice: 140 default: 141 // Bool, [U]?Int*, Float*, Complex*, Uintptr, String: encoded as normal 142 // Chan, Func: not supported by json 143 // Interface, Pointer: dereferenced above 144 // UnsafePointer: not supported by json, not safe to de-reference; leave alone 145 continue 146 } 147 148 b, err := encode(v) 149 if err != nil { 150 // Errors are written to stderr (ie, to `panic.log`) and stops the remaining 151 // hooks (ie, exporting to ETW) from firing. So add encoding errors to 152 // the entry data to be written out, but keep on processing. 153 d[k+"-"+logrus.ErrorKey] = err.Error() 154 // keep the original `v` as the value, 155 continue 156 } 157 d[k] = string(b) 158 } 159 } 160 161 func (h *Hook) addSpanContext(e *logrus.Entry) { 162 ctx := e.Context 163 if !h.AddSpanContext || ctx == nil { 164 return 165 } 166 span := trace.FromContext(ctx) 167 if span == nil { 168 return 169 } 170 sctx := span.SpanContext() 171 e.Data[logfields.TraceID] = sctx.TraceID.String() 172 e.Data[logfields.SpanID] = sctx.SpanID.String() 173 } 174