[Feature]: Switch to structured logging

[seantronsen]

Recently while working on log aggregation utilities for the OpenCHAMI services, I noticed many don't yet utilize a structured logging mechanism which results in increased difficulties for downstream monitoring efforts, mostly by way of overly complex/fragile regex.

Some logs are plain unstructured text, some are standard logfmt, and others fall into well-structured formats like JSON.

Below are some examples of attempts to automatically parse information from the smd logs (note, the original log message is in the JSON message property):

{
  "appname": "smd",
  "component_id": null,
  "data": {
    "-": true,
    "172.16.0.254": true,
    "200": true,
    "2026/03/02": true,
    "2302B": true,
    "23:46:15": true,
    "524.311µs": true,
    "GET http://demo.openchami.cluster:8443/hsm/v2/Inventory/EthernetInterfaces HTTP/1.1": true,
    "[smd/O7SH03fs8M-003832]": true,
    "from": true,
    "in": true
  },
  "facility": "user",
  "host": "localhost",
  "hostname": "localhost",
  "message": "2026/03/02 23:46:15 [smd/O7SH03fs8M-003832] \"GET http://demo.openchami.cluster:8443/hsm/v2/Inventory/EthernetInterfaces HTTP/1.1\" from 172.16.0.254 - 200 2302B in 524.311µs",
  "node_id": null,
  "parse_error": null,
  "procid": 3274397,
  "request_id": null,
  "request_uri": null,
  "request_user": null,
  "severity": "info",
  "source_ip": "127.0.0.1",
  "source_type": "syslog",
  "timestamp": "2026-03-02T16:46:15Z",
  "trace_id": null,
  "xname": null
}

Above, the weirdness in the .data subtree is caused by an attempt to parse the unstructured text in .message as logfmt (which is the default parser assigned to this service as it simplifies extraction for examples like those below.

{
  "appname": "smd",
  "component_id": null,
  "data": {
    "11:46PM": true,
    "INF": true,
    "Request": true,
    "bytes_in": "0",
    "bytes_out": "732",
    "duration": "0.664907",
    "method": "GET",
    "remote_addr": "172.16.0.254",
    "request_id": "smd/O7SH03fs8M-003833",
    "request_uri": "/hsm/v2/State/Components",
    "status": "OK",
    "status_code": "200",
    "user_agent": "Go-http-client/1.1"
  },
  "facility": "user",
  "host": "localhost",
  "hostname": "localhost",
  "message": "11:46PM INF Request bytes_in=0 bytes_out=732 duration=0.664907 method=GET remote_addr=172.16.0.254 request_id=smd/O7SH03fs 8M-003833 request_uri=/hsm/v2/State/Components status=OK status_code=200 user_agent=Go-http-client/1.1",
  "node_id": null,
  "parse_error": null,
  "procid": 3274397,
  "request_id": "smd/O7SH03fs8M-003833",
  "request_uri": "/hsm/v2/State/Components",
  "request_user": null,
  "severity": "err",
  "source_ip": "127.0.0.1",
  "source_type": "syslog",
  "timestamp": "2026-03-02T16:46:15Z",
  "trace_id": null,
  "xname": null
}

Upon a quick skim of the repository contents, I've determined these logs originated from calls to routines like these here below:

coresmd/internal/debug/debug.go

Lines 13 to 19 in d17a510

	func DebugRequest(log *logrus.Entry, req *dhcpv4.DHCPv4) {
	log.Debugf("REQUEST: %v", req.Summary())
	}
	func DebugResponse(log *logrus.Entry, resp *dhcpv4.DHCPv4) {
	log.Debugf("RESPONSE: %v", resp.Summary())
	}

Would it be possible to switch to a fully structured logging format? It would greatly simplify downstream monitoring efforts.

[seantronsen]

For an additional example:

{
  "appname": "coresmd-coredhcp",
  "component_id": null,
  "data": {
    "level": "info",
    "msg": "assigning 172.16.0.1 to 52:54:00:be:ef:01 (Node) with a lease duration of 1h0m0s",
    "prefix": "plugins/coresmd",
    "time": "2026-03-02T23:46:38Z"
  },
  "facility": "user",
  "host": "localhost",
  "hostname": "localhost",
  "message": "time=\"2026-03-02T23:46:38Z\" level=info msg=\"assigning 172.16.0.1 to 52:54:00:be:ef:01 (Node) with a lease duration of 1h0m0s\" prefix=\"plugins/coresmd\"",
  "node_id": null,
  "parse_error": null,
  "procid": 3274741,
  "request_id": null,
  "request_uri": null,
  "request_user": null,
  "severity": "err",
  "source_ip": "127.0.0.1",
  "source_type": "syslog",
  "timestamp": "2026-03-02T16:46:38Z",
  "trace_id": null,
  "xname": null
}

This log is already partially structured, but the ability to dissect it further would be outstanding as it would enable debugging techniques that query the smd logs for address assignment information. It would also enable tracing node events by mac address and IP, since in some other services, those are easier to trace than the expected xname fields which may or may not be present on the log.

[seantrons]

Adding improved example from the logs generated in some source locations as of v0.6.0:

{
  "component_id": null,
  "data": {
    "assigned_hostname": "unknown-0002",
    "assigned_ipv4": "192.168.0.2",
    "comp_id": ["x1900c0s4b0n0", "x1900c0s4b0n0"],
    "comp_ips": "[192.168.0.2]",
    "comp_mac": "c4:cb:e1:c4:73:64",
    "comp_nid": ["2", "2"],
    "comp_type": ["Node", "Node"],
    "ips": "[192.168.0.2]",
    "lease_duration": "24h0m0s",
    "level": ["info", "info"],
    "mac": "c4:cb:e1:c4:73:64",
    "msg": ["rule[0] (rule-73487412) matched", "DHCPv4 assignment"],
    "prefix": [
      "\"plugins/coresmd\"\ntime=\"2026-03-31T12:40:28Z\"",
      "plugins/coresmd"
    ],
    "router_ip": "",
    "server_ip": "192.168.0.252",
    "time": "2026-03-31T12:40:28Z"
  },
  "facility": "user",
  "host": "head",
  "hostname": "head",
  "level": "notice",
  "msg": "time=\"2026-03-31T12:40:28Z\" level=info msg=\"rule[0] (rule-73487412) matched\" comp_id=x1900c0s4b0n0 comp_nid=2 comp_type=Node ips=[192.168.0.2] mac=\"c4:cb:e1:c4:73:64\" prefix=\"plugins/coresmd\"\ntime=\"2026-03-31T12:40:28Z\" level=info msg=\"DHCPv4 assignment\" assigned_hostname=unknown-0002 assigned_ipv4=192.168.0.2 comp_id=x1900c0s4b0n0 comp_ips=[192.168.0.2] comp_mac=\"c4:cb:e1:c4:73:64\" comp_nid=2 comp_type=Node lease_duration=24h0m0s prefix=\"plugins/coresmd\" router_ip=\"\" server_ip=192.168.0.252",
  "node_id": "2",
  "parse_error": null,
  "request_id": null,
  "request_uri": null,
  "request_user": null,
  "service": "coresmd",
  "source_ip": "127.0.0.1",
  "source_type": "syslog",
  "timeQuality": {
    "isSynced": "1",
    "syncAccuracy": "163897",
    "tzKnown": "1"
  },
  "trace_id": null,
  "ts": "2026-03-31T13:58:09.540381Z",
  "version": 1,
  "xname": null
}

The main quirks to notice are the duplicates. You'll notice in parsing (.data), many fields are unnecessarily collection-types with duplicate items. The input log has these duplicates inline, so it makes sense that they get parsed into this structure. There's also some duplicates across different field names (e.g., ips vs. comp_ips). Lastly, there's an oddity with the parsing of .prefix where .time somehow snuck in there, but that's likely the result of the duplicates mentioned previously.

[seantrons]

Idea

Track DHCP options in a nested structure. Maybe something like...

{
    "assigned_hostname": "unknown-0002",
    "assigned_ipv4": "192.168.0.2",
    "comp_id": ["x1900c0s4b0n0", "x1900c0s4b0n0"],
    "comp_ips": "[192.168.0.2]",
    "comp_mac": "c4:cb:e1:c4:73:64",
    "mac": "c4:cb:e1:c4:73:64",
    "msg": ["rule[0] (rule-73487412) matched", "DHCPv4 assignment"],
    "dhcp": {
          "option27": "value-here",
          ...
    },
    ....
}

Albeit at the possible cost of readability in the journal, it might be worthwhile to switch to JSON format structured logging to simplify hierarchical patterns like this...