search

Azure / WALinuxAgent

Microsoft Azure Linux Guest Agent
http://azure.microsoft.com/
Apache License 2.0
539 stars 372 forks source link

[BUG] WALinuxAgent service should start after the cloud-config service #1938

Open carldjohnston opened 4 years ago

carldjohnston commented 4 years ago

Currently (On Canonical UbuntuServer 18.04-LTS) the WALinuxAgent service and cloud-init run in parallel on start-up causing issues with contention of the package repository.

I believe that WALinuxAgent should start after the cloud-config service to ensure that:

Distro and WALinuxAgent details:

Additional context My current situation when starting an Ubuntu 18.04 VM, with the Log Analytics extension is that:

  1. WALinuxAgent starts, installs the Log Analytics agent (through extension) then;
  2. Shortly after (~2 seconds or so) cloud-init starts with the following configuration: 
    package_upgrade: true
package_reboot_if_required: true
  3. WALinuxAgent or Log Analytics agent has the package repository lock, and causes cloud-init to fail

My current solution is to modify the service behaviour by adding this override to /etc/systemd/system/walinuxagent.service.d/override.conf from within bootcmd using cloud-init:

[Unit]
After=cloud-config.service
carldjohnston commented 4 years ago

Update on this; my proposed solution doesn't appear to work reliably.

I believe that the walinuxagent service needs to start after cloud-final to be more robust. I'm achieving that with the following in cloud-init:

bootcmd:
  - mkdir -p /etc/systemd/system/walinuxagent.service.d
  - echo "[Unit]\nAfter=cloud-final.service" > /etc/systemd/system/walinuxagent.service.d/override.conf
  - sed "s/After=multi-user.target//g" /lib/systemd/system/cloud-final.service > /etc/systemd/system/cloud-final.service
  - systemctl daemon-reload
trstringer commented 4 years ago

Thanks for opening this issue! We'll take a look. Cc // @anhvoms

ma-armenta commented 2 years ago

Good workaround but this should be fix, or allow extension sequencing for customScript extension.

alexey-nikolov-basemark-com commented 2 years ago

Still no progress? What a shame

graemefoster commented 2 years ago

Have this issue as-well. According to the readme this used to work so feels like a regression at some point (bold text for emphasis of previous behaviour): Is there a plan to fix this?

Provisioning.UseCloudInit Type: Boolean Default: n

This options enables / disables support for provisioning by means of cloud-init. When true ("y"), the agent will wait for cloud-init to complete before installing extensions and processing the latest goal state. Provisioning.Enabled must be disabled ("n") for this option to have an effect. Setting Provisioning.Enabled to true ("y") overrides this option and runs the built-in agent provisioning code.

Note: This configuration option has been removed and has no effect. waagent now auto-detects cloud-init as a provisioning agent (with an option to override with Provisioning.Agent).

AntonioSun commented 2 years ago

Note: This configuration option has been removed and has no effect. waagent now auto-detects cloud-init as a provisioning agent (with an option to override with Provisioning.Agent).

"waagent now auto-detects cloud-init as a provisioning agent" and the effect is that they both will/can work together?

I'm still having this issue though.

AntonioSun commented 2 years ago

Update on this; my proposed solution doesn't appear to work reliably.

I believe that the walinuxagent service needs to start after cloud-final to be more robust. I'm achieving that with the following in cloud-init:

bootcmd:
  - mkdir -p /etc/systemd/system/walinuxagent.service.d
  - echo "[Unit]\nAfter=cloud-final.service" > /etc/systemd/system/walinuxagent.service.d/override.conf
  - sed "s/After=multi-user.target//g" /lib/systemd/system/cloud-final.service > /etc/systemd/system/cloud-final.service
  - systemctl daemon-reload

This is what I got when trying it:

Cloud-init v. 20.2 running 'modules:config' at Sun, 19 Jun 2022 17:07:16 +0000. Up 12.87 seconds.
Reading package lists...
E: Could not get lock /var/lib/apt/lists/lock - open (11: Resource temporarily unavailable)
E: Unable to lock directory /var/lib/apt/lists/
Cloud-init v. 20.2 running 'modules:final' at Sun, 19 Jun 2022 17:07:18 +0000. Up 14.18 seconds.
2022-06-19 17:07:18,376 - util.py[WARNING]: Package update failed

Just to confirmed that I've done it properly:

$ cat /etc/systemd/system/walinuxagent.service.d/override.conf
[Unit]
After=cloud-final.service

$ cat /etc/systemd/system/cloud-final.service
[Unit]
Description=Execute cloud user/final scripts
After=network-online.target cloud-config.service rc-local.service

Before=apt-daily.service
Wants=network-online.target cloud-config.service

[Service]
Type=oneshot
ExecStart=/usr/bin/cloud-init modules --mode=final
RemainAfterExit=yes
TimeoutSec=0
KillMode=process
TasksMax=infinity

# Output needs to appear in instance console output
StandardOutput=journal+console

[Install]
WantedBy=cloud-init.target
dvavasour commented 1 year ago

+1

It seems utterly bizarre to leave this broken for two and a half years: cloud-init has been around for over a decade and is absolutely industry standard. To have an external agent that wades in without any reference to cloud-init renders it unusable. There is a provided mechanism to check if cloud-init is still running https://cloudinit.readthedocs.io/en/latest/reference/faq.html

Luiz-Monad commented 1 year ago

I had this same problem when trying to create a scale-set for my Azure DevOps agent pipeline.

This is the command I'm using to create the scale-set.


azps group create `
 --location westus3 `
 --name vsagent

azps vmss create `
 --name agentpool `
 --resource-group vsagent `
 --image 'Debian:debian-11-daily:11-gen2:latest' `
 --priority Spot `
 --vm-sku Standard_D2s_v3 `
 --storage-sku StandardSSD_LRS `
 --orchestration-mode Uniform `
 --instance-count 0 `
 --eviction-policy Delete `
 --upgrade-policy-mode Manual `
 --single-placement-group false `
 --platform-fault-domain-count 1 `
 --lb-sku Basic `
 --load-balancer '' `
 --vnet-name agentnet `
 --os-disk-caching readonly `
 --authentication-type SSH `
 --generate-ssh-keys `
 --ssh-key-values ~/.ssh/id_rsa.pub `
 --admin-username vsagent

azps vmss extension set `
 --vmss-name agentpool `
 --resource-group vsagent `
 --name CustomScript `
 --version 2.0 `
 --publisher Microsoft.Azure.Extensions `
 --settings '{ "commandToExecute": " apt-get -o DPkg::Lock::Timeout=60 update && apt-get install git && apt-get autoclean " }'

It conflicts with the Microsoft.Azure.DevOps.Pipelines.Agent extension

{
  "isPipelinesAgent": true,
  "agentFolder": "/agent",
  "agentDownloadUrl": "https://vstsagentpackage.azureedge.net/agent/3.224.1/vsts-agent-linux-x64-3.224.1.tar.gz",
  "enableScriptDownloadUrl": "https://vstsagenttools.blob.core.windows.net/tools/ElasticPools/Linux/15/enableagent.sh"
}
Boot log ``` [ OK ] Finished Microsft Azure Linux Agent (resourcedisk). Mounting /boot/efi... [ OK ] Found device /sys/subsystem/net/devices/eth0. [ 4.218465] cloud-init[379]: Cloud-init v. 22.2 running 'init-local' at Wed, 26 Jul 2023 20:30:41 +0000. Up 4.17 seconds. [ OK ] Mounted /boot/efi. [ OK ] Reached target Local File Systems. Starting Load AppArmor profiles... Starting Commit a transient machine-id on disk... Starting Create Volatile Files and Directories... [ OK ] Finished Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... [ 4.404689] KVM: vmx: using Hyper-V Enlightened VMCS [ OK ] Finished Update UTMP about System Boot/Shutdown. [ OK ] Finished Commit a transient machine-id on disk. [ 4.733756] UDF-fs: INFO Mounting volume 'UDF Volume', timestamp 2023/07/27 00:00 (1000) [ 4.750266] audit: type=1400 audit(1690403441.760:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lsb_release" pid=393 comm="apparmor_parser" [ 4.833285] audit: type=1400 audit(1690403441.844:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/chronyd" pid=394 comm="apparmor_parser" [ 4.958309] audit: type=1400 audit(1690403441.968:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/man" pid=402 comm="apparmor_parser" [ 4.968445] audit: type=1400 audit(1690403441.976:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_filter" pid=402 comm="apparmor_parser" [ 4.975821] audit: type=1400 audit(1690403441.980:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_groff" pid=402 comm="apparmor_parser" [ 4.982715] audit: type=1400 audit(1690403441.988:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="tcpdump" pid=398 comm="apparmor_parser" [ 5.022118] audit: type=1400 audit(1690403442.032:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=408 comm="apparmor_parser" [ 5.029304] audit: type=1400 audit(1690403442.036:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=408 comm="apparmor_parser" [ OK ] Finished Load AppArmor profiles. [ 5.848484] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ OK ] Finished Initial cloud-init job (pre-networking). [ OK ] Reached target Network (Pre). [ OK ] Started ifup for eth0. Starting Raise network interfaces... [ OK ] Finished Raise network interfaces. [ OK ] Reached target Network. Starting Initial cloud-ini… (metadata service crawler)... [ 9.544767] cloud-init[573]: Cloud-init v. 22.2 running 'init' at Wed, 26 Jul 2023 20:30:46 +0000. Up 9.52 seconds. [ 9.559247] cloud-init[573]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ [ 9.563146] cloud-init[573]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ [ 9.566906] cloud-init[573]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | [ 9.570639] cloud-init[573]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ [ 9.574369] cloud-init[573]: ci-info: | eth0 | True | 10.0.0.4 | 255.255.255.0 | global | 60:45:bd:c8:3e:59 | [ 9.577966] cloud-init[573]: ci-info: | eth0 | True | fe80::6245:bdff:fec8:3e59/64 | . | link | 60:45:bd:c8:3e:59 | [ 9.581691] cloud-init[573]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | [ 9.585360] cloud-init[573]: ci-info: | lo | True | ::1/128 | . | host | . | [ 9.589093] cloud-init[573]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ [ 9.592667] cloud-init[573]: ci-info: ++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++ [ 9.596012] cloud-init[573]: ci-info: +-------+-----------------+----------+-----------------+-----------+-------+ [ 9.599632] cloud-init[573]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | [ 9.603018] cloud-init[573]: ci-info: +-------+-----------------+----------+-----------------+-----------+-------+ [ 9.606009] cloud-init[573]: ci-info: | 0 | 0.0.0.0 | 10.0.0.1 | 0.0.0.0 | eth0 | UG | [ 9.608940] cloud-init[573]: ci-info: | 1 | 10.0.0.0 | 0.0.0.0 | 255.255.255.0 | eth0 | U | [ 9.611913] cloud-init[573]: ci-info: | 2 | 168.63.129.16 | 10.0.0.1 | 255.255.255.255 | eth0 | UGH | [ 9.614953] cloud-init[573]: ci-info: | 3 | 169.254.169.254 | 10.0.0.1 | 255.255.255.255 | eth0 | UGH | [ 9.617862] cloud-init[573]: ci-info: +-------+-----------------+----------+-----------------+-----------+-------+ [ 9.621025] cloud-init[573]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ [ 9.623412] cloud-init[573]: ci-info: +-------+-------------+---------+-----------+-------+ [ 9.625808] cloud-init[573]: ci-info: | Route | Destination | Gateway | Interface | Flags | [ 9.628139] cloud-init[573]: ci-info: +-------+-------------+---------+-----------+-------+ [ 9.630597] cloud-init[573]: ci-info: | 1 | fe80::/64 | :: | eth0 | U | [ 9.633026] cloud-init[573]: ci-info: | 3 | local | :: | eth0 | U | [ 9.635377] cloud-init[573]: ci-info: | 4 | multicast | :: | eth0 | U | [ 9.637731] cloud-init[573]: ci-info: +-------+-------------+---------+-----------+-------+ [ 9.771947] sr 0:0:0:2: [sr0] tag#24 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [ 9.777568] sr 0:0:0:2: [sr0] tag#24 Sense Key : Not Ready [current] [ 9.781656] sr 0:0:0:2: [sr0] tag#24 Add. Sense: Medium not present - tray open [ 9.786288] sr 0:0:0:2: [sr0] tag#24 CDB: Read(10) 28 00 00 00 00 02 00 00 02 00 [ 9.790996] blk_update_request: I/O error, dev sr0, sector 8 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0 [ 9.796998] sr 0:0:0:2: [sr0] tag#308 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [ 9.802452] sr 0:0:0:2: [sr0] tag#308 Sense Key : Not Ready [current] [ 9.806512] sr 0:0:0:2: [sr0] tag#308 Add. Sense: Medium not present - tray open [ 9.811511] sr 0:0:0:2: [sr0] tag#308 CDB: Read(10) 28 00 00 00 00 02 00 00 02 00 [ 9.816046] blk_update_request: I/O error, dev sr0, sector 8 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0 [ 9.821579] Buffer I/O error on dev sr0, logical block 1, async page read [ 9.999644] sdb: sdb1 [ 10.193409] EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null) [ 10.874886] cloud-init[573]: Generating public/private rsa key pair. [ 10.877632] cloud-init[573]: Your identification has been saved in /etc/ssh/ssh_host_rsa_key [ 10.880448] cloud-init[573]: Your public key has been saved in /etc/ssh/ssh_host_rsa_key.pub [ 10.883543] cloud-init[573]: The key fingerprint is: [ 10.888646] cloud-init[573]: The key's randomart image is: [ 10.910358] cloud-init[573]: Generating public/private dsa key pair. [ 10.912595] cloud-init[573]: Your identification has been saved in /etc/ssh/ssh_host_dsa_key [ 10.915533] cloud-init[573]: Your public key has been saved in /etc/ssh/ssh_host_dsa_key.pub [ 10.918463] cloud-init[573]: The key fingerprint is: [ 10.924315] cloud-init[573]: The key's randomart image is: [ 10.941929] cloud-init[573]: Generating public/private ecdsa key pair. [ 10.943878] cloud-init[573]: Your identification has been saved in /etc/ssh/ssh_host_ecdsa_key [ 10.946574] cloud-init[573]: Your public key has been saved in /etc/ssh/ssh_host_ecdsa_key.pub [ 10.949431] cloud-init[573]: The key fingerprint is: [ OK ] Finished Initial cloud-ini…ob (metadata service crawler). [ 10.953620] cloud-init[573]: SHA256: root@agent1ac4000003 [ OK ] Reached target Cloud-config availability. [ OK ] Reached target Network is Online. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on cloud-init hotplug hook socket. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Listening on UUID daemon activation socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting chrony, an NTP client/server... Starting Apply the settings specified in cloud-config... [ OK ] Started Regular background program processing daemon. [ 10.958466] cloud-init[573]: The key's randomart image is: [ OK ] Started D-Bus System Message Bus. Starting Remove Stale Onli…t4 Metadata Check Snapshots... Starting System Logging Service... Starting User Login Management... Starting Permit User Sessions... Starting Microsft Azure Linux Agent (provision)... [ OK ] Finished Permit User Sessions. [ OK ] Started Getty on tty1. [ 11.055840] cloud-init[573]: Generating public/private ed25519 key pair. [ OK ] Started Serial Getty on ttyS0. [ 11.072351] cloud-init[573]: Your identification has been saved in /etc/ssh/ssh_host_ed25519_key [ 11.078234] cloud-init[573]: Your public key has been saved in /etc/ssh/ssh_host_ed25519_key.pub [ 11.081256] cloud-init[573]: The key fingerprint is: [ OK ] Reached target Login Prompts. [ OK ] Started System Logging Service. [ 11.097833] cloud-init[573]: The key's randomart image is: [ OK ] Started chrony, an NTP client/server. [ OK ] Reached target System Time Synchronized. [ OK ] Started Daily apt download activities. [ OK ] Started Daily apt upgrade and clean activities. [ OK ] Started Periodic ext4 Onli…ata Check for All Filesystems. [ OK ] Started Discard unused blocks once a week. [ OK ] Started Daily rotation of log files. [ OK ] Started Daily man-db regeneration. [ OK ] Reached target Timers. [ OK ] Started User Login Management. [ OK ] Started Unattended Upgrades Shutdown. [ OK ] Finished Remove Stale Onli…ext4 Metadata Check Snapshots. 2023-07-26T20:30:48.411563Z INFO MainThread cloud-init is enabled: True 2023-07-26T20:30:48.414463Z INFO MainThread Using cloud-init for provisioning 2023-07-26T20:30:48.416915Z INFO MainThread Running CloudInit provisioning handler 2023-07-26T20:30:48.423571Z INFO MainThread Detect protocol endpoints 2023-07-26T20:30:48.425670Z INFO MainThread Clean protocol and wireserver endpoint 2023-07-26T20:30:48.428234Z INFO MainThread WireServer endpoint is not found. Rerun dhcp handler 2023-07-26T20:30:48.430876Z INFO MainThread Test for route to 168.63.129.16 2023-07-26T20:30:48.433107Z INFO MainThread Route to 168.63.129.16 exists 2023-07-26T20:30:48.435201Z INFO MainThread Wire server endpoint:168.63.129.16 2023-07-26T20:30:48.442937Z INFO MainThread Fabric preferred wire protocol version:2015-04-05 2023-07-26T20:30:48.445912Z INFO MainThread Wire protocol version:2012-11-30 2023-07-26T20:30:48.448004Z INFO MainThread Server preferred version:2015-04-05 2023-07-26T20:30:48.594735Z INFO MainThread Initializing goal state during protocol detection 2023-07-26T20:30:48.602281Z INFO MainThread Fetching new goal state [incarnation 1 (force update)] [ 11.579554] cloud-init[706]: Cloud-init v. 22.2 running 'modules:config' at Wed, 26 Jul 2023 20:30:48 +0000. Up 11.49 seconds. 2023-07-26T20:30:48.662980Z INFO MainThread Certificate with thumbprint F4D3711C36133C1D4E82CE72D2AE5666B2D09EA5 has no matching private key. 2023-07-26T20:30:48.672851Z INFO MainThread Fetch goal state completed 2023-07-26T20:30:48.680886Z INFO MainThread ssh host key found at: /etc/ssh/ssh_host_rsa_key.pub 2023-07-26T20:30:48.693313Z INFO MainThread Thumbprint obtained from : /etc/ssh/ssh_host_rsa_key.pub [ 11.682749] device-mapper: uevent: version 1.0.3 2023-07-26T20:30[ 11.686112] device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com :48.697465Z INFO MainThread Finished provisioning [ OK ] Finished Apply the settings specified in cloud-config. [ OK ] Finished Microsft Azure Linux Agent (provision). Starting OpenBSD Secure Shell server... [ OK ] Started Microsft Azure Linux Agent (apt setup). [ OK ] Started OpenBSD Secure Shell server. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Execute cloud user/final scripts... Starting Update UTMP about System Runlevel Changes... [ OK ] Started Microsft Azure Linux Agent. [ OK ] Finished Update UTMP about System Runlevel Changes. [ 12.836780] apt-setup[731]: Get:1 http://debian-archive.trafficmanager.net/debian bullseye InRelease [116 kB] [ 12.924555] apt-setup[731]: Get:2 http://debian-archive.trafficmanager.net/debian-security bullseye-security InRelease [48.4 kB] [ 12.932744] apt-setup[731]: Get:3 http://debian-archive.trafficmanager.net/debian bullseye-updates InRelease [44.1 kB] [ 12.952807] apt-setup[731]: Get:4 http://debian-archive.trafficmanager.net/debian bullseye-backports InRelease [49.0 kB] 2023-07-26T20:30:50.057221Z INFO Daemon Daemon Azure Linux Agent Version:2.2.47 2023-07-26T20:30:50.060304Z INFO Daemon Daemon OS: debian 11 2023-07-26T20:30:50.063666Z INFO Daemon Daemon Python: 3.9.2 2023-07-26T20:30:50.065982Z INFO Daemon Daemon Run daemon 2023-07-26T20:30:50.069110Z INFO Daemon Daemon No RDMA handler exists for distro='Debian GNU/Linux' version='11' 2023-07-26T20:30:50.086565Z INFO Daemon Daemon cloud-init is enabled: True 2023-07-26T20:30:50.089393Z INFO Daemon Daemon Using cloud-init for provisioning 2023-07-26T20:30:50.103663Z INFO Daemon Daemon cloud-init is enabled: True 2023-07-26T20:30:50.106162Z INFO Daemon Daemon Using cloud-init for provisioning 2023-07-26T20:30:50.108746Z INFO Daemon Daemon Clean protocol and wireserver endpoint 2023-07-26T20:30:50.112242Z INFO Daemon Daemon Provisioning already completed, skipping. 2023-07-26T20:30:50.114926Z INFO Daemon Daemon Detect protocol endpoints 2023-07-26T20:30:50.117271Z INFO Daemon Daemon Clean protocol and wireserver endpoint 2023-07-26T20:30:50.119883Z INFO Daemon Daemon WireServer endpoint is not found. Rerun dhcp handler 2023-07-26T20:30:50.122665Z INFO Daemon Daemon Test for route to 168.63.129.16 2023-07-26T20:30:50.125576Z INFO Daemon Daemon Route to 168.63.129.16 exists 2023-07-26T20:30:50.127773Z INFO Daemon Daemon Wire server endpoint:168.63.129.16 2023-07-26T20:30:50.139216Z INFO Daemon Daemon Fabric preferred wire protocol version:2015-04-05 2023-07-26T20:30:50.143337Z INFO Daemon Daemon Wire protocol version:2012-11-30 2023-07-26T20:30:50.146170Z INFO Daemon Daemon Server preferred version:2015-04-05 [ 13.232177] cloud-init[827]: Cloud-init v. 22.2 running 'modules:final' at Wed, 26 Jul 2023 20:30:50 +0000. Up 13.06 seconds. [ 13.270154] apt-setup[731]: Get:5 http://debian-archive.trafficmanager.net/debian bullseye/main Sources [8637 kB] ci-info: +++++++++++++++++++++++++++++++++Authorized keys from /home/vsagent/.ssh/authorized_keys for user vsagent++++++++++++++++++++++++++++++++++ ci-info: +---------+-------------------------------------------------------------------------------------------------+---------+---------------------+ 2023-07-26T20:30:50.347154Z INFO Daemon Daemon Initializing goal state during protocol detection ci-info: | Keytype | Fingerprint (sha256) | Options | Comment | ci-info: +---------+-------------------------------------------------------------------------------------------------+---------+---------------------+ ci-info: | ssh-rsa | | - | luizmonad@LuizMonad | 2023-07-26T20:30:50.371209Z INFO Daemon Daemon Fetching new goal state [incarnation 1 (force update)] ci-info: +---------+-------------------------------------------------------------------------------------------------+---------+---------------------+ 2023-07-26T20:30:50.451761Z INFO Daemon Daemon Certificate with thumbprint has no matching private key. 2023-07-26T20:30:50.463585Z INFO Daemon Daemon Fetch goal state completed 2023-07-26T20:30:50.494236Z WARNING Daemon Daemon Could not mount cgroups: [Errno 1] Operation not permitted: '/sys/fs/cgroup/cpu,cpuacct' -> '/sys/fs/cgroup/cpu' <14>Jul 26 20:30:50 cloud-init: ############################################################# <14>Jul 26 20:30:50 cloud-init: -----BEGIN SSH HOST KEY FINGERPRINTS----- <14>Jul 26 20:30:50 cloud-init: -----END SSH HOST KEY FINGERPRINTS----- <14>Jul 26 20:30:50 cloud-init: ############################################################# -----BEGIN SSH HOST KEY KEYS----- -----END SSH HOST KEY KEYS----- 2023-07-26T20:30:50.507717Z INFO Daemon Daemon CGroups Status: [Errno 1] Operation not permitted: '/sys/fs/cgroup/cpu,cpuacct' -> '/sys/fs/cgroup/cpu' 2023-07-26T20:30:50.556865Z INFO Daemon Daemon RDMA capabilities are not enabled, skipping 2023-07-26T20:30:50.560053Z INFO Daemon Daemon Installed Agent WALinuxAgent-2.2.47 is the most current agent [ 13.536336] apt-setup[731]: Get:6 http://debian-archive.trafficmanager.net/debian bullseye/main amd64 Packages [8183 kB] [ 13.554194] cloud-init[827]: Cloud-init v. 22.2 finished at Wed, 26 Jul 2023 20:30:50 +0000. Datasource DataSourceAzure [seed=/dev/sr0]. Up 13.52 seconds [ OK ] Finished Execute cloud user/final scripts. [ OK ] Reached target Cloud-init target. [ 13.717005] apt-setup[731]: Get:7 http://debian-archive.trafficmanager.net/debian bullseye/main Translation-en [6240 kB] [ 13.796222] apt-setup[731]: Get:8 http://debian-archive.trafficmanager.net/debian-security bullseye-security/main Sources [204 kB] [ 13.811737] apt-setup[731]: Get:9 http://debian-archive.trafficmanager.net/debian-security bullseye-security/main amd64 Packages [252 kB] [ 13.819117] apt-setup[731]: Get:10 http://debian-archive.trafficmanager.net/debian-security bullseye-security/main Translation-en [164 kB] [ 13.922541] apt-setup[731]: Get:11 http://debian-archive.trafficmanager.net/debian bullseye-updates/main Sources [5084 B] 2023-07-26T20:30:50.964777Z INFO ExtHandler ExtHandler Agent WALinuxAgent-2.2.47 is running as the goal state agent 2023-07-26T20:30:50.966612Z INFO ExtHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2023-07-26T20:30:50.967483Z INFO ExtHandler ExtHandler Wire server endpoint:168.63.129.16 2023-07-26T20:30:50.978317Z INFO ExtHandler ExtHandler Fetching new goal state [incarnation 1 (force update)] [ 13.943548] apt-setup[731]: Get:12 http://debian-archive.trafficmanager.net/debian bullseye-updates/main amd64 Packages [14.8 kB] [ 13.946008] apt-setup[731]: Get:13 http://debian-archive.trafficmanager.net/debian bullseye-updates/main Translation-en [8129 B] 2023-07-26T20:30:51.079862Z INFO ExtHandler ExtHandler Certificate with thumbprint has no matching private key. 2023-07-26T20:30:51.093171Z INFO ExtHandler ExtHandler Fetch goal state completed 2023-07-26T20:30:51.107370Z INFO ExtHandler ExtHandler Distro info: debian 11, osutil class being used: DebianOSModernUtil, agent service name: walinuxagent 2023-07-26T20:30:51.120722Z INFO ExtHandler ExtHandler Start env monitor service. 2023-07-26T20:30:51.121771Z INFO ExtHandler ExtHandler Configure routes 2023-07-26T20:30:51.122367Z INFO ExtHandler ExtHandler Gateway:None 2023-07-26T20:30:51.122837Z INFO ExtHandler ExtHandler Routes:None 2023-07-26T20:30:51.123277Z INFO ExtHandler ExtHandler Hostname record does not exist, creating [/var/lib/waagent/published_hostname] with hostname [agent1ac4000003] 2023-07-26T20:30:51.120379Z INFO MonitorHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2023-07-26T20:30:51.126202Z INFO MonitorHandler ExtHandler Wire server endpoint:168.63.129.16 2023-07-26T20:30:51.137802Z INFO ExtHandler ExtHandler WALinuxAgent-2.2.47 running as process 939 2023-07-26T20:30:51.140604Z INFO ExtHandler ExtHandler CGroups Status: The cgroup filesystem is ready to use [ 14.107758] apt-setup[731]: Get:14 http://debian-archive.trafficmanager.net/debian bullseye-backports/main Sources [438 kB] 2023-07-26T20:30:51.147152Z WARNING ExtHandler ExtHandler Failed to create a cgroup for the VM Agent; resource usage for the Agent will not be tracked. Error: [CGroupsException] Failed to get paths of agent's cgroups. Error: join() argument must be str, bytes, or os.PathLike object, not 'NoneType' 2023-07-26T20:30:51.149164Z INFO EnvHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2023-07-26T20:30:51.150412Z INFO EnvHandler ExtHandler Wire server endpoint:168.63.129.16 2023-07-26T20:30:51.151606Z INFO EnvHandler ExtHandler Set block dev timeout: sdb with timeout: 300 2023-07-26T20:30:51.152497Z INFO EnvHandler ExtHandler Set block dev timeout: sda with timeout: 300 [ 14.130113] apt-setup[731]: Get:15 http://debian-archive.trafficmanager.net/debian bullseye-backports/main amd64 Packages [422 kB] [ 14.131297] apt-setup[731]: Get:16 http://debian-archive.trafficmanager.net/debian bullseye-backports/main Translation-en [353 kB] 2023-07-26T20:30:51.214140Z INFO MonitorHandler ExtHandler Route table: [{"Iface": "eth0", "Destination": "0.0.0.0", "Gateway": "10.0.0.1", "Mask": "0.0.0.0", "Flags": "0x0003", "Metric": "0"},{"Iface": "eth0", "Destination": "10.0.0.0", "Gateway": "0.0.0.0", "Mask": "255.255.255.0", "Flags": "0x0001", "Metric": "0"},{"Iface": "eth0", "Destination": "168.63.129.16", "Gateway": "10.0.0.1", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "0"},{"Iface": "eth0", "Destination": "169.254.169.254", "Gateway": "10.0.0.1", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "0"}] 2023-07-26T20:30:51.266079Z INFO MonitorHandler ExtHandler Initial NIC state: [{ "name": "lo", "link": " 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": " mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000\ link/ether 60:45:bd:c8:3e:59 brd ff:ff:ff:ff:ff:ff" }] 2023-07-26T20:30:51.428233Z INFO ExtHandler ExtHandler Created slice for walinuxagent extensions system-walinuxagent.extensions.slice 2023-07-26T20:30:51.486510Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Target handler state: enabled [incarnation 1] 2023-07-26T20:30:51.487960Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] [Enable] current handler state is: notinstalled 2023-07-26T20:30:51.488487Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Downloading extension package: https://umsanpg40jst2qkqrh1w.blob.core.windows.net/5237dd14-0aad-f051-0fad-1e33e1b63091/5237dd14-0aad-f051-0fad-1e33e1b63091_2.1.10.zip 2023-07-26T20:30:51.636423Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Unzipping extension package: /var/lib/waagent/Microsoft.Azure.Extensions.CustomScript__2.1.10.zip Debian GNU/Linux 11 agent1ac4000003 ttyS0 agent1ac4000003 login: 2023-07-26T20:30:51.811587Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Initializing extension Microsoft.Azure.Extensions.CustomScript-2.1.10 2023-07-26T20:30:52.068251Z INFO ExtHandler ExtHandler Created slice for system-walinuxagent.extensions-Microsoft.Azure.Extensions.CustomScript_2.1.10.slice 2023-07-26T20:30:52.069673Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot retrieve cgroup for extension Microsoft.Azure.Extensions.CustomScript-2.1.10; resource usage will not be tracked. 2023-07-26T20:30:52.070800Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Update settings file: 1.settings 2023-07-26T20:30:52.071434Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Install extension [bin/custom-script-shim install] 2023-07-26T20:30:52.087457Z INFO ExtHandler ExtHandler Started extension using scope 'Microsoft.Azure.Extensions.CustomScript_2.1.10_c1a3b090-db64-4090-a351-5bdde65cc181' 2023-07-26T20:30:52.088690Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot create cgroup for extension Microsoft.Azure.Extensions.CustomScript-2.1.10; resource usage will not be tracked. 2023-07-26T20:30:52.089478Z INFO ExtHandler ExtHandler Started tracking new cgroup: Microsoft.Azure.Extensions.CustomScript-2.1.10, path: /sys/fs/cgroup/memory/system.slice/Microsoft.Azure.Extensions.CustomScript_2.1.10_c1a3b090-db64-4090-a351-5bdde65cc181.scope 2023-07-26T20:30:54.093599Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Enable extension [bin/custom-script-shim enable] 2023-07-26T20:30:54.098239Z INFO ExtHandler ExtHandler Started extension using scope 'Microsoft.Azure.Extensions.CustomScript_2.1.10_54953994-4564-4365-963b-4d922b0f4339' 2023-07-26T20:30:54.099429Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot create cgroup for extension Microsoft.Azure.Extensions.CustomScript-2.1.10; resource usage will not be tracked. 2023-07-26T20:30:54.100230Z INFO ExtHandler ExtHandler Started tracking new cgroup: Microsoft.Azure.Extensions.CustomScript-2.1.10, path: /sys/fs/cgroup/memory/system.slice/Microsoft.Azure.Extensions.CustomScript_2.1.10_54953994-4564-4365-963b-4d922b0f4339.scope [ 18.134684] apt-setup[731]: Fetched 25.2 MB in 5s (4670 kB/s) [ 18.696829] apt-setup[731]: Reading package lists... 2023-07-26T20:30:56.129655Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Target handler state: enabled [incarnation 1] 2023-07-26T20:30:56.134331Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] [Enable] current handler state is: notinstalled 2023-07-26T20:30:56.138878Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Downloading extension package: https://umsah0twc0d25lndsc0j.blob.core.windows.net/bab0cbee-153b-ca2c-b8ec-eea35f48a1e8/bab0cbee-153b-ca2c-b8ec-eea35f48a1e8_1.27.4.zip 2023-07-26T20:30:57.446473Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Unzipping extension package: /var/lib/waagent/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent__1.27.4.zip 2023-07-26T20:30:58.825997Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Initializing extension Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4 2023-07-26T20:30:59.001450Z INFO ExtHandler ExtHandler Created slice for system-walinuxagent.extensions-Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4.slice 2023-07-26T20:30:59.006698Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot retrieve cgroup for extension Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4; resource usage will not be tracked. 2023-07-26T20:30:59.013044Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Extension has no settings, write empty 0.settings 2023-07-26T20:30:59.017213Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Install extension [./shim.sh -install] 2023-07-26T20:30:59.023154Z INFO ExtHandler ExtHandler Started extension using scope 'Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4_1c8e6114-0b6e-4d56-81dc-05a064e6223f' 2023-07-26T20:30:59.028683Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot create cgroup for extension Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4; resource usage will not be tracked. 2023-07-26T20:30:59.035747Z INFO ExtHandler ExtHandler Started tracking new cgroup: Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4, path: /sys/fs/cgroup/memory/system.slice/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4_1c8e6114-0b6e-4d56-81dc-05a064e6223f.scope 2023-07-26T20:31:07.088337Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Enable extension [./shim.sh -enable] 2023-07-26T20:31:07.096108Z INFO ExtHandler ExtHandler Started extension using scope 'Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4_8cf834c7-961c-4c04-9308-d6c7e866d491' 2023-07-26T20:31:07.097620Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot create cgroup for extension Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4; resource usage will not be tracked. 2023-07-26T20:31:07.098483Z INFO ExtHandler ExtHandler Started tracking new cgroup: Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4, path: /sys/fs/cgroup/memory/system.slice/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4_8cf834c7-961c-4c04-9308-d6c7e866d491.scope 2023-07-26T20:31:12.131191Z INFO ExtHandler ExtHandler ProcessGoalState completed [incarnation 1; 20695 ms] 2023-07-26T20:31:12.173585Z ERROR ExtHandler ExtHandler Command: [iptables -w -t security -L OUTPUT --zero OUTPUT -nxv], return code: [4], result: [Chain OUTPUT (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination Zeroing chain `OUTPUT' ] 2023-07-26T20:31:12.175528Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.47 is running as the goal state agent [ 52.004583] hv_balloon: Max. dynamic memory size: 8192 MB ```
Boot log - another capture after a reboot ``` [ 6.098249] systemd[1]: Starting Microsft Azure Linux Agent (resourcedisk)... Starting Microsft Azure Linux Agent (resourcedisk)... [ 6.108151] systemd[1]: Mounted Huge Pages File System. [ 6.111966] EXT4-fs (sda1): re-mounted. Opts: discard,errors=remount-ro [ OK ] Mounted Huge Pages File System. [ 6.118980] systemd[1]: Mounted POSIX Message Queue File System. [ OK ] Mounted POSIX Message Queue File System. [ 6.124814] systemd[1]: Mounted Kernel Debug File System. [ OK ] Mounted Kernel Debug File System. [ 6.130520] systemd[1]: Mounted Kernel Trace File System. [ OK ] Mounted Kernel Trace File System. [ 6.136400] systemd[1]: Finished Create list of static device nodes for the current kernel. [ OK ] Finished Create list of st… nodes for the current kernel. [ 6.143998] systemd[1]: modprobe@configfs.service: Succeeded. [ 6.163180] systemd[1]: Finished Load Kernel Module configfs. [ OK ] Finished Load Kernel Module configfs. [ 6.169328] systemd[1]: modprobe@drm.service: Succeeded. [ 6.173036] systemd[1]: Finished Load Kernel Module drm. [ OK ] Finished Load Kernel Module drm. [ 6.179889] systemd[1]: modprobe@fuse.service: Succeeded. [ 6.184550] systemd[1]: Finished Load Kernel Module fuse. [ OK ] Finished Load Kernel Module fuse. [ 6.191337] systemd[1]: Finished Load Kernel Modules. [ OK ] Finished Load Kernel Modules. [ 6.198221] systemd[1]: Finished Remount Root and Kernel File Systems. [ OK ] Finished Remount Root and Kernel File Systems. [ 6.233038] systemd[1]: Mounting FUSE Control File System... Mounting FUSE Control File System... [ 6.242035] systemd[1]: Mounting Kernel Configuration File System... Mounting Kernel Configuration File System... [ 6.252531] systemd[1]: Starting Initial cloud-init job (pre-networking)... Starting Initial cloud-init job (pre-networking)... [ 6.264010] systemd[1]: Starting Grow File System on /... Starting Grow File System on /... [ 6.270188] systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. [ 6.273903] EXT4-fs (sda1): resizing filesystem from 7831296 to 7831296 blocks [ 6.275377] systemd[1]: Condition check resulted in Platform Persistent Storage Archival being skipped. [ 6.303911] systemd[1]: Starting Load/Save Random Seed... Starting Load/Save Random Seed... [ 6.311308] systemd[1]: Starting Apply Kernel Variables... Starting Apply Kernel Variables... [ 6.321703] systemd[1]: Starting Create System Users... Starting Create System Users... [ 6.328775] systemd[1]: Mounted FUSE Control File System. [ OK ] Mounted FUSE Control File System. [ 6.337160] systemd[1]: Mounted Kernel Configuration File System. [ OK ] Mounted Kernel Configuration File System. [ 6.344006] systemd[1]: Finished Coldplug All udev Devices. [ OK ] Finished Coldplug All udev Devices. [ 6.351547] systemd[1]: Finished Grow File System on /. [ OK ] Finished Grow File System on /. [ 6.379410] systemd[1]: Finished Load/Save Random Seed. [ OK ] Finished Load/Save Random Seed. [ 6.386027] systemd[1]: Finished Apply Kernel Variables. [ OK ] Finished Apply Kernel Variables. [ 6.392407] systemd[1]: Finished Create System Users. [ OK ] Finished Create System Users. [ 6.398356] systemd[1]: Condition check resulted in First Boot Complete being skipped. [ 6.420237] systemd[1]: Starting Helper to synchronize boot up for ifupdown... Starting Helper to synchronize boot up for ifupdown... [ 6.429263] systemd[1]: Starting Create Static Device Nodes in /dev... Starting Create Static Device Nodes in /dev... [ 6.441672] systemd[1]: Finished Helper to synchronize boot up for ifupdown. [ OK ] Finished Helper to synchronize boot up for ifupdown. [ 6.475378] systemd[1]: Finished Create Static Device Nodes in /dev. [ OK ] Finished Create Static Device Nodes in /dev. [ 6.482396] systemd[1]: Reached target Local File Systems (Pre). [ OK ] Reached target Local File Systems (Pre). [ 6.508764] systemd[1]: Starting Rule-based Manager for Device Events and Files... Starting Rule-based Manage…for Device Events and Files... [ 6.584142] systemd[1]: Started Rule-based Manager for Device Events and Files. [ OK ] Started Rule-based Manager for Device Events and Files. [ 6.594185] systemd[1]: Started Journal Service. [ OK ] Started Journal Service. Starting Flush Journal to Persistent Storage... [ 6.632956] systemd-journald[214]: Received client request to flush runtime journal. [ OK ] Finished Flush Journal to Persistent Storage. [ 6.695482] pps_core: LinuxPPS API ver. 1 registered [ 6.699651] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 6.699689] hv_vmbus: registering driver hyperv_fb [ 6.708294] hv_vmbus: registering driver hv_balloon [ 6.718241] hv_balloon: Using Dynamic Memory protocol version 2.0 [ 6.732782] PTP clock support registered [ 6.738296] hv_vmbus: registering driver hyperv_keyboard [ 6.746518] sd 0:0:0:0: Attached scsi generic sg0 type 0 [ 6.752058] input: AT Translated Set 2 keyboard as /devices/LNXSYSTM:00/LNXSYBUS:00/ACPI0004:00/VMBUS:00/d34b2567-b9b6-42b9-8778-0a4ec0b955bf/serio0/input/input0 [ 6.764295] pstore: Using crash dump compression: deflate [ 6.768222] pstore: Registered efi as persistent store backend [ OK ] Found device /dev/ttyS0. [ 6.787355] sd 0:0:0:1: Attached scsi generic sg1 type 0 [ 6.794286] hyperv_fb: Synthvid Version major 3, minor 5 [ 6.800039] hyperv_fb: Screen resolution: 1024x768, Color depth: 32, Frame buffer size: 8388608 [ 6.811688] fb0: switching to hyperv_fb from EFI VGA [ 6.813584] sr 0:0:0:2: Attached scsi generic sg2 type 5 [ 6.819799] Console: switching to colour dummy device 80x25 [ 6.823309] Console: switching to colour frame buffer device 128x48 [ 6.834445] hv_utils: Registering HyperV Utility Driver [ 6.837241] hv_vmbus: registering driver hv_utils 2023-07-26T20:32:46.390234Z INFO MainThread cloud-init is enabled: True 2023-07-26T20:32:46.393570Z INFO MainThread Using cloud-init for provisioning [ 6.874292] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 6.909082] cryptd: max_cpu_qlen set to 1000 [ 6.912031] hv_utils: Heartbeat IC version 3.0 [ 6.914201] hv_utils: Shutdown IC version 3.2 [ 6.916547] hv_utils: TimeSync IC version 4.0 [ OK ] Finished Microsft Azure Linux Agent (resourcedisk). [ OK ] Started Hyper-V key-value pair (KVP) daemon. [ 6.951903] AVX2 version of gcm_enc/dec engaged. [ 6.954152] AES CTR mode by8 optimization enabled [ 6.988733] hv_utils: KVP IC version 4.0 [ OK ] Found device Virtual_Disk 15. Mounting /boot/efi... [ OK ] Found device /sys/subsystem/net/devices/eth0. [ 7.100008] cloud-init[359]: Cloud-init v. 22.2 running 'init-local' at Wed, 26 Jul 2023 20:32:49 +0000. Up 7.04 seconds. [ OK ] Found device Virtual_Disk 1. Starting File System Check…/cloud/azure_resource-part1... [ OK ] Mounted /boot/efi. [ OK ] Reached target Local File Systems. Starting Load AppArmor profiles... Starting Create Volatile Files and Directories... [ OK ] Started File System Check Daemon to report status. [ OK ] Finished Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... [ 7.262557] audit: type=1400 audit(1690403569.748:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="lsb_release" pid=393 comm="apparmor_parser" [ OK ] Finished Update UTMP about System Boot/Shutdown. [ 7.280977] audit: type=1400 audit(1690403569.768:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/chronyd" pid=394 comm="apparmor_parser" [ 7.308235] audit: type=1400 audit(1690403569.788:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="tcpdump" pid=395 comm="apparmor_parser" [ 7.320027] audit: type=1400 audit(1690403569.808:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/man" pid=396 comm="apparmor_parser" [ 7.328417] audit: type=1400 audit(1690403569.808:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_filter" pid=396 comm="apparmor_parser" [ 7.336927] KVM: vmx: using Hyper-V Enlightened VMCS [ OK ] Finished Load AppArmor profiles. [ 7.343521] audit: type=1400 audit(1690403569.808:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_groff" pid=396 comm="apparmor_parser" [ 7.363353] audit: type=1400 audit(1690403569.808:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=397 comm="apparmor_parser" [ 7.375768] audit: type=1400 audit(1690403569.808:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=397 comm="apparmor_parser" [ OK ] Finished File System Check…sk/cloud/azure_resource-part1. Mounting /mnt... [ 7.413622] EXT4-fs (sdb1): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /mnt. [ OK ] Finished Initial cloud-init job (pre-networking). [ OK ] Reached target Network (Pre). [ OK ] Started ifup for eth0. Starting Raise network interfaces... [ 7.465356] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ OK ] Finished Raise network interfaces. [ OK ] Reached target Network. Starting Initial cloud-ini… (metadata service crawler)... [ 9.250918] cloud-init[560]: Cloud-init v. 22.2 running 'init' at Wed, 26 Jul 2023 20:32:51 +0000. Up 9.23 seconds. [ 9.263369] cloud-init[560]: ci-info: +++++++++++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++++++++++ [ 9.267386] cloud-init[560]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ [ 9.271366] cloud-init[560]: ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | [ 9.275259] cloud-init[560]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ [ 9.279071] cloud-init[560]: ci-info: | eth0 | True | 10.0.0.4 | 255.255.255.0 | global | 60:45:bd:c8:3e:59 | [ 9.283031] cloud-init[560]: ci-info: | eth0 | True | fe80::6245:bdff:fec8:3e59/64 | . | link | 60:45:bd:c8:3e:59 | [ 9.287075] cloud-init[560]: ci-info: | lo | True | 127.0.0.1 | 255.0.0.0 | host | . | [ 9.291048] cloud-init[560]: ci-info: | lo | True | ::1/128 | . | host | . | [ 9.294971] cloud-init[560]: ci-info: +--------+------+------------------------------+---------------+--------+-------------------+ [ 9.298843] cloud-init[560]: ci-info: ++++++++++++++++++++++++++++++Route IPv4 info+++++++++++++++++++++++++++++++ [ 9.302336] cloud-init[560]: ci-info: +-------+-----------------+----------+-----------------+-----------+-------+ [ 9.306026] cloud-init[560]: ci-info: | Route | Destination | Gateway | Genmask | Interface | Flags | [ 9.309511] cloud-init[560]: ci-info: +-------+-----------------+----------+-----------------+-----------+-------+ [ 9.313241] cloud-init[560]: ci-info: | 0 | 0.0.0.0 | 10.0.0.1 | 0.0.0.0 | eth0 | UG | [ 9.316599] cloud-init[560]: ci-info: | 1 | 10.0.0.0 | 0.0.0.0 | 255.255.255.0 | eth0 | U | [ 9.320200] cloud-init[560]: ci-info: | 2 | 168.63.129.16 | 10.0.0.1 | 255.255.255.255 | eth0 | UGH | [ 9.323680] cloud-init[560]: ci-info: | 3 | 169.254.169.254 | 10.0.0.1 | 255.255.255.255 | eth0 | UGH | [ 9.327260] cloud-init[560]: ci-info: +-------+-----------------+----------+-----------------+-----------+-------+ [ 9.331003] cloud-init[560]: ci-info: +++++++++++++++++++Route IPv6 info+++++++++++++++++++ [ 9.334026] cloud-init[560]: ci-info: +-------+-------------+---------+-----------+-------+ [ 9.336921] cloud-init[560]: ci-info: | Route | Destination | Gateway | Interface | Flags | [ 9.339686] cloud-init[560]: ci-info: +-------+-------------+---------+-----------+-------+ [ 9.342351] cloud-init[560]: ci-info: | 1 | fe80::/64 | :: | eth0 | U | [ 9.345034] cloud-init[560]: ci-info: | 3 | local | :: | eth0 | U | [ 9.347664] cloud-init[560]: ci-info: | 4 | multicast | :: | eth0 | U | [ 9.350740] cloud-init[560]: ci-info: +-------+-------------+---------+-----------+-------+ [ 9.418872] sr 0:0:0:2: [sr0] tag#46 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE cmd_age=0s [ 9.424694] sr 0:0:0:2: [sr0] tag#46 Sense Key : Not Ready [current] [ 9.428687] sr 0:0:0:2: [sr0] tag#46 Add. Sense: Medium not present - tray closed [ 9.433209] sr 0:0:0:2: [sr0] tag#46 CDB: Read(10) 28 00 00 07 ff fc 00 00 02 00 [ 9.437743] print_req_error: 975 callbacks suppressed [ 9.437745] blk_update_request: I/O error, dev sr0, sector 2097136 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0 [ OK ] Finished Initial cloud-ini…ob (metadata service crawler). [ OK ] Reached target Cloud-config availability. [ OK ] Reached target Network is Online. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on cloud-init hotplug hook socket. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Listening on UUID daemon activation socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Azure Monitor Agent Launcher daemon (on systemd). [ OK ] Started Azure Monitor Agen…CoreAgent daemon (on systemd). Starting Azure Monitor Agent daemon (on systemd)... Starting chrony, an NTP client/server... Starting Apply the settings specified in cloud-config... [ OK ] Started Regular background program processing daemon. [ OK ] Started D-Bus System Message Bus. Starting Remove Stale Onli…t4 Metadata Check Snapshots... Starting System Logging Service... Starting User Login Management... Starting Permit User Sessions... Starting Microsft Azure Linux Agent (provision)... [ OK ] Started System Logging Service. [ OK ] Finished Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Finished Remove Stale Onli…ext4 Metadata Check Snapshots. [ OK ] Started chrony, an NTP client/server. [ OK ] Reached target System Time Synchronized. [ OK ] Started Daily apt download activities. [ OK ] Started Daily apt upgrade and clean activities. [ OK ] Started Periodic ext4 Onli…ata Check for All Filesystems. [ OK ] Started Discard unused blocks once a week. [ OK ] Started Daily rotation of log files. [ OK ] Started Daily man-db regeneration. [ OK ] Reached target Timers. [ OK ] Started User Login Management. [ OK ] Started Unattended Upgrades Shutdown. [ OK ] Started Azure Monitor Agent daemon (on systemd). 2023-07-26T20:32:55.238498Z INFO MainThread cloud-init is enabled: True 2023-07-26T20:32:55.241213Z INFO MainThread Using cloud-init for provisioning 2023-07-26T20:32:55.244149Z INFO MainThread Provisioning already completed, skipping. [ OK ] Finished Microsft Azure Linux Agent (provision). Starting OpenBSD Secure Shell server... [ OK ] Started Microsft Azure Linux Agent (apt setup). [ OK ] Started OpenBSD Secure Shell server. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Microsft Azure Linux Agent. [ OK ] Finished Update UTMP about System Runlevel Changes. [ 12.900410] cloud-init[807]: Cloud-init v. 22.2 running 'modules:config' at Wed, 26 Jul 2023 20:32:55 +0000. Up 12.78 seconds. [ OK ] Finished Apply the settings specified in cloud-config. Starting Execute cloud user/final scripts... 2023-07-26T20:32:55.573143Z INFO Daemon Daemon Azure Linux Agent Version:2.2.47 2023-07-26T20:32:55.575925Z INFO Daemon Daemon OS: debian 11 2023-07-26T20:32:55.577969Z INFO Daemon Daemon Python: 3.9.2 2023-07-26T20:32:55.580102Z INFO Daemon Daemon Run daemon 2023-07-26T20:32:55.582030Z INFO Daemon Daemon No RDMA handler exists for distro='Debian GNU/Linux' version='11' 2023-07-26T20:32:55.592774Z INFO Daemon Daemon cloud-init is enabled: True 2023-07-26T20:32:55.595305Z INFO Daemon Daemon Using cloud-init for provisioning 2023-07-26T20:32:55.605856Z INFO Daemon Daemon cloud-init is enabled: True 2023-07-26T20:32:55.608157Z INFO Daemon Daemon Using cloud-init for provisioning 2023-07-26T20:32:55.610346Z INFO Daemon Daemon Clean protocol and wireserver endpoint 2023-07-26T20:32:55.613455Z INFO Daemon Daemon Provisioning already completed, skipping. 2023-07-26T20:32:55.615986Z INFO Daemon Daemon Detect protocol endpoints 2023-07-26T20:32:55.617997Z INFO Daemon Daemon Clean protocol and wireserver endpoint 2023-07-26T20:32:55.620461Z INFO Daemon Daemon WireServer endpoint is not found. Rerun dhcp handler 2023-07-26T20:32:55.623132Z INFO Daemon Daemon Test for route to 168.63.129.16 2023-07-26T20:32:55.626073Z INFO Daemon Daemon Route to 168.63.129.16 exists 2023-07-26T20:32:55.628514Z INFO Daemon Daemon Wire server endpoint:168.63.129.16 2023-07-26T20:32:55.649487Z INFO Daemon Daemon Fabric preferred wire protocol version:2015-04-05 2023-07-26T20:32:55.653430Z INFO Daemon Daemon Wire protocol version:2012-11-30 2023-07-26T20:32:55.655805Z INFO Daemon Daemon Server preferred version:2015-04-05 2023-07-26T20:32:55.702022Z INFO Daemon Daemon Initializing goal state during protocol detection 2023-07-26T20:32:55.711682Z INFO Daemon Daemon Fetching new goal state [incarnation 1 (force update)] 2023-07-26T20:32:55.778617Z INFO Daemon Daemon Certificate with thumbprint F4D3711C36133C1D4E82CE72D2AE5666B2D09EA5 has no matching private key. 2023-07-26T20:32:55.787984Z INFO Daemon Daemon Fetch goal state completed 2023-07-26T20:32:55.825982Z WARNING Daemon Daemon Could not mount cgroups: [Errno 1] Operation not permitted: '/sys/fs/cgroup/cpu,cpuacct' -> '/sys/fs/cgroup/cpu' 2023-07-26T20:32:55.830782Z INFO Daemon Daemon CGroups Status: [Errno 1] Operation not permitted: '/sys/fs/cgroup/cpu,cpuacct' -> '/sys/fs/cgroup/cpu' 2023-07-26T20:32:55.836127Z INFO Daemon Daemon RDMA capabilities are not enabled, skipping 2023-07-26T20:32:55.839412Z INFO Daemon Daemon Installed Agent WALinuxAgent-2.2.47 is the most current agent [ 13.390196] cloud-init[841]: Cloud-init v. 22.2 running 'modules:final' at Wed, 26 Jul 2023 20:32:55 +0000. Up 13.28 seconds. [ 13.456152] cloud-init[841]: Cloud-init v. 22.2 finished at Wed, 26 Jul 2023 20:32:55 +0000. Datasource DataSourceAzure [seed=/dev/sr0]. Up 13.45 seconds [ OK ] Finished Execute cloud user/final scripts. [ OK ] Reached target Cloud-init target. 2023-07-26T20:32:56.052573Z INFO ExtHandler ExtHandler Agent WALinuxAgent-2.2.47 is running as the goal state agent 2023-07-26T20:32:56.052913Z INFO ExtHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2023-07-26T20:32:56.053328Z INFO ExtHandler ExtHandler Wire server endpoint:168.63.129.16 2023-07-26T20:32:56.059696Z INFO ExtHandler ExtHandler Fetching new goal state [incarnation 1 (force update)] 2023-07-26T20:32:56.109286Z INFO ExtHandler ExtHandler Certificate with thumbprint F4D3711C36133C1D4E82CE72D2AE5666B2D09EA5 has no matching private key. 2023-07-26T20:32:56.122241Z INFO ExtHandler ExtHandler Fetch goal state completed 2023-07-26T20:32:56.134681Z INFO ExtHandler ExtHandler Distro info: debian 11, osutil class being used: DebianOSModernUtil, agent service name: walinuxagent 2023-07-26T20:32:56.141019Z INFO MonitorHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2023-07-26T20:32:56.141221Z INFO MonitorHandler ExtHandler Wire server endpoint:168.63.129.16 2023-07-26T20:32:56.142205Z INFO ExtHandler ExtHandler Start env monitor service. 2023-07-26T20:32:56.142890Z INFO ExtHandler ExtHandler Configure routes 2023-07-26T20:32:56.143344Z INFO ExtHandler ExtHandler Gateway:None 2023-07-26T20:32:56.143751Z INFO ExtHandler ExtHandler Routes:None 2023-07-26T20:32:56.155600Z INFO EnvHandler ExtHandler WireServer endpoint 168.63.129.16 read from file 2023-07-26T20:32:56.157893Z INFO ExtHandler ExtHandler WALinuxAgent-2.2.47 running as process 839 2023-07-26T20:32:56.164007Z INFO EnvHandler ExtHandler Wire server endpoint:168.63.129.16 2023-07-26T20:32:56.164679Z INFO EnvHandler ExtHandler Set block dev timeout: sdb with timeout: 300 2023-07-26T20:32:56.166689Z INFO EnvHandler ExtHandler Set block dev timeout: sda with timeout: 300 2023-07-26T20:32:56.173298Z INFO ExtHandler ExtHandler CGroups Status: The cgroup filesystem is ready to use 2023-07-26T20:32:56.177605Z WARNING ExtHandler ExtHandler Failed to create a cgroup for the VM Agent; resource usage for the Agent will not be tracked. Error: [CGroupsException] Failed to get paths of agent's cgroups. Error: join() argument must be str, bytes, or os.PathLike object, not 'NoneType' 2023-07-26T20:32:56.205048Z INFO MonitorHandler ExtHandler Route table: [{"Iface": "eth0", "Destination": "0.0.0.0", "Gateway": "10.0.0.1", "Mask": "0.0.0.0", "Flags": "0x0003", "Metric": "0"},{"Iface": "eth0", "Destination": "10.0.0.0", "Gateway": "0.0.0.0", "Mask": "255.255.255.0", "Flags": "0x0001", "Metric": "0"},{"Iface": "eth0", "Destination": "168.63.129.16", "Gateway": "10.0.0.1", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "0"},{"Iface": "eth0", "Destination": "169.254.169.254", "Gateway": "10.0.0.1", "Mask": "255.255.255.255", "Flags": "0x0007", "Metric": "0"}] 2023-07-26T20:32:56.214950Z INFO MonitorHandler ExtHandler Initial NIC state: [{ "name": "lo", "link": " 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": " mtu 1500 qdisc mq state UP mode DEFAULT group default qlen 1000\ link/ether 60:45:bd:c8:3e:59 brd ff:ff:ff:ff:ff:ff" }] 2023-07-26T20:32:56.425219Z INFO ExtHandler ExtHandler Created slice for walinuxagent extensions system-walinuxagent.extensions.slice 2023-07-26T20:32:56.476477Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Target handler state: enabled [incarnation 1] 2023-07-26T20:32:56.481075Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] [Enable] current handler state is: enabled 2023-07-26T20:32:56.484982Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Update settings file: 1.settings 2023-07-26T20:32:56.489140Z INFO ExtHandler [Microsoft.Azure.Extensions.CustomScript-2.1.10] Enable extension [bin/custom-script-shim enable] 2023-07-26T20:32:56.495599Z INFO ExtHandler ExtHandler Started extension using scope 'Microsoft.Azure.Extensions.CustomScript_2.1.10_18a09254-77e0-4f58-937d-678ef8c11a2a' 2023-07-26T20:32:56.500946Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot create cgroup for extension Microsoft.Azure.Extensions.CustomScript-2.1.10; resource usage will not be tracked. 2023-07-26T20:32:56.507470Z INFO ExtHandler ExtHandler Started tracking new cgroup: Microsoft.Azure.Extensions.CustomScript-2.1.10, path: /sys/fs/cgroup/memory/system.slice/Microsoft.Azure.Extensions.CustomScript_2.1.10_18a09254-77e0-4f58-937d-678ef8c11a2a.scope Debian GNU/Linux 11 agent1ac4000003 ttyS0 agent1ac4000003 login: 2023-07-26T20:32:58.545676Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Target handler state: enabled [incarnation 1] 2023-07-26T20:32:58.550829Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] [Enable] current handler state is: enabled 2023-07-26T20:32:58.555167Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Extension has no settings, write empty 0.settings 2023-07-26T20:32:58.559862Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4] Enable extension [./shim.sh -enable] 2023-07-26T20:32:58.565989Z INFO ExtHandler ExtHandler Started extension using scope 'Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4_17820870-19dd-4856-818b-1837ccd576c5' 2023-07-26T20:32:58.571628Z WARNING ExtHandler ExtHandler Cgroup controller "cpu" is not mounted. Cannot create cgroup for extension Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4; resource usage will not be tracked. 2023-07-26T20:32:58.578151Z INFO ExtHandler ExtHandler Started tracking new cgroup: Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.27.4, path: /sys/fs/cgroup/memory/system.slice/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.27.4_17820870-19dd-4856-818b-1837ccd576c5.scope 2023-07-26T20:33:01.607090Z INFO ExtHandler ExtHandler ProcessGoalState completed [incarnation 1; 5174 ms] 2023-07-26T20:33:01.648707Z ERROR ExtHandler ExtHandler Command: [iptables -w -t security -L OUTPUT --zero OUTPUT -nxv], return code: [4], result: [Chain OUTPUT (policy ACCEPT 0 packets, 0 bytes) pkts bytes target prot opt in out source destination Zeroing chain `OUTPUT' ] 2023-07-26T20:33:01.649907Z INFO ExtHandler ExtHandler [HEARTBEAT] Agent WALinuxAgent-2.2.47 is running as the goal state agent [ 54.819391] hv_balloon: Max. dynamic memory size: 8192 MB ```
validis-ad commented 9 months ago

This is still an issue.

jmyeary commented 8 months ago

having this issue as well. its crashed three VMs, all Debian and ubuntu. Going to try this out

Luiz-Monad commented 8 months ago

+1

It seems utterly bizarre to leave this broken for two and a half years: cloud-init has been around for over a decade and is absolutely industry standard. To have an external agent that wades in without any reference to cloud-init renders it unusable. There is a provided mechanism to check if cloud-init is still running https://cloudinit.readthedocs.io/en/latest/reference/faq.html

Indeed, the solution for that problem is basically just use cloud-init and do everything through it. Don't use WAAgent. I was trying to use WAagent to upgrade the packages, and it runs at the wrong time.

I'm using this instead https://learn.microsoft.com/en-us/azure/virtual-machines/user-data

azps vmss create `
 --name agentpool `
 --resource-group vsagent `
 --image 'Debian:debian-11-daily:11-gen2:latest' `
 --priority Spot `
 --vm-sku Standard_D2s_v3 `
 --storage-sku StandardSSD_LRS `
 --orchestration-mode Uniform `
 --instance-count 0 `
 --eviction-policy Delete `
 --upgrade-policy-mode Manual `
 --single-placement-group false `
 --platform-fault-domain-count 1 `
 --lb-sku Basic `
 --load-balancer '' `
 --vnet-name agentnet `
 --os-disk-caching readonly `
 --authentication-type SSH `
 --generate-ssh-keys `
 --ssh-key-values ~/.ssh/id_rsa.pub `
 --admin-username vsagent `
 --user-data @"
#cloud-config
# docs: https://cloudinit.readthedocs.io/en/latest/reference/examples.html#additional-apt-configuration-and-repositories
package_update: true
packages: ['git']
"@
charlysotelo commented 6 months ago

Still a problem...