RFE - Structured Logging

[jeffspahr]

It would be nice to be able to enable structured json logging for Trident. This is beneficial for use in log aggregation solutions like the Elastic Stack so you don't have to parse fields in a single log message.

It looks like Trident is using logrus which supports json logging so hopefully the LOE isn't terrible.

[clintonk]

Hi, @jeffspahr. Using a JSON formatter in logrus will make each log statement a separate JSON block, like this:

{"aggregate":"VICE08_aggr2","level":"debug","mediaType":"hybrid","msg":"Read aggregate attributes.","time":"2019-10-16T11:34:03-04:00"}
{"backend":"\u0026{Driver:0xc0000f5040 Name:ontapnas_10.63.171.70 BackendUUID: Online:true State:online Storage:map[VICE07_aggr1:0xc00052e700 VICE07_aggr2:0xc00052e740 VICE08_aggr1:0xc00052e780 VICE08_aggr2:0xc00052e7c0] Volumes:map[]}","level":"info","msg":"Created new storage backend.","time":"2019-10-16T11:34:03-04:00"}
{"backend":"ontapnas_10.63.171.70","backend.BackendUUID":"","level":"debug","msg":"Adding a new backend.","time":"2019-10-16T11:34:03-04:00"}
{"backend":"ontapnas_10.63.171.70","level":"debug","msg":"Passthrough store adding backend.","time":"2019-10-16T11:34:03-04:00"}
{"backend":"ontapnas_10.63.171.70","level":"info","msg":"Newly added backend satisfies no storage classes.","time":"2019-10-16T11:34:03-04:00"}
{"backend":"ontapnas_10.63.171.70","backendUUID":"","handler":"Bootstrap","level":"info","msg":"Added an existing backend.","online":"false","persistentBackends.BackendUUID":"","state":"online","time":"2019-10-16T11:34:03-04:00"}
{"level":"info","msg":"Added 1 existing volume(s)","time":"2019-10-16T11:34:04-04:00"}
{"level":"info","msg":"Trident bootstrapped successfully.","time":"2019-10-16T11:34:04-04:00"}
{"clientAPIVersion":"1.39","clientArch":"amd64","clientOS":"linux","clientVersion":"18.09.0","level":"debug","msg":"Docker version info.","serverAPIVersion":"1.39","serverArch":"amd64","serverOS":"linux","serverVersion":"18.09.0","time":"2019-10-16T11:34:08-04:00"}
{"driver":"ontap-nas","level":"debug","msg":"Logged EMS message.","time":"2019-10-16T11:34:13-04:00"}

Would you please confirm that is what you need? The built-in JSON formatter in logrus didn't work well, but it was straightforward to write a custom one. And would you need to specify this to the Trident installer?

[jeffspahr]

Hey @clintonk,

This looks great! I have two field name suggestions since logrus has interesting defaults. This will better align with out of the box Elasticsearch expectations.
Change msg to message.
Change time to @timestamp.

const (
    FieldKeyMsg   = "message"
    FieldKeyLevel = "level"
    FieldKeyTime  = "@timestamp"
)

Here's what this looks like after running it through our logging pipeline:

Note that @timestamp didn't get replaced with time so it's using the time the log was picked up by filebeat vs the time application wrote the log.

Thanks,
Jeff

[jeffspahr]

And would you need to specify this to the Trident installer?

Yeah that would make sense.

[clintonk]

@jeffspahr Thanks for the feedback. Time is very short for 19.10, so I'd appreciate your confirming this works for you:

{"@timestamp":"2019-10-18T11:00:29-04:00","aggregate":"VICE07_aggr1","level":"debug","mediaType":"hybrid","message":"Read aggregate attributes."}
{"@timestamp":"2019-10-18T11:00:29-04:00","aggregate":"VICE07_aggr2","level":"debug","mediaType":"hybrid","message":"Read aggregate attributes."}
{"@timestamp":"2019-10-18T11:00:29-04:00","aggregate":"VICE08_aggr1","level":"debug","mediaType":"hybrid","message":"Read aggregate attributes."}
{"@timestamp":"2019-10-18T11:00:29-04:00","aggregate":"VICE08_aggr2","level":"debug","mediaType":"hybrid","message":"Read aggregate attributes."}
{"@timestamp":"2019-10-18T11:00:29-04:00","backend":"\u0026{Driver:0xc000192000 Name:ontapnas_10.63.171.70 BackendUUID: Online:true State:online Storage:map[VICE07_aggr1:0xc000586d00 VICE07_aggr2:0xc000586d40 VICE08_aggr1:0xc000586d80 VICE08_aggr2:0xc000586dc0] Volumes:map[]}","level":"info","message":"Created new storage backend."}
{"@timestamp":"2019-10-18T11:00:29-04:00","backend":"ontapnas_10.63.171.70","backend.BackendUUID":"","level":"debug","message":"Adding a new backend."}
{"@timestamp":"2019-10-18T11:00:29-04:00","backend":"ontapnas_10.63.171.70","level":"debug","message":"Passthrough store adding backend."}
{"@timestamp":"2019-10-18T11:00:29-04:00","backend":"ontapnas_10.63.171.70","level":"info","message":"Newly added backend satisfies no storage classes."}
{"@timestamp":"2019-10-18T11:00:29-04:00","backend":"ontapnas_10.63.171.70","backendUUID":"","handler":"Bootstrap","level":"info","message":"Added an existing backend.","online":"false","persistentBackends.BackendUUID":"","state":"online"}
{"@timestamp":"2019-10-18T11:00:29-04:00","level":"info","message":"Added 1 existing volume(s)"}
{"@timestamp":"2019-10-18T11:00:29-04:00","level":"info","message":"Trident bootstrapped successfully."}
{"@timestamp":"2019-10-18T11:00:34-04:00","clientAPIVersion":"1.39","clientArch":"amd64","clientOS":"linux","clientVersion":"18.09.0","level":"debug","message":"Docker version info.","serverAPIVersion":"1.39","serverArch":"amd64","serverOS":"linux","serverVersion":"18.09.0"}
{"@timestamp":"2019-10-18T11:00:39-04:00","driver":"ontap-nas","level":"debug","message":"Logged EMS message."}

[jeffspahr]

I just ran this through our pipeline as well. @timestamp worked as expected. message looks good too. Thank you for this feature!