Metadata key/value pairs don't maintain order between runs using StreamLogHandler

[qasim]

When adding metadata to loggers and using StreamLogHandler, the order of key/value pairs are not maintained. Should this be the case or is it intentional?

[qasim]

Reading through #110 I can see that this may be solved with a more robust implementation of LogHandler elsewhere, that has an ordered dictionary backing the metadata.

[ktoso]

The storage is dictionary (as well as conceptually, it's a "bag of key/values"), I don't think anyone should depend on order of things in those bags, esp as they may be passed around and revived from other contexts and thus preserving order I don't think is trivial (nor something we should strive for) for metadata.

So: Yes, I'd say this is on purpose and should not change.

[weissi]

@ktoso Everything you say is right. However it's quite weird that if you do

log.info("hello", metadata: ["a": "b", "c": "d"])
log.info("hello", metadata: ["a": "b", "c": "d"])

you may get

a=b c=d hello
c=d a=b hello

it can be quite frustrating to read. That we're using a dictionary is really just an implementation detail. So of course, we not change it and use it as an incentive to have people write their own LogHandlers but we could also argue that this should serve as an example. And in the real world, I think it's fair to expect that the order is stable. We could just sort them for example? WDYT?

[ShivaHuang]

I think there is no problem to let logging backends decide the final output format.

If they want to display the metadata in order, no matter by key, by value, ascending or descending, they can sort it in their way.

In this case StreamLogHandler, we can simply change the following implementation

private func prettify(_ metadata: Logger.Metadata) -> String? {
    return !metadata.isEmpty ? metadata.map { "\($0)=\($1)" }.joined(separator: " ") : nil
}

to something like

private func prettify(_ metadata: Logger.Metadata) -> String? {
    return !metadata.isEmpty ? metadata.sorted(by: <).map { "\($0)=\($1)" }.joined(separator: " ") : nil
}

to achieve the requirement.

I think this modification is useful and I'll be happy with it, but maybe we should consider how far should StreamLogHandler go?

I guess there might someone says: "Why the key/value pairs not separated by a common?" or "Why not wrap the metadata in a pair of [] to distinguish from the message body?" and so on. Should this package complete all these requests? or leave StreamLogHandler a simple but just working sample implementation?

[ktoso]

a=b c=d hello
c=d a=b hello

it can be quite frustrating to read.

@weissi Absolutely, that's enough to drive one mad! 😉

And as someone who looks at logs a lot I've also hit this frustration a long time ago as well, but I don't believe changing the storage is the solution. It is up to the backend how to print (that's what they do!) and not for the storage to decide -- as @ShivaHuang also points out very well above.

Since I look at logs a lot in my work, that's also exactly what I do in a LogHandler I have:

for key in metadata.keys.sorted() ... 

It's up to formatters to do that.

It's unfortunate with the existence of StreamLogHandler inside of this "API only (but not really)" package, since we hit the

[...] maybe we should consider how far should StreamLogHandler go?

I guess there might someone says: "Why the key/value pairs not separated by a common?" or "Why not wrap the metadata in a pair of [] to distinguish from the message body?" and so on. Should this package complete all these requests? or leave StreamLogHandler a simple but just working sample implementation?

trouble again...

At some point we really should "split off" work on a good log handler into a separate project and do all the right things there.

Is that time now perhaps?

[ktoso]

(Additional thought even answering this "what does order mean" here may have different interpretations: you said "I wrote a,b so I expect a,b but that means "keep order" while often you might actually want "alphabetically" rather than "keep order" if metadata is set in various places etc... So even this already has some nuances heh).

[glbrntt]

[...] maybe we should consider how far should StreamLogHandler go?
I guess there might someone says: "Why the key/value pairs not separated by a common?" or "Why not wrap the metadata in a pair of [] to distinguish from the message body?" and so on. Should this package complete all these requests? or leave StreamLogHandler a simple but just working sample implementation?

trouble again...

At some point we really should "split off" work on a good log handler into a separate project and do all the right things there.

I don't think the provided log handler has to be amazing or even great, but the lack of consistent ordering can be very frustrating as has been pointed out! I don't think a separate great handler would even be the right solution here, it's the low barrier to entry of this handler that's useful: I often hit this issue when I'm developing or debugging when it's more frustrating to pull in another dependency.

FWIW I don't think it really matters how they're ordered, as long as it's consistent.

[ktoso]

I guess we all agree random order sucks (I don't deny that, it's completely unusable to me as well, but I use custom handlers so I live with it fine); You are right though, many people will run with the default... And maybe we then have to analyze those logs, and it'd be nice to not lose sanity... 🤔

So, maybe just sorted by keys as a "stable predictable" way to print them? Would you want to send in a PR @glbrntt?

[ktoso]

Fixed in #151, could land as soon as 1.4.1, we'll see when we cut that.