Commits on Nov 19, 2021

1. examples: use current klog, add structured logging example …

   Structured logging with InfoS is formatted differently than traditional output,
   so it's worthwhile to have an example that demostrates that.
   
   The new example didn't compile initially because an older version of klog was
   used. This gets avoids by always using the source from the current directory.

   

   pohly committed Nov 19, 2021
   Configuration menu

   • View commit details
   • Copy full SHA for 5ecf788
   • Browse repository at this point

   Copy the full SHA

   5ecf788 View commit details

   Browse the repository at this point in the history

2. structured logging: support log messages with line breaks …

   The initial structured logging output (almost) always produced a single line
   per log message, with quoting of strings to represent line breaks as \n.  This
   made the output hard to read (see
   kubernetes/kubernetes#104868).
   
   It was still possible to get line breaks when formatting a value with `%+v` and
   that ended up emitting line breaks; this was probably not intended.
   
   Now the message is never quoted, as in non-structured output. String values are
   quoted if they contain no line break. If they do, start/end markers delimit the
   text which appears on its own lines.
   
   All additional lines of a structure log message get indented by one space. This
   makes it obvious where a new log message starts, which is an improvement
   compared to the traditional format.
   
   Traditional output:
   
    I1112 14:06:35.783354  328441 structured_logging.go:42] someData printed using InfoF: {hello world 0}
    I1112 14:06:35.783472  328441 structured_logging.go:43] longData printed using InfoF: {long Multiple
    lines
    with quite a bit
    of text. 0}
    I1112 14:06:35.783483  328441 structured_logging.go:44] stringData printed using InfoF,
    with the message across multiple lines:
    long: Multiple
    lines
    with quite a bit
    of text.
    I1112 14:06:35.898176  142908 structured_logging.go:54] logData printed using InfoF:
    {log output from some program I0000 12:00:00.000000  123456 main.go:42] Starting
    E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
     0}
   
   Old InfoS output before this commit:
   
    I1112 14:06:35.783512  328441 structured_logging.go:50] "using InfoS" someData={Name:hello Data:world internal:0}
    I1112 14:06:35.783529  328441 structured_logging.go:51] "using InfoS" longData={Name:long Data:Multiple
    lines
    with quite a bit
    of text. internal:0}
    I1112 14:06:35.783549  328441 structured_logging.go:52] "using InfoS with\nthe message across multiple lines" int=1 stringData="long: Multiple\nlines\nwith quite a bit\nof text." str="another value"
    I1112 14:06:35.783565  328441 structured_logging.go:61] "Did something" item="foobar"
    I1112 14:06:35.783576  328441 structured_logging.go:63] "This is a full sentence." item="foobar"
    I1112 14:06:35.898278  142908 structured_logging.go:65] "using InfoS" logData={Name:log output from some program Data:I0000 12:00:00.000000  123456 main.go:42] Starting
    E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
     internal:0}
   
   New InfoS output:
   
    I1112 15:01:48.696617  413871 structured_logging.go:50] using InfoS: someData={Name:hello Data:world internal:0}
    I1112 15:01:48.696646  413871 structured_logging.go:51] using InfoS: ===start of longData===
     {Name:long Data:Multiple
     lines
     with quite a bit
     of text. internal:0}
     ===end of longData===
    I1112 15:01:48.696677  413871 structured_logging.go:52] using InfoS with
     the message across multiple lines: int=1 ===start of stringData===
     long: Multiple
     lines
     with quite a bit
     of text.
     ===end of stringData=== str="another value"
    I1112 15:01:48.788207  143146 structured_logging.go:65] using InfoS: ===start of logData===
     {Name:log output from some program Data:I0000 12:00:00.000000  123456 main.go:42] Starting
     E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
      internal:0}
     ===end of logData===
    I1112 15:01:48.696704  413871 structured_logging.go:61] Did something: item="foobar"
    I1112 15:01:48.696719  413871 structured_logging.go:63] This is a full sentence. item="foobar"

   

   pohly committed Nov 19, 2021
   Configuration menu

   • View commit details
   • Copy full SHA for 2ccf744
   • Browse repository at this point

   Copy the full SHA

   2ccf744 View commit details

   Browse the repository at this point in the history

3. use different delimiters …

   Multi-line strings are now shown as
      fieldName>>>
      <<<
   and "| " is used as separator between message and values.
   
   This is shorter:
   
   I1119 13:18:00.210970   78836 structured_logging.go:58] using InfoS | someData={Name:hello Data:world internal:0}
   I1119 13:18:00.210988   78836 structured_logging.go:59] using InfoS | longData>>>
    {Name:long Data:Multiple
    lines
    with quite a bit
    of text. internal:0}
    <<<
   I1119 13:18:00.211009   78836 structured_logging.go:60] using InfoS with
    the message across multiple lines | int=1 stringData>>>
    long: Multiple
    lines
    with quite a bit
    of text.
    <<< str="another value"
   I1119 13:18:00.211032   78836 structured_logging.go:65] using InfoS | logData>>>
    {Name:log output from some program Data:I0000 12:00:00.000000  123456 main.go:42] Starting
    E0000 12:00:01.000000  123456 main.go:43] Failed for some reason
     internal:0}
    <<<
   I1119 13:18:00.211055   78836 structured_logging.go:66] using InfoS | boolean=true int=1 float=0.1
   I1119 13:18:00.211068   78836 structured_logging.go:71] Did something | item="foobar"
   I1119 13:18:00.211079   78836 structured_logging.go:73] This is a full sentence. item="foobar"

   

   pohly committed Nov 19, 2021
   Configuration menu

   • View commit details
   • Copy full SHA for 954847b
   • Browse repository at this point

   Copy the full SHA

   954847b View commit details

   Browse the repository at this point in the history