SolidFire mNode and HCC Log Fowarding

2020-11-27 00:00 10 minute read

SolidFire Management Node (aka mNode) is a VM that runs Hybrid Cloud Services (various "management stuff".) Let's say we wanted to collect and analyze those logs.

How could we get the logs out the smart way?

Before we begin, we need to know what we're dealing with. As of today, we have two groups of logs on mNode:

mNode system logs (the usual Linux stuff)
HCC service logs (JBOC, just a bunch of containers)

There are no local users so presumably everything that's worthy of our attention is in system and HCC log(s).

Key software components:

NetApp SolidFire Management Node (mNode) v12.2
- Docker v18.09.8
- rsyslogd 8.1904.0
NetApp Hybrid Cloud Control (HCC) v2.16.66

mNode

Backup your /etc/rsyslog.conf and hack away! I added these three rows for my $DST server reachable at $DST_PORT ($DST:$DST_PORT such as 2.2.2.2:2514):

*.* action(type="omfwd" target="$DST" port="$DST_PORT" protocol="tcp"
            action.resumeRetryCount="100"
            queue.type="linkedList" queue.size="10000")

There are fancy features in this module. You can compress the log, set a re-try interval (for the 100 tries mentioned above; see ActionSendTCPRebindInterval in the rsyslog documentation), or even use a specific network device (which may be useful if you have multiple NICs as users who use mNode with Persistent Volumes do, or want to use a secure network to forward your logs) and so on. RTFM!

With this set up, we can now monitor OS-level events:

Nov 27 10:30:21 192.168.1.31 sshd[19710]: Postponed keyboard-interactive for admin from 192.168.1.12 port 58430 ssh2 [preauth]
Nov 27 10:30:23 192.168.1.31 sshd[19710]: Postponed keyboard-interactive/pam for admin from 192.168.1.12 port 58430 ssh2 [preauth]
Nov 27 10:30:23 192.168.1.31 sshd[19710]: Accepted keyboard-interactive/pam for admin from 192.168.1.12 port 58430 ssh2

I should note that there are all sorts of logs under /var/log, some of which are likely not captured by syslog, so additional modifications to rsyslog.conf would be required if we wanted to capture those logs.

HCC

This one seems easy. Backup /etc/docker/daemon.json and hack away, right? Wrong!

With log-related additions to daemon.json we can send Docker logs to $DST:$DST_PORT, also using TCP like we did with rsyslog.

{
    "bip" : "169.254.100.1/22",
    "log-driver": "syslog",
    "log-opts": {
        "syslog-address": "tcp://$DST:$DST_PORT",
           "tag": "solidfire"
    }
}

The bip thing was there before - I only added the log-related entries.

The tag key may be useful for classification and grouping at the destination. I should probably have done something similar for the rsyslog above. With that tag Docker logs (below tagged with hcc) are easier to tell apart from mNode (OS) logs (systemd), although we could also use syslog at the destination to save each source to a different file:

Nov 27 10:28:27 192.168.1.31 systemd[1]: Stopping Deploy Element Auth service...
Nov 27 10:28:27 192.168.1.31 systemd[1]: Stopping Login Service...
Nov 27 10:28:27 192.168.1.31 hcc[20264]: killing the spooler with pid 6

Once we're done with changes to rsyslog.conf and Docker's daemon.json, we can reboot mNode.

Wait, what do you mean "reboot"

Yep, I just rebooted mNode to see if my settings worked. What if we wanted to reload rather than reboot? Feel free to JFGI (I'm not too curious how to do that on Docker v18.09.8!)

At the destination syslog server, tail the forwarded log(s) to see a combined log from mNode's rsyslog and Docker:

Nov 27 08:16:01 192.168.1.31 CROND[30647]: (root) CMD (cd / && /usr/bin/flock -x /var/lib/sftracing/lock -c 'logrotate --state=/var/lib/sftracing/status /var/lib/sftracing/logrotate.conf' >/dev/null)
Nov 27 08:16:51 192.168.1.31 dockerd[20264]: time="2020-11-27T08:16:51.520518736Z" level=info msg="NetworkDB stats mnode(2e34102d1390) - netID:jsgguqh5mxhgjxxf1qkvlvs0t leaving:false netPeers:1 entries:43 Queue qLen:0 netMsg/s:0"
Nov 27 08:16:51 192.168.1.31 dockerd[20264]: time="2020-11-27T08:16:51.520610196Z" level=info msg="NetworkDB stats mnode(2e34102d1390) - netID:moxqzm0ca0yon5wgri3yyty94 leaving:false netPeers:1 entries:3 Queue qLen:0 netMsg/s:0"
Nov 27 08:16:51 192.168.1.31 dockerd[20264]: time="2020-11-27T08:16:51.520624912Z" level=info msg="NetworkDB stats mnode(2e34102d1390) - netID:lp5fpj7cqik3pqsqsg7o56xsi leaving:false netPeers:1 entries:8 Queue qLen:0 netMsg/s:0"
Nov 27 08:17:01 192.168.1.31 CROND[30752]: (root) CMD (cd / && /usr/bin/flock -x /var/lib/sftracing/lock -c 'logrotate --state=/var/lib/sftracing/status /var/lib/sftracing/logrotate.conf' >/dev/null)
Nov 27 08:17:06 192.168.1.31 lldpd[21648]: unable to bind to raw socket for interface veth20d4528: No such device
Nov 27 08:17:06 192.168.1.31 lldpd[21651]: unable to initialize veth20d4528

System and Docker service log are there, but wait - those docker logs seem very sparse, what's up with that?

Logs of Individual Containers

We need to do something about the container logs. What only 30 minutes ago seemed like a trivial exercise is becoming a way to waste an entire evening…

Container logs go to /var/lib/docker/containers/${Id}/${Id}-json.log (where ID is the container ID) as expected. These IDs change after each restart (for example, in the case of container image logs-svc , we'd get a different ID every time the OS or container are restarted.)

For now the important part is that the information we need is there:

{"log":"[pid: 9|app: 0|req: 972/1678] 10.0.0.40 () {32 vars in 1303 bytes} [Fri Nov 27 08:33:13 2020] GET /1/assets/storage-clusters/5a6502a3-8bcb-4617-8cce-64127996545c =\u003e generated 735 bytes in 6 msecs (HTTP/1.1 200) 5 headers in 154 bytes (1 switches on core 0)\n","stream":"stderr","time":"2020-11-27T08:33:13.665314987Z"}
{"log":"[pid: 9|app: 0|req: 973/1679] 10.0.0.40 () {32 vars in 1303 bytes} [Fri Nov 27 08:33:23 2020] GET /1/assets/storage-clusters/5a6502a3-8bcb-4617-8cce-64127996545c =\u003e generated 735 bytes in 6 msecs (HTTP/1.1 200) 5 headers in 154 bytes (1 switches on core 0)\n","stream":"stderr","time":"2020-11-27T08:33:23.670857855Z"}

Next we need to figure out why that stuff isn't being forwarded out. The problem is we may not be able to do much with that information: we can't change HCC's container startup parameters (not in a supported way anyway).

We don't have to be worried about that scenario because we can always get to the container logs via the HCC API which lets us poll the HCC API endpoint and those logs every $N seconds (or get last $M lines from particular container log). That functionality reflects the logs command of Docker:

sudo docker logs c43bcd1f0431 --since 2020-11-26

While we can poll the API for container logs this way, a better approach would be to run an agent that scans /var/lib/docker/containers/ and takes care of everything.

But why are the logs not sent together with Docker logs? The answer is under /etc/rsyslog.d - in the file named 30-docker.conf, to be precise:

:syslogtag, startswith, "docker" /var/log/docker.info
& stop

We'd have to hack that file or come up with another file (40-hcc.conf, for example) where we'd ask rsyslog to find our logs in /var/lib/docker/containers/*/*-json.log. But - alas! - this version of rsyslog doesn't do directory name wildcards so that's out of the question as well.

We could write a new fancy rsyslog rule and dynamically reload rsyslog.conf, but that wouldn't be pain-free either because interesting HCC container logs are all owned by root:root which wouldn't work for rsyslog.conf (another can of worms.)

Time to take another look at that HCC API method…

HCC `GET /logs`

HCC logs seem to be rotated very slowly (weeks) so it appears quite safe to fetch them every X minutes or hours. We can use the since parameter to dynamically get log entries created in last X minutes or hours, and avoid fetching the logs of stopped containers named logs-svc (we only want the logs of a running logs-svc container).

curl -X GET "https://${mNode-IP}/mnode/logs?since=2020-11-26T06%3A00%3A00Z&service-name=logs-svc&stopped=false ...

That would query mNode for the log of a running logs-svc container and return something like this:

Response body
Download
=========================================================
    mnode_logs-svc.1.nxk8szxmjuuiyo30frxdltcel
=========================================================
[uWSGI] getting INI configuration from uwsgi_app.ini
*** Starting uWSGI 2.0.19.1 (64bit) on [Fri Nov 27 10:57:26 2020] ***
compiled with version: 9.3.0 on 08 October 2020 02:01:58
os: Linux-4.19.37-solidfire7 #1 SMP Wed Jun 24 20:10:57 UTC 2020
nodename: 42d366150c41
machine: x86_64
clock source: unix
detected number of CPU cores: 6
current working directory: /app
detected binary path: /usr/local/bin/uwsgi

This particular log isn't structured, but some other services that deal with API calls have structured logs.

Another detail we should consider is if we want to get logs from particular service, or "all". We should definitively gather logs one by one. If we look at all Up containers in the output of docker ps -a, our initial list may look like this:

node-api-gateway
hcc-ui
credential-svc
vcp-sioc
mongo
redis
logs-svc
hci-monitor
mnode-api
mnode-svc-mon-grafana
package-svc
hardware-svc
vcenter-svc
telemetry-service
storage-service
mnode-svc-authz
inventory-service
mnode-svc-mon-prometheus
docker-proxy
mnode-svc-task-monitor
k8sdeployer
mnode-svc-aiq-collector

We could now look at the mNode and HCC documentation and decide which logs we're not interested in. For example we may take a look at the logs of mnode-svc-mon-prometheus and decide we don't want those.

With that information we should be able to prune the list to a more manageable length and create a script that loops through a list of container services and every N minutes fetches last (N+1) minutes of service logs.

Fowarding to Multiple Destinations

For rsyslog I would assume one can simply repeat an rsyslog action twice.

For Docker, depending on the version and configuration, docker logs may or may not work the way you expect - and that also depends upon your expectations.)

As you can see at that page, Docker cannot log to multiple destinations. Oops! It also can't retry like rsyslog can. So it appears for some folks it may be better to log to local and have a 3rd party agent (or just rsyslog) gather those logs and send them to multiple destinations.

What about SolidFire storage cluster logs

Short version: you can set one or more syslog destinations with a simple CLI or API call to MVIP.

See my repo Awesome SolidFire and SolidFire logging-related videos on YouTube.

Conclusion

mNode system and Docker service logs can be forwarded with ease, but at this time logs of individual containers should be gathered by using the HCC API.

While that is not very inconvenient, we should also investigate 3rd party log forwarding tools that could be deployed inside of mNode VM and eliminate the need to use the API.

If you make any changes on your production system, don't work by these blog posts. Consult the documentation, read the KB articles and check with Support.

Follow-up (2020/12/05)

As mentioned earlier, it's not supported to add your own containers to mNode VM. Why? It doesn't matter, what matters is it's not supported. It likely has to do with VM capacity and resources, as well as unpredictable interactions with existing container and non-container workloads. But whatever it is, the point is there's no need to create a how-to because the right how-to is "don't do it" so I'll just add some notes on how I made it work in a non-supported manner.

Input

Filebeat documentation for Docker isn't great, but (h/t: logz.io) I used prima/filebeat and didn't want to spend much time on making it look and work nice. My inputs were all Docker logs:

filebeat.prospectors:
 - input_type: log
  paths:
    - /var/lib/docker/containers/*/*-json.log
  ...

The above, once it starts churning through logs, can eat up 2 CPU cores easily. Similarly for RAM and disk space. In other words, if you don't increase mNode VM resources or restrict this container's resources, it can easily take down your mNode or individual HCC services.

What if you want to collect just some, rather than all, logs? The list of containers is in this post and what they do is in the documentation. Create multiple filebeat containers or create multiple definitions (YAML format), one per each individual container, and load them like so:

filebeat.config.inputs:
  enabled: true
  path: hcc.d/*.yml

You'd probably have to read the docs to use this approach.

After a bit of googling and RTFM I also managed to capture individual container logs (hcc-ui, in this example) with this:

filebeat.autodiscover:
  providers:
    - type: docker
      templates:
        - condition:
            contains:
              docker.container.image: hcc-ui
          config:
            - type: container
              paths:
                - /var/lib/docker/containers/${data.docker.container.id}/*.log
              exclude_lines: ["^\\s+[\\-`('.|_]"]

Output

Filebeat can send container logs to external recepients.

output.elasticsearch:
  hosts: ["192.168.1.146:9200"]

If you want to send it to two destinations, run two filebeat containers with identical configuration.

Or, if you wanted to store logs locally, you could add this directory to rsyslog configuration and leave the forwarding to multiple destinations to rsyslog:

output.file:
  path: "/var/logs/docker/filebeat/"
  filename: filebeat
  rotate_every_kb: 1000
  number_of_files: 7
  permissions: 0644

In this example retain only 7 x 1 MiB files. That's probably not what you want to do. Likewise, although you're not supposed to have any local users on mNode, you'd probably want those permissions tighter (0640, for example).

Result

You'll get some extra junk you may not want, but Filebeat has options and processors that let you strip that, and so does rsyslog. By the looks of it (see the values like jit in this JSON file) you may want to ensure that logs are either stripped of confidential info at the source, or sent to destination over encrypted connection.

{
	"@timestamp": "2020-12-04T17:06:02.511Z",
	"@metadata": {
		"beat": "filebeat",
		"type": "doc",
		"version": "6.2.3"
	},
	"source": "/var/lib/docker/containers/f14f10d6aefccf3be511c259a79e1cdae46f6f1da24479704392e3852cd45aa8/f14f10d6aefccf3be511c259a79e1cdae46f6f1da24479704392e3852cd45aa8-json.log",
	"offset": 73282162,
	"log": "2020-11-28T23:49:25.683922Z |     6 | 132721654 |    MainProcess-uWSGIWorker1Core0  |         flask_authtools:117  | DEBUG   | Authenticated user with claims: {'nbf': 1606607365, 'exp': 1606607485, 'iss': 'https://192.168.1.30/auth', 'aud': ['mnode_api', 'mnode_credential'], 'client_id': 'hci-monitor', 'iat': 1606607365, 'jti': 'YECZS3fkjxfpPx38gofKlg', 'scope': ['mnode_api:r', 'mnode_credential:r']}\n",
	"stream": "stderr",
	"time": "2020-11-28T23:49:25.684342722Z",
	"beat": {
		"hostname": "59e98457dadf",
		"version": "6.2.3",
		"name": "59e98457dadf"
	}
}

Share on

X LinkedIn

SolidFire mNode and HCC Log Fowarding

mNode

HCC

Wait, what do you mean "reboot"

Logs of Individual Containers

HCC `GET /logs`

Fowarding to Multiple Destinations

What about SolidFire storage cluster logs

Conclusion

Follow-up (2020/12/05)

Input

Output

Result

Share on

You may also enjoy

SolidFire Maintenance Mode

SolidFire Support Bundle Log with Automation, OneCollect

SolidFire monitoring with Elasticsearch

SolidFire capacity and efficiency report generator

mNode

HCC

Wait, what do you mean "reboot"

Logs of Individual Containers

HCC GET /logs

Fowarding to Multiple Destinations

What about SolidFire storage cluster logs

Conclusion

Follow-up (2020/12/05)

Input

Output

Result

Share on

You may also enjoy

SolidFire Maintenance Mode

SolidFire Support Bundle Log with Automation, OneCollect

SolidFire monitoring with Elasticsearch

SolidFire capacity and efficiency report generator

HCC `GET /logs`