Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

json logger panics on write failures #38

Closed
notnoop opened this issue Apr 23, 2019 · 1 comment · Fixed by #39
Closed

json logger panics on write failures #38

notnoop opened this issue Apr 23, 2019 · 1 comment · Fixed by #39

Comments

@notnoop
Copy link
Contributor

notnoop commented Apr 23, 2019

The json logger unexpectedly panics when writing json format to writer backend fails:

go-hclog/intlogger.go

Lines 370 to 373 in 6907afb

err := json.NewEncoder(l.writer).Encode(vals)
if err != nil {
panic(err)
}
. In contrast the plain text formatter ignores any write error:

go-hclog/intlogger.go

Lines 145 to 256 in 6907afb

func (l *intLogger) log(t time.Time, level Level, msg string, args ...interface{}) {
l.writer.WriteString(t.Format(l.timeFormat))
l.writer.WriteByte(' ')
s, ok := _levelToBracket[level]
if ok {
l.writer.WriteString(s)
} else {
l.writer.WriteString("[?????]")
}
if l.caller {
if _, file, line, ok := runtime.Caller(3); ok {
l.writer.WriteByte(' ')
l.writer.WriteString(trimCallerPath(file))
l.writer.WriteByte(':')
l.writer.WriteString(strconv.Itoa(line))
l.writer.WriteByte(':')
}
}
l.writer.WriteByte(' ')
if l.name != "" {
l.writer.WriteString(l.name)
l.writer.WriteString(": ")
}
l.writer.WriteString(msg)
args = append(l.implied, args...)
var stacktrace CapturedStacktrace
if args != nil && len(args) > 0 {
if len(args)%2 != 0 {
cs, ok := args[len(args)-1].(CapturedStacktrace)
if ok {
args = args[:len(args)-1]
stacktrace = cs
} else {
args = append(args, "<unknown>")
}
}
l.writer.WriteByte(':')
FOR:
for i := 0; i < len(args); i = i + 2 {
var (
val string
raw bool
)
switch st := args[i+1].(type) {
case string:
val = st
case int:
val = strconv.FormatInt(int64(st), 10)
case int64:
val = strconv.FormatInt(int64(st), 10)
case int32:
val = strconv.FormatInt(int64(st), 10)
case int16:
val = strconv.FormatInt(int64(st), 10)
case int8:
val = strconv.FormatInt(int64(st), 10)
case uint:
val = strconv.FormatUint(uint64(st), 10)
case uint64:
val = strconv.FormatUint(uint64(st), 10)
case uint32:
val = strconv.FormatUint(uint64(st), 10)
case uint16:
val = strconv.FormatUint(uint64(st), 10)
case uint8:
val = strconv.FormatUint(uint64(st), 10)
case CapturedStacktrace:
stacktrace = st
continue FOR
case Format:
val = fmt.Sprintf(st[0].(string), st[1:]...)
default:
v := reflect.ValueOf(st)
if v.Kind() == reflect.Slice {
val = l.renderSlice(v)
raw = true
} else {
val = fmt.Sprintf("%v", st)
}
}
l.writer.WriteByte(' ')
l.writer.WriteString(args[i].(string))
l.writer.WriteByte('=')
if !raw && strings.ContainsAny(val, " \t\n\r") {
l.writer.WriteByte('"')
l.writer.WriteString(val)
l.writer.WriteByte('"')
} else {
l.writer.WriteString(val)
}
}
}
l.writer.WriteString("\n")
if stacktrace != "" {
l.writer.WriteString(string(stacktrace))
}
}
.

We noticed it because json logger paniced when writing to Stderr, a closed pipe at the time. You can find more details in hashicorp/go-plugin#114 .

I'd suggest treating logging here as best-effort (like in the non-json case), or returning and propagating the error back to make it an application concern.

Also, I may suggest distinguishing between write failures (ignore these) and json marshaling failures (in which case, add a log line indicating a log line was dropped due to json incompatibility).

I'd be happy to submit a PR with the suggested changes if they seem reasonable to maintainers.

@evanphx
Copy link
Contributor

evanphx commented Apr 23, 2019

Yes, the code should be removed such that if Encode() fails we move on silently. Go ahead and submit that PR.

notnoop pushed a commit that referenced this issue Apr 23, 2019
Handle cases where json logging fails to write:
* json serialization errors; log plain message with
metadata with a field indicating that args are omitted from logs
* io errors: ignore them, the same as non-json logging

Panicing in either case is somewhat unexpected and lead to unexpected
crashes, that can escalate  a minor bad untested logging into an process
crashes.

Fixes #38
notnoop pushed a commit that referenced this issue Apr 23, 2019
Handle cases where json logging fails to write:
* json serialization errors; log plain message with
metadata with a field indicating that args are omitted from logs
* io errors: ignore them, the same as non-json logging

Panicing in either case is somewhat unexpected and lead to unexpected
crashes, that can escalate  a minor bad untested logging into an process
crashes.

Fixes #38
notnoop pushed a commit that referenced this issue Apr 23, 2019
Handle cases where json logging fails to write:
* json serialization errors; log plain message with
metadata with a field indicating that args are omitted from logs
* io errors: ignore them, the same as non-json logging

Panicing in either case is somewhat unexpected and lead to unexpected
crashes, that can escalate  a minor bad untested logging into an process
crashes.

Fixes #38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants