Excessive logging from NMS

[markbeierl]

Describe the bug

I have an NMS that has been running for a couple weeks now:

control-plane    nms-0                                    2/2     Running   170 (3h22m ago)   16

Today I noticed in the Loki logs an excessive amount of what appear to be startup messages coming from the NMS. Note multiple events within milliseconds of each other.

To Reproduce

Deploy sdcore control plane and integrate it with COS. Go to Grafana explore and filter on charm = sdcore-nms-k8s. Watch for duplicate entries showing.

Expected behavior

Logging should be kept to a minimum. From what I can see in running pebble logs for the NMS, the event is only happening once, but is being logged multiple times in Loki.

Screenshots

Logs

Except from pebble log around the same time:

2024-04-04T19:28:21.516Z [pebble] GET /v1/notices?timeout=30s 30.004930785s 200
2024-04-04T19:28:40.560Z [pebble] GET /v1/files?action=list&path=%2Fnms%2Fconfig%2Fupf_config.json&itself=true 297.008µs 200
2024-04-04T19:28:40.561Z [pebble] GET /v1/files?action=read&path=%2Fnms%2Fconfig%2Fupf_config.json 199.037µs 200
2024-04-04T19:28:40.599Z [pebble] GET /v1/files?action=list&path=%2Fnms%2Fconfig%2Fgnb_config.json&itself=true 487.151µs 200
2024-04-04T19:28:40.602Z [pebble] GET /v1/files?action=read&path=%2Fnms%2Fconfig%2Fgnb_config.json 157.835µs 200
2024-04-04T19:28:40.606Z [pebble] GET /v1/plan?format=yaml 407.371µs 200
2024-04-04T19:28:40.647Z [pebble] POST /v1/layers 665.796µs 200
2024-04-04T19:28:40.694Z [pebble] POST /v1/services 46.396841ms 202
2024-04-04T19:28:40.746Z [pebble] Service "sdcore-nms" stopped
2024-04-04T19:28:40.804Z [pebble] Service "sdcore-nms" starting: /bin/bash -c 'cd /app && npm run start'
2024-04-04T19:28:41.369Z [sdcore-nms] 
2024-04-04T19:28:41.370Z [sdcore-nms] > [email protected] start
2024-04-04T19:28:41.370Z [sdcore-nms] > next start
2024-04-04T19:28:41.370Z [sdcore-nms] 
2024-04-04T19:28:41.841Z [pebble] GET /v1/changes/23086/wait?timeout=4.000s 1.143919655s 200
2024-04-04T19:28:41.905Z [sdcore-nms]    ▲ Next.js 14.1.2
2024-04-04T19:28:41.906Z [sdcore-nms]    - Local:        http://localhost:3000
2024-04-04T19:28:41.907Z [sdcore-nms] 
2024-04-04T19:28:42.237Z [sdcore-nms]  ✓ Ready in 741ms
2024-04-04T19:28:51.517Z [pebble] GET /v1/notices?timeout=30s 30.000686052s 200

As there is only one event, it looks like something in the logging configuration is additive.

[patriciareinoso]

Duplicated: canonical/sdcore-nms-k8s-operator#90