https://rancher.com/ logo
Powered by
#k3s
Title
b

broad-laptop-19151

01/19/2023, 6:41 PM
Hi! X-posting here, hoping to get some input. 🙂 Summary: We are trying to track down a flake test issue in our operator end-to-end tests. The operator under test is installed into a single node ephemeral k3s (k3d) cluster running on hosted GitHub runners (with limited resources). More details in the Kubernetes Slack post: https://kubernetes.slack.com/archives/C18NZM5K9/p1674144533725179
c

creamy-pencil-82913

01/19/2023, 7:02 PM
are the logs on the actual node truncated? You can just look at the contents of /var/log/pods on the node. See if it’s truncated there, or if kubectl is somehow messing with it. I suspect that the output you’re getting from 
kubectl logs
mirrors what’s in the actual log file.
You might also look at what’s happening to truncate it. Is the process getting terminated early due to a OOM or something, and that is causing it to end before writing all the content?
b

broad-laptop-19151

01/19/2023, 7:05 PM
Thanks! I will check the logs on the node. Obtaining the logs through the API shows that they are actually truncated. The log files on the node will probably indicate the same. The pod seems to have completed normally - nothing special in pod status. I am suspecting the CLI tool, but want to eliminate any other potential cause....
Is there any chance for the logs to "escape" because of limited resources available just when the pod is terminated? Or should that be consistent?
c

creamy-pencil-82913

01/19/2023, 7:31 PM
not that I have ever seen, no
that is all handled by the container runtime though (containerd) not the kubelet
👍 1
b

broad-laptop-19151

01/19/2023, 9:05 PM
As expected, the logs on the node are also truncated. Here is an extract (nothing after this):
Copy code
2023-01-19T20:53:02.001262317Z stdout F   {
2023-01-19T20:53:02.001265017Z stdout F     "fixedVersion": "215-17+deb8u11",
2023-01-19T20:53:02.001267717Z stdout F     "installedVersion": "215-17+deb8u4",
2023-01-19T20:53:02.001270417Z stdout F     "pkgName": "systemd-sysv",
2023-01-19T20:53:02.001273117Z stdout F     "primaryURL": "<https://avd.aquasec.com/nvd/cve-2019-3815>",
2023-01-19T20:53:02.001275917Z stdout F     "severity": "LOW",
2023-01-19T20:53:02.001278717Z stdout F     "title": "systemd: memory leak in journald-server.c introduced by fix for CVE-2018-16864",
2023-01-19T20:53:02.001281517Z stdout F     "vulnerabilityID": "CVE-2019-3815"
2023-01-19T20:53:02.001284217Z stdout F   },
2023-01-19T20:53:02.001287017Z stdout F   {
2023-01-19T20:53:02.001289717Z stdout F     "installedVersion": "215-17+deb8u4",
2023-01-19T20:53:02.001292517Z stdout F     "pkgName": "systemd-sysv",
2023-01-19T20:53:02.001295217Z stdout F     "primaryURL": "<https://avd.aquasec.com/nvd/cve-2020-13529>",
2023-01-19T20:53:02.001298017Z stdout F     "severity": "LOW",
2023-01-19T20:53:02.001420918Z stdout P     "title": "systemd: DHCP FORCERENEW authentication not implemented can cause a system running the DHCP client to hav
And the job pod completed successfully. 🤔 I wonder what is causing this.... Any other suggestions?
Any idea what the suspicious P on the last line might indicate? Partial?
c

creamy-pencil-82913

01/19/2023, 9:32 PM
Is the process exiting before flushing all the output or something?
yeah that does stand for partial though
👍 1
b

broad-laptop-19151

01/19/2023, 9:36 PM
That's also what I suspect. But I have been browsing through the source code without finding any traces of buffering. The app seems to use os.Stdout, and AFAIK it is unbuffered. I think I'll raise an issue over there to get further. The main issue (for me), is that this is hard to reproduce. Thanks a lot for your help. https://github.com/aquasecurity/trivy
c

creamy-pencil-82913

01/19/2023, 9:37 PM
the format that those files are in is notably not documented: https://github.com/kubernetes/kubernetes/issues/70539
😅 1
but you can see it check for P (as 
runtimeapi.LogTagPartial
) in there https://github.com/kubernetes/kubernetes/blob/master/pkg/kubelet/kuberuntime/logs/logs.go#L125-L169
🙌 1
and on the containerd side, the bit that pipes the output into the files: https://github.com/containerd/containerd/blob/main/pkg/cri/io/logger.go#L114
🙌 1
Have you considered having your scanner job dump the output to a file and then send that file out to another service for processing, instead of the fairly convoluted process of writing everything to stdout and then deploying something else to watch the logs by running 
kubectl logs
? That’s a pretty rube-goldeberg pipeline you’ve built there.
b

broad-laptop-19151

01/19/2023, 9:45 PM
Well, good question. There are a couple of reasons. First of all we want to perform a filesystem scanning running on the workload image. And as this is a multi-tenant cluster, we cannot expect anything, not even a shell, to be available.
For the record. Here is the yaml for the pod with partial logs. Do you see anything that indicates an error? I don't.
Copy code
apiVersion: v1
  kind: Pod
  metadata:
    creationTimestamp: "2023-01-19T21:26:32Z"
    generateName: deployment-vuln-app-app-eccf8-77bda-
    labels:
      <http://app.kubernetes.io/managed-by|app.kubernetes.io/managed-by>: image-scanner
      <http://app.kubernetes.io/name|app.kubernetes.io/name>: trivy
      controller-uid: 281d6325-15bb-47cb-9213-cfb7eb69c7a5
      <http://controller.statnett.no/namespace|controller.statnett.no/namespace>: kuttl-test-daring-goat
      <http://controller.statnett.no/uid|controller.statnett.no/uid>: 39a65615-de9c-4476-a882-97d76875eb5a
      job-name: deployment-vuln-app-app-eccf8-77bda
      <http://workload.statnett.no/kind|workload.statnett.no/kind>: Deployment
      <http://workload.statnett.no/name|workload.statnett.no/name>: vuln-app
      <http://workload.statnett.no/namespace|workload.statnett.no/namespace>: kuttl-test-daring-goat
    name: deployment-vuln-app-app-eccf8-77bda-tkh6c
    namespace: image-scanner-jobs
    ownerReferences:
    - apiVersion: batch/v1
      blockOwnerDeletion: true
      controller: true
      kind: Job
      name: deployment-vuln-app-app-eccf8-77bda
      uid: 281d6325-15bb-47cb-9213-cfb7eb69c7a5
    resourceVersion: "1486"
    uid: e265d033-d24f-49b0-84ca-4825fcf70758
  spec:
    affinity:
      nodeAffinity:
        preferredDuringSchedulingIgnoredDuringExecution:
        - preference:
            matchFields:
            - key: metadata.name
              operator: In
              values:
              - k3d-image-scanner-server-0
          weight: 100
    automountServiceAccountToken: false
    containers:
    - args:
      - filesystem
      - /
      command:
      - /var/run/image-scanner/trivy
      env:
      - name: HOME
        value: /tmp
      - name: TRIVY_OFFLINE_SCAN
        value: "true"
      - name: TRIVY_SECURITY_CHECKS
        value: vuln
      - name: TRIVY_CACHE_DIR
        value: /tmp
      - name: TRIVY_SERVER
        value: <http://trivy.image-scanner.svc.cluster.local>
      - name: TRIVY_QUIET
        value: "true"
      - name: TRIVY_FORMAT
        value: template
      - name: TRIVY_TEMPLATE
        value: |
          {{- $vulns := list -}}
          {{- range . }}
              {{- range .Vulnerabilities -}}
                  {{- $vuln := dict -}}
                  {{- $_ := set $vuln "vulnerabilityID" .VulnerabilityID -}}
                  {{- $_ := set $vuln "pkgName" .PkgName -}}
                  {{- $_ := set $vuln "installedVersion" .InstalledVersion -}}
                  {{- $_ := set $vuln "severity" .Severity -}}
                  {{- if .PkgPath }}{{ $_ := set $vuln "pkgPath" .PkgPath }}{{ end -}}
                  {{- if .FixedVersion }}{{ $_ := set $vuln "fixedVersion" .FixedVersion }}{{ end -}}
                  {{- if .Title }}{{ $_ := set $vuln "title" .Title }}{{ end -}}
                  {{- if .PrimaryURL }}{{ $_ := set $vuln "primaryURL" .PrimaryURL }}{{ end -}}
                  {{- $vulns = append $vulns $vuln -}}
              {{- end -}}
          {{- end -}}
          {{- toPrettyJson $vulns }}
      - name: TRIVY_TIMEOUT
        value: 1h0m0s
      - name: TRIVY_SEVERITY
        value: MEDIUM,HIGH,CRITICAL
      image: <http://docker.io/kennship/http-echo@sha256:144322e8e96be2be6675dcf6e3ee15697c5d052d14d240e8914871a2a83990af|docker.io/kennship/http-echo@sha256:144322e8e96be2be6675dcf6e3ee15697c5d052d14d240e8914871a2a83990af>
      imagePullPolicy: IfNotPresent
      name: scan-image
      resources:
        limits:
          cpu: 500m
          memory: 500M
        requests:
          cpu: 100m
          memory: 100M
      securityContext:
        allowPrivilegeEscalation: false
        capabilities:
          drop:
          - all
        privileged: false
        readOnlyRootFilesystem: true
        runAsUser: 0
      terminationMessagePath: /dev/termination-log
      terminationMessagePolicy: FallbackToLogsOnError
      volumeMounts:
      - mountPath: /var/run/image-scanner
        name: image-scanner
      - mountPath: /tmp
        name: tmp
      workingDir: /tmp
    dnsPolicy: ClusterFirst
    enableServiceLinks: true
    initContainers:
    - command:
      - cp
      - -v
      - /usr/local/bin/trivy
      - /var/run/image-scanner/trivy
      image: <http://ghcr.io/aquasecurity/trivy:0.36.1|ghcr.io/aquasecurity/trivy:0.36.1>
      imagePullPolicy: IfNotPresent
      name: trivy
      resources:
        limits:
          cpu: 50m
          memory: 200Mi
        requests:
          cpu: 10m
          memory: 50Mi
      terminationMessagePath: /dev/termination-log
      terminationMessagePolicy: FallbackToLogsOnError
      volumeMounts:
      - mountPath: /var/run/image-scanner
        name: image-scanner
    nodeName: k3d-image-scanner-server-0
    preemptionPolicy: PreemptLowerPriority
    priority: 0
    restartPolicy: OnFailure
    schedulerName: default-scheduler
    securityContext: {}
    serviceAccount: image-scanner
    serviceAccountName: image-scanner
    terminationGracePeriodSeconds: 30
    tolerations:
    - effect: NoExecute
      key: <http://node.kubernetes.io/not-ready|node.kubernetes.io/not-ready>
      operator: Exists
      tolerationSeconds: 300
    - effect: NoExecute
      key: <http://node.kubernetes.io/unreachable|node.kubernetes.io/unreachable>
      operator: Exists
      tolerationSeconds: 300
    volumes:
    - emptyDir: {}
      name: image-scanner
    - emptyDir: {}
      name: tmp
  status:
    conditions:
    - lastProbeTime: null
      lastTransitionTime: "2023-01-19T21:26:36Z"
      reason: PodCompleted
      status: "True"
      type: Initialized
    - lastProbeTime: null
      lastTransitionTime: "2023-01-19T21:26:43Z"
      reason: PodCompleted
      status: "False"
      type: Ready
    - lastProbeTime: null
      lastTransitionTime: "2023-01-19T21:26:43Z"
      reason: PodCompleted
      status: "False"
      type: ContainersReady
    - lastProbeTime: null
      lastTransitionTime: "2023-01-19T21:26:32Z"
      status: "True"
      type: PodScheduled
    containerStatuses:
    - containerID: <containerd://256860a1ab03d515ca56a7fb65b09b6aedba2cface02e66a824dec560a2e66b>b
      image: sha256:c1c085fb330eea7d222e40bdf5ad0ea400e751285847ce2ae76889ee0d961c04
      imageID: <http://docker.io/kennship/http-echo@sha256:144322e8e96be2be6675dcf6e3ee15697c5d052d14d240e8914871a2a83990af|docker.io/kennship/http-echo@sha256:144322e8e96be2be6675dcf6e3ee15697c5d052d14d240e8914871a2a83990af>
      lastState: {}
      name: scan-image
      ready: false
      restartCount: 0
      started: false
      state:
        terminated:
          containerID: <containerd://256860a1ab03d515ca56a7fb65b09b6aedba2cface02e66a824dec560a2e66b>b
          exitCode: 0
          finishedAt: "2023-01-19T21:26:43Z"
          reason: Completed
          startedAt: "2023-01-19T21:26:36Z"
    hostIP: 172.18.0.2
    initContainerStatuses:
    - containerID: <containerd://b6bb18aa1bb7f4d79ce2a4d200725531aed837f211451921583b5acaefa7ddb>2
      image: <http://ghcr.io/aquasecurity/trivy:0.36.1|ghcr.io/aquasecurity/trivy:0.36.1>
      imageID: <http://ghcr.io/aquasecurity/trivy@sha256:fcd4eddc8082be2d7c929cb07c989d62d2d50669513b8a0889116b40feab435f|ghcr.io/aquasecurity/trivy@sha256:fcd4eddc8082be2d7c929cb07c989d62d2d50669513b8a0889116b40feab435f>
      lastState: {}
      name: trivy
      ready: true
      restartCount: 0
      state:
        terminated:
          containerID: <containerd://b6bb18aa1bb7f4d79ce2a4d200725531aed837f211451921583b5acaefa7ddb>2
          exitCode: 0
          finishedAt: "2023-01-19T21:26:36Z"
          reason: Completed
          startedAt: "2023-01-19T21:26:33Z"
    phase: Succeeded
    podIP: 10.42.0.32
    podIPs:
    - ip: 10.42.0.32
    qosClass: Burstable
    startTime: "2023-01-19T21:26:32Z"
c

creamy-pencil-82913

01/19/2023, 9:54 PM
right but if you can deploy a scanner pod, and another pod to watch for the scanner pods and tail their logs… couldn’t you replace the log-tail pods with another pod that takes the scan json in via a HTTP POST or something? and modify the scan jobs to output it to a file and then POST that file to the service. That way you have a direct path from the scan pod to the ingest pod without rube-goldberging everything through the kubernetes apiserver.
🤔 1
b

broad-laptop-19151

01/19/2023, 9:56 PM
Thanks for your input. We could probably do something by building a small wrapper app around the trivy CLI running inside the image to be scanned. Really appreciate your point of view!
c

creamy-pencil-82913

01/19/2023, 9:58 PM
it looks to me like the trivy scan initcontainer exited normally too. not sure why the output would be truncated 🤷
b

broad-laptop-19151

01/19/2023, 9:58 PM
But I want to get to the bottom of the trucated logs.
Been bugging us for days now.
c

creamy-pencil-82913

01/19/2023, 9:59 PM
I am curious if you would see the same thing if you redirected the report output to a file as opposed to relying on containerd to collect it all
b

broad-laptop-19151

01/19/2023, 9:59 PM
How would that look like? I'll probably need a shell to do that, or what?
c

creamy-pencil-82913

01/19/2023, 10:00 PM
ohh nevermind. I thought you were doing the whole scan in the initcontainer
I see that the initcontainer is just copying over the trivy binary
b

broad-laptop-19151

01/19/2023, 10:01 PM
This particular test image has a shell, so I could try anything.
Yes, the initContainer is just to make the binary available inside the workload image.
c

creamy-pencil-82913

01/19/2023, 10:01 PM
You’re doing an offline scan but have a trivy server available?
and then you’re pulling the scan logs from the offline scan via the container logs?
b

broad-laptop-19151

01/19/2023, 10:02 PM
Yes, it is running in a neighbor namespace
c

creamy-pencil-82913

01/19/2023, 10:02 PM
Doesn’t Trivy already solve this problem for you if you just let it upload the results to the server?
b

broad-laptop-19151

01/19/2023, 10:02 PM
The server runs aside the operator orchestrating all this.
That is not how the server works.
🙂
The server is performing the scan, and caches the result. The role of the operator is to provide feedback to workload owners through custom resources and metrics.
c

creamy-pencil-82913

01/19/2023, 10:05 PM
ah OK. I used Prisma Cloud (formerly TwistLock) at a previous job and it would aggregate the results for you
b

broad-laptop-19151

01/19/2023, 10:05 PM
It is a bit rube-goldberg, but has proven very useful.
And our users like it.
c

creamy-pencil-82913

01/19/2023, 10:05 PM
so you didn’t have to hand-roll a scan result analysis pipeline
b

broad-laptop-19151

01/19/2023, 10:05 PM
Oh no, not at all.
This issue is specifically in my e2e-test workflow running on GH.
We have never had issues like this in our real clusters.
Running this in multiple Openshift clusters with 50-100 nodes.
c

creamy-pencil-82913

01/19/2023, 10:07 PM
huh
b

broad-laptop-19151

01/19/2023, 10:07 PM
I am trying to get us over to Rancher, but no luck so far.
😄
I've been experimenting with RKE 2, in addition to k3s/k3d - which we use a lot in development and CI.
This is the operator, if you want to take it for a spin: https://github.com/statnett/image-scanner-operator
It is pretty fresh in the public, and still lacks proper documentation. But running in all our clusters.
c

creamy-pencil-82913

01/19/2023, 10:14 PM
containerd collects stdout/stderr through a pipe, it could be that in more resource constrained environments the pipe reads are slower and don’t have time to complete when the process exits? If you modified your scan command to sleep afterwards for a second or two I bet you’d see the truncated output go away.
but in general I would consider re-implementing this to not rely on listing containers and tailing their output. It’s going to be much more reliable and put less load on the control-plane if you just send the output you need, directly to where you need it.
✅ 1
b

broad-laptop-19151

01/19/2023, 10:15 PM
Hmmm, I wonder if I can achieve that.
Again, thanks a lot for your input. I will take a look tomorrow morning.
c

creamy-pencil-82913

01/19/2023, 10:17 PM
gl!
❤️ 1
b

broad-laptop-19151

01/19/2023, 10:18 PM
If I can find a way to wrap the trivy binary, this will be a simple adjustment on the operator-side.
I don't want to dig into the actual scanning details.
c

creamy-pencil-82913

01/19/2023, 10:26 PM
yeah I see that you’re copying over trivy in the initcontainer and then running the scan in the main image. If you can’t depend on there being anything in the main image, you might need to add another non-initcontainer sidecar container that has a shell and curl (or a more purpose-built tool) for sending the scan output to a receiver.
👍 1
b

broad-laptop-19151

01/19/2023, 10:27 PM
Exactly! I need to solve that.
c

creamy-pencil-82913

01/19/2023, 10:28 PM
busybox’s 
wget
has POST upload support, you could probably use that.
👍 1
4 Views
Powered by