Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Custom Extension Occasionally Failing on apt update #210

Open
matferrari-msft opened this issue Apr 7, 2023 · 1 comment
Open

Custom Extension Occasionally Failing on apt update #210

matferrari-msft opened this issue Apr 7, 2023 · 1 comment

Comments

@matferrari-msft
Copy link
Member

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
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@matferrari-msft @fnallian