[BUG] swapfile is needlessly zeroed and apparently created twice
- Dominant language
- Python
- Stars
- 581
- Forks
- 397
- Avg merge
- 2d 15h
- Merged PRs (30d)
- 9
Description
**Describe the bug**
A simple "systemctl restart walinuxagent.service" (as performed by Debian's needrestart(1) results in a very sluggish system. Apparently this is due to a bug in walinuxagent as can be seen from ps(1) output:
root 27944 0.0 0.0 4480 92 ? S 05:32 0:00 /bin/sh -c umask 0077 && dd if=/dev/zero bs=67108864 count=64 conv=notrunc of='/res/swapfile'
root 27945 0.8 7.1 72940 66200 ? D 05:32 0:02 dd if=/dev/zero bs=67108864 count=64 conv=notrunc of=/res/swapfile
root 27946 0.0 0.0 4480 96 ? S 05:32 0:00 /bin/sh -c umask 0077 && dd if=/dev/zero bs=67108864 count=64 conv=notrunc of='/res/swapfile'
root 27947 1.1 7.1 72940 66220 ? D 05:32 0:03 dd if=/dev/zero bs=67108864 count=64 conv=notrunc of=/res/swapfile
root 29043 0.0 0.0 6080 896 pts/10 S+ 05:37 0:00 grep --color=auto dd
So that's two dd(1) processes zeroing the exact same swap file at the exact same time...
**Distro and WALinuxAgent details (please complete the following information):**
(#) root@apollo-1.destinatech.local:~
>>> lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description: Debian GNU/Linux buster/sid
Release: testing
Codename: buster
(#) root@apollo-1.destinatech.local:~
>>> waagent -version
WALinuxAgent-2.2.26 running on debian buster/sid
Python: 3.7.2
Goal state agent: 2.2.26
**Additional context**
Relevant entries from /var/log/waagent.log:
2019/01/13 05:32:18.830262 INFO Agent WALinuxAgent-2.2.26 forwarding signal 15 to WALinuxAgent-2.2.26
2019/01/13 05:32:21.254091 INFO Running default provisioning handler
2019/01/13 05:32:21.311066 INFO Azure Linux Agent Version:2.2.26
2019/01/13 05:32:21.311626 INFO Activate resource disk
2019/01/13 05:32:21.357050 INFO Copying ovf-env.xml
2019/01/13 05:32:21.393751 INFO OS: debian buster/sid
2019/01/13 05:32:21.446320 INFO Resource disk [/dev/sdb1] is already mounted [/res]
2019/01/13 05:32:21.480008 INFO Wire server endpoint:168.63.129.16
2019/01/13 05:32:21.521661 INFO Python: 3.7.2
2019/01/13 05:32:21.578896 INFO Enable swap
2019/01/13 05:32:21.614818 INFO Run daemon
2019/01/13 05:32:21.624978 ERROR Event: name=WALinuxAgent, op=Provision, message=[ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to get dvd device from /dev
Inner error: The following devices were found, but none matched the pattern [(sr[0-9]|hd[c-z]|cdrom[0-9]|cd[0-9])]: ['sg2', 'sg1', 'sg0', 'vmbus', 'ptp0', 'fb0', 'snd', 'vhost-vsock', 'vhost-net', 'uhid', 'vhci', 'vfio', 'mapper', 'uinput
', 'ppp', 'net', 'loop-control', 'cuse', 'fuse', 'vcsa6', 'vcsu6', 'vcs6', 'vcsa5', 'vcsu5', 'vcs5', 'vcsa4', 'vcsu4', 'vcs4', 'vcsa3', 'vcsu3', 'vcs3', 'vcsa2', 'vcsu2', 'vcs2', 'mqueue', 'hugepages', 'log', 'initctl', 'shm', 'autofs', '
btrfs-control', 'disk', 'sdc1', 'sdc', 'sdb1', 'sda3', 'sda2', 'sda1', 'sdb', 'sda', 'bsg', 'block', 'fd0', 'rtc', 'char', 'stderr', 'stdout', 'stdin', 'fd', 'core', 'pts', 'memory_bandwidth', 'network_throughput', 'network_latency', 'cpu
_dma_latency', 'rtc0', 'psaux', 'input', 'hpet', 'ttyS3', 'ttyS2', 'ttyS1', 'ttyS0', 'ptmx', 'snapshot', 'tty63', 'tty62', 'tty61', 'tty60', 'tty59', 'tty58', 'tty57', 'tty56', 'tty55', 'tty54', 'tty53', 'tty52', 'tty51', 'tty50', 'tty49'
, 'tty48', 'tty47', 'tty46', 'tty45', 'tty44', 'tty43', 'tty42', 'tty41', 'tty40', 'tty39', 'tty38', 'tty37', 'tty36', 'tty35', 'tty34', 'tty33', 'tty32', 'tty31', 'tty30', 'tty29', 'tty28', 'tty27', 'tty26', 'tty25', 'tty24', 'tty23', 't
ty22', 'tty21', 'tty20', 'tty19', 'tty18', 'tty17', 'tty16', 'tty15', 'tty14', 'tty13', 'tty12', 'tty11', 'tty10', 'tty9', 'tty8', 'tty7', 'tty6', 'tty5', 'tty4', 'tty3', 'tty2', 'tty1', 'vcsa1', 'vcsu1', 'vcs1', 'vcsa', 'vcsu', 'vcs', 't
ty0', 'console', 'tty', 'kmsg', 'urandom', 'random', 'full', 'zero', 'port', 'null', 'mem', 'vga_arbiter']
, duration=0
2019/01/13 05:32:21.666338 INFO Remove old swap file
2019/01/13 05:32:21.747478 INFO No RDMA handler exists for distro='debian' version='buster/sid'
2019/01/13 05:32:22.216909 ERROR Provisioning failed: [ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to get dvd device from /dev
Inner error: The following devices were found, but none matched the pattern [(sr[0-9]|hd[c-z]|cdrom[0-9]|cd[0-9])]: ['sg2', 'sg1', 'sg0', 'vmbus', 'ptp0', 'fb0', 'snd', 'vhost-vsock', 'vhost-net', 'uhid', 'vhci', 'vfio', 'mapper', 'uinput
', 'ppp', 'net', 'loop-control', 'cuse', 'fuse', 'vcsa6', 'vcsu6', 'vcs6', 'vcsa5', 'vcsu5', 'vcs5', 'vcsa4', 'vcsu4', 'vcs4', 'vcsa3', 'vcsu3', 'vcs3', 'vcsa2', 'vcsu2', 'vcs2', 'mqueue', 'hugepages', 'log', 'initctl', 'shm', 'autofs', '
btrfs-control', 'disk', 'sdc1', 'sdc', 'sdb1', 'sda3', 'sda2', 'sda1', 'sdb', 'sda', 'bsg', 'block', 'fd0', 'rtc', 'char', 'stderr', 'stdout', 'stdin', 'fd', 'core', 'pts', 'memory_bandwidth', 'network_throughput', 'network_latency', 'cpu
_dma_latency', 'rtc0', 'psaux', 'input', 'hpet', 'ttyS3', 'ttyS2', 'ttyS1', 'ttyS0', 'ptmx', 'snapshot', 'tty63', 'tty62', 'tty61', 'tty60', 'tty59', 'tty58', 'tty57', 'tty56', 'tty55', 'tty54', 'tty53', 'tty52', 'tty51', 'tty50', 'tty49'
, 'tty48', 'tty47', 'tty46', 'tty45', 'tty44', 'tty43', 'tty42', 'tty41', 'tty40', 'tty39', 'tty38', 'tty37', 'tty36', 'tty35', 'tty34', 'tty33', 'tty32', 'tty31', 'tty30', 'tty29', 'tty28', 'tty27', 'tty26', 'tty25', 'tty24', 'tty23', 't
ty22', 'tty21', 'tty20', 'tty19', 'tty18', 'tty17', 'tty16', 'tty15', 'tty14', 'tty13', 'tty12', 'tty11', 'tty10', 'tty9', 'tty8', 'tty7', 'tty6', 'tty5', 'tty4', 'tty3', 'tty2', 'tty1', 'vcsa1', 'vcsu1', 'vcs1', 'vcsa', 'vcsu', 'vcs', 't
ty0', 'console', 'tty', 'kmsg', 'urandom', 'random', 'full', 'zero', 'port', 'null', 'mem', 'vga_arbiter']
2019/01/13 05:32:22.322254 INFO Activate resource disk
2019/01/13 05:32:23.220103 INFO Create swap file
2019/01/13 05:32:23.387872 INFO Resource disk [/dev/sdb1] is already mounted [/res]
2019/01/13 05:32:23.467938 INFO Enable swap
2019/01/13 05:32:23.492581 INFO Remove old swap file
2019/01/13 05:32:23.516162 INFO Create swap file
2019/01/13 05:32:23.772865 ERROR Command: 'umask 0077 && fallocate -l 4294967296 '/res/swapfile''
2019/01/13 05:32:23.817984 ERROR Command: 'umask 0077 && fallocate -l 4294967296 '/res/swapfile''
2019/01/13 05:32:23.867820 ERROR Return code: 1
2019/01/13 05:32:23.889784 ERROR Return code: 1
2019/01/13 05:32:23.906443 ERROR Result:
2019/01/13 05:32:23.922792 ERROR Result:
2019/01/13 05:32:23.938830 INFO fallocate unsuccessful, falling back to dd
2019/01/13 05:32:23.962549 INFO fallocate unsuccessful, falling back to dd
2019/01/13 05:38:12.952517 ERROR Command: 'umask 0077 && dd if=/dev/zero bs=67108864 count=64 conv=notrunc of='/res/swapfile''
2019/01/13 05:38:12.956451 ERROR Command: 'umask 0077 && dd if=/dev/zero bs=67108864 count=64 conv=notrunc of='/res/swapfile''
2019/01/13 05:38:13.371225 ERROR Return code: 1
2019/01/13 05:38:13.393395 ERROR Return code: 1
2019/01/13 05:38:13.415976 ERROR Result:
2019/01/13 05:38:13.440641 ERROR Result:
2019/01/13 05:38:13.458955 ERROR dd unsuccessful
2019/01/13 05:38:13.478362 ERROR dd unsuccessful
2019/01/13 05:38:13.516572 ERROR Command: 'mkswap /res/swapfile'
2019/01/13 05:38:13.538247 ERROR Command: 'mkswap /res/swapfile'
2019/01/13 05:38:13.557934 ERROR Return code: 1
2019/01/13 05:38:13.573392 ERROR Return code: 1
2019/01/13 05:38:13.590904 ERROR Result: Setting up swapspace version 1, size = 3.9 GiB (4125745152 bytes)
no label, UUID=234e926f-c0b8-4579-9fb1-85af11733a6c
2019/01/13 05:38:13.622013 ERROR Result: Setting up swapspace version 1, size = 3.9 GiB (4125745152 bytes)
no label, UUID=aa8c305e-6f37-466c-bb30-99302490f99e
2019/01/13 05:38:15.346289 ERROR Command: 'swapon /res/swapfile'
2019/01/13 05:38:15.366010 INFO Enabled 4194304KB of swap at /res/swapfile
2019/01/13 05:38:15.391769 ERROR Return code: 255
2019/01/13 05:38:15.409851 INFO Clean protocol
2019/01/13 05:38:15.426641 ERROR Result:
2019/01/13 05:38:15.446552 INFO Running default provisioning handler
2019/01/13 05:38:15.465130 ERROR Failed to enable swap [ResourceDiskError] /res/swapfile
2019/01/13 05:38:15.496063 INFO Copying ovf-env.xml
2019/01/13 05:38:15.534445 INFO Detect protocol endpoints
2019/01/13 05:38:15.564670 INFO Clean protocol
2019/01/13 05:38:15.581233 INFO WireServer endpoint is not found. Rerun dhcp handler
2019/01/13 05:38:15.608966 INFO Test for route to 168.63.129.16
2019/01/13 05:38:15.629119 INFO Route to 168.63.129.16 exists
2019/01/13 05:38:15.651717 INFO Wire server endpoint:168.63.129.16
2019/01/13 05:38:15.690664 INFO Fabric preferred wire protocol version:2015-04-05
2019/01/13 05:38:15.719493 INFO Wire protocol version:2012-11-30
2019/01/13 05:38:15.741926 INFO Server preferred version:2015-04-05
2019/01/13 05:38:16.018924 ERROR Event: name=WALinuxAgent, op=Provision, message=[ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to get dvd device from /dev
Inner error: The following devices were found, but none matched the pattern [(sr[0-9]|hd[c-z]|cdrom[0-9]|cd[0-9])]: ['sg2', 'sg1', 'sg0', 'vmbus', 'ptp0', 'fb0', 'snd', 'vhost-vsock', 'vhost-net', 'uhid', 'vhci', 'vfio', 'mapper', 'uinput', 'ppp', 'net', 'loop-control', 'cuse', 'fuse', 'vcsa6', 'vcsu6', 'vcs6', 'vcsa5', 'vcsu5', 'vcs5', 'vcsa4', 'vcsu4', 'vcs4', 'vcsa3', 'vcsu3', 'vcs3', 'vcsa2', 'vcsu2', 'vcs2', 'mqueue', 'hugepages', 'log', 'initctl', 'shm', 'autofs', 'btrfs-control', 'disk', 'sdc1', 'sdc', 'sdb1', 'sda3', 'sda2', 'sda1', 'sdb', 'sda', 'bsg', 'block', 'fd0', 'rtc', 'char', 'stderr', 'stdout', 'stdin', 'fd', 'core', 'pts', 'memory_bandwidth', 'network_throughput', 'network_latency', 'cpu_dma_latency', 'rtc0', 'psaux', 'input', 'hpet', 'ttyS3', 'ttyS2', 'ttyS1', 'ttyS0', 'ptmx', 'snapshot', 'tty63', 'tty62', 'tty61', 'tty60', 'tty59', 'tty58', 'tty57', 'tty56', 'tty55', 'tty54', 'tty53', 'tty52', 'tty51', 'tty50', 'tty49', 'tty48', 'tty47', 'tty46', 'tty45', 'tty44', 'tty43', 'tty42', 'tty41', 'tty40', 'tty39', 'tty38', 'tty37', 'tty36', 'tty35', 'tty34', 'tty33', 'tty32', 'tty31', 'tty30', 'tty29', 'tty28', 'tty27', 'tty26', 'tty25', 'tty24', 'tty23', 'tty22', 'tty21', 'tty20', 'tty19', 'tty18', 'tty17', 'tty16', 'tty15', 'tty14', 'tty13', 'tty12', 'tty11', 'tty10', 'tty9', 'tty8', 'tty7', 'tty6', 'tty5', 'tty4', 'tty3', 'tty2', 'tty1', 'vcsa1', 'vcsu1', 'vcs1', 'vcsa', 'vcsu', 'vcs', 'tty0', 'console', 'tty', 'kmsg', 'urandom', 'random', 'full', 'zero', 'port', 'null', 'mem', 'vga_arbiter']
, duration=0
2019/01/13 05:38:16.513198 ERROR Provisioning failed: [ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to get dvd device from /dev
Inner error: The following devices were found, but none matched the pattern [(sr[0-9]|hd[c-z]|cdrom[0-9]|cd[0-9])]: ['sg2', 'sg1', 'sg0', 'vmbus', 'ptp0', 'fb0', 'snd', 'vhost-vsock', 'vhost-net', 'uhid', 'vhci', 'vfio', 'mapper', 'uinput', 'ppp', 'net', 'loop-control', 'cuse', 'fuse', 'vcsa6', 'vcsu6', 'vcs6', 'vcsa5', 'vcsu5', 'vcs5', 'vcsa4', 'vcsu4', 'vcs4', 'vcsa3', 'vcsu3', 'vcs3', 'vcsa2', 'vcsu2', 'vcs2', 'mqueue', 'hugepages', 'log', 'initctl', 'shm', 'autofs', 'btrfs-control', 'disk', 'sdc1', 'sdc', 'sdb1', 'sda3', 'sda2', 'sda1', 'sdb', 'sda', 'bsg', 'block', 'fd0', 'rtc', 'char', 'stderr', 'stdout', 'stdin', 'fd', 'core', 'pts', 'memory_bandwidth', 'network_throughput', 'network_latency', 'cpu_dma_latency', 'rtc0', 'psaux', 'input', 'hpet', 'ttyS3', 'ttyS2', 'ttyS1', 'ttyS0', 'ptmx', 'snapshot', 'tty63', 'tty62', 'tty61', 'tty60', 'tty59', 'tty58', 'tty57', 'tty56', 'tty55', 'tty54', 'tty53', 'tty52', 'tty51', 'tty50', 'tty49', 'tty48', 'tty47', 'tty46', 'tty45', 'tty44', 'tty43', 'tty42', 'tty41', 'tty40', 'tty39', 'tty38', 'tty37', 'tty36', 'tty35', 'tty34', 'tty33', 'tty32', 'tty31', 'tty30', 'tty29', 'tty28', 'tty27', 'tty26', 'tty25', 'tty24', 'tty23', 'tty22', 'tty21', 'tty20', 'tty19', 'tty18', 'tty17', 'tty16', 'tty15', 'tty14', 'tty13', 'tty12', 'tty11', 'tty10', 'tty9', 'tty8', 'tty7', 'tty6', 'tty5', 'tty4', 'tty3', 'tty2', 'tty1', 'vcsa1', 'vcsu1', 'vcs1', 'vcsa', 'vcsu', 'vcs', 'tty0', 'console', 'tty', 'kmsg', 'urandom', 'random', 'full', 'zero', 'port', 'null', 'mem', 'vga_arbiter']
2019/01/13 05:38:16.989740 INFO RDMA capabilities are not enabled, skipping
2019/01/13 05:38:17.024508 INFO Installed Agent WALinuxAgent-2.2.26 is the most current agent
2019/01/13 05:38:17.730858 INFO Agent WALinuxAgent-2.2.26 is running as the goal state agent
2019/01/13 05:38:17.774856 INFO Wire server endpoint:168.63.129.16
2019/01/13 05:38:17.810809 INFO Start env monitor service.
2019/01/13 05:38:17.841672 INFO Configure routes
2019/01/13 05:38:17.863878 INFO Gateway:None
2019/01/13 05:38:17.887447 INFO Routes:None
2019/01/13 05:38:17.927283 INFO WALinuxAgent-2.2.26 running as process 29197
2019/01/13 05:38:17.958822 INFO Wire server endpoint:168.63.129.16
2019/01/13 05:38:17.990777 INFO Wire server endpoint:168.63.129.16
2019/01/13 05:38:18.019853 INFO Purging disk cache, current incarnation is 3
2019/01/13 05:38:18.085014 INFO [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] Target handler state: enabled
2019/01/13 05:38:18.128990 INFO [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] [Enable] current handler state is: enabled
2019/01/13 05:38:18.177228 INFO [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] Update settings file: 0.settings
2019/01/13 05:38:18.223810 INFO [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] Enable extension [diagnostic.py -enable]
2019/01/13 05:38:18 LinuxAzureDiagnostic started to handle.
2019/01/13 05:38:18 [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] cwd is /var/lib/waagent/Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029
2019/01/13 05:38:18 [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] Change log file to /var/log/azure/Microsoft.OSTCExtensions.LinuxDiagnostic/2.3.9029/extension.log
2019/01/13 05:38:19 LinuxAzureDiagnostic started to handle.
2019/01/13 05:38:19 [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] cwd is /var/lib/waagent/Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029
2019/01/13 05:38:19 [Microsoft.OSTCExtensions.LinuxDiagnostic-2.3.9029] Change log file to /var/log/azure/Microsoft.OSTCExtensions.LinuxDiagnostic/2.3.9029/extension.log
2019/01/13 05:38:24.274484 INFO Event: name=Microsoft.OSTCExtensions.LinuxDiagnostic, op=Enable, message=Launch command succeeded: diagnostic.py -enable, duration=6035
2019/01/13 05:38:24.392401 INFO Event: name=WALinuxAgent, op=ProcessGoalState, message=Incarnation 3, duration=6401
Contributor guide
Research direction
Start by tracing the WALinuxAgent service restart path through the swap setup shown in the log, especially the repeated Remove old swap file and Create swap file entries. Reproduce the restart while observing the two fallocate or dd processes. Done means swapfile creation is not launched twice and a restart does not needlessly zero the same file concurrently.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- infrastructure
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100