Azure / Azure/azure-linux-extensions
AzureMonitorLinuxAgent causing customer package installation to fail
- Dominant language
- Python
- Stars
- 333
- Forks
- 278
- Avg merge
- 2d 9h
- Merged PRs (30d)
- 4
Description
We recently noticed many packages that customers install using [cloud-init custom data](https://cloudinit.readthedocs.io/en/latest/topics/modules.html#package-update-upgrade-install) are failing due to dpkg being locked. This seems as a recent regression as we haven't noticed that issue before. The issue happens intermittently but it's becoming more frequent. I took a deeper look at the logs and found out that it's AzureMonitorAgent that's locking dpkg.
If the agent needs to install packages, it has to run after the cloud-final.service where customer packages are installed.
You can repro this issue by simply creating a Linux VM with cloud-init custom data that installs some packages. You may need to repeat these steps a few times until you get a hit.
- Create a file "custom-data.yml" with the following content:
```
#cloud-config
package_upgrade: true
packages:
- httpd
- jq
```
- Create a Linux VM using the following command:
`az vm create -g -n --image Canonical:0001-com-ubuntu-server-focal:20_04-lts:latest --size Standard_D2ds_v5 --os-disk-size-gb 32 --admin-username azureuser --generate-ssh-keys --public-ip-sku Standard`
- SSH into the VM and check the /var/log/syslog for errors like:
` E: Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable)`
Here's sample logs for your reference:
waagent.log:
```
2022-03-02T23:11:02.690048Z INFO ExtHandler ExtHandler Executing systemctl daemon-reload...
2022-03-02T23:11:03.057827Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3] Update settings file: 0.settings
2022-03-02T23:11:03.063843Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3] Install extension [./shim.sh -install]
2022-03-02T23:11:03.065002Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3] Executing command: /var/lib/waagent/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3/./shim.sh -install with environment variables: {"AZURE_GUEST_AGENT_UNINSTALL_CMD_EXIT_CODE": "NOT_RUN", "AZURE_GUEST_AGENT_EXTENSION_PATH": "/var/lib/waagent/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3", "AZURE_GUEST_AGENT_EXTENSION_VERSION": "1.15.3", "AZURE_GUEST_AGENT_WIRE_PROTOCOL_ADDRESS": "168.63.129.16", "ConfigSequenceNumber": "0", "AZURE_GUEST_AGENT_EXTENSION_SUPPORTED_FEATURES": "[{\"Key\": \"ExtensionTelemetryPipeline\", \"Value\": \"1.0\"}]"}
2022-03-02T23:11:03.075397Z INFO ExtHandler ExtHandler Started extension in unit 'install_452b9862-b2e2-4b10-8b42-04cbdb60040d.scope'
2022-03-02T23:11:03.076427Z INFO ExtHandler ExtHandler Started tracking cgroup Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3 [/sys/fs/cgroup/cpu,cpuacct/azure.slice/azure-vmextensions.slice/azure-vmextensions-Microsoft.Azure.Monitor.AzureMonitorLinuxAgent_1.15.3.slice]
2022/03/02 23:11:03 Azure Monitoring Agent for Linux started to handle.
2022/03/02 23:11:03 [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3] cwd is /var/lib/waagent/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3
2022/03/02 23:11:03 [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3] Change log file to /var/log/azure/Microsoft.Azure.Monitor.AzureMonitorLinuxAgent/extension.log
2022-03-02T23:11:12.086285Z INFO ExtHandler [Microsoft.Azure.Monitor.AzureMonitorLinuxAgent-1.15.3] Command: ./shim.sh -install
[stdout]
2022/03/02 23dpkg and azuremonitoragent_1.15.3-build.master.348_x86_64.deb
nstall,success,0,Install succeeded
[stderr]
Running scope as unit: install_452b9862-b2e2-4b10-8b42-04cbdb60040d.scope
```
/var/log/dpkg.log:
```
2022-03-02 23:11:03 startup archives install
2022-03-02 23:11:05 install azuremonitoragent:amd64 1.15.3-build.master.348
2022-03-02 23:11:05 status half-installed azuremonitoragent:amd64 1.15.3-build.master.348
```
/var/log/syslog
```
Mar 2 23:11:04 daily-cloudinit-vm-220302230923316 cloud-init[1584]: Reading package lists...
Mar 2 23:11:04 daily-cloudinit-vm-220302230923316 cloud-init[1584]: E: Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable)
Mar 2 23:11:04 daily-cloudinit-vm-220302230923316 cloud-init[1584]: E: Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Mar 2 23:11:04 daily-cloudinit-vm-220302230923316 cloud-init[1584]: E: Could not get lock /var/lib/dpkg/lock-frontend - open (11: Resource temporarily unavailable)
Mar 2 23:11:04 daily-cloudinit-vm-220302230923316 cloud-init[1584]: E: Unable to acquire the dpkg frontend lock (/var/lib/dpkg/lock-frontend), is another process using it?
Mar 2 23:11:04 daily-cloudinit-vm-220302230923316 cloud-init[1584]: sudo: pip: command not found
```
Please have a look ASAP as this is affecting all customers installing packages using cloud-init custom data.
Contributor guide
No contributing guide indexed for this repository
Assessment
This issue has not been assessed yet.