Pointers for creating a MongoDB 4.4 log format file for lnav?

[macintacos]

I'm trying to specify a formatter for lnav that'll support MongoDB 4.4's new structured logging, but I can't quite seem to get it to work properly.

Here's the link to the documentation for 4.4's logging: https://docs.mongodb.com/manual/reference/log-messages/index.html

Here's what I have so far:

{
  "mongod_log": {
    "title": "MongoDB 4.4 Log format",
    "description": "New log format beginning with MongoDB 4.4",
    "url": "https://docs.mongodb.com/manual/reference/log-messages/index.html#structured-logging",
    "json": true,
    "file-pattern": ".*mongod.*",
    "line-format": [
      { "field": "t" },
      "{",
      { "field": "$date" },
      "}",
      { "field": "s" },
      "\t",
      { "field": "c" },
      "\t",
      { "field": "id" },
      "\t",
      { "field": "ctx" },
      { "field": "msg" },
      { "field": "attr" }
    ],
    "timestamp-field": "$date",
    "level-field": "s",
    "level": {
      "fatal": "F",
      "error": "E",
      "warning": "W",
      "info": "I",
      "debug": "D1",
      "debug2": "D2",
      "debug3": "D3",
      "debug4": "D4",
      "debug5": "D5"
    },
    "body-field": "msg",
    "value": {
      "t": { "kind": "json" },
      "$date": { "kind": "string" },
      "s": { "kind": "string" },
      "c": { "kind": "string" },
      "id": { "kind": "integer", "identifier": true },
      "ctx": { "kind": "string", "identifier": true },
      "msg": { "kind": "string" },
      "attr": { "kind": "json" }
    }
  }
}

There are a number of things I'm unsure about:

1. The documentation doesn't seem to give a full-blown example for specifying a JSON log, but I did find a sample in ~/.lnav/default (journald_json_log) that helped a little bit. It'd be nice if there were a canonical example in the docs.
2. The file format doesn't seem to be recognized when I open a file that I think that matches file-pattern; again, the documentation isn't really descriptive about what it accepts, so it's a guess at this point. I think it should be working? For reference, the file name is in the rough form of <hostname>_mongodb.log.gz.
3. I think that it's trying my format because if I mess up one of the values (like level for example), the log won't load. That might be a side effect of how lnav works though but I'm not sure

I'd love some help trying to get this figured out. Here are some sample log lines in a file that I'm testing this on:

{"t":{"$date":"2020-08-11T13:28:01.958+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn17","msg":"connection ended","attr":{"remote":"0.0.0.0:45210","connectionCount":5}}
{"t":{"$date":"2020-08-11T13:28:01.959+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn18","msg":"connection ended","attr":{"remote":"0.0.0.0:45212","connectionCount":4}}
{"t":{"$date":"2020-08-11T13:28:01.973+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"connection accepted","attr":{"remote":"0.0.0.0:45214","sessionId":19,"connectionCount":5}}
{"t":{"$date":"2020-08-11T13:28:01.973+00:00"},"s":"I",  "c":"NETWORK",  "id":22943,   "ctx":"listener","msg":"connection accepted","attr":{"remote":"0.0.0.0:45216","sessionId":20,"connectionCount":6}}
{"t":{"$date":"2020-08-11T13:28:01.974+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn15","msg":"connection ended","attr":{"remote":"0.0.0.0:45206","connectionCount":5}}
{"t":{"$date":"2020-08-11T13:28:01.981+00:00"},"s":"I",  "c":"NETWORK",  "id":22944,   "ctx":"conn20","msg":"connection ended","attr":{"remote":"0.0.0.0:45216","connectionCount":4}}
{"t":{"$date":"2020-08-11T13:28:07.407+00:00"},"s":"I",  "c":"NETWORK",  "id":51800,   "ctx":"conn86","msg":"client metadata","attr":{"remote":"0.0.0.0:45356","client":"conn86","doc":{"driver":{"name":"mongo-go-driver","version":"v1.1.4"},"os":{"type":"linux","architecture":"amd64"},"platform":"go1.13.10","application":{"name":"Some program (git: somehash)"}}}}

[tstack]

2. The file format doesn't seem to be recognized when I open a file that I think that matches file-pattern; again, the documentation isn't really descriptive about what it accepts, so it's a guess at this point. I think it should be working? For reference, the file name is in the rough form of _mongodb.log.gz.

It was an issue with the timestamp not being found. Since $date is inside the t object, a JSON-Pointer reference needs to be used for the timestamp-field (t/$date in this case). You're right about the file pattern.

I've made the following changes to your format and pasted it below:

• Added convert-to-local-time to convert the UTC timestamps to your current timezone.
• Used the special __timestamp__ field identifier to display the converted timestamp.
• Changed the t field in the format to be hidden by default since it seems to just have the timestamp, which is already displayed a different way.
• Changed the ctx field in the line-format to have a minimum width and make it right-aligned.
• Removed the attr field from the line-format so that it is displayed below the main message line. (I just like displaying JSON blobs on separate lines)

{
  "mongod_log": {
    "title": "MongoDB 4.4 Log format",
    "description": "New log format beginning with MongoDB 4.4",
    "url": "https://docs.mongodb.com/manual/reference/log-messages/index.html#structured-logging",
    "json": true,
    "file-pattern": ".*mongod.*",
    "convert-to-local-time" : true,
    "line-format": [
      { "field": "__timestamp__" },
      { "field": "s" },
      "\t",
      { "field": "c" },
      "\t",
      { "field": "id" },
      { "field": "ctx", "min-width": 10, "align": "right" },
      "\t",
      { "field": "msg" }
    ],
    "timestamp-field": "t/$date",
    "level-field": "s",
    "level": {
      "fatal": "F",
      "error": "E",
      "warning": "W",
      "info": "I",
      "debug": "D1",
      "debug2": "D2",
      "debug3": "D3",
      "debug4": "D4",
      "debug5": "D5"
    },
    "body-field": "msg",
    "value": {
      "t": {"kind": "string", "hidden": true },
      "t/$date": { "kind": "string" },
      "s": { "kind": "string" },
      "c": { "kind": "string" },
      "id": { "kind": "integer", "identifier": true },
      "ctx": { "kind": "string", "identifier": true },
      "msg": { "kind": "string" },
      "attr": { "kind": "json" }
    }
  }
}

Here's what your sample log looks like with the updated format:

Thanks for the detailed report! Leave this open so I can make sure to get the docs updated.

(Sorry for the late reply)

[macintacos]

This is awesome, thank you! I'll add this and let you know how it goes and if there are any edge cases that I missed based on the logs tha tI have available.

[macintacos]

@tstack It's a bit interesting that the id field isn't getting any kind of distinct coloring, considering that it's an identifier. Is there something else that needs to be done there to make sure that the color for that is similar to how the ctx is being colored?

[macintacos]

I ended up going with this: https://gist.github.com/macintacos/c6f58d2b0ed167b71466b20ec3fed7e7 (sincere thanks for your help here!). Would still be nice to figure out that coloring stuff though, so if you have any pointers on that I'd be happy to see them.

[tstack]

It's a bit interesting that the id field isn't getting any kind of distinct coloring

It looks like a bug where non-string properties in JSON logs are not colored correctly if they're identifiers.

[tstack]

I think the highlighting issue should be fixed with this commit -- 4563054

[macintacos]

Awesome, I guess my last question is; when will there be a new release? 🙂