Is it possible to write a test to test the order of keys logged

Question

Logrus logs keys alphabetically and this is what I want and need, but I would like to write a test to make sure that is not changed, I tried adding hooks but I don't think I can get access to the full log with the custom context I have added using WithFields I could only get the message logged example

func TestSomething(t*testing.T){
  logger, hook := test.NewNullLogger()
  logger.WithField("correlationId","123").WithField("id","1").Info("hello")

  assert.Equal(t, 1, len(hook.Entries))
  assert.Equal(t, logrus.(Level, hook.LastEntry().Level)
  assert.Equal(t, "Hello", hook.LastEntry().Message)

  hook.Reset()
  assert.Nil(t, hook.LastEntry())
}

I would like to test that message came before t in the output

log.SetFormatter(&log.JSONFormatter{
        FieldMap: log.FieldMap{
            log.FieldKeyMsg: "message",
            log.FieldKeyTime: "t",
        },
    })
    logger := log.WithFields(
        log.Fields{
            "id":        context.id,
            "correlationId":       context.CorrelationId,
        },

Maps are un-ordered, therefore you cannot test the order. If the logging package guarantees the output to be sorted, then it's not your code's concern to test the logging package itself. — JimB, Mar 01 '21 at 13:29

Elias Van Ootegem · Answer 1 · 2021-03-02T16:05:54.003

Logrus logs keys alphabetically

No, it actually doesn't. A FieldMap is actually just a standard go map (as you can see here). The same file shows how the JSON marshalling of the fieldmap is handled. There's nothing in there to suggest there's any specific key sorting being done.

It's well possible that, owing to how the map keys are hashed, the output is seemingly in alphabetical order in your specific case, on your platform, with your specific version of both logrus and the go compiler. There is, however, no guarantee that this will always be the case. If you compile the same code for a different architecture/operating system (GOARCH and GOOS), the output may not be the same. Things look to be in alphabetical order now, but that's just coincidence. Writing a test to ensure your luck hasn't run out isn't the point of tests.

Maps are, by definition, un-ordered data structures. If you want the log output to be ordered alphabetically, then you could write your own formatter for logrus, iterate over the fieldmap, add all the keys (as strings) to a slice, sort said slice, and then iterate over the sorted keys to print out the keys in alphabetical order. Then again, I would really be curious to know what your use-case is to justify such a thing.

Right, on closer inspection, it does seem that the encoding/json package actually marshals maps as JSON objects, with keys being sorted:

Map values encode as JSON objects. The map's key type must either be a string, an integer type, or implement encoding.TextMarshaler. The map keys are sorted and used as JSON object keys by applying the following rules, subject to the UTF-8 coercion described for string values above

That's fine, and provided the standard library doesn't change (or you don't decide to swap it out for some alternative that behaves differently), you should be good. This behaviour also isn't guaranteed when using a different formatter. Your outset was to ensure that replacing the logging package wouldn't break this behaviour. In that case, you're testing the wrong thing... it's not the logging package itself, but rather the json encoding package (marshaller) you're using.

You're basically looking for a way to test whether or not someone plugs in an alternative marshalling package into an external package you're using. If the next version of logrus ends up switching over to a package like ffjson, your tests would fail, despite only having bumped the version of your log package, and making no other changes other than that. A unit test just isn't the best way to enforce this. You could maintain your own fork of the logrus package, or just lock in a known good version in your go.mod file instead, and call it a day.

I have an odd use case in that the contents of the message key is used by the centralized logging system to override the timestamp value of the actual log - I took from [this comment](https://github.com/sirupsen/logrus/issues/670#issuecomment-345531507) that the json is sorted alphbetically, it looks like it's the json marshaler that sorts them for me. — M_K, Mar 01 '21 at 14:53
Also the point of writing the test is so if somebody tries to switch logging library and this library does not sort the way it is now, well then they'll know about it. :) — M_K, Mar 01 '21 at 14:55
I see no evidence that the marshaller outputs fields alphabetically. This may have changed since that comment was posted, and may change with future version of go. All the same, I would try to avoid writing my application in a way to suit my logging system. I'd much rather write something that ingests log output of my application and does whatever processing needed after the fact. It keeps the runtime of the application clean, and offloads sorting of log stuff, leaving my app to perform at its best — Elias Van Ootegem, Mar 01 '21 at 15:00
this https://golang.org/src/encoding/json/encode.go?#796 suggests that it does, right now it's good enough for this odd use case. — M_K, Mar 02 '21 at 12:07
Indeed, had a closer look at the `encoding/json` documentation, and it does mention sorting. The thing is: it's the json encoding package that oversees the sorting. There's nothing specific to logrus about the behaviour. If logrus changes over to a different json encoding package, you may see different behaviour all the same. Updated my answer to reflect this — Elias Van Ootegem, Mar 02 '21 at 16:07

Is it possible to write a test to test the order of keys logged

1 Answers1