SELinux "denied" errors

Description
Hi, I am trying to integrate the vault-csi-provider into my cluster which I got an error!
│ 2023-04-03T12:01:38.605Z [INFO]  Creating new gRPC server                                                                                │
│ 2023-04-03T12:01:38.605Z [INFO]  Opening unix socket: endpoint=/provider/vault.sock                                                                                │
│ 2023-04-03T12:01:38.606Z [ERROR] Error running provider: err="failed to listen on unix socket at /provider/vault.sock: listen unix /provider/vault.sock: bind: permission denied"                                                                                │
│ Stream closed EOF for vault/vault-csi-provider-csi-provider-mwtd6 (vault-csi-provider)

I have checked on the nodes and realized it is not able to create that file on the host os, I just have disabled the policy enforcing to test if that is causing it and was able to run the vault csi provider on the node that setenforce flag was disabled as you can see in below.

Is there any way that I can attach customized policy based on the need?
Kube.tf file
module "kube-hetzner" {

  providers = {
    hcloud = hcloud
  }

  hcloud_token    = var.HCLOUD_TOKEN
  source          = "kube-hetzner/kube-hetzner/hcloud"
  version         = "2.0.2"
  ssh_public_key  = tls_private_key.kube_hetzner.public_key_openssh
  ssh_private_key = tls_private_key.kube_hetzner.private_key_openssh
  network_region  = "eu-central"

  control_plane_nodepools = [
    {
      name        = "control-plane",
      server_type = "cpx11",
      location    = "fsn1",
      labels      = [],
      taints      = [],
      count       = 3
    }
  ]

  agent_nodepools = [
    {
      name        = "worker",
      server_type = "cx51",
      location    = "fsn1",
      labels      = [],
      taints      = [],
      floating_ip = false,
      count       = 3
    }
  ]

  load_balancer_type     = "lb11"
  load_balancer_location = "fsn1"

  ingress_controller        = "none"
  cluster_name              = "test"
  cni_plugin                = "cilium"
  enable_cert_manager       = true
  use_control_plane_lb      = true
  create_kubeconfig         = false
  create_kustomization      = false
  restrict_outbound_traffic = false
}

Screenshots
No response
Platform
Linux

@honarkhah Good catch, please SSH into your node, and execute that command sudo grep "avc:  denied" /var/log/audit/audit.log | audit2allow -M my_custom_policy. Then copy paste here the value of your generated my_custom_policy.te file.
Ideally, before that, apply the generate .pp to double check that it works. If not, re-run the command and apply again the .pp, until you get vault working, and then either open a PR with the content of the .te added to the policy section in locals.tf, or just copy it here so that I add it myself.

@honarkhah FYI, you can apply the .pp with semodule -i my_custom_policy.pp.

grep "avc: denied" /var/log/audit/audit.log | audit2allow -M my_custom_policy

I have tried it couple of times, but I still get permission denied!
$:~ # grep "avc:  denied" /var/log/audit/audit.log
type=AVC msg=audit(1680592959.117:208937): avc:  denied  { write } for  pid=12053 comm="vault-csi-provi" name="secrets-store-csi-providers" dev="overlay" ino=97 scontext=system_u:system_r:container_t:s0:c735,c822 tcontext=system_u:object_r:etc_t:s0 tclass=dir permissive=0

policy.te file:
module my_custom_policy 1.0;

require {
        type container_t;
        type etc_t;
        class dir { add_name remove_name write };
        class sock_file create;
}

#============= container_t ==============

#!!!! This avc is allowed in the current policy
allow container_t etc_t:dir { add_name remove_name write };

#!!!! This avc is allowed in the current policy
allow container_t etc_t:sock_file create;

Ah, finally got it working, the issue was the socket was created before, after deleting and let it to create with new policy it worked

I have similar problem with the Filebeat.
Error from the container:
failed to create Beat meta file: open /usr/share/filebeat/data/meta.json.new: permission denied

Pod's manifest:
apiVersion: v1
kind: Pod
metadata:
  annotations:
    beat.k8s.elastic.co/config-hash: '2123631025'
  creationTimestamp: '2023-04-04T08:33:30Z'
  generateName: filebeat-elk-beat-filebeat-
  labels:
    beat.k8s.elastic.co/name: filebeat-elk
    beat.k8s.elastic.co/version: 8.3.0
    common.k8s.elastic.co/type: beat
    controller-revision-hash: 697549fdf6
    pod-template-generation: '1'
  managedFields:
    - apiVersion: v1
      fieldsType: FieldsV1
      fieldsV1:
        :metadata:
      manager: k3s
      operation: Update
      subresource: status
      time: '2023-04-04T08:36:44Z'
  name: filebeat-elk-beat-filebeat-ctgx5
  namespace: logging
  ownerReferences:
    - apiVersion: apps/v1
      blockOwnerDeletion: true
      controller: true
      kind: DaemonSet
      name: filebeat-elk-beat-filebeat
      uid: aaacb244-8de3-48f8-9c5e-7372a2cc28db
  resourceVersion: '702767'
  uid: 50035b3e-c551-4fc7-8a93-f6cb52862a44
spec:
  affinity:
    nodeAffinity:
      requiredDuringSchedulingIgnoredDuringExecution:
        nodeSelectorTerms:
          - matchFields:
              - key: metadata.name
                operator: In
                values:
                  - k3s-agent-hel1-dnp
  automountServiceAccountToken: true
  containers:
    - args:
        - '-e'
        - '-c'
        - /etc/beat.yml
      env:
        - name: NODE_NAME
          valueFrom:
            fieldRef:
              apiVersion: v1
              fieldPath: spec.nodeName
      image: docker.elastic.co/beats/filebeat:8.3.0
      imagePullPolicy: IfNotPresent
      name: filebeat
      resources:
        limits:
          cpu: 250m
          memory: 500Mi
        requests:
          cpu: 100m
          memory: 200Mi
      securityContext:
        runAsUser: 0
      terminationMessagePath: /dev/termination-log
      terminationMessagePolicy: File
      volumeMounts:
        - mountPath: /usr/share/filebeat/data
          name: beat-data
        - mountPath: /etc/beat.yml
          name: config
          readOnly: true
          subPath: beat.yml
        - mountPath: /var/lib/docker/containers
          name: varlibdockercontainers
        - mountPath: /var/log/containers
          name: varlogcontainers
        - mountPath: /var/log/pods
          name: varlogpods
        - mountPath: /var/run/secrets/kubernetes.io/serviceaccount
          name: kube-api-access-s4rcs
          readOnly: true
  dnsPolicy: ClusterFirstWithHostNet
  enableServiceLinks: true
  hostNetwork: true
  nodeName: k3s-agent-hel1-dnp
  preemptionPolicy: PreemptLowerPriority
  priority: 0
  restartPolicy: Always
  schedulerName: default-scheduler
  securityContext: {}
  serviceAccount: filebeat-elk
  serviceAccountName: filebeat-elk
  terminationGracePeriodSeconds: 30
  tolerations:
    - effect: NoSchedule
      key: dedicated
      operator: Exists
    - effect: NoExecute
      key: node.kubernetes.io/not-ready
      operator: Exists
    - effect: NoExecute
      key: node.kubernetes.io/unreachable
      operator: Exists
    - effect: NoSchedule
      key: node.kubernetes.io/disk-pressure
      operator: Exists
    - effect: NoSchedule
      key: node.kubernetes.io/memory-pressure
      operator: Exists
    - effect: NoSchedule
      key: node.kubernetes.io/pid-pressure
      operator: Exists
    - effect: NoSchedule
      key: node.kubernetes.io/unschedulable
      operator: Exists
    - effect: NoSchedule
      key: node.kubernetes.io/network-unavailable
      operator: Exists
  volumes:
    - hostPath:
        path: /var/lib/logging/filebeat-elk/filebeat-data
        type: DirectoryOrCreate
      name: beat-data
    - name: config
      secret:
        defaultMode: 292
        optional: false
        secretName: filebeat-elk-beat-filebeat-config
    - hostPath:
        path: /var/lib/docker/containers
        type: ''
      name: varlibdockercontainers
    - hostPath:
        path: /var/log/containers
        type: ''
      name: varlogcontainers
    - hostPath:
        path: /var/log/pods
        type: ''
      name: varlogpods
    - name: kube-api-access-s4rcs
      projected:
        defaultMode: 420
        sources:
          - serviceAccountToken:
              expirationSeconds: 3607
              path: token
          - configMap:
              items:
                - key: ca.crt
                  path: ca.crt
              name: kube-root-ca.crt
          - downwardAPI:
              items:
                - fieldRef:
                    apiVersion: v1
                    fieldPath: metadata.namespace
                  path: namespace
status:
  conditions:
    - lastProbeTime: null
      lastTransitionTime: '2023-04-04T08:33:30Z'
      status: 'True'
      type: Initialized
    - lastProbeTime: null
      lastTransitionTime: '2023-04-04T08:36:44Z'
      message: 'containers with unready status: [filebeat]'
      reason: ContainersNotReady
      status: 'False'
      type: Ready
    - lastProbeTime: null
      lastTransitionTime: '2023-04-04T08:36:44Z'
      message: 'containers with unready status: [filebeat]'
      reason: ContainersNotReady
      status: 'False'
      type: ContainersReady
    - lastProbeTime: null
      lastTransitionTime: '2023-04-04T08:33:30Z'
      status: 'True'
      type: PodScheduled
  containerStatuses:
    - containerID: >-
        containerd://85f2c69219d0a831dab2dba4032c0f61e07917ddb7b8a4919552263bf49f0933
      image: docker.elastic.co/beats/filebeat:8.3.0
      imageID: >-
        docker.elastic.co/beats/filebeat@sha256:2972cf06e669fc62d319bd2135ab7bebb9c476f26ec82934061ba5932a5db5b1
      lastState:
        terminated:
          containerID: >-
            containerd://85f2c69219d0a831dab2dba4032c0f61e07917ddb7b8a4919552263bf49f0933
          exitCode: 1
          finishedAt: '2023-04-04T08:36:43Z'
          reason: Error
          startedAt: '2023-04-04T08:36:42Z'
      name: filebeat
      ready: false
      restartCount: 5
      started: false
      state:
        waiting:
          message: >-
            back-off 2m40s restarting failed container=filebeat
            pod=filebeat-elk-beat-filebeat-ctgx5_logging(50035b3e-c551-4fc7-8a93-f6cb52862a44)
          reason: CrashLoopBackOff
  hostIP: <IP_ADDRESS>
  phase: Running
  podIP: <IP_ADDRESS>
  podIPs:
    - ip: <IP_ADDRESS>
  qosClass: Burstable
  startTime: '2023-04-04T08:33:30Z'

my_custom_policy.te:
module my_custom_policy 1.0;

require {
        type container_var_lib_t;
        type container_t;
        class file create;
}

#============= container_t ==============
allow container_t container_var_lib_t:file create;

Hi! I'm also getting these avc errors when trying to write on volumes provisioned using local-path-provisioner.
Any workarounds? What would happen if I just disable SELinux?

@honarkhah Good catch, please SSH into your node, and execute that command sudo grep "avc: denied" /var/log/audit/audit.log | audit2allow -M my_custom_policy. Then copy paste here the value of your generated my_custom_policy.te file.
Ideally, before that, apply the generate .pp to double check that it works. If not, re-run the command and apply again the .pp, until you get vault working, and then either open a PR with the content of the .te added to the policy section in locals.tf, or just copy it here so that I add it myself.

Have you guys followed the instructions?
I have followed the path and after couple of try and error got the final policy in place and created a PR

ah, sorry - I must have skipped that part. will try

I use this project to setup cheaper dev/test/staging kubernetes clusters. After reinstalling an older cluster I got the following problems:

fluent-bit (needs access to local files on the node):

[error] [sqldb] cannot open database /var/log/flb_kube.db
[error] [input:tail:tail.0] could not open/create database
[error] failed initialize input tail.0
[error] [engine] input initialization failed
[error] [lib] backend failed

openvpn(needs to load "tun" and "conntrack" kernel modules):

Error: Could not process rule: No such file or directory
add rule ip filter INPUT iifname tun0 ct state related,established accept
^^^^^^^^

ERROR: Cannot open TUN/TAP dev /dev/net/tun: No such device (errno=19) (((Even though I did mknod /dev/net/tun c 10 200 )))

lbnodeagent (don't know what it needs):

{"caller":"panic.go:884","msg":"done","op":"shutdown"}
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1358ad9]
goroutine 1 [running]:
purelb.io/internal/local.(*announcer).announceRemote(0xc000200420, 0xc0007b8d60, 0xc0006a4ad0, 0xc00042b420?, {0xc00042b420, 0x10, 0x10})
/usr/src/internal/local/announcer_local.go:273 +0x519
purelb.io/internal/local.(*announcer).SetBalancer(0xc000200420, 0xc0007b8d60, 0x16c9ff1?)
/usr/src/internal/local/announcer_local.go:193 +0x5cf
main.(*controller).ServiceChanged(0xc000204190, 0xc0007b8d60, 0xc000492501?)
/usr/src/cmd/lbnodeagent/controller.go:102 +0x9e3
purelb.io/internal/k8s.(*Client).sync(0xc0000bc9a0, {0x14312e0?, 0xc0004925e0?})
/usr/src/internal/k8s/k8s.go:403 +0x3bd
purelb.io/internal/k8s.(*Client).Run(0xc0000bc9a0, 0xc0001140c0)
/usr/src/internal/k8s/k8s.go:280 +0x2be
main.main()
/usr/src/cmd/lbnodeagent/main.go:119 +0xf2b
Stream closed EOF for purelb/lbnodeagent-dlr82 (lbnodeagent)
`

These issues have been solved by disabling Selinux. Probably not the smartest Idea but I don't mind to do it on a throwaway clusters.
This is how I did it:

ssh<EMAIL_ADDRESS>setenforce Permissive #This disabeles it until the next restart
vi /etc/sysconfig/selinux-policy #set SELINUX=permissive and save, this will persist the setting after node reboot.

From this use case of mine I can conclude that it is probably best to have the Selinux settings be exposed in the kube.tf.example similar to how extra_firewall_rules are. Preferably with documentation on how to configure it like with the Examples section in the readme.md This is necessary because different users have different needs and it's not possible to cover everything in locals.tf

@honarkhah Good job, will merge later on tonight.
@maaft Test it via applying th generated .pp file, if works great, if not, re-run the command for it to post the latest errors. Normally, it will convert all uses cases, so if the above is your final .te that is proven to work, I will integrate it.
@michailkorenev Perfect, .te noted, will integrate, also make sure to test with .pp as described above.
@phinx110 Please grab your .te, test your .pp, if all good post your .te, don't worry no need to disable SELinux I need your help to make this project compatible with SELinux while being has secure as possible, just generate and share your .te file please, will merge later tonight.

@honarkhah Good job, will merge later on tonight.
@maaft Test it via applying th generated .pp file, if works great, if not, re-run the command for it to post the latest errors. Normally, it will convert all uses cases, so if the above is your final .te that is proven to work, I will integrate it.
@michailkorenev Perfect, .te noted, will integrate, also make sure to test with .pp as described above.
@phinx110 Please grab your .te, test your .pp, if all good post your .te, don't worry no need to disable selinux.

@mysticaltech its a very time-consuming process:

my postgres db does init from backup (takes time)
after that, new errors occur
reapply .pp, throw away DB, restart restore procedure
i have multiple agents where the pods need to run due to HA-postgres-cluster (different /var/log/audit/audit.log content - how to aggregate easily?)
when the cluster finally runs - how can I be sure that everything is included? maybe at the next backup there is still some permission missing?

What I want to say is, wouldn't it be easier to allow just everything regarding files and folders? If yes, where to find such a list?

@maaft No worries that, I will include a quick flag "enable_selinux" to turn off selinux at the k3s level, how it was before. It has always been active at the OS level, but not the k3s level.

Now for best security, you would leave it active, and after you run your cluster, issue the above command to pickup the denied stuff, submit a PR and voila.

@maaft My theory is that applications actually are not that different. Probably the new updated policy with the values above, will fix most issues, and after a few iterations, we will have convered the whole playing field.
So my advice, both @maaft and @phinx110 see the command above, generate your te and pp file, test pp, if good and everything works, submit your final .te content here that is just text. That way we will really map all possible use cases, there aren't so many.

Thanks @honarkhah, really appreciate it!

@maaft @phinx110 @michailkorenev Along with the recently merged SELinux rules additions by @honarkhah, I have merged your respective rules provided above. Please give v2.0.4 a shot, you do not need to create the snapshot, but you do not need updated and at least create new nodepools (while taking bringing the count to the old nodepools to 0 after draining the old nodes), or if you prefer completely recreate the cluster.
If that works, great! If not, please let's iterate a little bit, either you add your rules to locals.tf directly via a PR, or you create a discussion about additional SELinux rules and add them there tagging me explicitly so that I add them ASAP.
I believe we are near to mapping all the possible use cases, I also proactively added permissions based on GPT-4 recommendations of common uses cases.
If that approach works, great! If however in the future we see the need for custom rules, we will provide a variable for you to add it, and if necessary, we will provide the ability to turn off SELinux at the k3s level (not the OS level), hopefully that will not be necessary so that clusters deployed with this tool stay as secure as possible.
Again to create your needed policy if you see denied errors:

SSH in the affected node.
Run: sudo grep "denied" /var/log/audit/audit.log | audit2allow -M my_custom_policy
Apply with semodule -i my_custom_policy.pp
Test, and if failed again, re-rerun the above two commands to catch the remaining denied errors.
When success, submit in a discussion tagging me.

@mysticaltech
When testing lbnodeagent I got the following but I'm not sure if this is actually doing anything because it was the first one I tested. It's possible that something else is causing this and not lbnodeagent so I wouldn't include this in the locals.tf just yet:
purelb-lbnodeagent 1.0;

require {
	type init_t;
	type container_t;
	class file { open read };
}

#============= container_t ==============
allow container_t init_t:file { open read };

I need this to load the "tun" (openvpn) and "conntrack" (nftables) kernel modules:
module kernel_module_request 1.0;

require {
	type container_t;
	type kernel_t;
	class system module_request;
}

#============= container_t ==============

#!!!! This avc can be allowed using the boolean 'domain_kernel_load_modules'
allow container_t kernel_t:system module_request;

Regarding the fluentbit-cluster-monitoring it was a mess. I got the following 3 configs:
module fluentbit-cluster-monitoring 1.0;

require {
	type container_log_t;
	type container_t;
	type var_log_t;
	class file { create lock open read setattr watch write };
	class dir { add_name read write };
	class lnk_file read;
}

#============= container_t ==============
allow container_t container_log_t:dir read;
allow container_t container_log_t:file { open read watch };
allow container_t container_log_t:lnk_file read;
allow container_t var_log_t:dir { add_name write };
allow container_t var_log_t:file { create lock open read setattr write };

module fluentbit-cluster-monitoring2 1.0;

require {
	type var_log_t;
	type container_t;
	class dir remove_name;
	class file unlink;
}

#============= container_t ==============
allow container_t var_log_t:dir remove_name;
allow container_t var_log_t:file unlink;

module filesystem_associate 1.0;

require {
	type proc_t;
	type container_t;
	class filesystem associate;
}

#============= container_t ==============
allow container_t proc_t:filesystem associate;

After loading all these modules with semodule -i, the fluentbit still keeps crashing duo to permission problems. If I disable selinux it works again however, grep "denied" /var/log/audit/audit.log | audit2allow does not return to me anything new so now I'm stuck.
I understand the desire to have a fully locked down k3s installation however, even with good instructions provided, it still remains a tedious iterative process, especially if you have to do this for multiple individual failing components separately, in order to have the semodules separated as well, like I did, and in the end it still did not end up working for me. With the older version of this project I had a working setup but after a reinstall I suddenly had to spend quite some time to get it working the correct way. In the end I have decided to just give up on this and disable selinux altogether to get on with it because of timepresure. I simply cannot afford to keep working on this any longer then I currently have and I assume there are quite a few other developers who end up in the same position as I am.
The main reason to have "selinux at the k3s level" is if you run your production on Hetzner. In my case we run our production on AWS and use Hetzner as a cheaper environments to run different version/copies of our software for different departments (dev/test/staging). I would strongly consider the ability to disable "selinux at the k3s level" as a valid "feature" that I would like to request.

@maaft @phinx110 Your new rules have been integrated in v2.0.5, please upgrade with terraform init -upgrade and try again.
@phinx110 Your are close to your goal, try if everything runs well please and if not, find that missing rule as explain above, and please tag me again for me to add it.
If you want to contribute the feature to disable selinux for k3s, just search "selinux:" in the project and you will understand, all we need is a new variable for it. But again, let's keep that as a last option, basically if it works with SELinux disabled, it will work with SELinux enabled with the right policy, up to you to determine that policy.

Hi @mysticaltech, sorry to resurrect this issue, but I'm having trouble following the debug instructions. I have the same permission errors as described in #739 when running the node exporter integration of Grafana Agent:
grafana-agent caller=collector.go:185 level=error component=integrations integration=node_exporter instance=xx:8080 msg="collector failed" name=filesystem err="open /host/proc/1/mounts: permission denied"
grafana-agent caller=collector.go:185 level=error component=integrations integration=node_exporter instance=xx:8080 msg="collector failed" name=processes err="unable to retrieve number of allocated threads: error reading stat for pid 1: open /host/proc/1/stat: permission denied"

When I ssh into the node I can't find anything related in the audit.log:
grep "avc:  denied" /var/log/audit/audit.log
grep denied /var/log/audit/audit.log
grep avc /var/log/audit/audit.log
grep proc /var/log/audit/audit.log
grep stat /var/log/audit/audit.log
grep mount /var/log/audit/audit.log
grep permission /var/log/audit/audit.log
grep filesystem /var/log/audit/audit.log
grep process /var/log/audit/audit.log

No matches found. Does that mean that the error isn't actually related to SELinux...? What else could I investigate?
Thanks!

@dstockhammer Use an audit.log analyzer, liked audit2why and audit2allow to gen the missing rules and paste them here.

Ok it looks like SELinux has nothing to do with this; apologies for resurrecting the wrong issue in that case. I'll ask OP in the referenced issue.
~ # audit2why < /var/log/audit/audit.log
Nothing to do

~ # audit2why -a
<no matches>

@aleksasiriski Perfect, will add it tonight 🙏

@aleksasiriski I actually forgot to add the previous one, so will do now. Could be minio indeed.

@aleksasiriski Added in v2.12.2 🚀

@mysticaltech
I tried running k8s-csi-s3 with the default geesefs backend and it would fail to start it. audit2allow  -a -M geesefs generated:
module geesefs 1.0;

require {
	type container_t;
	type fuse_device_t;
	type init_t;
	type container_file_t;
	type http_port_t;
	type io_uring_t;
	class file { execute execute_no_trans };
	class tcp_socket name_connect;
	class chr_file { open read write };
	class io_uring sqpoll;
	class anon_inode { create map read write };
}

#============= container_t ==============
allow container_t io_uring_t:anon_inode { create map read write };
allow container_t self:io_uring sqpoll;

#============= init_t ==============
allow init_t container_file_t:file { execute execute_no_trans };
allow init_t fuse_device_t:chr_file { open read write };

#!!!! This avc can be allowed using the boolean 'nis_enabled'
allow init_t http_port_t:tcp_socket name_connect;

(works with the generated module applied)
Do you want to keep adding rules like this or should there be some way to insert custom ones? 🤔

@jhass Thanks for reporting this. Just added the missing rules in v2.13.2 🚀

I have a similar issue with the Promtail helm chart from Grafana:
i get "... permission denied" errors from the pods.
If i deactivate SELinux on a node, the pod will work as expected on this specific node.
I have tried to generate a custom policy with:
grep "avc: denied" /var/log/audit/audit.log | audit2allow -M my_custom_policy
installed the policy with
semodule -i my_custom_policy.pp
I have tested if i worked, by rerunning the pod. If not i reran the two commands.
The my_custom_policy.te file changed at first and so did the errors i the pod
but after a couple of reruns of the two commands and rerun of the pod, i end up with the same content in my_custom_policy.te file everytime
i consistently get this error from the promtail pod:
... error writing positions file" error="lstat /run/promtail/positions.yaml: permission denied"
Any ideas on what else to try? 🤞

@rlj-daf share the contents of your policy with me to have a look.

@rlj-daf Added to v2.13.3, enjoy!

@mysticaltech thanks! Actually one question, what's the intended upgrade path here? Since the policy is part of the cloud-init template it applies only to new nodes as far as I can tell.

@jhass Absolutely right. Please try to re-run cloud-init on a per node nasis and let me know:
sudo cloud-init init
sudo cloud-init modules --mode config
sudo cloud-init modules --mode final
Also check:
cat /var/log/cloud-init.log

@mysticaltech It doesn't look to me like it's really doing anything.

cloud-init rerun

$ rm /var/log/cloud-init.log
$  cloud-init init
Cloud-init v. 23.3-8.1 running 'init' at Wed, 13 Mar 2024 18:48:56 +0000. Up 1817.53 seconds.
ci-info: ++++++++++++++++++++++++++++++++++++++++Net device info++++++++++++++++++++++++++++++++++++++++
ci-info: +--------+------+------------------------------+-----------------+--------+-------------------+
ci-info: | Device |  Up  |           Address            |       Mask      | Scope  |     Hw-Address    |
ci-info: +--------+------+------------------------------+-----------------+--------+-------------------+
ci-info: | enp7s0 | True |         <IP_ADDRESS>         | <IP_ADDRESS> | global | 86:00:00:7c:0b:10 |
ci-info: | enp7s0 | True | fe80::25e3:8f99:36e6:9194/64 |        .        |  link  | 86:00:00:7c:0b:10 |
ci-info: |  eth0  | True |         <IP_ADDRESS>          | <IP_ADDRESS> | global | 96:00:03:13:96:b0 |
ci-info: |  eth0  | True | fe80::9dfd:2b8f:1fa9:2aa9/64 |        .        |  link  | 96:00:03:13:96:b0 |
ci-info: |   lo   | True |          <IP_ADDRESS>           |    <IP_ADDRESS>    |  host  |         .         |
ci-info: |   lo   | True |           ::1/128            |        .        |  host  |         .         |
ci-info: +--------+------+------------------------------+-----------------+--------+-------------------+
ci-info: +++++++++++++++++++++++++++++Route IPv4 info++++++++++++++++++++++++++++++
ci-info: +-------+-------------+------------+-----------------+-----------+-------+
ci-info: | Route | Destination |  Gateway   |     Genmask     | Interface | Flags |
ci-info: +-------+-------------+------------+-----------------+-----------+-------+
ci-info: |   0   |   <IP_ADDRESS>   | <IP_ADDRESS> |     <IP_ADDRESS>     |    eth0   |   UG  |
ci-info: |   1   |   <IP_ADDRESS>  |  <IP_ADDRESS>  |    <IP_ADDRESS>    |   enp7s0  |   UG  |
ci-info: |   2   |   <IP_ADDRESS>  |  <IP_ADDRESS>   | <IP_ADDRESS> |   enp7s0  |   UH  |
ci-info: |   3   |  <IP_ADDRESS> |  <IP_ADDRESS>   | <IP_ADDRESS> |    eth0   |   UH  |
ci-info: +-------+-------------+------------+-----------------+-----------+-------+
ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: | Route | Destination | Gateway | Interface | Flags |
ci-info: +-------+-------------+---------+-----------+-------+
ci-info: |   0   |  fe80::/64  |    ::   |   enp7s0  |   U   |
ci-info: |   1   |  fe80::/64  |    ::   |    eth0   |   U   |
ci-info: |   3   |    local    |    ::   |   enp7s0  |   U   |
ci-info: |   4   |    local    |    ::   |    eth0   |   U   |
ci-info: |   5   |  multicast  |    ::   |   enp7s0  |   U   |
ci-info: |   6   |  multicast  |    ::   |    eth0   |   U   |
ci-info: +-------+-------------+---------+-----------+-------+
$ cloud-init modules --mode config
Cloud-init v. 23.3-8.1 running 'modules:config' at Wed, 13 Mar 2024 18:49:28 +0000. Up 1849.66 seconds.
$ cloud-init modules --mode final
Cloud-init v. 23.3-8.1 running 'modules:final' at Wed, 13 Mar 2024 18:49:35 +0000. Up 1856.29 seconds.
Cloud-init v. 23.3-8.1 finished at Wed, 13 Mar 2024 18:49:35 +0000. Datasource DataSourceHetzner.  Up 1856.38 seconds
$ cat /var/log/cloud-init.log
2024-03-13 18:48:56,409 - util.py[DEBUG]: Cloud-init v. 23.3-8.1 running 'init' at Wed, 13 Mar 2024 18:48:56 +0000. Up 1817.53 seconds.
2024-03-13 18:48:56,409 - main.py[DEBUG]: No kernel command line url found.
2024-03-13 18:48:56,409 - main.py[DEBUG]: Closing stdin.
2024-03-13 18:48:56,415 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud (recursive=False)
2024-03-13 18:48:56,421 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts (recursive=False)
2024-03-13 18:48:56,423 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts/per-instance (recursive=False)
2024-03-13 18:48:56,425 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts/per-once (recursive=False)
2024-03-13 18:48:56,426 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts/per-boot (recursive=False)
2024-03-13 18:48:56,427 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/scripts/vendor (recursive=False)
2024-03-13 18:48:56,428 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/seed (recursive=False)
2024-03-13 18:48:56,429 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances (recursive=False)
2024-03-13 18:48:56,429 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/handlers (recursive=False)
2024-03-13 18:48:56,430 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/sem (recursive=False)
2024-03-13 18:48:56,431 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data (recursive=False)
2024-03-13 18:48:56,431 - util.py[DEBUG]: Restoring selinux mode for /run/cloud-init/sem (recursive=False)
2024-03-13 18:48:56,432 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [640] 0 bytes
2024-03-13 18:48:56,433 - util.py[DEBUG]: Restoring selinux mode for /var/log/cloud-init.log (recursive=False)
2024-03-13 18:48:56,435 - util.py[DEBUG]: Restoring selinux mode for /var/log/cloud-init.log (recursive=False)
2024-03-13 18:48:56,436 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:0
2024-03-13 18:48:56,436 - subp.py[DEBUG]: Running command ['ip', '--json', 'addr'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,439 - subp.py[DEBUG]: Running command ['ip', '-o', 'route', 'list'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,441 - subp.py[DEBUG]: Running command ['ip', '--oneline', '-6', 'route', 'list', 'table', 'all'] with allowed return codes [0, 1] (shell=False, capture=True)
2024-03-13 18:48:56,443 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust]
2024-03-13 18:48:56,443 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False)
2024-03-13 18:48:56,443 - util.py[DEBUG]: Read 38374 bytes from /var/lib/cloud/instance/obj.pkl
2024-03-13 18:48:56,448 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False)
2024-03-13 18:48:56,448 - util.py[DEBUG]: Read 9 bytes from /run/cloud-init/.instance-id
2024-03-13 18:48:56,448 - stages.py[DEBUG]: restored from cache with run check: DataSourceHetzner
2024-03-13 18:48:56,449 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceHetzner
2024-03-13 18:48:56,449 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2024-03-13 18:48:56,449 - util.py[DEBUG]: Read 1088 bytes from /etc/cloud/cloud.cfg
2024-03-13 18:48:56,449 - util.py[DEBUG]: Attempting to load yaml from string of length 1088 with allowed root types (,)
2024-03-13 18:48:56,454 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2024-03-13 18:48:56,454 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2024-03-13 18:48:56,454 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,)
2024-03-13 18:48:56,456 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False)
2024-03-13 18:48:56,456 - util.py[DEBUG]: Read 35 bytes from /run/cloud-init/cloud.cfg
2024-03-13 18:48:56,456 - util.py[DEBUG]: Attempting to load yaml from string of length 35 with allowed root types (,)
2024-03-13 18:48:56,456 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,)
2024-03-13 18:48:56,456 - util.py[DEBUG]: loaded blob returned None, returning default.
2024-03-13 18:48:56,457 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2024-03-13 18:48:56,457 - util.py[DEBUG]: Read 8401 bytes from /var/lib/cloud/instance/cloud-config.txt
2024-03-13 18:48:56,457 - util.py[DEBUG]: Attempting to load yaml from string of length 8401 with allowed root types (,)
2024-03-13 18:48:56,465 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/vendor-cloud-config.txt (quiet=False)
2024-03-13 18:48:56,466 - util.py[DEBUG]: Read 4452 bytes from /var/lib/cloud/instance/vendor-cloud-config.txt
2024-03-13 18:48:56,466 - util.py[DEBUG]: Attempting to load yaml from string of length 4452 with allowed root types (,)
2024-03-13 18:48:56,469 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance
2024-03-13 18:48:56,469 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/44169089'
2024-03-13 18:48:56,470 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/handlers (recursive=False)
2024-03-13 18:48:56,471 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/scripts (recursive=False)
2024-03-13 18:48:56,472 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/sem (recursive=False)
2024-03-13 18:48:56,473 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/44169089/datasource (quiet=False)
2024-03-13 18:48:56,473 - util.py[DEBUG]: Read 37 bytes from /var/lib/cloud/instances/44169089/datasource
2024-03-13 18:48:56,473 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/datasource - wb: [644] 37 bytes
2024-03-13 18:48:56,474 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/datasource (recursive=False)
2024-03-13 18:48:56,476 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/datasource (recursive=False)
2024-03-13 18:48:56,476 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 37 bytes
2024-03-13 18:48:56,477 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data/previous-datasource (recursive=False)
2024-03-13 18:48:56,478 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data/previous-datasource (recursive=False)
2024-03-13 18:48:56,479 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False)
2024-03-13 18:48:56,479 - util.py[DEBUG]: Read 9 bytes from /var/lib/cloud/data/instance-id
2024-03-13 18:48:56,479 - stages.py[DEBUG]: previous iid found to be 44169089
2024-03-13 18:48:56,479 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 9 bytes
2024-03-13 18:48:56,480 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data/instance-id (recursive=False)
2024-03-13 18:48:56,481 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data/instance-id (recursive=False)
2024-03-13 18:48:56,482 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 9 bytes
2024-03-13 18:48:56,482 - util.py[DEBUG]: Restoring selinux mode for /run/cloud-init/.instance-id (recursive=False)
2024-03-13 18:48:56,483 - util.py[DEBUG]: Restoring selinux mode for /run/cloud-init/.instance-id (recursive=False)
2024-03-13 18:48:56,483 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 9 bytes
2024-03-13 18:48:56,484 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data/previous-instance-id (recursive=False)
2024-03-13 18:48:56,485 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/data/previous-instance-id (recursive=False)
2024-03-13 18:48:56,486 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 38374 bytes
2024-03-13 18:48:56,487 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/obj.pkl (recursive=False)
2024-03-13 18:48:56,489 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/obj.pkl (recursive=False)
2024-03-13 18:48:56,489 - main.py[DEBUG]: [net] init will now be targeting instance id: 44169089. new=False
2024-03-13 18:48:56,489 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2024-03-13 18:48:56,489 - util.py[DEBUG]: Read 1088 bytes from /etc/cloud/cloud.cfg
2024-03-13 18:48:56,489 - util.py[DEBUG]: Attempting to load yaml from string of length 1088 with allowed root types (,)
2024-03-13 18:48:56,492 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2024-03-13 18:48:56,492 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2024-03-13 18:48:56,492 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,)
2024-03-13 18:48:56,494 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False)
2024-03-13 18:48:56,494 - util.py[DEBUG]: Read 35 bytes from /run/cloud-init/cloud.cfg
2024-03-13 18:48:56,494 - util.py[DEBUG]: Attempting to load yaml from string of length 35 with allowed root types (,)
2024-03-13 18:48:56,494 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,)
2024-03-13 18:48:56,494 - util.py[DEBUG]: loaded blob returned None, returning default.
2024-03-13 18:48:56,494 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2024-03-13 18:48:56,494 - util.py[DEBUG]: Read 8401 bytes from /var/lib/cloud/instance/cloud-config.txt
2024-03-13 18:48:56,494 - util.py[DEBUG]: Attempting to load yaml from string of length 8401 with allowed root types (,)
2024-03-13 18:48:56,503 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/vendor-cloud-config.txt (quiet=False)
2024-03-13 18:48:56,503 - util.py[DEBUG]: Read 4452 bytes from /var/lib/cloud/instance/vendor-cloud-config.txt
2024-03-13 18:48:56,503 - util.py[DEBUG]: Attempting to load yaml from string of length 4452 with allowed root types (,)
2024-03-13 18:48:56,507 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2024-03-13 18:48:56,507 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2024-03-13 18:48:56,507 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2024-03-13 18:48:56,507 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2024-03-13 18:48:56,507 - util.py[DEBUG]: Reading from /sys/class/net/enp7s0/address (quiet=False)
2024-03-13 18:48:56,507 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/enp7s0/address
2024-03-13 18:48:56,508 - stages.py[DEBUG]: Allowed events: {: {}}
2024-03-13 18:48:56,508 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot
2024-03-13 18:48:56,508 - stages.py[DEBUG]: Allowed events: {: {}}
2024-03-13 18:48:56,508 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy
2024-03-13 18:48:56,508 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed
2024-03-13 18:48:56,508 - stages.py[DEBUG]: applying net config names for {'config': [{'mac_address': '96:00:03:13:96:b0', 'name': 'eth0', 'subnets': [{'ipv4': True, 'type': 'dhcp'}, {'address': '2a01:4f8:c012:8de1::1/64', 'dns_nameservers': ['2a01:4ff:ff00::add:2', '2a01:4ff:ff00::add:1'], 'gateway': 'fe80::1', 'ipv6': True, 'type': 'static'}], 'type': 'physical'}], 'version': 1}
2024-03-13 18:48:56,508 - stages.py[DEBUG]: Using distro class
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/eth0/device/device (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eth0/device/device
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/eth0/addr_assign_type (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/eth0/addr_assign_type
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/eth0/uevent (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 25 bytes from /sys/class/net/eth0/uevent
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/eth0/address (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/eth0/address
2024-03-13 18:48:56,509 - __init__.py[DEBUG]: ovs-vsctl not in PATH; not detecting Open vSwitch interfaces
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/eth0/device/device (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/eth0/device/device
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/lo/addr_assign_type (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/lo/addr_assign_type
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/lo/uevent (quiet=False)
2024-03-13 18:48:56,509 - util.py[DEBUG]: Read 23 bytes from /sys/class/net/lo/uevent
2024-03-13 18:48:56,509 - util.py[DEBUG]: Reading from /sys/class/net/lo/address (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/lo/address
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/lo/device/device (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/enp7s0/addr_assign_type (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 2 bytes from /sys/class/net/enp7s0/addr_assign_type
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/enp7s0/uevent (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 27 bytes from /sys/class/net/enp7s0/uevent
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/enp7s0/address (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 18 bytes from /sys/class/net/enp7s0/address
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/enp7s0/device/device (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 7 bytes from /sys/class/net/enp7s0/device/device
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/eth0/operstate (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/eth0/operstate
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/lo/operstate (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 8 bytes from /sys/class/net/lo/operstate
2024-03-13 18:48:56,510 - util.py[DEBUG]: Reading from /sys/class/net/enp7s0/operstate (quiet=False)
2024-03-13 18:48:56,510 - util.py[DEBUG]: Read 3 bytes from /sys/class/net/enp7s0/operstate
2024-03-13 18:48:56,510 - subp.py[DEBUG]: Running command ['ip', '-6', 'addr', 'show', 'permanent', 'scope', 'global'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,513 - subp.py[DEBUG]: Running command ['ip', '-4', 'addr', 'show'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,515 - __init__.py[DEBUG]: Detected interfaces {'eth0': {'downable': False, 'device_id': '0x0001', 'driver': 'virtio_net', 'mac': '96:00:03:13:96:b0', 'name': 'eth0', 'up': True}, 'lo': {'downable': False, 'device_id': None, 'driver': None, 'mac': '00:00:00:00:00:00', 'name': 'lo', 'up': True}, 'enp7s0': {'downable': False, 'device_id': '0x0001', 'driver': 'virtio_net', 'mac': '86:00:00:7c:0b:10', 'name': 'enp7s0', 'up': True}}
2024-03-13 18:48:56,515 - __init__.py[DEBUG]: no work necessary for renaming of [['96:00:03:13:96:b0', 'eth0', 'virtio_net', '0x0001']]
2024-03-13 18:48:56,515 - handlers.py[DEBUG]: start: init-network/setup-datasource: setting up datasource
2024-03-13 18:48:56,515 - handlers.py[DEBUG]: finish: init-network/setup-datasource: SUCCESS: setting up datasource
2024-03-13 18:48:56,516 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/user-data.txt - wb: [600] 2989 bytes
2024-03-13 18:48:56,517 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/user-data.txt (recursive=False)
2024-03-13 18:48:56,519 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/user-data.txt (recursive=False)
2024-03-13 18:48:56,521 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/user-data.txt.i - wb: [600] 9067 bytes
2024-03-13 18:48:56,522 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/user-data.txt.i (recursive=False)
2024-03-13 18:48:56,524 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/user-data.txt.i (recursive=False)
2024-03-13 18:48:56,524 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/vendor-data.txt - wb: [600] 4755 bytes
2024-03-13 18:48:56,526 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data.txt (recursive=False)
2024-03-13 18:48:56,527 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data.txt (recursive=False)
2024-03-13 18:48:56,528 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/vendor-data.txt.i - wb: [600] 4777 bytes
2024-03-13 18:48:56,529 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data.txt.i (recursive=False)
2024-03-13 18:48:56,531 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data.txt.i (recursive=False)
2024-03-13 18:48:56,531 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/vendor-data2.txt - wb: [600] 0 bytes
2024-03-13 18:48:56,532 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data2.txt (recursive=False)
2024-03-13 18:48:56,533 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data2.txt (recursive=False)
2024-03-13 18:48:56,534 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/vendor-data2.txt.i - wb: [600] 308 bytes
2024-03-13 18:48:56,535 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data2.txt.i (recursive=False)
2024-03-13 18:48:56,536 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-data2.txt.i (recursive=False)
2024-03-13 18:48:56,537 - cc_set_hostname.py[DEBUG]: Configuration option 'preserve_hostname' is set, not setting the hostname in module set_hostname
2024-03-13 18:48:56,537 - helpers.py[DEBUG]: consume_data already ran (freq=once-per-instance)
2024-03-13 18:48:56,537 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data
2024-03-13 18:48:56,537 - stages.py[DEBUG]: Added default handler for {'text/cloud-config', 'text/cloud-config-jsonp'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']]
2024-03-13 18:48:56,537 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']]
2024-03-13 18:48:56,537 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript-per-boot'} from ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']]
2024-03-13 18:48:56,537 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript-per-instance'} from ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']]
2024-03-13 18:48:56,537 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript-per-once'} from ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']]
2024-03-13 18:48:56,538 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']]
2024-03-13 18:48:56,538 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']]
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency always
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: {'Content-Disposition': 'attachment; filename="init.cfg"', 'Content-Transfer-Encoding': '7bit', 'Content-Type': 'text/cloud-config', 'Mime-Version': '1.0'}
2024-03-13 18:48:56,538 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, init.cfg, 3) with frequency always
2024-03-13 18:48:56,538 - util.py[DEBUG]: Attempting to load yaml from string of length 8730 with allowed root types (,)
2024-03-13 18:48:56,546 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
2024-03-13 18:48:56,546 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency always
2024-03-13 18:48:56,554 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/cloud-config.txt - wb: [600] 8401 bytes
2024-03-13 18:48:56,556 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/cloud-config.txt (recursive=False)
2024-03-13 18:48:56,557 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/cloud-config.txt (recursive=False)
2024-03-13 18:48:56,558 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,558 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,558 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,558 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,558 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,558 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency always
2024-03-13 18:48:56,559 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data
2024-03-13 18:48:56,559 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data
2024-03-13 18:48:56,559 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2024-03-13 18:48:56,559 - util.py[DEBUG]: Read 8401 bytes from /var/lib/cloud/instance/cloud-config.txt
2024-03-13 18:48:56,559 - util.py[DEBUG]: Attempting to load yaml from string of length 8401 with allowed root types (,)
2024-03-13 18:48:56,568 - stages.py[DEBUG]: vendordata will be consumed. disabled_handlers=None
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/cloud-config', 'text/cloud-config-jsonp'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']]
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']]
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript-per-boot'} from ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']]
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript-per-instance'} from ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']]
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript-per-once'} from ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']]
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']]
2024-03-13 18:48:56,568 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']]
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency always
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: {'Content-Type': 'text/cloud-config; charset="us-ascii"', 'MIME-Version': '1.0', 'Content-Transfer-Encoding': '7bit', 'Content-Disposition': 'attachment; filename="cloud-config"'}
2024-03-13 18:48:56,569 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, cloud-config, 3) with frequency always
2024-03-13 18:48:56,569 - util.py[DEBUG]: Attempting to load yaml from string of length 4200 with allowed root types (,)
2024-03-13 18:48:56,571 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])]
2024-03-13 18:48:56,572 - __init__.py[DEBUG]: {'Content-Type': 'text/cloud-boothook; charset="us-ascii"', 'MIME-Version': '1.0', 'Content-Transfer-Encoding': '7bit', 'Content-Disposition': 'attachment; filename="hc-boot-script"'}
2024-03-13 18:48:56,572 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (text/cloud-boothook, hc-boot-script, 2) with frequency always
2024-03-13 18:48:56,572 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/boothooks/hc-boot-script - wb: [700] 12 bytes
2024-03-13 18:48:56,573 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/boothooks/hc-boot-script (recursive=False)
2024-03-13 18:48:56,575 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/boothooks/hc-boot-script (recursive=False)
2024-03-13 18:48:56,575 - subp.py[DEBUG]: Running command ['/var/lib/cloud/instances/44169089/boothooks/hc-boot-script'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,578 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency always
2024-03-13 18:48:56,582 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/44169089/vendor-cloud-config.txt - wb: [600] 4452 bytes
2024-03-13 18:48:56,583 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-cloud-config.txt (recursive=False)
2024-03-13 18:48:56,585 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/vendor-cloud-config.txt (recursive=False)
2024-03-13 18:48:56,586 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,586 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-boot']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,586 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-instance']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,586 - __init__.py[DEBUG]: Calling handler ShellScriptByFreqPartHandler: [['text/x-shellscript-per-once']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,586 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency always
2024-03-13 18:48:56,586 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency always
2024-03-13 18:48:56,586 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data
2024-03-13 18:48:56,586 - handlers.py[DEBUG]: start: init-network/consume-vendor-data2: reading and applying vendor-data2
2024-03-13 18:48:56,586 - stages.py[DEBUG]: no vendordata2 from datasource
2024-03-13 18:48:56,586 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data2: SUCCESS: reading and applying vendor-data2
2024-03-13 18:48:56,586 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False)
2024-03-13 18:48:56,586 - util.py[DEBUG]: Read 1088 bytes from /etc/cloud/cloud.cfg
2024-03-13 18:48:56,587 - util.py[DEBUG]: Attempting to load yaml from string of length 1088 with allowed root types (,)
2024-03-13 18:48:56,589 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False)
2024-03-13 18:48:56,589 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg
2024-03-13 18:48:56,589 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,)
2024-03-13 18:48:56,591 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False)
2024-03-13 18:48:56,591 - util.py[DEBUG]: Read 35 bytes from /run/cloud-init/cloud.cfg
2024-03-13 18:48:56,591 - util.py[DEBUG]: Attempting to load yaml from string of length 35 with allowed root types (,)
2024-03-13 18:48:56,592 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,)
2024-03-13 18:48:56,592 - util.py[DEBUG]: loaded blob returned None, returning default.
2024-03-13 18:48:56,592 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2024-03-13 18:48:56,592 - util.py[DEBUG]: Read 8401 bytes from /var/lib/cloud/instance/cloud-config.txt
2024-03-13 18:48:56,592 - util.py[DEBUG]: Attempting to load yaml from string of length 8401 with allowed root types (,)
2024-03-13 18:48:56,601 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/vendor-cloud-config.txt (quiet=False)
2024-03-13 18:48:56,601 - util.py[DEBUG]: Read 4452 bytes from /var/lib/cloud/instance/vendor-cloud-config.txt
2024-03-13 18:48:56,601 - util.py[DEBUG]: Attempting to load yaml from string of length 4452 with allowed root types (,)
2024-03-13 18:48:56,605 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/combined-cloud-config.json (via temporary file /run/cloud-init/tmp8alj0ict) - w: [600] 15101 bytes/chars
2024-03-13 18:48:56,605 - util.py[DEBUG]: Reading from /run/cloud-init/instance-data-sensitive.json (quiet=False)
2024-03-13 18:48:56,605 - util.py[DEBUG]: Read 32180 bytes from /run/cloud-init/instance-data-sensitive.json
2024-03-13 18:48:56,606 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data-sensitive.json (via temporary file /run/cloud-init/tmpfp61s3sv) - w: [600] 32180 bytes/chars
2024-03-13 18:48:56,606 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,606 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,614 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False)
2024-03-13 18:48:56,614 - util.py[DEBUG]: Read 8401 bytes from /var/lib/cloud/instance/cloud-config.txt
2024-03-13 18:48:56,614 - util.py[DEBUG]: Attempting to load yaml from string of length 8401 with allowed root types (,)
2024-03-13 18:48:56,623 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/vendor-cloud-config.txt (quiet=False)
2024-03-13 18:48:56,623 - util.py[DEBUG]: Read 4452 bytes from /var/lib/cloud/instance/vendor-cloud-config.txt
2024-03-13 18:48:56,623 - util.py[DEBUG]: Attempting to load yaml from string of length 4452 with allowed root types (,)
2024-03-13 18:48:56,629 - handlers.py[DEBUG]: start: init-network/activate-datasource: activating datasource
2024-03-13 18:48:56,630 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 38374 bytes
2024-03-13 18:48:56,632 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/obj.pkl (recursive=False)
2024-03-13 18:48:56,635 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/obj.pkl (recursive=False)
2024-03-13 18:48:56,636 - handlers.py[DEBUG]: finish: init-network/activate-datasource: SUCCESS: activating datasource
2024-03-13 18:48:56,636 - main.py[DEBUG]: no di_report found in config.
2024-03-13 18:48:56,637 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,637 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,639 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,639 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,641 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,641 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,643 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,643 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,645 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,645 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,647 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,647 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,649 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,649 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,651 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,651 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,652 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,652 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,654 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,654 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,656 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,657 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,659 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:48:56,659 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:48:56,661 - stages.py[DEBUG]: Using distro class
2024-03-13 18:48:56,662 - modules.py[INFO]: Skipping modules 'bootcmd,disk_setup,rsyslog' because no applicable config is provided.
2024-03-13 18:48:56,663 - modules.py[DEBUG]: Running module migrator () with frequency always
2024-03-13 18:48:56,663 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always
2024-03-13 18:48:56,663 - helpers.py[DEBUG]: Running config-migrator using lock ()
2024-03-13 18:48:56,663 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names
2024-03-13 18:48:56,663 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully
2024-03-13 18:48:56,664 - modules.py[DEBUG]: Running module write-files () with frequency once-per-instance
2024-03-13 18:48:56,664 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance
2024-03-13 18:48:56,664 - helpers.py[DEBUG]: config-write-files already ran (freq=once-per-instance)
2024-03-13 18:48:56,664 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files previously ran
2024-03-13 18:48:56,664 - modules.py[DEBUG]: Running module growpart () with frequency always
2024-03-13 18:48:56,664 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always
2024-03-13 18:48:56,664 - helpers.py[DEBUG]: Running config-growpart using lock ()
2024-03-13 18:48:56,664 - subp.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,672 - util.py[DEBUG]: Reading from /proc/1864/mountinfo (quiet=False)
2024-03-13 18:48:56,672 - util.py[DEBUG]: Read 4050 bytes from /proc/1864/mountinfo
2024-03-13 18:48:56,672 - util.py[DEBUG]: Reading from /sys/class/block/sda2/partition (quiet=False)
2024-03-13 18:48:56,672 - util.py[DEBUG]: Read 2 bytes from /sys/class/block/sda2/partition
2024-03-13 18:48:56,672 - util.py[DEBUG]: Reading from /sys/devices/pci0000:00/0000:00:02.5/0000:06:00.0/virtio5/host0/target0:0:0/0:0:0:1/block/sda/dev (quiet=False)
2024-03-13 18:48:56,672 - util.py[DEBUG]: Read 4 bytes from /sys/devices/pci0000:00/0000:00:02.5/0000:06:00.0/virtio5/host0/target0:0:0/0:0:0:1/block/sda/dev
2024-03-13 18:48:56,673 - util.py[DEBUG]: Reading from /proc/1864/mountinfo (quiet=False)
2024-03-13 18:48:56,673 - util.py[DEBUG]: Read 4050 bytes from /proc/1864/mountinfo
2024-03-13 18:48:56,673 - util.py[DEBUG]: Reading from /proc/1864/mountinfo (quiet=False)
2024-03-13 18:48:56,673 - util.py[DEBUG]: Read 4050 bytes from /proc/1864/mountinfo
2024-03-13 18:48:56,674 - subp.py[DEBUG]: Running command ['growpart', '--dry-run', '/dev/sda', '2'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,722 - util.py[DEBUG]: resize_devices took 0.050 seconds
2024-03-13 18:48:56,722 - cc_growpart.py[DEBUG]: '/var' NOCHANGE: no change necessary (/dev/sda, 2)
2024-03-13 18:48:56,722 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully
2024-03-13 18:48:56,722 - modules.py[DEBUG]: Running module resizefs () with frequency always
2024-03-13 18:48:56,722 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always
2024-03-13 18:48:56,722 - helpers.py[DEBUG]: Running config-resizefs using lock ()
2024-03-13 18:48:56,722 - util.py[DEBUG]: Reading from /proc/1864/mountinfo (quiet=False)
2024-03-13 18:48:56,723 - util.py[DEBUG]: Read 4050 bytes from /proc/1864/mountinfo
2024-03-13 18:48:56,723 - cc_resizefs.py[DEBUG]: resize_info: dev=/dev/sda2 mnt_point=/ path=/
2024-03-13 18:48:56,723 - util.py[DEBUG]: Reading from /proc/1864/mountinfo (quiet=False)
2024-03-13 18:48:56,723 - util.py[DEBUG]: Read 4050 bytes from /proc/1864/mountinfo
2024-03-13 18:48:56,723 - subp.py[DEBUG]: Running command ['btrfs', '--version'] with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,725 - cc_resizefs.py[DEBUG]: Resizing / (btrfs) using btrfs filesystem resize --enqueue max //.snapshots
2024-03-13 18:48:56,725 - subp.py[DEBUG]: Running command ('btrfs', 'filesystem', 'resize', '--enqueue', 'max', '//.snapshots') with allowed return codes [0] (shell=False, capture=True)
2024-03-13 18:48:56,727 - util.py[DEBUG]: Resizing took 0.002 seconds
2024-03-13 18:48:56,727 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=btrfs, val=True)
2024-03-13 18:48:56,727 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully
2024-03-13 18:48:56,727 - modules.py[DEBUG]: Running module mounts () with frequency once-per-instance
2024-03-13 18:48:56,727 - handlers.py[DEBUG]: start: init-network/config-mounts: running config-mounts with frequency once-per-instance
2024-03-13 18:48:56,727 - helpers.py[DEBUG]: config-mounts already ran (freq=once-per-instance)
2024-03-13 18:48:56,727 - handlers.py[DEBUG]: finish: init-network/config-mounts: SUCCESS: config-mounts previously ran
2024-03-13 18:48:56,727 - modules.py[DEBUG]: Running module set_hostname () with frequency once-per-instance
2024-03-13 18:48:56,727 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance
2024-03-13 18:48:56,728 - helpers.py[DEBUG]: config-set_hostname already ran (freq=once-per-instance)
2024-03-13 18:48:56,728 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname previously ran
2024-03-13 18:48:56,728 - modules.py[DEBUG]: Running module update_hostname () with frequency always
2024-03-13 18:48:56,728 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always
2024-03-13 18:48:56,728 - helpers.py[DEBUG]: Running config-update_hostname using lock ()
2024-03-13 18:48:56,728 - cc_update_hostname.py[DEBUG]: Configuration option 'preserve_hostname' is set, not updating the hostname in module update_hostname
2024-03-13 18:48:56,728 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully
2024-03-13 18:48:56,728 - modules.py[DEBUG]: Running module update_etc_hosts () with frequency always
2024-03-13 18:48:56,728 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always
2024-03-13 18:48:56,728 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock ()
2024-03-13 18:48:56,728 - util.py[DEBUG]: Reading from /etc/cloud/templates/hosts.suse.tmpl (quiet=False)
2024-03-13 18:48:56,728 - util.py[DEBUG]: Read 1067 bytes from /etc/cloud/templates/hosts.suse.tmpl
2024-03-13 18:48:56,728 - templater.py[DEBUG]: Rendering content of '/etc/cloud/templates/hosts.suse.tmpl' using renderer jinja
2024-03-13 18:48:56,732 - util.py[DEBUG]: Writing to /etc/hosts - wb: [644] 911 bytes
2024-03-13 18:48:56,735 - util.py[DEBUG]: Restoring selinux mode for /etc/hosts (recursive=False)
2024-03-13 18:48:56,737 - util.py[DEBUG]: Restoring selinux mode for /etc/hosts (recursive=False)
2024-03-13 18:48:56,737 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully
2024-03-13 18:48:56,738 - modules.py[DEBUG]: Running module users-groups () with frequency once-per-instance
2024-03-13 18:48:56,738 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance
2024-03-13 18:48:56,738 - helpers.py[DEBUG]: config-users-groups already ran (freq=once-per-instance)
2024-03-13 18:48:56,738 - handlers.py[DEBUG]: finish: init-network/config-users-groups: SUCCESS: config-users-groups previously ran
2024-03-13 18:48:56,738 - modules.py[DEBUG]: Running module ssh () with frequency once-per-instance
2024-03-13 18:48:56,738 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance
2024-03-13 18:48:56,738 - helpers.py[DEBUG]: config-ssh already ran (freq=once-per-instance)
2024-03-13 18:48:56,738 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh previously ran
2024-03-13 18:48:56,738 - main.py[DEBUG]: Ran 10 modules with 0 failures
2024-03-13 18:48:56,739 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmps7csl5fa) - w: [644] 597 bytes/chars
2024-03-13 18:48:56,739 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2024-03-13 18:48:56,739 - util.py[DEBUG]: Read 16 bytes from /proc/uptime
2024-03-13 18:48:56,739 - util.py[DEBUG]: cloud-init mode 'init' took 0.440 seconds (0.44)
2024-03-13 18:48:56,739 - handlers.py[DEBUG]: finish: init-network: SUCCESS: searching for network datasources
2024-03-13 18:49:28,570 - util.py[DEBUG]: Cloud-init v. 23.3-8.1 running 'modules:config' at Wed, 13 Mar 2024 18:49:28 +0000. Up 1849.66 seconds.
2024-03-13 18:49:28,571 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,572 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,575 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,575 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,578 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,578 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,580 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,580 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,583 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,583 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,585 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,585 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,586 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,586 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,588 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:28,588 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:28,589 - stages.py[DEBUG]: Using distro class
2024-03-13 18:49:28,590 - modules.py[INFO]: Skipping modules 'timezone,resolv_conf,ntp,zypper_add_repo,disable-ec2-metadata' because no applicable config is provided.
2024-03-13 18:49:28,590 - modules.py[DEBUG]: Running module locale () with frequency once-per-instance
2024-03-13 18:49:28,591 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance
2024-03-13 18:49:28,591 - helpers.py[DEBUG]: config-locale already ran (freq=once-per-instance)
2024-03-13 18:49:28,591 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale previously ran
2024-03-13 18:49:28,591 - modules.py[DEBUG]: Running module set-passwords () with frequency once-per-instance
2024-03-13 18:49:28,591 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance
2024-03-13 18:49:28,591 - helpers.py[DEBUG]: config-set-passwords already ran (freq=once-per-instance)
2024-03-13 18:49:28,591 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords previously ran
2024-03-13 18:49:28,591 - modules.py[DEBUG]: Running module runcmd () with frequency once-per-instance
2024-03-13 18:49:28,592 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance
2024-03-13 18:49:28,592 - helpers.py[DEBUG]: config-runcmd already ran (freq=once-per-instance)
2024-03-13 18:49:28,592 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd previously ran
2024-03-13 18:49:28,592 - main.py[DEBUG]: Ran 3 modules with 0 failures
2024-03-13 18:49:28,592 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpq2a2w7fc) - w: [644] 597 bytes/chars
2024-03-13 18:49:28,592 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2024-03-13 18:49:28,592 - util.py[DEBUG]: Read 16 bytes from /proc/uptime
2024-03-13 18:49:28,592 - util.py[DEBUG]: cloud-init mode 'modules' took 0.164 seconds (0.16)
2024-03-13 18:49:28,593 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config
2024-03-13 18:49:35,204 - util.py[DEBUG]: Cloud-init v. 23.3-8.1 running 'modules:final' at Wed, 13 Mar 2024 18:49:35 +0000. Up 1856.29 seconds.
2024-03-13 18:49:35,206 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,206 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,209 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,209 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,211 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,211 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,212 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,213 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,214 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,214 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,215 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,215 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,217 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,217 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,218 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,219 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,220 - util.py[DEBUG]: Reading from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json (quiet=False)
2024-03-13 18:49:35,220 - util.py[DEBUG]: Read 136743 bytes from /usr/lib/python3.11/site-packages/cloudinit/config/schemas/schema-cloud-config-v1.json
2024-03-13 18:49:35,222 - stages.py[DEBUG]: Using distro class
2024-03-13 18:49:35,223 - modules.py[INFO]: Skipping modules 'salt-minion,phone-home,power-state-change' because no applicable config is provided.
2024-03-13 18:49:35,223 - modules.py[DEBUG]: Running module scripts-vendor () with frequency once-per-instance
2024-03-13 18:49:35,224 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance
2024-03-13 18:49:35,224 - helpers.py[DEBUG]: config-scripts-vendor already ran (freq=once-per-instance)
2024-03-13 18:49:35,224 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor previously ran
2024-03-13 18:49:35,224 - modules.py[DEBUG]: Running module scripts-per-once () with frequency once
2024-03-13 18:49:35,224 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once
2024-03-13 18:49:35,224 - helpers.py[DEBUG]: config-scripts-per-once already ran (freq=once)
2024-03-13 18:49:35,224 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once previously ran
2024-03-13 18:49:35,224 - modules.py[DEBUG]: Running module scripts-per-boot () with frequency always
2024-03-13 18:49:35,225 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always
2024-03-13 18:49:35,225 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock ()
2024-03-13 18:49:35,225 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully
2024-03-13 18:49:35,225 - modules.py[DEBUG]: Running module scripts-per-instance () with frequency once-per-instance
2024-03-13 18:49:35,225 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance
2024-03-13 18:49:35,225 - helpers.py[DEBUG]: config-scripts-per-instance already ran (freq=once-per-instance)
2024-03-13 18:49:35,225 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance previously ran
2024-03-13 18:49:35,225 - modules.py[DEBUG]: Running module scripts-user () with frequency once-per-instance
2024-03-13 18:49:35,225 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance
2024-03-13 18:49:35,225 - helpers.py[DEBUG]: config-scripts-user already ran (freq=once-per-instance)
2024-03-13 18:49:35,225 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user previously ran
2024-03-13 18:49:35,225 - modules.py[DEBUG]: Running module final-message () with frequency always
2024-03-13 18:49:35,226 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always
2024-03-13 18:49:35,226 - helpers.py[DEBUG]: Running config-final-message using lock ()
2024-03-13 18:49:35,226 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2024-03-13 18:49:35,226 - util.py[DEBUG]: Read 16 bytes from /proc/uptime
2024-03-13 18:49:35,230 - util.py[DEBUG]: Cloud-init v. 23.3-8.1 finished at Wed, 13 Mar 2024 18:49:35 +0000. Datasource DataSourceHetzner.  Up 1856.38 seconds
2024-03-13 18:49:35,230 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [644] 56 bytes
2024-03-13 18:49:35,234 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/boot-finished (recursive=False)
2024-03-13 18:49:35,240 - util.py[DEBUG]: Restoring selinux mode for /var/lib/cloud/instances/44169089/boot-finished (recursive=False)
2024-03-13 18:49:35,241 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully
2024-03-13 18:49:35,241 - main.py[DEBUG]: Ran 6 modules with 0 failures
2024-03-13 18:49:35,241 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpwv81szl0) - w: [644] 597 bytes/chars
2024-03-13 18:49:35,242 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/result.json (via temporary file /var/lib/cloud/data/tmpltao_bck) - w: [644] 68 bytes/chars
2024-03-13 18:49:35,242 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json'
2024-03-13 18:49:35,242 - util.py[DEBUG]: Reading from /proc/uptime (quiet=False)
2024-03-13 18:49:35,242 - util.py[DEBUG]: Read 16 bytes from /proc/uptime
2024-03-13 18:49:35,242 - util.py[DEBUG]: cloud-init mode 'modules' took 0.177 seconds (0.17)
2024-03-13 18:49:35,242 - handlers.py[DEBUG]: finish: modules-final: SUCCESS: running modules for final
$ cat /var/lib/cloud/instance/cloud-config.txt
#cloud-config
from 1 files
init.cfg

debug: true
growpart:
devices:
- /var
hostname: k3s-control-plane-fsn1-xnr
preserve_hostname: true
runcmd:

btrfs
filesystem
resize
max
/var

checkmodule
-M
-m
-o
/root/kube_hetzner_selinux.mod
/root/kube_hetzner_selinux.te

semodule_package
-o
/root/kube_hetzner_selinux.pp
-m
/root/kube_hetzner_selinux.mod

semodule
-i
/root/kube_hetzner_selinux.pp

setsebool
-P
virt_use_samba
'1'

setsebool
-P
domain_kernel_load_modules
'1'

systemctl
disable
--now
rebootmgr.service

systemctl
reload
NetworkManager

sed
-i
s/#SystemMaxUse=/SystemMaxUse=3G/g
/etc/systemd/journald.conf

sed
-i
s/#MaxRetentionSec=/MaxRetentionSec=1week/g
/etc/systemd/journald.conf

sed
-i
s/NUMBER_LIMIT="2-10"/NUMBER_LIMIT="4"/g
/etc/snapper/configs/root

sed
-i
s/NUMBER_LIMIT_IMPORTANT="4-10"/NUMBER_LIMIT_IMPORTANT="3"/g
/etc/snapper/configs/root

chmod
+x
/etc/cloud/rename_interface.sh

systemctl
restart
sshd

systemctl
restart
NetworkManager

systemctl
status
NetworkManager

ip
route
add
default
via
<IP_ADDRESS>
dev
eth0

truncate
-s
'0'
/var/log/audit/audit.log
ssh_authorized_keys:

ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIMa5Es7358E4u5u5cVGZ/6E/uOU6A13QtZZZZjmlfIBd
<EMAIL_ADDRESS>write_files:

content: "#!/bin/bash\nset -euo pipefail\n\nsleep 11\n\nINTERFACE=$(ip link show
\ | awk '/^3:/{print $2}' | sed 's/://g')\nMAC=$(cat /sys/class/net/$INTERFACE/address)\n
\ncat < /etc/udev/rules.d/70-persistent-net.rules\nSUBSYSTEM=="net"
, ACTION=="add", DRIVERS=="?*", ATTR{address}=="$MAC", NAME="eth1"
\nEOF\n\nip link set $INTERFACE down\nip link set $INTERFACE name eth1\nip
\ link set eth1 up\n\neth0_connection=$(nmcli -g GENERAL.CONNECTION device
\ show eth0)\nnmcli connection modify "$eth0_connection" \\n  con-name
\ eth0 \\n  connection.interface-name eth0\n\neth1_connection=$(nmcli -g
\ GENERAL.CONNECTION device show eth1)\nnmcli connection modify "$eth1_connection"
\ \\n  con-name eth1 \\n  connection.interface-name eth1\n\nsystemctl restart
\ NetworkManager\n"
path: /etc/cloud/rename_interface.sh
permissions: '0744'

content: 'Port 22
PasswordAuthentication no

X11Forwarding no

MaxAuthTries 2

AllowTcpForwarding no

AllowAgentForwarding no

AuthorizedKeysFile .ssh/authorized_keys

'

path: /etc/ssh/sshd_config.d/kube-hetzner.conf

content: 'REBOOT_METHOD=kured
'

path: /etc/transactional-update.conf

content: '[rancher-k3s-common-stable]
name=Rancher K3s Common (stable)

baseurl=https://rpm.rancher.io/k3s/stable/common/microos/noarch

enabled=1

gpgcheck=1

repo_gpgcheck=0

gpgkey=https://rpm.rancher.io/public.key

'

path: /etc/zypp/repos.d/rancher-k3s-common.repo

content: "module kube_hetzner_selinux 1.0;\n\nrequire {\n  type kernel_t, bin_t,
\ kernel_generic_helper_t, iscsid_t, iscsid_exec_t, var_run_t,\n  init_t,
\ unlabeled_t, systemd_logind_t, systemd_hostnamed_t, container_t,\n  cert_t,
\ container_var_lib_t, etc_t, usr_t, container_file_t, container_log_t,\n
\  container_share_t, container_runtime_exec_t, container_runtime_t, var_log_t,
\ proc_t, io_uring_t, fuse_device_t, http_port_t;\n  class key { read view
\ };\n  class file { open read execute execute_no_trans create link lock rename
\ write append setattr unlink getattr watch };\n  class sock_file { watch
\ write create unlink };\n  class unix_dgram_socket create;\n  class unix_stream_socket
\ { connectto read write };\n  class dir { add_name create getattr link lock
\ read rename remove_name reparent rmdir setattr unlink search write watch
\ };\n  class lnk_file { read create };\n  class system module_request;\n
\  class filesystem associate;\n  class bpf map_create;\n  class io_uring
\ sqpoll;\n  class anon_inode create;\n  class tcp_socket name_connect;\n
\  class chr_file { open read write };\n}\n\n#============= kernel_generic_helper_t
\ ==============\nallow kernel_generic_helper_t bin_t:file execute_no_trans;\n
allow kernel_generic_helper_t kernel_t:key { read view };\nallow kernel_generic_helper_t
\ self:unix_dgram_socket create;\n\n#============= iscsid_t ==============\n
allow iscsid_t iscsid_exec_t:file execute;\nallow iscsid_t var_run_t:sock_file
\ write;\nallow iscsid_t var_run_t:unix_stream_socket connectto;\n\n#=============
\ init_t ==============\nallow init_t unlabeled_t:dir { add_name remove_name
\ rmdir };\nallow init_t unlabeled_t:lnk_file create;\nallow init_t container_t:file
\ { open read };\nallow init_t container_file_t:file { execute execute_no_trans
\ };\nallow init_t fuse_device_t:chr_file { open read write };\nallow init_t
\ http_port_t:tcp_socket name_connect;\n\n#============= systemd_logind_t
\ ==============\nallow systemd_logind_t unlabeled_t:dir search;\n\n#=============
\ systemd_hostnamed_t ==============\nallow systemd_hostnamed_t unlabeled_t:dir
\ search;\n\n#============= container_t ==============\n# Basic file and directory
\ operations for specific types\nallow container_t cert_t:dir read;\nallow
\ container_t cert_t:lnk_file read;\nallow container_t cert_t:file { read
\ open };\nallow container_t container_var_lib_t:file { create open read write
\ rename lock };\nallow container_t etc_t:dir { add_name remove_name write
\ create setattr watch };\nallow container_t etc_t:file { create setattr unlink
\ write };\nallow container_t etc_t:sock_file { create unlink };\nallow container_t
\ usr_t:dir { add_name create getattr link lock read rename remove_name reparent
\ rmdir setattr unlink search write };\nallow container_t usr_t:file { append
\ create execute getattr link lock read rename setattr unlink write };\n\n
# Additional rules for container_t\nallow container_t container_file_t:file
\ { open read write append getattr setattr };\nallow container_t container_file_t:sock_file
\ watch;\nallow container_t container_log_t:file { open read write append
\ getattr setattr };\nallow container_t container_share_t:dir { read write
\ add_name remove_name };\nallow container_t container_share_t:file { read
\ write create unlink };\nallow container_t container_runtime_exec_t:file
\ { read execute execute_no_trans open };\nallow container_t container_runtime_t:unix_stream_socket
\ { connectto read write };\nallow container_t kernel_t:system module_request;\n
allow container_t container_log_t:dir { read watch };\nallow container_t container_log_t:file
\ { open read watch };\nallow container_t container_log_t:lnk_file read;\n
allow container_t var_log_t:dir { add_name write };\nallow container_t var_log_t:file
\ { create lock open read setattr write };\nallow container_t var_log_t:dir
\ remove_name;\nallow container_t var_log_t:file unlink;\nallow container_t
\ proc_t:filesystem associate;\nallow container_t self:bpf map_create;\nallow
\ container_t io_uring_t:anon_inode create;\nallow container_t self:io_uring
\ sqpoll;\nallow container_t io_uring_t:anon_inode { create map read write
\ };\n"
path: /root/kube_hetzner_selinux.te

content: IA==
encoding: base64
path: /etc/rancher/k3s/registries.yaml

content: '[main]
dns=none

'

path: /etc/NetworkManager/conf.d/dns.conf

content: 'nameserver <IP_ADDRESS>
nameserver <IP_ADDRESS>

nameserver 2606:4700:4700::1111

'

path: /etc/resolv.conf
permissions: '0644'
...

Note how the log has no mention of any write files tasks.

Besides, isn't the cloud-config passed via [`user_data`](https://registry.terraform.io/providers/hetznercloud/hcloud/latest/docs/resources/server#user_data) and isn't that immutable after instance creation anyhow? I haven't observed any changes to the `hcloud_server` resource from that attribute changing, there's no way to update in the Hetzner console and both the wording on the provider docs and in things like https://community.hetzner.com/tutorials/basic-cloud-config suggest to me it's only possible to set once on creation. So even if rerunning cloud-init would write the files, I don't think it would be enough to just rerun it.

Okay, after some searching, going by https://stackoverflow.com/a/71152408/2199687 what could work I guess is manually updating /var/lib/cloud/instance/cloud-config.txt via a file provisioner and then running cloud-init single --name write-files --frequency always, cloud-init single --name scripts-user --frequency always (possibly more)

Okay, after some searching, going by https://stackoverflow.com/a/71152408/2199687 what could work I guess is manually updating /var/lib/cloud/instance/cloud-config.txt via a file provisioner and then running cloud-init single --name write-files --frequency always, cloud-init single --name scripts-user --frequency always (possibly more)

@jhass Please try it if you can, and PR most welcome!
Otherwise, just to get SElinux going try such a shell script https://chat.openai.com/share/c2ace355-82ce-4df4-a5b4-590e81443cea. But make sure to replace by the latest version of the policy from locals.tf.

hi @mysticaltech
not sure if something really weird is going on, since my .te file is huge. But I'll post it anyway.

module kube_hetzner_selinux 1.0;
require {
type kernel_t, bin_t, kernel_generic_helper_t, iscsid_t, iscsid_exec_t, var_run_t,
init_t, unlabeled_t, systemd_logind_t, systemd_hostnamed_t, container_t,
cert_t, container_var_lib_t, etc_t, usr_t, container_file_t, container_log_t,
container_share_t, container_runtime_exec_t, container_runtime_t, var_log_t, proc_t, io_uring_t, fuse_device_t, http_port_t,
container_var_run_t;
class key { read view };
class file { open read execute execute_no_trans create link lock rename write append setattr unlink getattr watch };
class sock_file { watch write create unlink };
class unix_dgram_socket create;
class unix_stream_socket { connectto read write };
class dir { add_name create getattr link lock read rename remove_name reparent rmdir setattr unlink search write watch };
class lnk_file { read create };
class system module_request;
class filesystem associate;
class bpf map_create;
class io_uring sqpoll;
class anon_inode { create map read write };
class tcp_socket name_connect;
class chr_file { open read write };
}
#============= kernel_generic_helper_t ==============
allow kernel_generic_helper_t bin_t:file execute_no_trans;
allow kernel_generic_helper_t kernel_t:key { read view };
allow kernel_generic_helper_t self:unix_dgram_socket create;
#============= iscsid_t ==============
allow iscsid_t iscsid_exec_t:file execute;
allow iscsid_t var_run_t:sock_file write;
allow iscsid_t var_run_t:unix_stream_socket connectto;
#============= init_t ==============
allow init_t unlabeled_t:dir { add_name remove_name rmdir };
allow init_t unlabeled_t:lnk_file create;
allow init_t container_t:file { open read };
allow init_t container_file_t:file { execute execute_no_trans };
allow init_t fuse_device_t:chr_file { open read write };
allow init_t http_port_t:tcp_socket name_connect;
#============= systemd_logind_t ==============
allow systemd_logind_t unlabeled_t:dir search;
#============= systemd_hostnamed_t ==============
allow systemd_hostnamed_t unlabeled_t:dir search;
#============= container_t ==============
Basic file and directory operations for specific types
allow container_t cert_t:dir read;
allow container_t cert_t:lnk_file read;
allow container_t cert_t:file { read open };
allow container_t container_var_lib_t:file { create open read write rename lock };
allow container_t etc_t:dir { add_name remove_name write create setattr watch };
allow container_t etc_t:file { create setattr unlink write };
allow container_t etc_t:sock_file { create unlink };
allow container_t usr_t:dir { add_name create getattr link lock read rename remove_name reparent rmdir setattr unlink search write };
allow container_t usr_t:file { append create execute getattr link lock read rename setattr unlink write };
Additional rules for container_t
allow container_t container_file_t:file { open read write append getattr setattr };
allow container_t container_file_t:sock_file watch;
allow container_t container_log_t:file { open read write append getattr setattr };
allow container_t container_log_t:dir read;
allow container_t container_share_t:dir { read write add_name remove_name };
allow container_t container_share_t:file { read write create unlink };
allow container_t container_runtime_exec_t:file { read execute execute_no_trans open };
allow container_t container_runtime_t:unix_stream_socket { connectto read write };
allow container_t kernel_t:system module_request;
allow container_t container_log_t:dir { read watch };
allow container_t container_log_t:file { open read watch };
allow container_t container_log_t:lnk_file read;
allow container_t var_log_t:dir { add_name write };
allow container_t var_log_t:file { create lock open read setattr write };
allow container_t var_log_t:dir remove_name;
allow container_t var_log_t:file unlink;
allow container_t proc_t:filesystem associate;
allow container_t self:bpf map_create;
allow container_t self:io_uring sqpoll;
allow container_t io_uring_t:anon_inode { create map read write };
allow container_t container_var_run_t:dir { add_name remove_name write };
allow container_t container_var_run_t:file { create open read rename unlink write };

Here's what I noticed:

running an arm64 cluster for 2-3 weeks without any issues
without touching the cluster, suddenly some nodes loose network connection and cluster becomes completely broken

For broken nodes:

no ping  working
can only access broken nodes through other working nodes (via private network ssh)
from within broken nodes, i cannot even ping google.de
audit yields huge list of rules

do you have any idea what could have gone wrong here?

@maaft Apparently sometimes node automatic upgrade breaks the networking changes, we are currently investigating. Please try to see if you can reapply cloud-init manually, maybe it's saved on the machine. Or look at the code to see what it does and do thst manually. If it works for you, we will be able to create a boot script that does that automatically.

@maaft Apparently sometimes node automatic upgrade breaks the networking changes, we are currently investigating. Please try to see if you can reapply cloud-init manually, maybe it's saved on the machine. Or look at the code to see what it does and do thst manually. If it works for you, we will be able to create a boot script that does that automatically.

okay, thanks - will try it later.
What are the current workarounds? Disable automatic upgrades?

@maaft Thanks for confirming and trying it out. With that I can work on a permanent fix. Will do ASAP 🙏
@kube-hetzner/maintainers FYI

And yes, turning off upgrade would solve that, but not necessary, will create a fix. Probably a systemctl shell that run after each reboot to make sure everything is kosher.

Forcing a re-run of cloud-init requires commands like cloud-init single --frequency always --name <> with the name value set to write_files, runcmd etc.
However that seems rather brittle because 1. cloud-init files are never updated after node creation (changing user_data has no effect after node creation) and 2. if they were to be updated manually with a provisioner one might forget to add or remove a module from the boot command as the config is changed.
I guess one approach to workaround this somewhat is to reduce the cloud init config to the bare minimum of just invoking a script that does the setup and have that script reprovisioned. That should also help with updating the SELinux rules I guess.
Nonetheless the automatic "atomic" updates somehow rolling back the system prior the first cloud-init run (without rerunning cloud-init since the state for that is in a stateful part of the system) seems like a deeper issue that shouldn't be just hacked around :/ I've had to completely remove and re-add nodes due to this because even re-initializing the node through a combination of forced cloud-init reruns and manually tainting terraform state since I couldn't recover the kubelet's node key in that state sometimes.

@mysticaltech Hey friend! Did you have time to investigate this issue? Anything I can do to help?

@maaft  Today will put my head on this, it will be fixed. Keep you posted 🙏

Forcing a re-run of cloud-init requires commands like cloud-init single --frequency always --name <> with the name value set to write_files, runcmd etc.
However that seems rather brittle because 1. cloud-init files are never updated after node creation (changing user_data has no effect after node creation) and 2. if they were to be updated manually with a provisioner one might forget to add or remove a module from the boot command as the config is changed.
I guess one approach to workaround this somewhat is to reduce the cloud init config to the bare minimum of just invoking a script that does the setup and have that script reprovisioned. That should also help with updating the SELinux rules I guess.
Nonetheless the automatic "atomic" updates somehow rolling back the system prior the first cloud-init run (without rerunning cloud-init since the state for that is in a stateful part of the system) seems like a deeper issue that shouldn't be just hacked around :/ I've had to completely remove and re-add nodes due to this because even re-initializing the node through a combination of forced cloud-init reruns and manually tainting terraform state didn't help since I couldn't recover the kubelet's node key in that state sometimes.

@jhass Thanks for sharing this. The nodes are pretty stateless and unchanging apart from the updates, there is indeed a deeper bug in microos, but it will get fixed probably (someone was asked to signal it and I tagged the project lead too), but anyways even if not, running cloudinit after each reboot is a quick "backup" work-around, even though it does not pull the new user-data, this is actually not needed as it pretty much does not change.

there is indeed a deeper bug in microos

Are you sure it is MicroOS? Because my old clusters (provisioned with a version of this repo ~ 1.5 years ago, continue to run and upgrade their OS flawlessly.
If the reason is really a bug in MicroOS, all my clusters would be non-functional by now

@maaft If your system is HA, adding --force-reboot to kured_options will protect you from this. As identified by @andi0b, the potential issue are caused by systems that fail to drain and reboot for more than 20 days, after which the old snapshot is gone.

@mysticaltech
I experienced similar problem on one of the nodes. After the OS upgrade all the pods on this node lost their Internet connection (except Cilium). It's network was configured to use floating IP, but this IP was assigned to a different node. After removing floating IP config and rebooting the node, network connectivity was restored.
Kube-Hetzner version used:  2.0.2
Network plugin: cilium, strict replacement of kube-proxy
Commands for setting up floating IP:
      CONN_UUID="$(nmcli connection show | grep eth0 | awk -F '  ' '{print $1}')"
      nmcli connection modify "$CONN_UUID" +ipv4.address <FLOATING_IP_ADDRESS>/32
      nmcli connection modify "$CONN_UUID" connection.autoconnect yes
      touch /var/run/reboot-required

Commands for removing floating IP config:
      CONN_UUID="$(nmcli connection show | grep eth0 | awk -F '  ' '{print $1}')"
      nmcli connection modify "$CONN_UUID" -ipv4.address <FLOATING_IP_ADDRESS>/32

Found some more:
module my_custom_policy 1.0;

require {
	type shell_exec_t;
	type systemd_generic_generator_t;
	type snapperd_data_t;
	type bin_t;
	type systemd_fstab_generator_t;
	type udev_var_run_t;
	type passwd_file_t;
	class file { execute execute_no_trans getattr open read };
	class dir { getattr search };
}

#============= systemd_fstab_generator_t ==============
allow systemd_fstab_generator_t snapperd_data_t:dir getattr;

#============= systemd_generic_generator_t ==============
allow systemd_generic_generator_t bin_t:file { execute execute_no_trans };
allow systemd_generic_generator_t passwd_file_t:file { getattr open read };
allow systemd_generic_generator_t shell_exec_t:file execute;
allow systemd_generic_generator_t udev_var_run_t:dir { getattr search };

New ones, required by SigNoz to mount hostfs (/) to read the host metrics:
module my_custom_policy 1.0;

require {
        type fixed_disk_device_t;
        type container_t;
        type removable_device_t;
        class blk_file getattr;
}

#============= container_t ==============

#!!!! This avc can be allowed using the boolean 'container_use_devices'
allow container_t fixed_disk_device_t:blk_file getattr;

#!!!! This avc can be allowed using the boolean 'container_use_devices'
allow container_t removable_device_t:blk_file getattr;

I believe we should consider disabling SELinux by default, at least for agent nodes. I believe the whole point is to make it secure for one owns cluster, not to include a lot of default allowences since that defeats the purpose. This could be a topic of dicussion for the v3, I plan to open a dicussion soon on this repo so we can talk about defaults and behaviors since the rewrite is going very well and is nearing completion.

@aleksasiriski You have a point, will run it through o1, see what it says ☺

New ones for juicefs:
#============= container_t ==============
allow container_t container_var_lib_t:sock_file write;

And another one:
module my_custom_policy 1.0;

require {
	type container_var_run_t;
	type container_t;
	class dir write;
}

#============= container_t ==============
allow container_t container_var_run_t:dir write;

This time for isito CNI to work.

Have you disabled all three of the provided CNIs to have Istio or is it running alongside one of the supported ones?