log: add option to place prefix text immediately before log text

[cespare]

At my company we use the log package extensively. A shortcoming we often encounter is that we want to include a text prefix on every log line before the logged text but after the automatic prefix. That is, if you have

l := log.New(os.Stderr, "xyz: ", log.LstdFlags)
l.Print("Frobnicating the turboencabulator")

You get

xyz: 2019/05/15 11:36:18 Frobnicating the turboencabulator

And we often want

2019/05/15 11:36:18 xyz: Frobnicating the turboencabulator

One place this comes up is in scenarios where we are processing different items and we want to include context about them in the log messages:

logger := /* some previously created "parent" logger */
for id, item := range items {
	subLogger := log.New(logger.Writer(), fmt.Sprintf("%d: ", id), logger.Flags())
	process(item, subLogger)
}

// ...

func process(it *item, l *log.Logger) {
	l.Print("Frobnicating the turboencabulator")
	// ...
}

(This is tangentially related to creating a "child" logger, which is possible as of Go 1.12.)

Without any way to put the prefix where we want, we end up needing some workaround such as passing an additional logPrefix string around and remembering to include it in every log message, or else using custom logging code.

I think that if the standard logger became an interface then our code would mostly pass around that interface and it would be easy to implement this cleanly ourselves. But that has proved to be a thorny issue and little progress has been made in the past few years. In the meantime, here are two alternatives for addressing this issue today:

Idea 1

Add a new log flag:

@@ -40,6 +40,7 @@ const (
        Llongfile                     // full file name and line number: /a/b/c/d.go:23
        Lshortfile                    // final file name element and line number: d.go:23. overrides Llongfile
        LUTC                          // if Ldate or Ltime is set, use UTC rather than the local time zone
+       LmsgPrefix                    // place prefix text immediately before the message instead of the beginning of the line
        LstdFlags     = Ldate | Ltime // initial values for the standard logger
 )

l := log.New(os.Stderr, "xyz: ", log.LstdFlags|log.LmsgPrefix)
l.Print("Frobnicating the turboencabulator")
// 2019/05/15 11:36:18 xyz: Frobnicating the turboencabulator

Idea 2

// MessagePrefix returns the output message prefix for the logger.
func (l *Logger) MessagePrefix() string

// SetMessagePrefix sets the output message prefix for the logger.
func (l *Logger) SetMessagePrefix(prefix string)

(It would need better documentation.) There need not be top-level MessagePrefix/SetMessagePrefix functions because this type of prefix doesn't make much sense globally. Then we would do

l := log.New(os.Stderr, "", log.LstdFlags)
l.SetMessagePrefix("xyz: ")
l.Print("Frobnicating the turboencabulator")
// 2019/05/15 11:36:18 xyz: Frobnicating the turboencabulator

[bradfitz]

This bites me every time I've tried to use the log prefix. Then I re-remember where it inserts it and I stop using the log prefix and write my own log wrapper func instead.

[rsc]

This hits me each time I try to use this too. I always expect the date to be before the prefix, not after. A bit to say "put the date and file (if there) before the prefix" makes sense to me, but I am not sure about the name. LmsgPrefix makes it sound like you just want to show the prefix, and the prefix is always shown.

/cc @robpike

[rsc]

@robpike, thoughts about what the API change should be?

[robpike]

@rsc Does it need API? You have SetFlags. Add a flag with boolean effect like LdateFirst. Haven't thought about it much though.

[cespare]

Yeah, LmsgPrefix isn't great.

I was going to say that the problem with LdateFirst is that it's not just that the date should be first: the file:line (if present) should also precede the prefix text.

l := log.New(os.Stderr, "xyz: ", log.Ldate|log.Ltime|log.Lshortfile|log.LtoBeNamed)
l.Print("Hello")
// Should this print
//   2019/06/19 09:11:16 test.go:12: xyz: Hello
// or
//   2019/06/19 09:11:16 xyz: test.go:12: Hello

But now that I've written it out, I'm not sure. Either way kind of seems fine to me: the important part is that the date is first. So I'd be okay with LdateFirst and having it output

[date] [prefix] [file:line] text

[rsc]

I think the point of moving things was to attach the prefix more clearly to the message text being printed. That would mean putting it after the file:line too.

That would align nicely with the original request for Lmsgprefix. (Not LmsgPrefix; see Lshortfile, Llongfile etc. LstdFlags is the odd man out.)

Any objections to Lmsgprefix?

/cc @robpike

[robpike]

Fine with me.

[rsc]

Marking accepted based on discussion.

[gopherbot]

Change https://golang.org/cl/186182 mentions this issue: log: add Lmsgprefix flag

[anuj-agrawal]

Does LprefixAfterHeaders sound like a better name than LmsgPrefix?

[gopherbot]

Change https://golang.org/cl/217126 mentions this issue: doc/go1.14: mention new log.Lmsgprefix flag