Implement additional log format: json access logs

[sfinke0]

Hi there,

to prevent having additional work on the logs parsing side, I thought it would be nice to have nginx directly emit JSON logs. I added an additional log_format which is set to cachelog as the default and can now be set to cachelog-json via the NGINX_LOG_FORMAT environment variable.

Here is an example of what the JSON access logs look like:

``` {"timestamp":"1676882165.157","time_local":"20/Feb/2023:09:36:05 +0100","cache_identifier":"steam","remote_addr":"10.160.7.124","forwarded_for":"","remote_user":"","status":"200","bytes_sent":333728,"referer":"","user_agent":"Valve/Steam HTTP Client 1.0","upstream_cache_status":"HIT","host":"cache6-fra2.steamcontent.com","http_range":"","method":"GET","path":"/depot/621/chunk/3b267b871cf5e6b97a5f82bc4dbafc426c0d198e","proto":"HTTP/1.1","scheme":"http"} {"timestamp":"1676883410.966","time_local":"20/Feb/2023:09:56:50 +0100","cache_identifier":"blizzard","remote_addr":"10.160.7.124","forwarded_for":"","remote_user":"","status":"206","bytes_sent":2383,"referer":"","user_agent":"","upstream_cache_status":"HIT","host":"level3.blizzard.com","http_range":"bytes=0-2382","method":"GET","path":"/tpr/ovw/patch/90/91/9091ec25b9acaf4b1113be387151a61e","proto":"HTTP/1.1","scheme":"http"} {"timestamp":"1676885073.633","time_local":"20/Feb/2023:10:24:33 +0100","cache_identifier":"epicgames","remote_addr":"10.160.7.124","forwarded_for":"","remote_user":"","status":"403","bytes_sent":110,"referer":"","user_agent":"EpicGamesLauncher/14.6.1-24267999+++Portal+Release-Live Windows/10.0.22621.1.256.64bit","upstream_cache_status":"MISS","host":"download.epicgames.com","http_range":"","method":"GET","path":"/Builds/Org/o-37m6jbj5wcvrcvm4wusv7nazdfvbjk/fbb7b5df655a4b07ad280fec947d0d9f/default/pqhHqDkaRBRz08hzTUy_rMfA4PCcQw.manifest?Policy=eyJTdGF0ZW1lbnQiOiBbeyJSZXNvdXJjZSI6IiovQnVpbGRzL09yZy9vLTM3bTZqYmo1d2N2cmN2bTR3dXN2N25hemRmdmJqay9mYmI3YjVkZjY1NWE0YjA3YWQyODBmZWM5NDdkMGQ5Zi9kZWZhdWx0L3BxaEhxRGthUkJSejA4aHpUVXlfck1mQTRQQ2NRdy5tYW5pZmVzdCIsIkNvbmRpdGlvbiI6eyJEYXRlTGVzc1RoYW4iOnsiQVdTOkVwb2NoVGltZSI6MTY3Njg4NTM3M30sIklwQWRkcmVzcyI6eyJBV1M6U291cmNlSXAiOiIwLjAuMC4wLzAifX19XX0_&Signature=7iWms7T7n3r3SyOa3wg6cD5RAyml8HpU0het1jbZoEK2YmtLHmCyjzejvC3gGwFAuLuVYyTWvgzHFejwXBVA8QeW-n5bYcOq2tXY0G5CjHCksL83JAl0RkW3FiAp69e9phYm0V6Q8ZYltV8AH8n50PoIhFvsp~WNnkEpVQW6aQRyUhTa7Gd3N9v3haPdb9Yw9MsNJsA~4b6TGCKPGre~hndpwQCRv-ZA-ZXEEkHsfZ3-iiWl6F4aU6lz2NCAgwNxzswxvGlGqhNZeRmNIdDZ1R9xbw37-bNRhyljqqojpiQ7jBPrJb0S2cPlsQgj5rji33lev6IpyAu4d2kQ6Z-Gcg__&Key-Pair-Id=APKAJP7WU44FM4EHJYFQ","proto":"HTTP/1.1","scheme":"http"} {"timestamp":"1676883213.860","time_local":"20/Feb/2023:09:53:33 +0100","cache_identifier":"wsus","remote_addr":"10.160.7.124","forwarded_for":"","remote_user":"","status":"304","bytes_sent":0,"referer":"","user_agent":"Microsoft-CryptoAPI/10.0","upstream_cache_status":"","host":"ctldl.windowsupdate.com","http_range":"","method":"GET","path":"/msdownload/update/v3/static/trustedr/en/authrootstl.cab?6483b98637265188","proto":"HTTP/1.1","scheme":"http"} ```

Please have a look and let me know if I can improve something or where this could be documented for others to see.

Thanks in advance Sebastian

EDIT: changed "bytes_sent" from string value to numeric value to have out of the box support for aggregation e.g. in Opensearch

[sfinke0]

After running lancache at home with JSON logs enabled for a week I got some dashboards working in Grafana and Kibana. Datasource is Opensearch ☺️

[zunder1990]

Yes is looking really cool, cant wait to get it. Can you please make sure to include config files and instructions how to set it up too.

[bonkersGER]

Any News here?

[sfinke0]

Hi @VibroAxe, could you have a look please? Our upcoming LAN party with ~400 guests will be next month already and I would really like to use the official docker image, instead of having to build one myself.

I'm happy to discuss any issues of concern.

Cheers Sebastian

[VibroAxe]

Lgtm thanks for the input. Merged now, I'd be interested to see some setup instructions added to the documentation site if you could fit grafana

[bonkersGER]

@sfinke0

hey do you have a dashboard to share? So I don’t have to start at zero

[sfinke0]

Hi @bonkersGER,

I can share my simple Grafana dashboard shown in the screenshot above. Just came back from a Lanparty this weekend and will write documentation about log analysis in the coming weeks for the Lancache website.

Grafana Dashboard

Please note: this dashboard only runs with Opensearch. When you're using ELK / Opendistro it might be easily adapted. ```json { "__inputs": [ { "name": "DS_OPENSEARCH", "label": "OpenSearch", "description": "", "type": "datasource", "pluginId": "grafana-opensearch-datasource", "pluginName": "OpenSearch" }, { "name": "DS_EXPRESSION", "label": "Expression", "description": "", "type": "datasource", "pluginId": "__expr__" } ], "__elements": {}, "__requires": [ { "type": "datasource", "id": "__expr__", "version": "1.0.0" }, { "type": "grafana", "id": "grafana", "name": "Grafana", "version": "9.5.2" }, { "type": "datasource", "id": "grafana-opensearch-datasource", "name": "OpenSearch", "version": "2.4.0" }, { "type": "panel", "id": "piechart", "name": "Pie chart", "version": "" }, { "type": "panel", "id": "stat", "name": "Stat", "version": "" }, { "type": "panel", "id": "table", "name": "Table", "version": "" } ], "annotations": { "list": [ { "builtIn": 1, "datasource": { "type": "grafana", "uid": "-- Grafana --" }, "enable": true, "hide": true, "iconColor": "rgba(0, 211, 255, 1)", "name": "Annotations & Alerts", "target": { "limit": 100, "matchAny": false, "tags": [], "type": "dashboard" }, "type": "dashboard" } ] }, "editable": true, "fiscalYearStartMonth": 0, "graphTooltip": 0, "id": null, "links": [], "liveNow": false, "panels": [ { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "color": { "mode": "palette-classic" }, "custom": { "hideFrom": { "legend": false, "tooltip": false, "viz": false } }, "mappings": [] }, "overrides": [] }, "gridPos": { "h": 11, "w": 7, "x": 0, "y": 0 }, "id": 2, "options": { "displayLabels": [ "percent", "name" ], "legend": { "displayMode": "list", "placement": "right", "showLegend": true, "values": [] }, "pieType": "pie", "reduceOptions": { "calcs": [ "lastNotNull" ], "fields": "/^Count$/", "values": true }, "tooltip": { "mode": "multi", "sort": "asc" } }, "pluginVersion": "2.0.4", "targets": [ { "alias": "", "bucketAggs": [ { "field": "message.cache_identifier.keyword", "id": "3", "settings": { "min_doc_count": "0", "order": "desc", "orderBy": "_term", "size": "10" }, "type": "terms" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "metrics": [ { "id": "1", "type": "count" } ], "query": "", "queryType": "lucene", "refId": "A", "timeField": "timestamp" } ], "title": "Lancache Requests per Cache Identifier", "type": "piechart" }, { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "color": { "mode": "palette-classic" }, "custom": { "hideFrom": { "legend": false, "tooltip": false, "viz": false } }, "mappings": [] }, "overrides": [] }, "gridPos": { "h": 11, "w": 7, "x": 7, "y": 0 }, "id": 3, "options": { "displayLabels": [ "percent", "name" ], "legend": { "displayMode": "list", "placement": "right", "showLegend": false, "values": [] }, "pieType": "pie", "reduceOptions": { "calcs": [ "lastNotNull" ], "fields": "", "values": true }, "tooltip": { "mode": "single", "sort": "asc" } }, "pluginVersion": "2.0.4", "targets": [ { "alias": "", "bucketAggs": [ { "field": "message.upstream_cache_status.keyword", "id": "3", "settings": { "min_doc_count": "0", "order": "desc", "orderBy": "_term", "size": "10" }, "type": "terms" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "metrics": [ { "id": "1", "type": "count" } ], "query": "NOT message.upstream_cache_status.keyword:\"\"", "queryType": "lucene", "refId": "A", "timeField": "timestamp" } ], "title": "Lancache HIT/MISS Ratio", "type": "piechart" }, { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "mappings": [], "thresholds": { "mode": "absolute", "steps": [ { "color": "#56ff40b8", "value": null } ] }, "unit": "decbytes" }, "overrides": [] }, "gridPos": { "h": 5, "w": 5, "x": 14, "y": 0 }, "id": 5, "links": [], "options": { "colorMode": "background", "graphMode": "none", "justifyMode": "auto", "orientation": "auto", "reduceOptions": { "calcs": [ "sum" ], "fields": "", "values": false }, "textMode": "auto" }, "pluginVersion": "9.5.2", "targets": [ { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "2", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "metrics": [ { "field": "message.bytes_sent", "id": "1", "type": "sum" } ], "query": "message.upstream_cache_status.keyword:\"HIT\"", "queryType": "lucene", "refId": "HIT", "timeField": "timestamp" } ], "title": "Lancache traffic served", "type": "stat" }, { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "mappings": [], "thresholds": { "mode": "absolute", "steps": [ { "color": "semi-dark-yellow", "value": null } ] }, "unit": "decbytes" }, "overrides": [] }, "gridPos": { "h": 5, "w": 5, "x": 19, "y": 0 }, "id": 6, "links": [], "options": { "colorMode": "background", "graphMode": "none", "justifyMode": "auto", "orientation": "auto", "reduceOptions": { "calcs": [ "sum" ], "fields": "", "values": false }, "textMode": "auto" }, "pluginVersion": "9.5.2", "targets": [ { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "2", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "metrics": [ { "field": "message.bytes_sent", "id": "1", "type": "sum" } ], "query": "message.upstream_cache_status.keyword:\"MISS\"", "queryType": "lucene", "refId": "MISS", "timeField": "timestamp" } ], "title": "Lancache traffic forward", "type": "stat" }, { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "mappings": [], "thresholds": { "mode": "absolute", "steps": [ { "color": "dark-green", "value": null } ] }, "unit": "decbytes" }, "overrides": [] }, "gridPos": { "h": 6, "w": 5, "x": 14, "y": 5 }, "id": 7, "links": [], "options": { "colorMode": "value", "graphMode": "none", "justifyMode": "auto", "orientation": "auto", "reduceOptions": { "calcs": [ "sum" ], "fields": "", "values": false }, "textMode": "auto" }, "pluginVersion": "9.5.2", "targets": [ { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "2", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "hide": true, "metrics": [ { "field": "message.bytes_sent", "id": "1", "type": "sum" } ], "query": "message.upstream_cache_status.keyword:\"MISS\"", "queryType": "lucene", "refId": "MISS", "timeField": "timestamp" }, { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "2", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "hide": true, "metrics": [ { "field": "message.bytes_sent", "id": "1", "type": "sum" } ], "query": "message.upstream_cache_status.keyword:\"HIT\"", "queryType": "lucene", "refId": "HIT", "timeField": "timestamp" }, { "datasource": { "type": "__expr__", "uid": "${DS_EXPRESSION}" }, "expression": "$HIT - $MISS", "hide": false, "refId": "A", "type": "math" } ], "title": "Traffic saved through Lancache", "type": "stat" }, { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "color": { "mode": "thresholds" }, "mappings": [], "thresholds": { "mode": "absolute", "steps": [ { "color": "dark-green", "value": null } ] }, "unit": "percentunit" }, "overrides": [] }, "gridPos": { "h": 6, "w": 5, "x": 19, "y": 5 }, "id": 10, "links": [], "options": { "colorMode": "value", "graphMode": "none", "justifyMode": "auto", "orientation": "auto", "reduceOptions": { "calcs": [ "sum" ], "fields": "", "values": false }, "textMode": "auto" }, "pluginVersion": "9.5.2", "targets": [ { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "2", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "hide": true, "metrics": [ { "field": "message.bytes_sent", "id": "1", "type": "sum" } ], "query": "message.upstream_cache_status.keyword:\"MISS\"", "queryType": "lucene", "refId": "MISS", "timeField": "timestamp" }, { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "2", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "hide": true, "metrics": [ { "field": "message.bytes_sent", "id": "1", "type": "sum" } ], "query": "message.upstream_cache_status.keyword:\"HIT\"", "queryType": "lucene", "refId": "HIT", "timeField": "timestamp" }, { "datasource": { "type": "__expr__", "uid": "${DS_EXPRESSION}" }, "expression": "MISS", "hide": true, "reducer": "sum", "refId": "A", "type": "reduce" }, { "datasource": { "type": "__expr__", "uid": "${DS_EXPRESSION}" }, "expression": "HIT", "hide": true, "reducer": "sum", "refId": "B", "type": "reduce" }, { "datasource": { "type": "__expr__", "uid": "${DS_EXPRESSION}" }, "expression": "$B / $A - 1", "hide": false, "refId": "C", "type": "math" } ], "title": "Traffic saved through Lancache", "type": "stat" }, { "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "fieldConfig": { "defaults": { "custom": { "align": "auto", "cellOptions": { "type": "auto" }, "filterable": true, "inspect": false }, "mappings": [], "thresholds": { "mode": "absolute", "steps": [ { "color": "green", "value": null }, { "color": "red", "value": 80 } ] } }, "overrides": [ { "matcher": { "id": "byName", "options": "timestamp" }, "properties": [ { "id": "custom.width", "value": 185 } ] }, { "matcher": { "id": "byName", "options": "file" }, "properties": [ { "id": "custom.width", "value": 241 } ] }, { "matcher": { "id": "byName", "options": "http status" }, "properties": [ { "id": "custom.width", "value": 110 } ] }, { "matcher": { "id": "byName", "options": "client" }, "properties": [ { "id": "custom.width", "value": 111 } ] }, { "matcher": { "id": "byName", "options": "cache status" }, "properties": [ { "id": "custom.width", "value": 193 } ] }, { "matcher": { "id": "byName", "options": "bytes" }, "properties": [ { "id": "custom.width", "value": 89 } ] }, { "matcher": { "id": "byName", "options": "cache ID" }, "properties": [ { "id": "custom.width", "value": 95 } ] }, { "matcher": { "id": "byName", "options": "host" }, "properties": [ { "id": "custom.width", "value": 210 } ] }, { "matcher": { "id": "byName", "options": "path" }, "properties": [ { "id": "custom.width", "value": 299 } ] } ] }, "gridPos": { "h": 21, "w": 14, "x": 0, "y": 11 }, "id": 9, "options": { "cellHeight": "sm", "footer": { "countRows": false, "enablePagination": true, "fields": "", "reducer": [ "sum" ], "show": false }, "showHeader": true, "sortBy": [ { "desc": true, "displayName": "timestamp" } ] }, "pluginVersion": "9.5.2", "targets": [ { "alias": "", "bucketAggs": [ { "field": "timestamp", "id": "1", "settings": { "interval": "auto" }, "type": "date_histogram" } ], "datasource": { "type": "grafana-opensearch-datasource", "uid": "${DS_OPENSEARCH}" }, "format": "table", "metrics": [ { "id": "1", "type": "logs" } ], "query": "", "queryType": "lucene", "refId": "A", "timeField": "timestamp" } ], "timeFrom": "2h", "title": "Lancache logs", "transformations": [ { "id": "organize", "options": { "excludeByName": { "_id": true, "_index": true, "_source": true, "_type": true, "file": true, "host": true, "index_prefix": true, "logtype": true, "message.forwarded_for": true, "message.http_range": true, "message.method": true, "message.proto": true, "message.referer": true, "message.remote_user": true, "message.scheme": true, "message.time_local": true, "message.timestamp": true, "message.user_agent": true, "source_type": true }, "indexByName": { "_id": 2, "_index": 3, "_source": 4, "_type": 5, "file": 6, "host": 7, "index_prefix": 8, "logtype": 9, "message.bytes_sent": 10, "message.cache_identifier": 1, "message.forwarded_for": 11, "message.host": 12, "message.http_range": 13, "message.method": 14, "message.path": 15, "message.proto": 16, "message.referer": 17, "message.remote_addr": 18, "message.remote_user": 19, "message.scheme": 20, "message.status": 21, "message.time_local": 22, "message.timestamp": 23, "message.upstream_cache_status": 24, "message.user_agent": 25, "source_type": 26, "timestamp": 0 }, "renameByName": { "message.bytes_sent": "bytes", "message.cache_identifier": "cache ID", "message.host": "host", "message.path": "path", "message.remote_addr": "client", "message.scheme": "", "message.status": "http status", "message.upstream_cache_status": "cache status", "message.user_agent": "user agent" } } } ], "type": "table" } ], "refresh": "1m", "revision": 1, "schemaVersion": 38, "style": "dark", "tags": [], "templating": { "list": [] }, "time": { "from": "now-7d", "to": "now" }, "timepicker": {}, "timezone": "", "title": "Lancache Stats", "uid": "1mkT_Cx4k", "version": 9, "weekStart": "" } ```

Cheers.