-
Bug
-
Resolution: Done
-
Critical
-
Logging 5.5.1
-
False
-
None
-
False
-
NEW
-
OBSDA-57 - Enable Cloud Operations (GCP StackDriver) forwarding
-
VERIFIED
-
Before this update, absence of a `level` field in audit logs caused an error in vector logs. With this update, the addition of a `level` field in the audit log record resolves the issue.
Version of components:
clusterlogging.v5.5.1-preview.1
4.11.0-0.nightly-2022-08-17-152830
Kubernetes Version: v1.24.0+4f0dd4d
Description of the issue:
When forwarding logs to Google Cloud Logging using vector as collector, the collector pods show the follwoing errors.
2022-08-18T08:52:22.752793Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Unknown severity value string, using DEFAULT. value=Metadata internal_log_rate_secs=10
2022-08-18T08:52:22.752890Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] is being rate limited.
2022-08-18T08:52:32.783471Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] has been rate limited 201 times.
2022-08-18T08:52:32.783491Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Unknown severity value string, using DEFAULT. value=Metadata internal_log_rate_secs=10
2022-08-18T08:52:32.783578Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] is being rate limited.
Steps to reproduce the issue.
*Install the Cluster Logging 5.5.1 operator.
*Create a secret with Google Cloud SA key.
oc -n openshift-logging create secret generic gcp-secret --from-file google-application-credentials.json=service_account.json
*Create the ClusterLogForwarder instance.
oc create -f aosqe-tools/logging/log_template/vector/clf_google_cloud_logging.yaml apiVersion: "logging.openshift.io/v1" kind: "ClusterLogForwarder" metadata: name: "instance" namespace: "openshift-logging" spec: outputs: - name: gcp-1 type: googleCloudLogging secret: name: gcp-secret googleCloudLogging: projectId : "openshift-qe" logId : "aosqe-logging" pipelines: - name: test-app inputRefs: - application - infrastructure - audit outputRefs: - gcp-1
*Create Cluster Logging instance.
oc create -f aosqe-tools/logging/log_template/vector/cli_collector_only.yaml apiVersion: "logging.openshift.io/v1" kind: "ClusterLogging" metadata: name: "instance" namespace: "openshift-logging" spec: managementState: "Managed" collection: logs: type: "vector" vector: {}
*Check the collector pod logs.
2022-08-18T09:00:00.586636Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] has been rate limited 4 times.
2022-08-18T09:00:00.586658Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Unknown severity value string, using DEFAULT. value=unknown internal_log_rate_secs=10
2022-08-18T09:00:00.586822Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] is being rate limited.
2022-08-18T09:00:03.950152Z INFO source{component_kind="source" component_id=raw_container_logs component_type=kubernetes_logs component_name=raw_container_logs}:file_server: vector::internal_events::file::source: Found new file to watch. file=/var/log/pods/openshift-operator-lifecycle-manager_collect-profiles-27680220-z5j78_dd5825c7-a938-4a1a-8d65-e1ddd1f6bf6a/collect-profiles/0.log
2022-08-18T09:00:10.594039Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] has been rate limited 27 times.
2022-08-18T09:00:10.594059Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Unknown severity value string, using DEFAULT. value=unknown internal_log_rate_secs=10
2022-08-18T09:00:47.222496Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Unknown severity value string, using DEFAULT. value=unknown internal_log_rate_secs=10
2022-08-18T09:00:47.222557Z WARN sink{component_kind="sink" component_id=gcp_1 component_type=gcp_stackdriver_logs component_name=gcp_1}: vector::sinks::gcp::stackdriver_logs: Internal log [Unknown severity value string, using DEFAULT.] is being rate limited.
2022-08-18T09:01:15.979633Z INFO source{component_kind="source" component_id=raw_container_logs component_type=kubernetes_logs component_name=raw_container_logs}:file_server: vector::internal_events::file::source: Stopped watching file. file=/var/log/pods/openshift-operator-lifecycle-manager_collect-profiles-27680175-56rl2_df511c15-7219-4634-a97f-dc79bbc82a1a/collect-profiles/0.log
*The generated vector.toml is attached to the jira.
Additional notes:
Log record sent to Google Cloud Logging with different severity.
INFO
{
"insertId": "1htzq9zfagxq5n",
"jsonPayload": {
"@timestamp": "2022-08-18T09:05:50.506407495Z",
"file": "/var/log/pods/openshift-cluster-version_cluster-version-operator-b77cbb678-wjscv_b6e69da2-1ab7-477a-922f-daf477fa4b44/cluster-version-operator/0.log",
"hostname": "ip-10-0-179-25.us-east-2.compute.internal",
"kubernetes": {
"annotations": {
"openshift.io/scc": "hostaccess"
},
"container_id": "cri-o://9e4a4cc1d1d1d62af60c52416107be3124ce06cc39f9e06b4b1650b956ece7c3",
"container_image": "registry.ci.openshift.org/ocp/release@sha256:2529a7c67d6253e8e534cb5f4462f40aaf642d03f9e451839d4ab5d6f42436a8",
"container_name": "cluster-version-operator",
"labels": {
"k8s-app": "cluster-version-operator",
"pod-template-hash": "b77cbb678"
},
"namespace_labels": {
"kubernetes.io/metadata.name": "openshift-cluster-version",
"name": "openshift-cluster-version",
"olm.operatorgroup.uid/4cd2a20f-7185-4bff-8eda-eaf280517b23": "",
"openshift.io/cluster-monitoring": "true",
"openshift.io/run-level": "",
"pod-security.kubernetes.io/audit": "privileged",
"pod-security.kubernetes.io/enforce": "privileged",
"pod-security.kubernetes.io/warn": "privileged"
},
"namespace_name": "openshift-cluster-version",
"pod_id": "b6e69da2-1ab7-477a-922f-daf477fa4b44",
"pod_ip": "10.0.179.25",
"pod_name": "cluster-version-operator-b77cbb678-wjscv",
"pod_owner": "ReplicaSet/cluster-version-operator-b77cbb678"
},
"log_type": "infrastructure",
"message": "I0818 09:05:50.506391 1 sync_worker.go:944] Running sync for imagestream \"openshift/must-gather\" (470 of 803)"
},
"logName": "projects/openshift-qe/logs/aosqe-logging",
"receiveTimestamp": "2022-08-18T09:05:50.795948891Z",
"resource": {
"labels": {
"cluster_name": "",
"location": "",
"node_name": "ip-10-0-179-25.us-east-2.compute.internal",
"project_id": "openshift-qe"
},
"type": "k8s_node"
},
"severity": "INFO",
"timestamp": "2022-08-18T09:05:50.795948891Z"
},
ERROR
{
"insertId": "nvawikfu2wdor",
"jsonPayload": {
"@timestamp": "2022-08-18T09:06:55.676388Z",
"_STREAM_ID": "24a65cea835248c196fa5c3ba3ee86cf",
"_SYSTEMD_INVOCATION_ID": "eb9367c74fd0417f8bca362cfc957830",
"hostname": "ip-10-0-198-127",
"log_type": "infrastructure",
"message": "E0818 09:06:55.676351 1450 kubelet_pods.go:413] \"Hostname for pod was too long, truncated it\" podName=\"kube-controller-manager-guard-ip-10-0-198-127.us-east-2.compute.internal\" hostnameMaxLen=63 truncatedHostname=\"kube-controller-manager-guard-ip-10-0-198-127.us-east-2.compute\"",
"systemd": {
"t": {
"BOOT_ID": "03beea18e4174a278256e9977e84d794",
"CAP_EFFECTIVE": "1ffffffffff",
"CMDLINE": "kubelet --config=/etc/kubernetes/kubelet.conf --bootstrap-kubeconfig=/etc/kubernetes/kubeconfig --kubeconfig=/var/lib/kubelet/kubeconfig --container-runtime=remote --container-runtime-endpoint=/var/run/crio/crio.sock --runtime-cgroups=/system.slice/crio.service --node-labels=node-role.kubernetes.io/master,node.openshift.io/os_id=rhcos --node-ip= --minimum-container-ttl-duration=6m0s --cloud-provider=aws --volume-plugin-dir=/etc/kubernetes/kubelet-plugins/volume/exec --hostname-override=ip-10-0-198-127.us-east-2.compute.internal --provider-id=aws:///us-east-2c/i-0733cd21ab26102dc --register-with-taints=node-role.kubernetes.io/master=:NoSchedule --pod-infra-container-image=quay.io/openshift-release-dev/ocp-v4.0-art-dev@sha256:86e0050aaa7477b8aeef382e3bf8092463d207adfa5cd8c88358b367bb624869 --system-reserved=cpu=500m,memory=1Gi --v=2",
"COMM": "kubelet",
"EXE": "/usr/bin/kubelet",
"GID": "0",
"MACHINE_ID": "ec2df3bf68b009fad8d6d59880a19188",
"PID": "1450",
"SELINUX_CONTEXT": "system_u:system_r:kubelet_t:s0-s0:c0.c1023",
"STREAM_ID": "24a65cea835248c196fa5c3ba3ee86cf",
"SYSTEMD_CGROUP": "/system.slice/kubelet.service",
"SYSTEMD_INVOCATION_ID": "eb9367c74fd0417f8bca362cfc957830",
"SYSTEMD_SLICE": "system.slice",
"SYSTEMD_UNIT": "kubelet.service",
"TRANSPORT": "stdout",
"UID": "0"
},
"u": {
"SYSLOG_FACILITY": "3",
"SYSLOG_IDENTIFIER": "hyperkube"
}
},
"tag": ".journal.system",
"time": "2022-08-18T09:06:55+00:00"
},
"logName": "projects/openshift-qe/logs/aosqe-logging",
"receiveTimestamp": "2022-08-18T09:06:56.182700115Z",
"resource": {
"labels": {
"cluster_name": "",
"location": "",
"node_name": "ip-10-0-198-127",
"project_id": "openshift-qe"
},
"type": "k8s_node"
},
"severity": "ERROR",
"timestamp": "2022-08-18T09:06:56.182700115Z"
},
WARNING
{
"insertId": "kt8bggfu2m5fi",
"jsonPayload": {
"@timestamp": "2022-08-18T09:08:16.921526094Z",
"file": "/var/log/pods/openshift-monitoring_cluster-monitoring-operator-64b6c7bc75-zmnpd_5177313a-4f83-4073-b6aa-80e7d7873ef6/cluster-monitoring-operator/0.log",
"hostname": "ip-10-0-198-127.us-east-2.compute.internal",
"kubernetes": {
"annotations": {
"k8s.v1.cni.cncf.io/network-status": "[{\n \"name\": \"openshift-sdn\",\n \"interface\": \"eth0\",\n \"ips\": [\n \"10.129.0.26\"\n ],\n \"default\": true,\n \"dns\": {}\n}]",
"k8s.v1.cni.cncf.io/networks-status": "[{\n \"name\": \"openshift-sdn\",\n \"interface\": \"eth0\",\n \"ips\": [\n \"10.129.0.26\"\n ],\n \"default\": true,\n \"dns\": {}\n}]",
"openshift.io/scc": "restricted-v2",
"seccomp.security.alpha.kubernetes.io/pod": "runtime/default"
},
"container_id": "cri-o://94736d519fb8a35c9005b7a6b2804a6c519eaf488ccf52def88d14ec67422664",
"container_image": "quay.io/openshift-release-dev/ocp-v4.0-art-dev@sha256:f15249736c67cbf440deb68891faf4eadc896fa2f378590c8a355e2ff39ebd94",
"container_name": "cluster-monitoring-operator",
"labels": {
"app": "cluster-monitoring-operator",
"app.kubernetes.io/name": "cluster-monitoring-operator",
"pod-template-hash": "64b6c7bc75"
},
"namespace_labels": {
"kubernetes.io/metadata.name": "openshift-monitoring",
"name": "openshift-monitoring",
"network.openshift.io/policy-group": "monitoring",
"olm.operatorgroup.uid/4cd2a20f-7185-4bff-8eda-eaf280517b23": "",
"openshift.io/cluster-monitoring": "true",
"pod-security.kubernetes.io/audit": "privileged",
"pod-security.kubernetes.io/enforce": "privileged",
"pod-security.kubernetes.io/warn": "privileged"
},
"namespace_name": "openshift-monitoring",
"pod_id": "5177313a-4f83-4073-b6aa-80e7d7873ef6",
"pod_ip": "10.129.0.26",
"pod_name": "cluster-monitoring-operator-64b6c7bc75-zmnpd",
"pod_owner": "ReplicaSet/cluster-monitoring-operator-64b6c7bc75"
},
"log_type": "infrastructure",
"message": "W0818 09:08:16.921481 1 reflector.go:324] github.com/openshift/cluster-monitoring-operator/pkg/alert/relabel_controller.go:116: failed to list *v1alpha1.AlertRelabelConfig: alertrelabelconfigs.monitoring.openshift.io is forbidden: User \"system:serviceaccount:openshift-monitoring:cluster-monitoring-operator\" cannot list resource \"alertrelabelconfigs\" in API group \"monitoring.openshift.io\" in the namespace \"openshift-monitoring\""
},
"logName": "projects/openshift-qe/logs/aosqe-logging",
"receiveTimestamp": "2022-08-18T09:08:17.400430729Z",
"resource": {
"labels": {
"cluster_name": "",
"location": "",
"node_name": "ip-10-0-198-127.us-east-2.compute.internal",
"project_id": "openshift-qe"
},
"type": "k8s_node"
},
"severity": "WARNING",
"timestamp": "2022-08-18T09:08:17.400430729Z"
},
DEFAULT
{
"insertId": "1gfztsyfuo51gh",
"jsonPayload": {
"@timestamp": "2022-08-18T09:12:55.426571341Z",
"annotations": {
"authorization.k8s.io/decision": "allow",
"authorization.k8s.io/reason": ""
},
"apiVersion": "audit.k8s.io/v1",
"auditID": "f5d56294-78bf-407e-a8c3-5f2d96992ad1",
"file": "/var/log/kube-apiserver/audit.log",
"hostname": "ip-10-0-198-127.us-east-2.compute.internal",
"kind": "Event",
"log_type": "audit",
"objectRef": {
"apiGroup": "coordination.k8s.io",
"apiVersion": "v1",
"name": "ip-10-0-139-70.us-east-2.compute.internal",
"namespace": "kube-node-lease",
"resource": "leases",
"resourceVersion": "130405",
"uid": "8bfe7d82-166c-4542-886c-bce14261b007"
},
"requestReceivedTimestamp": "2022-08-18T09:12:55.415319Z",
"requestURI": "/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-0-139-70.us-east-2.compute.internal?timeout=10s",
"responseStatus": {
"code": 200,
"metadata": {}
},
"sourceIPs": [
"10.0.215.184"
],
"source_type": "file",
"stage": "ResponseComplete",
"stageTimestamp": "2022-08-18T09:12:55.423089Z",
"tag": ".k8s-audit.log",
"user": {
"groups": [
"system:nodes",
"system:authenticated"
],
"username": "system:node:ip-10-0-139-70.us-east-2.compute.internal"
},
"userAgent": "kubelet/v1.24.0+4f0dd4d (linux/amd64) kubernetes/0a57f1f",
"verb": "update"
},
"logName": "projects/openshift-qe/logs/aosqe-logging",
"receiveTimestamp": "2022-08-18T09:12:55.479292513Z",
"resource": {
"labels": {
"cluster_name": "",
"location": "",
"node_name": "ip-10-0-198-127.us-east-2.compute.internal",
"project_id": "openshift-qe"
},
"type": "k8s_node"
},
"timestamp": "2022-08-18T09:12:55.479292513Z"
},
DEBUG
No logs found with debug severity.
Log missing the severity field:
{
"insertId": "1htzq9zfal2r86",
"jsonPayload": {
"@timestamp": "2022-08-18T09:32:52.631435316Z",
"file": "/var/log/pods/test_loggen-qa-json-tftpf_97bfef75-c764-46c5-845b-ab76bf07f497/loggen-qa-json/0.log",
"hostname": "ip-10-0-143-124.us-east-2.compute.internal",
"kubernetes": {
"annotations": {
"k8s.v1.cni.cncf.io/network-status": "[{\n \"name\": \"openshift-sdn\",\n \"interface\": \"eth0\",\n \"ips\": [\n \"10.131.0.23\"\n ],\n \"default\": true,\n \"dns\": {}\n}]",
"k8s.v1.cni.cncf.io/networks-status": "[{\n \"name\": \"openshift-sdn\",\n \"interface\": \"eth0\",\n \"ips\": [\n \"10.131.0.23\"\n ],\n \"default\": true,\n \"dns\": {}\n}]",
"openshift.io/scc": "restricted-v2",
"seccomp.security.alpha.kubernetes.io/pod": "runtime/default"
},
"container_id": "cri-o://4318796ee63d55f8f343a1055518aa068aee14941de181d605b3c61088e99830",
"container_image": "quay.io/openshifttest/ocp-logtest@sha256:16232868ba1143721b786dbabb3f7384645acb663fadb4af48e9ea1228a67635",
"container_name": "loggen-qa-json",
"labels": {
"run": "centos-logtest",
"test": "loggen-qa-json"
},
"namespace_labels": {
"kubernetes.io/metadata.name": "test",
"pod-security.kubernetes.io/audit": "restricted",
"pod-security.kubernetes.io/audit-version": "v1.24",
"pod-security.kubernetes.io/warn": "restricted",
"pod-security.kubernetes.io/warn-version": "v1.24"
},
"namespace_name": "test",
"pod_id": "97bfef75-c764-46c5-845b-ab76bf07f497",
"pod_ip": "10.131.0.23",
"pod_name": "loggen-qa-json-tftpf",
"pod_owner": "ReplicationController/loggen-qa-json"
},
"log_type": "application",
"message": "{\"message\": \"MERGE_JSON_LOG=true\", \"level\": \"debug\",\"Layer1\": \"layer1 0\", \"layer2\": {\"name\":\"Layer2 1\", \"tips\":\"Decide by PRESERVE_JSON_LOG\"}, \"StringNumber\":\"10\", \"Number\": 10,\"foo.bar\":\"Dot Item\",\"{foobar}\":\"Brace Item\",\"[foobar]\":\"Bracket Item\", \"foo:bar\":\"Colon Item\",\"foo bar\":\"Space Item\" }"
},
"logName": "projects/openshift-qe/logs/aosqe-logging",
"receiveTimestamp": "2022-08-18T09:32:53.910009439Z",
"resource": {
"labels": {
"cluster_name": "",
"location": "",
"node_name": "ip-10-0-143-124.us-east-2.compute.internal",
"project_id": "openshift-qe"
},
"type": "k8s_node"
},
"timestamp": "2022-08-18T09:32:53.910009439Z"
},
- links to
- mentioned on
