Log messages do not have stable argument ordering

[joeblubaugh]

What happened:

I'm using the github.com/grafana/grafana-plugin-sdk-go/backend/log package in my SDK code, writing logs like so:

logger.Info("Log Message", "fieldOne", "1", "fieldTwo", "2")

Log messages are printed with nondeterministic ordering after the message field:

msg="Log Message" fieldOne=1 fieldTwo=2
msg="Log Message" fieldTwo=2 fieldOne=1
msg="Log Message" fieldTwo=2 fieldOne=1
msg="Log Message" fieldOne=1 fieldTwo=2
msg="Log Message" fieldTwo=2 fieldOne=1
msg="Log Message" fieldOne=1 fieldTwo=2
msg="Log Message" fieldOne=1 fieldTwo=2

The logger uses hclog and marshals to JSON at some point, passing through a map[string]interface{}, which makes the output order non-deterministic

What you expected to happen: Log fields should always be written to Grafana logs in the order that they're provided.

How to reproduce it (as minimally and precisely as possible):

pkg main

import (
    "github.com/grafana/grafana-plugin-sdk-go/backend/log"
)

func main() {
  l := log.New()
  t := time.NewTimer(1*time.Second)
  for {
    select {
      case <- t.C:
        l.Info("msg", "fieldOne", "1", "fieldTwo", "2")
    }
  }
}

Anything else we need to know?:

Environment:

• SDK version: v0.164.0
• Grafana version: v10.0.1
• Go version: 1.21

[oshirohugo]

This issue is happening in github.com/hashicorp/go-plugin As @joeblubaugh indicated, t's indeed an problem related to unmarshalling and marshalling the logs. The host pipes the plugin logs, unmarshal and marshal it to wrap it into the host logger and the issue comes from this process which is not deterministic.

I created an issue on their repo: https://github.com/hashicorp/go-plugin/issues/266 And I've also submitted a PR for the issue: https://github.com/hashicorp/go-plugin/pull/267

Once this is accepted we can update the package and fix the issue

[joeblubaugh]

I'm re-opening since the issue isn't actually addressed yet (waiting on upstream submission to hashicorp plugin library).