search

Azure / custom-script-extension-linux

Azure Custom Script Virtual Machine Extension :new:
Apache License 2.0
108 stars 33 forks source link

Custom Extension Occasionally Failing on apt update #210

Open matferrari-msft opened 1 year ago

matferrari-msft commented 1 year ago

I believe that this issue might be caused by a race condition with the cloud init script where the package source is switched to Azure's archive.

I have the following script:

#!/bin/bash

set -euo pipefail

# Install nginx
apt update
apt install -y nginx

That is invoked by the following bicep:

resource bootstrapNginx 'Microsoft.Compute/virtualMachines/extensions@2022-11-01' = {
  parent: proxy
  name: 'bootstrap-nginx'
  location: location
  tags: tags
  properties: {
    publisher: 'Microsoft.Azure.Extensions'
    type: 'CustomScript'
    typeHandlerVersion: '2.1'
    autoUpgradeMinorVersion: true
    settings: {
      script: base64(loadTextContent('../assets/bootstrap-nginx.sh'))
    }
    protectedSettings: {}
  }
}

50% of the time, the script executes successfully, but 50% of the time it fails with the following output:

[stdout]
Get:1 http://security.ubuntu.com/ubuntu focal-security InRelease [114 kB]\nHit:2 http://archive.ubuntu.com/ubuntu focal InRelease\nGet:3 http://archive.ubuntu.com/ubuntu focal-updates InRelease [114 kB]\nGet:4 http://archive.ubuntu.com/ubuntu focal-backports InRelease [108 kB]\nGet:5 http://security.ubuntu.com/ubuntu focal-security/main amd64 Packages [2083 kB]\nGet:6 http://archive.ubuntu.com/ubuntu focal/universe amd64 Packages [8628 kB]\nGet:7 http://security.ubuntu.com/ubuntu focal-security/main Translation-en [338 kB]\nGet:8 http://security.ubuntu.com/ubuntu focal-security/main amd64 c-n-f Metadata [12.5 kB]\nGet:9 http://security.ubuntu.com/ubuntu focal-security/restricted amd64 Packages [1605 kB]\nGet:10 http://security.ubuntu.com/ubuntu focal-security/restricted amd64 c-n-f Metadata [612 B]\nGet:11 http://security.ubuntu.com/ubuntu focal-security/universe amd64 Packages [820 kB]\nGet:12 http://security.ubuntu.com/ubuntu focal-security/universe Translation-en [165 kB]\nGet:13 http://security.ubuntu.com/ubuntu focal-security/universe amd64 c-n-f Metadata [17.6 kB]\nGet:14 http://security.ubuntu.com/ubuntu focal-security/multiverse amd64 Packages [22.9 kB]\nGet:15 http://security.ubuntu.com/ubuntu focal-security/multiverse Translation-en [5488 B]\nGet:16 http://security.ubuntu.com/ubuntu focal-security/multiverse amd64 c-n-f Metadata [516 B]\nGet:17 http://archive.ubuntu.com/ubuntu focal/universe Translation-en [5124 kB]\nGet:18 http://archive.ubuntu.com/ubuntu focal/universe amd64 c-n-f Metadata [265 kB]\nGet:19 http://archive.ubuntu.com/ubuntu focal/multiverse amd64 Packages [144 kB]\nGet:20 http://archive.ubuntu.com/ubuntu focal/multiverse Translation-en [104 kB]\nGet:21 http://archive.ubuntu.com/ubuntu focal/multiverse amd64 c-n-f Metadata [9136 B]\nGet:22 http://archive.ubuntu.com/ubuntu focal-updates/main amd64 Packages [2465 kB]\nGet:23 http://archive.ubuntu.com/ubuntu focal-updates/main Translation-en [420 kB]\nGet:24 http://archive.ubuntu.com/ubuntu focal-updates/main amd64 c-n-f Metadata [16.4 kB]\nGet:25 http://archive.ubuntu.com/ubuntu focal-updates/restricted amd64 Packages [1714 kB]\nGet:26 http://archive.ubuntu.com/ubuntu focal-updates/restricted amd64 c-n-f Metadata [612 B]\nGet:27 http://archive.ubuntu.com/ubuntu focal-updates/universe amd64 Packages [1047 kB]\nGet:28 http://archive.ubuntu.com/ubuntu focal-updates/universe Translation-en [247 kB]\nGet:29 http://archive.ubuntu.com/ubuntu focal-updates/universe amd64 c-n-f Metadata [24.2 kB]\nGet:30 http://archive.ubuntu.com/ubuntu focal-updates/multiverse amd64 Packages [25.3 kB]\nGet:31 http://archive.ubuntu.com/ubuntu focal-updates/multiverse Translation-en [7408 B]\nGet:32 http://archive.ubuntu.com/ubuntu focal-updates/multiverse amd64 c-n-f Metadata [592 B]\nGet:33 http://archive.ubuntu.com/ubuntu focal-backports/main amd64 Packages [45.7 kB]\nGet:34 http://archive.ubuntu.com/ubuntu focal-backports/main Translation-en [16.3 kB]\nGet:35 http://archive.ubuntu.com/ubuntu focal-backports/main amd64 c-n-f Metadata [1420 B]\nGet:36 http://archive.ubuntu.com/ubuntu focal-backports/restricted amd64 c-n-f Metadata [116 B]\nGet:37 http://archive.ubuntu.com/ubuntu focal-backports/universe amd64 Packages [24.9 kB]\nGet:38 http://archive.ubuntu.com/ubuntu focal-backports/universe Translation-en [16.3 kB]\nGet:39 http://archive.ubuntu.com/ubuntu focal-backports/universe amd64 c-n-f Metadata [880 B]\nGet:40 http://archive.ubuntu.com/ubuntu focal-backports/multiverse amd64 c-n-f Metadata [116 B]\nFetched 25.8 MB in 5s (4855 kB/s)\nReading package lists...\n\n

[stderr]
WARNING: apt does not have a stable CLI interface. Use with caution in scripts.\n\nE: Could not open file /var/lib/apt/lists/archive.ubuntu.com_ubuntu_dists_focal-backports_multiverse_cnf_Commands-amd64 - open (2: No such file or directory)\nTraceback (most recent call last):\n  File \"/usr/lib/cnf-update-db\", line 27, in <module>\n    col.create(db)\n  File \"/usr/lib/python3/dist-packages/CommandNotFound/db/creator.py\", line 95, in create\n    self._fill_commands(con)\n  File \"/usr/lib/python3/dist-packages/CommandNotFound/db/creator.py\", line 141, in _fill_commands\n    raise subprocess.CalledProcessError(returncode=sub.returncode, \nsubprocess.CalledProcessError: Command '/usr/lib/apt/apt-helper cat-file /var/lib/apt/lists/archive.ubuntu.com_ubuntu_dists_focal-backports_multiverse_cnf_Commands-amd64' returned non-zero exit status 100.\nE: Problem executing scripts APT::Update::Post-Invoke-Success 'if /usr/bin/test -w /var/lib/command-not-found/ -a -e /usr/lib/cnf-update-db; then /usr/lib/cnf-update-db > /dev/null; fi'\nE: Sub-process returned an error code\n\"\r\n\r\nMore information on troubleshooting is available at https://aka.ms/VMExtensionCSELinuxTroubleshoot

Handler.log

~$ cat /var/log/azure/custom-script/handler.log
+ /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-extension install
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event=start
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 status="not reported for operation (by design)"
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event="migrate to mrseq" error="Can't find out seqnum from /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/status, not enough files."
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event="created data dir" path=/var/lib/waagent/custom-script
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event=installed
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 status="not reported for operation (by design)"
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event=end
Writing a placeholder status file indicating progress before forking: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/status/0.status
+ nohup /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-extension enable
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=start
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=pre-check
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="comparing seqnum" path=mrseq
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="seqnum saved" path=mrseq
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="reading configuration"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="read configuration"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="validating json schema"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="json schema valid"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="parsing configuration json"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="parsed configuration json"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="validating configuration logically"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="validated configuration"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="creating output directory" path=/var/lib/waagent/custom-script/download/0
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="created output directory"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 files=0
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="executing command" output=/var/lib/waagent/custom-script/download/0
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="executing public script" output=/var/lib/waagent/custom-script/download/0
time=2023-04-07T04:09:30Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="failed to execute command" error="command terminated with exit status=100" output=/var/lib/waagent/custom-script/download/0
time=2023-04-07T04:09:30Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="enable failed"
time=2023-04-07T04:09:30Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="failed to handle" error="failed to execute command: command terminated with exit status=100"
Not writing a placeholder status file, already exists: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/status/0.status
+ nohup /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-extension enable
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=start
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=pre-check
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="comparing seqnum" path=mrseq
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=exit message="the script configuration has already been processed, will not run again"
~$ cat /var/log/waagent.log
2023-04-07T04:09:13.676772Z INFO Daemon Azure Linux Agent Version:2.2.46
2023-04-07T04:09:13.680786Z INFO Daemon OS: ubuntu 20.04
2023-04-07T04:09:13.683504Z INFO Daemon Python: 3.8.10
2023-04-07T04:09:13.686229Z INFO Daemon CGroups Status: The cgroup filesystem is ready to use
2023-04-07T04:09:13.690483Z INFO Daemon Run daemon
2023-04-07T04:09:13.699474Z INFO Daemon cloud-init is enabled: True
2023-04-07T04:09:13.702189Z INFO Daemon Using cloud-init for provisioning
2023-04-07T04:09:13.705437Z INFO Daemon Clean protocol and wireserver endpoint
2023-04-07T04:09:13.708660Z INFO Daemon Running CloudInit provisioning handler
2023-04-07T04:09:13.714716Z INFO Daemon Detect protocol endpoints
2023-04-07T04:09:13.717625Z INFO Daemon Clean protocol and wireserver endpoint
2023-04-07T04:09:13.720587Z INFO Daemon WireServer endpoint is not found. Rerun dhcp handler
2023-04-07T04:09:13.723925Z INFO Daemon Test for route to 168.63.129.16
2023-04-07T04:09:13.726941Z INFO Daemon Route to 168.63.129.16 exists
2023-04-07T04:09:13.729696Z INFO Daemon Wire server endpoint:168.63.129.16
2023-04-07T04:09:13.737836Z INFO Daemon Fabric preferred wire protocol version:2015-04-05
2023-04-07T04:09:13.741253Z INFO Daemon Wire protocol version:2012-11-30
2023-04-07T04:09:13.743926Z INFO Daemon Server preferred version:2015-04-05
2023-04-07T04:09:13.958006Z INFO Daemon Found private key matching thumbprint E3B486B7752EC0122CE7370392E4C14A19B87DD3
2023-04-07T04:09:13.971497Z INFO Daemon ssh host key found at: /etc/ssh/ssh_host_rsa_key.pub
2023-04-07T04:09:13.979519Z INFO Daemon Thumbprint obtained from : /etc/ssh/ssh_host_rsa_key.pub
2023-04-07T04:09:13.984172Z INFO Daemon Finished provisioning
2023-04-07T04:09:15.003219Z INFO Daemon RDMA capabilities are not enabled, skipping
2023-04-07T04:09:15.006984Z INFO Daemon Installed Agent WALinuxAgent-2.2.46 is the most current agent
2023-04-07T04:09:15.224112Z INFO ExtHandler Agent WALinuxAgent-2.2.46 is running as the goal state agent
2023-04-07T04:09:15.228405Z INFO ExtHandler Distro info: ubuntu 20.04, osutil class being used: UbuntuOSUtil, agent service name: walinuxagent
2023-04-07T04:09:15.236190Z INFO ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:09:15.240089Z INFO ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:09:15.258969Z INFO ExtHandler Start env monitor service.
2023-04-07T04:09:15.261612Z INFO ExtHandler Configure routes
2023-04-07T04:09:15.263823Z INFO ExtHandler Gateway:None
2023-04-07T04:09:15.265991Z INFO ExtHandler Routes:None
2023-04-07T04:09:15.268184Z INFO ExtHandler Hostname record does not exist, creating [/var/lib/waagent/published_hostname] with hostname [vm-proxy-usgovva]
2023-04-07T04:09:15.290225Z WARNING ExtHandler Dhcp client is not running.
2023-04-07T04:09:15.298764Z INFO ExtHandler WALinuxAgent-2.2.46 running as process 979
2023-04-07T04:09:15.297623Z INFO ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:09:15.303960Z INFO ExtHandler CGroups Status: The cgroup filesystem is ready to use
2023-04-07T04:09:15.307382Z INFO ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:09:15.321733Z INFO ExtHandler Started tracking new cgroup: walinuxagent.service, path: /sys/fs/cgroup/cpu/system.slice/walinuxagent.service
2023-04-07T04:09:15.327088Z INFO ExtHandler Started tracking new cgroup: walinuxagent.service, path: /sys/fs/cgroup/memory/system.slice/walinuxagent.service
2023-04-07T04:09:15.429892Z INFO ExtHandler Route table: [{"Iface": "eth0", "Destination": "0.0.0.0", "Gateway": "10.50.16.33", "Mask": "0.0.0.0", "Flags": "0x0003", "Metric": "100"},{"Iface": "eth0", "Destination": "10.50.16.32", "Gateway": "0.0.0.0", "Mask": "255.255.255.248", "Flags": "0x0001", "Metric": "0"},{"Iface": "eth0", "Destination": "168.63.129.16", "Gateway": "10.50.16.33", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "100"},{"Iface": "eth0", "Destination": "169.254.169.254", "Gateway": "10.50.16.33", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "100"}]
2023-04-07T04:09:15.473266Z INFO ExtHandler Initial NIC state: [{ "name": "lo", "link": "<LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000\    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00" }, { "name": "eth0", "link": "<BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000\    link/ether 00:1d:d8:06:78:54 brd ff:ff:ff:ff:ff:ff" }]
2023-04-07T04:09:15.587052Z INFO ExtHandler Successfully added Azure fabric firewall rules
2023-04-07T04:09:15.599212Z INFO ExtHandler Firewall rules:
Chain INPUT (policy ACCEPT 0 packets, 0 bytes)
    pkts      bytes target     prot opt in     out     source               destination

Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
    pkts      bytes target     prot opt in     out     source               destination

Chain OUTPUT (policy ACCEPT 0 packets, 0 bytes)
    pkts      bytes target     prot opt in     out     source               destination
       0        0 ACCEPT     tcp  --  *      *       0.0.0.0/0            168.63.129.16        owner UID match 0
       0        0 DROP       tcp  --  *      *       0.0.0.0/0            168.63.129.16        ctstate INVALID,NEW

2023-04-07T04:09:15.622875Z INFO ExtHandler Set block dev timeout: sdb with timeout: 300
2023-04-07T04:09:15.626003Z INFO ExtHandler Set block dev timeout: sda with timeout: 300
2023-04-07T04:09:15.755089Z INFO ExtHandler Created slice for walinuxagent extensions system-walinuxagent.extensions.slice
2023-04-07T04:09:15.761405Z INFO ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:09:15.764831Z INFO ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:09:15.822007Z INFO ExtHandler Found private key matching thumbprint E3B486B7752EC0122CE7370392E4C14A19B87DD3
2023-04-07T04:09:16.026356Z INFO ExtHandler Agent WALinuxAgent-2.2.46 discovered update WALinuxAgent-2.9.0.4 -- exiting
2023-04-07T04:09:17.014798Z INFO Daemon Agent WALinuxAgent-2.2.46 launched with command 'python3 -u /usr/sbin/waagent -run-exthandlers' is successfully running
2023-04-07T04:09:17.023563Z INFO Daemon Determined Agent WALinuxAgent-2.9.0.4 to be the latest agent
2023-04-07T04:09:17.549726Z INFO ExtHandler ExtHandler The agent will now check for updates and then will process extensions. Output to /dev/console will be suspended during those operations.
2023-04-07T04:09:17.665781Z INFO ExtHandler ExtHandler Azure Linux Agent (Goal State Agent version 2.9.0.4)
2023-04-07T04:09:17.666264Z INFO ExtHandler ExtHandler OS: ubuntu 20.04
2023-04-07T04:09:17.666374Z INFO ExtHandler ExtHandler Python: 3.8.10
2023-04-07T04:09:17.715224Z INFO ExtHandler ExtHandler Distro: ubuntu-20.04; OSUtil: Ubuntu18OSUtil; AgentService: walinuxagent; Python: 3.8.10; systemd: True; LISDrivers: name:           hv_vmbus
; logrotate: logrotate 3.14.0;
2023-04-07T04:09:17.716034Z INFO ExtHandler ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:09:17.716303Z INFO ExtHandler ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:09:17.729656Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 2]
2023-04-07T04:09:17.745889Z INFO ExtHandler ExtHandler HostGAPlugin version: 1.0.8.139
2023-04-07T04:09:17.746544Z INFO ExtHandler
2023-04-07T04:09:17.746656Z INFO ExtHandler Fetched new vmSettings [HostGAPlugin correlation ID: 323a5752-8b07-471f-841e-69071a8eee7d eTag: 2921692812838925475 source: Fabric]
2023-04-07T04:09:17.747046Z INFO ExtHandler The vmSettings originated via Fabric; will ignore them.
2023-04-07T04:09:17.747737Z INFO ExtHandler
2023-04-07T04:09:17.747823Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 2]
2023-04-07T04:09:17.893661Z INFO ExtHandler Downloaded certificate {'thumbprint': 'E3B486B7752EC0122CE7370392E4C14A19B87DD3', 'hasPrivateKey': True}
2023-04-07T04:09:17.894662Z INFO ExtHandler Fetch goal state completed
2023-04-07T04:09:17.909628Z INFO ExtHandler ExtHandler WALinuxAgent-2.9.0.4 running as process 1107
2023-04-07T04:09:17.917536Z INFO ExtHandler ExtHandler [CGI] systemd version: systemd 245 (245.4-4ubuntu3.20)
+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid

2023-04-07T04:09:17.930160Z INFO ExtHandler ExtHandler [CGI] Removed /etc/systemd/system/system-walinuxagent.extensions.slice
2023-04-07T04:09:17.931826Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/azure.slice
2023-04-07T04:09:17.940210Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/azure-vmextensions.slice
2023-04-07T04:09:17.940840Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/azure-walinuxagent-logcollector.slice
2023-04-07T04:09:17.941580Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/walinuxagent.service.d/10-Slice.conf
2023-04-07T04:09:17.942243Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/walinuxagent.service.d/11-CPUAccounting.conf
2023-04-07T04:09:17.942887Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/walinuxagent.service.d/13-MemoryAccounting.conf
2023-04-07T04:09:17.943456Z INFO ExtHandler ExtHandler Executing systemctl daemon-reload...
2023-04-07T04:09:18.427742Z INFO ExtHandler ExtHandler The CPU cgroup controller is mounted at /sys/fs/cgroup/cpu,cpuacct
2023-04-07T04:09:18.428283Z INFO ExtHandler ExtHandler The memory cgroup controller is mounted at /sys/fs/cgroup/memory
2023-04-07T04:09:18.432896Z INFO ExtHandler ExtHandler [CGI] cgroups v2 mounted at /sys/fs/cgroup/unified.  Controllers: []
2023-04-07T04:09:18.446046Z INFO ExtHandler ExtHandler [CGI] CPUAccounting: yes
2023-04-07T04:09:18.457043Z INFO ExtHandler ExtHandler [CGI] CPUQuota: infinity
2023-04-07T04:09:18.468015Z INFO ExtHandler ExtHandler [CGI] MemoryAccounting: yes
2023-04-07T04:09:18.469049Z INFO ExtHandler ExtHandler [CGI] Agent CPU cgroup: /sys/fs/cgroup/cpu,cpuacct/system.slice/walinuxagent.service
2023-04-07T04:09:18.469809Z INFO ExtHandler ExtHandler [CGI] Ensuring the agent's CPUQuota is 50%
2023-04-07T04:09:18.470553Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/walinuxagent.service.d/12-CPUQuota.conf
2023-04-07T04:09:18.471155Z INFO ExtHandler ExtHandler Executing systemctl daemon-reload...
2023-04-07T04:09:18.968436Z INFO ExtHandler ExtHandler Started tracking cgroup walinuxagent.service [/sys/fs/cgroup/cpu,cpuacct/system.slice/walinuxagent.service]
2023-04-07T04:09:18.969386Z INFO ExtHandler ExtHandler [CGI] Agent Memory cgroup: /sys/fs/cgroup/memory/system.slice/walinuxagent.service
2023-04-07T04:09:18.970423Z INFO ExtHandler ExtHandler Started tracking cgroup walinuxagent.service [/sys/fs/cgroup/memory/system.slice/walinuxagent.service]
2023-04-07T04:09:18.970718Z INFO ExtHandler ExtHandler [CGI] Agent cgroups enabled: True
2023-04-07T04:09:18.973222Z INFO ExtHandler ExtHandler Starting setup for Persistent firewall rules
2023-04-07T04:09:19.000809Z INFO ExtHandler ExtHandler Firewalld service not running/unavailable, trying to set up walinuxagent-network-setup.service
2023-04-07T04:09:19.001365Z INFO ExtHandler ExtHandler Successfully updated the Binary file /var/lib/waagent/waagent-network-setup.py for firewall setup
2023-04-07T04:09:19.017726Z INFO ExtHandler ExtHandler Service: walinuxagent-network-setup.service not enabled. Adding it now
2023-04-07T04:09:19.478800Z INFO ExtHandler ExtHandler Executing systemctl daemon-reload for setting up walinuxagent-network-setup.service
2023-04-07T04:09:19.982306Z INFO ExtHandler ExtHandler Successfully added and enabled the walinuxagent-network-setup.service
2023-04-07T04:09:19.984593Z INFO ExtHandler ExtHandler Persistent firewall rules setup successfully
2023-04-07T04:09:20.032375Z INFO ExtHandler ExtHandler Firewall rule to allow DNS TCP request to wireserver for a non root user unavailable. Setting it now.
2023-04-07T04:09:20.040170Z INFO ExtHandler ExtHandler Succesfully added firewall rule to allow non root users to do a DNS TCP request to wireserver
2023-04-07T04:09:20.047590Z INFO ExtHandler ExtHandler Checking if log collection is allowed at this time [True]. All three conditions must be met: configuration enabled [True], cgroups enabled [True], python supported: [True]
2023-04-07T04:09:20.054981Z INFO ExtHandler ExtHandler Starting env monitor service.
2023-04-07T04:09:20.059433Z INFO MonitorHandler ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:09:20.061458Z INFO MonitorHandler ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:09:20.062296Z INFO MonitorHandler ExtHandler Monitor.NetworkConfigurationChanges is disabled.
2023-04-07T04:09:20.065539Z INFO MonitorHandler ExtHandler Routing table from /proc/net/route:
Iface   Destination     Gateway         Flags   RefCnt  Use     Metric  Mask            MTU     Window  IRTT

eth0    00000000        2110320A        0003    0       0       100     00000000        0       0       0

eth0    2010320A        00000000        0001    0       0       0       F8FFFFFF        0       0       0

eth0    10813FA8        2110320A        0007    0       0       100     FFFFFFFF        0       0       0

eth0    FEA9FEA9        2110320A        0007    0       0       100     FFFFFFFF        0       0       0

2023-04-07T04:09:20.072037Z INFO ExtHandler ExtHandler Start SendTelemetryHandler service.
2023-04-07T04:09:20.078198Z INFO EnvHandler ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:09:20.079849Z INFO EnvHandler ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:09:20.081765Z INFO EnvHandler ExtHandler Configure routes
2023-04-07T04:09:20.094779Z INFO ExtHandler ExtHandler Start Extension Telemetry service.
2023-04-07T04:09:20.098400Z INFO EnvHandler ExtHandler Gateway:None
2023-04-07T04:09:20.098950Z INFO EnvHandler ExtHandler Routes:None
2023-04-07T04:09:20.094076Z INFO SendTelemetryHandler ExtHandler Successfully started the SendTelemetryHandler thread
2023-04-07T04:09:20.105938Z INFO TelemetryEventsCollector ExtHandler Extension Telemetry pipeline enabled: True
2023-04-07T04:09:20.110118Z INFO TelemetryEventsCollector ExtHandler Successfully started the TelemetryEventsCollector thread
2023-04-07T04:09:20.112220Z INFO ExtHandler ExtHandler Goal State Period: 6 sec. This indicates how often the agent checks for new goal states and reports status.
2023-04-07T04:09:20.143292Z INFO MonitorHandler ExtHandler Network interfaces:
Executing ['ip', '-a', '-o', 'link']:
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000\    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000\    link/ether 00:1d:d8:06:78:54 brd ff:ff:ff:ff:ff:ff

Executing ['ip', '-4', '-a', '-o', 'address']:
1: lo    inet 127.0.0.1/8 scope host lo\       valid_lft forever preferred_lft forever
2: eth0    inet 10.50.16.36/29 brd 10.50.16.39 scope global eth0\       valid_lft forever preferred_lft forever

Executing ['ip', '-6', '-a', '-o', 'address']:
1: lo    inet6 ::1/128 scope host \       valid_lft forever preferred_lft forever
2: eth0    inet6 fe80::21d:d8ff:fe06:7854/64 scope link \       valid_lft forever preferred_lft forever

2023-04-07T04:09:20.172956Z INFO ExtHandler ExtHandler No requested version specified, checking for all versions for agent update (family: Prod)
2023-04-07T04:09:20.222156Z INFO ExtHandler ExtHandler
2023-04-07T04:09:20.224413Z INFO ExtHandler ExtHandler ProcessExtensionsGoalState started [incarnation_2 channel: WireServer source: Fabric activity: 35dc73a7-d95c-4496-84c5-0f33a3a5d64d correlation 3c0a505c-4026-4ddc-851e-67cd8982cc54 created: 2023-04-07T04:09:06.411392Z]
2023-04-07T04:09:20.306537Z INFO EnvHandler ExtHandler Current Firewall rules:
Chain INPUT (policy ACCEPT 35 packets, 23497 bytes)
    pkts      bytes target     prot opt in     out     source               destination

Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
    pkts      bytes target     prot opt in     out     source               destination

Chain OUTPUT (policy ACCEPT 24 packets, 3541 bytes)
    pkts      bytes target     prot opt in     out     source               destination
       0        0 ACCEPT     tcp  --  *      *       0.0.0.0/0            168.63.129.16        tcp dpt:53
      82    11742 ACCEPT     tcp  --  *      *       0.0.0.0/0            168.63.129.16        owner UID match 0
       0        0 DROP       tcp  --  *      *       0.0.0.0/0            168.63.129.16        ctstate INVALID,NEW

2023-04-07T04:09:20.328301Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Target handler state: enabled [incarnation_2]
2023-04-07T04:09:20.333595Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] [Enable] current handler state is: notinstalled
2023-04-07T04:09:20.448553Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Unzipping extension package: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript__2.1.3.zip
2023-04-07T04:09:20.604264Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Initializing extension Microsoft.Azure.Extensions.CustomScript-2.1.3
2023-04-07T04:09:20.614765Z INFO ExtHandler ExtHandler [CGI] Ensuring the Microsoft.Azure.Extensions.CustomScript-2.1.3's CPUQuota is
2023-04-07T04:09:20.615644Z INFO ExtHandler ExtHandler [CGI] Created /lib/systemd/system/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice
2023-04-07T04:09:20.616279Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Update settings file: 0.settings
2023-04-07T04:09:20.616783Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Install extension [bin/custom-script-shim install]
2023-04-07T04:09:20.617313Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Executing command: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-shim install with environment variables: {"AZURE_GUEST_AGENT_UNINSTALL_CMD_EXIT_CODE": "NOT_RUN", "AZURE_GUEST_AGENT_EXTENSION_PATH": "/var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3", "AZURE_GUEST_AGENT_EXTENSION_VERSION": "2.1.3", "AZURE_GUEST_AGENT_WIRE_PROTOCOL_ADDRESS": "168.63.129.16", "ConfigSequenceNumber": "0", "AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES": "[{\"Key\": \"ExtensionTelemetryPipeline\", \"Value\": \"1.0\"}]"}
2023-04-07T04:09:20.622020Z INFO ExtHandler ExtHandler Started extension in unit 'install_576969c8-124c-4727-8c30-a74e13ffb7b1.scope'
2023-04-07T04:09:20.627918Z INFO ExtHandler ExtHandler Started tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/cpu,cpuacct/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:09:20.628244Z INFO ExtHandler ExtHandler Started tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/memory/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:09:22.630633Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Command: bin/custom-script-shim install
[stdout]
+ /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-extension install
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event=start
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 status="not reported for operation (by design)"
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event="migrate to mrseq" error="Can't find out seqnum from /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/status, not enough files."
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event="created data dir" path=/var/lib/waagent/custom-script
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event=installed
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 status="not reported for operation (by design)"
time=2023-04-07T04:09:20Z version=v2.1.3/git@4cd2b9f-clean operation=install seq=0 event=end
[stderr]
Running scope as unit: install_576969c8-124c-4727-8c30-a74e13ffb7b1.scope
2023-04-07T04:09:22.631974Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Requested extension state: enabled
2023-04-07T04:09:22.632488Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Enable extension: [bin/custom-script-shim enable]
2023-04-07T04:09:22.632889Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Executing command: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-shim enable with environment variables: {"AZURE_GUEST_AGENT_UNINSTALL_CMD_EXIT_CODE": "NOT_RUN", "AZURE_GUEST_AGENT_EXTENSION_PATH": "/var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3", "AZURE_GUEST_AGENT_EXTENSION_VERSION": "2.1.3", "AZURE_GUEST_AGENT_WIRE_PROTOCOL_ADDRESS": "168.63.129.16", "ConfigSequenceNumber": "0", "AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES": "[{\"Key\": \"ExtensionTelemetryPipeline\", \"Value\": \"1.0\"}]"}
2023-04-07T04:09:22.640930Z INFO ExtHandler ExtHandler Started extension in unit 'enable_6658155c-d541-4cb3-8ef2-e79200ae8094.scope'
2023-04-07T04:09:24.644246Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Command: bin/custom-script-shim enable
[stdout]
Writing a placeholder status file indicating progress before forking: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/status/0.status
+ nohup /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-extension enable
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=start
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=pre-check
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="comparing seqnum" path=mrseq
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="seqnum saved" path=mrseq
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="reading configuration"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="read configuration"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="validating json schema"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="json schema valid"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="parsing configuration json"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="parsed configuration json"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="validating configuration logically"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="validated configuration"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="creating output directory" path=/var/lib/waagent/custom-script/download/0
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="created output directory"
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 files=0
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="executing command" output=/var/lib/waagent/custom-script/download/0
time=2023-04-07T04:09:22Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="executing public script" output=/var/lib/waagent/custom-script/download/0
[stderr]
Running scope as unit: enable_6658155c-d541-4cb3-8ef2-e79200ae8094.scope
2023-04-07T04:09:24.648362Z INFO ExtHandler ExtHandler ProcessExtensionsGoalState completed [incarnation_2 4426 ms]

2023-04-07T04:09:24.712167Z INFO ExtHandler ExtHandler Extension status: [('Microsoft.Azure.Extensions.CustomScript', 'transitioning')]
2023-04-07T04:09:24.713515Z INFO ExtHandler ExtHandler Looking for existing remote access users.
2023-04-07T04:09:24.740492Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.9.0.4 is running as the goal state agent [DEBUG HeartbeatCounter: 0;HeartbeatId: C53A0CBB-3E34-4A51-BEAB-A4FE61C1B84E;DroppedPackets: 0;UpdateGSErrors: 0;AutoUpdate: 1]
2023-04-07T04:09:36.792560Z INFO ExtHandler ExtHandler Extension status: [('Microsoft.Azure.Extensions.CustomScript', 'error')]
2023-04-07T04:09:36.793364Z INFO ExtHandler ExtHandler All extensions in the goal state have reached a terminal state: [('Microsoft.Azure.Extensions.CustomScript', 'error')]
2023-04-07T04:14:20.125931Z INFO CollectLogsHandler ExtHandler WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:14:20.126157Z INFO CollectLogsHandler ExtHandler Wire server endpoint:168.63.129.16
2023-04-07T04:14:20.126335Z INFO CollectLogsHandler ExtHandler Starting log collection...
2023-04-07T04:14:20.228613Z INFO MonitorHandler ExtHandler Stopped tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/cpu,cpuacct/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:14:20.228825Z INFO MonitorHandler ExtHandler Stopped tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/memory/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:14:28.456905Z INFO MainThread LogCollector Running log collector mode normal
2023-04-07T04:14:28.655076Z INFO MainThread LogCollector WireServer endpoint 168.63.129.16 read from file
2023-04-07T04:14:28.655282Z INFO MainThread LogCollector Wire server endpoint:168.63.129.16
2023-04-07T04:14:28.655431Z INFO MainThread LogCollector Forcing an update of the goal state.
2023-04-07T04:14:28.756325Z INFO MainThread Fetched a new incarnation for the WireServer goal state [incarnation 2]
2023-04-07T04:14:28.856056Z INFO MainThread LogCollector HostGAPlugin version: 1.0.8.139
2023-04-07T04:14:28.856663Z INFO MainThread
2023-04-07T04:14:28.856789Z INFO MainThread Fetched new vmSettings [HostGAPlugin correlation ID: 905cf788-1d3a-476f-8093-9163bca9bac6 eTag: 2921692812838925475 source: Fabric]
2023-04-07T04:14:28.857163Z INFO MainThread The vmSettings originated via Fabric; will ignore them.
2023-04-07T04:14:28.857755Z INFO MainThread
2023-04-07T04:14:28.857853Z INFO MainThread Fetching full goal state from the WireServer [incarnation 2]
2023-04-07T04:14:29.856058Z INFO MainThread Downloaded certificate {'thumbprint': 'E3B486B7752EC0122CE7370392E4C14A19B87DD3', 'hasPrivateKey': True}
2023-04-07T04:14:29.857011Z INFO MainThread Fetch goal state completed
2023-04-07T04:14:30.555462Z INFO MainThread LogCollector Log collection successfully completed. Archive can be found at /var/lib/waagent/logcollector/logs.zip and detailed log output can be found at /var/lib/waagent/logcollector/results.txt
2023-04-07T04:14:32.455388Z INFO CollectLogsHandler ExtHandler Successfully collected logs. Archive size: 64967 b, elapsed time: 12328 ms.
2023-04-07T04:14:32.468060Z INFO CollectLogsHandler ExtHandler Successfully uploaded logs.
2023-04-07T04:19:32.970049Z INFO ExtHandler Fetched a new incarnation for the WireServer goal state [incarnation 3]
2023-04-07T04:19:32.979127Z INFO ExtHandler
2023-04-07T04:19:32.979287Z INFO ExtHandler Fetched new vmSettings [HostGAPlugin correlation ID: 68db04a6-5a28-43c9-a019-9f8b78bca183 eTag: 11126400132818787565 source: Fabric]
2023-04-07T04:19:32.979715Z INFO ExtHandler The vmSettings originated via Fabric; will ignore them.
2023-04-07T04:19:32.980378Z INFO ExtHandler
2023-04-07T04:19:32.980480Z INFO ExtHandler Fetching full goal state from the WireServer [incarnation 3]
2023-04-07T04:19:33.086655Z INFO ExtHandler Downloaded certificate {'thumbprint': 'E3B486B7752EC0122CE7370392E4C14A19B87DD3', 'hasPrivateKey': True}
2023-04-07T04:19:33.087640Z INFO ExtHandler Fetch goal state completed
2023-04-07T04:19:33.088630Z INFO ExtHandler ExtHandler
2023-04-07T04:19:33.088757Z INFO ExtHandler ExtHandler ProcessExtensionsGoalState started [incarnation_3 channel: WireServer source: Fabric activity: 30317c7b-936a-4217-9e3e-dd2de70033ba correlation a3b8289b-3e9e-41c5-b493-4d596a28bc13 created: 2023-04-07T04:09:06.411392Z]
2023-04-07T04:19:33.142258Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Target handler state: enabled [incarnation_3]
2023-04-07T04:19:33.142852Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] [Enable] current handler state is: enabled
2023-04-07T04:19:33.143001Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Update settings file: 0.settings
2023-04-07T04:19:33.143292Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Requested extension state: enabled
2023-04-07T04:19:33.143731Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Enable extension: [bin/custom-script-shim enable]
2023-04-07T04:19:33.144047Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Executing command: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-shim enable with environment variables: {"AZURE_GUEST_AGENT_UNINSTALL_CMD_EXIT_CODE": "NOT_RUN", "AZURE_GUEST_AGENT_EXTENSION_PATH": "/var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3", "AZURE_GUEST_AGENT_EXTENSION_VERSION": "2.1.3", "AZURE_GUEST_AGENT_WIRE_PROTOCOL_ADDRESS": "168.63.129.16", "ConfigSequenceNumber": "0", "AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES": "[{\"Key\": \"ExtensionTelemetryPipeline\", \"Value\": \"1.0\"}]"}
2023-04-07T04:19:33.147587Z INFO ExtHandler ExtHandler Started extension in unit 'enable_1fada438-33dc-416e-8f05-4ce9b1cb4bef.scope'
2023-04-07T04:19:33.148358Z INFO ExtHandler ExtHandler Started tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/cpu,cpuacct/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:19:33.148500Z INFO ExtHandler ExtHandler Started tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/memory/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:19:35.151605Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.3] Command: bin/custom-script-shim enable
[stdout]
Not writing a placeholder status file, already exists: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/status/0.status
+ nohup /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript-2.1.3/bin/custom-script-extension enable
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=start
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=pre-check
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event="comparing seqnum" path=mrseq
time=2023-04-07T04:19:33Z version=v2.1.3/git@4cd2b9f-clean operation=enable seq=0 event=exit message="the script configuration has already been processed, will not run again"
[stderr]
Running scope as unit: enable_1fada438-33dc-416e-8f05-4ce9b1cb4bef.scope
2023-04-07T04:19:35.154200Z INFO ExtHandler ExtHandler ProcessExtensionsGoalState completed [incarnation_3 2065 ms]

2023-04-07T04:19:35.169451Z INFO ExtHandler ExtHandler Extension status: [('Microsoft.Azure.Extensions.CustomScript', 'error')]
2023-04-07T04:19:35.169877Z INFO ExtHandler ExtHandler All extensions in the goal state have reached a terminal state: [('Microsoft.Azure.Extensions.CustomScript', 'error')]
2023-04-07T04:24:17.062994Z INFO Daemon Agent WALinuxAgent-2.9.0.4 launched with command 'python3 -u bin/WALinuxAgent-2.9.0.4-py2.7.egg -run-exthandlers' is successfully running
2023-04-07T04:24:20.295634Z INFO MonitorHandler ExtHandler Stopped tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/cpu,cpuacct/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
2023-04-07T04:24:20.295805Z INFO MonitorHandler ExtHandler Stopped tracking cgroup Microsoft.Azure.Extensions.CustomScript-2.1.3 [/sys/fs/cgroup/memory/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Extensions.CustomScript_2.1.3.slice]
fnallian commented 5 months ago

Any update regarding this issue? as this still seems to occur for us aswell