[SCALE] Log Traceback spam about cdrom
Description
Problem/Justification
None
Impact
None
SmartDraw Connector
Katalon Manual Tests (BETA)
Activity
Show:
Umer Saleem January 17, 2022 at 2:46 PM
Umer Saleem
January 17, 2022 at 2:46 PM
@Leeroy R the spam does not stop, with or without the image present in the cdrom.
The problem is with WaLinuxAgent. WaLinuxAgent service is enabled by default in TrueNAS SCALE 21.06-BETA.1:
truenas# systemctl status walinuxagent
● walinuxagent.service - Microsft Azure Linux Agent
Loaded: loaded (/lib/systemd/system/walinuxagent.service; enabled; vendor preset: enabled)
Active: inactive (dead) since Mon 2022-01-17 02:59:32 PST; 3h 24min ago
Process: 3039 ExecStart=/usr/sbin/waagent -daemon (code=killed, signal=TERM)
Main PID: 3039 (code=killed, signal=TERM)Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.844357Z INFO Daemon Daemon Clean protocol and wireserver endpoint
Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.848447Z INFO Daemon Daemon WireServer endpoint is not found. Rerun dhcp handler
Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.853100Z INFO Daemon Daemon Test for route to xxx.xx.xxx.xx
Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.856690Z WARNING Daemon Daemon No route exists to xxx.xx.xxx.xx
Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.861173Z INFO Daemon Daemon Checking for dhcp lease cache
Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.864629Z INFO Daemon Daemon looking for leases in path [/var/lib/dhcp/dhclient.*.leases]
Jan 17 02:59:21 truenas.local waagent[3039]: 2022-01-17T10:59:21.870351Z INFO Daemon Daemon cached endpoint not found
Jan 17 02:59:32 truenas.local systemd[1]: Stopping Microsft Azure Linux Agent...
Jan 17 02:59:32 truenas.local systemd[1]: walinuxagent.service: Succeeded.
Jan 17 02:59:32 truenas.local systemd[1]: Stopped Microsft Azure Linux Agent.
truenas# waagent --version
WALinuxAgent-2.2.47 running on debian 11
Python: 3.9.2
Goal state agent: 2.2.47With the latest TrueNAS SCALE build or TrueNAS SCALE-22.02-20220115-015745, since the service is disabled by default, so you do not see any spam:
root@truenas[~]# systemctl status walinuxagent
● walinuxagent.service - Microsft Azure Linux Agent
Loaded: loaded (/lib/systemd/system/walinuxagent.service; disabled; vendor>
Active: inactive (dead)
root@truenas[~]# waagent --version
WALinuxAgent-2.4.0.2 running on debian 11
Python: 3.9.2
Goal state agent: 2.4.0.2You can stop the spam on the previous build by stopping and disabling the WaLinuxAgent service.
To stop the service:
systemctl stop walinuxagentTo disable the service entirely:
systemctl disable walinuxagentLeeroy R January 15, 2022 at 1:37 AM
Leeroy R
January 15, 2022 at 1:37 AM
Can't say that cdrom without image worked for me:
Although, after upgrade to TrueNAS-SCALE-22.02-MASTER-20220114-172926 there is no more spam in console.
Why waagent package is there in the first place?
Is it not optional and Scale would have it pre-installed by default no matter the platform?
Umer Saleem January 14, 2022 at 5:01 PM
Umer Saleem
January 14, 2022 at 5:01 PM
I was able to reproduce this issue with TrueNAS SCALE 21.06-BETA.1.
This issue is related to Microsoft Azure Linux Guest Agent. WALinuxAgent/waagent manages Linux provisioning and VM interaction with the Azure Fabric Controller. It provides the functionality for Linux IaaS deployment, for which it uses a boot-time attached DVD. This DVD includes an OVF-compliant configuration file (ovf-env.xml) that includes all provisioning information.
WALinuxAgent upon initialization, recognizes that it is running on Hyper-V and tries to fetch from ovf-env.xml DVD medium over and over again.
Following errors are seen when DVD ROM is empty:
2022-01-14T11:21:39.762037Z WARNING MainThread Mounting dvd failed [retry 2/5, sleeping 5 sec]
2022-01-14T11:21:44.990277Z WARNING MainThread Mounting dvd failed [retry 3/5, sleeping 5 sec]
2022-01-14T11:21:56.221232Z WARNING MainThread Mounting dvd failed [retry 4/5, sleeping 5 sec]
2022-01-14T11:22:01.409166Z WARNING MainThread Mounting dvd failed [retry 5/5, sleeping 5 sec]
2022-01-14T11:22:06.416573Z ERROR MainThread Provisioning failed: [ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to mount dvd device
Inner error: [mount -o ro -t udf,iso9660 /dev/sr0 /mnt/cdrom/secure] returned 32: (86.20s)
2022-01-14T11:22:06.418862Z INFO MainThread Detect protocol endpoints
2022-01-14T11:22:06.420382Z INFO MainThread Clean protocol and wireserver endpoint
2022-01-14T11:22:06.421175Z INFO MainThread WireServer endpoint is not found. Rerun dhcp handler
2022-01-14T11:22:06.422559Z INFO MainThread Test for route to 168.63.129.16
2022-01-14T11:22:06.423296Z WARNING MainThread No route exists to 168.63.129.16
2022-01-14T11:22:06.424952Z INFO MainThread Checking for dhcp lease cache
2022-01-14T11:22:06.426898Z INFO MainThread looking for leases in path [/var/lib/dhcp/dhclient.*.leases]
2022-01-14T11:22:06.428797Z INFO MainThread cached endpoint not found
2022-01-14T11:22:06.430187Z INFO MainThread Cache exists [False]
2022-01-14T11:22:06.431424Z INFO MainThread Send dhcp request
2022-01-14T11:22:06.433159Z INFO MainThread Examine /proc/net/route for primary interface
2022-01-14T11:22:06.434411Z INFO MainThread Primary interface is [eth0]
2022-01-14T11:22:06.546944Z ERROR MainThread Failed to run 'provision': Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 94, in copy_ovf_env
self.osutil.mount_dvd()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 661, in mount_dvd
raise OSUtilError("Failed to mount dvd device", inner=err)
azurelinuxagent.common.exception.OSUtilError: [OSUtilError] Failed to mount dvd device
Inner error: [mount -o ro -t udf,iso9660 /dev/sr0 /mnt/cdrom/secure] returned 32:During handling of the above exception, another exception occurred:Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 78, in run
ovf_env = self.protocol_util.copy_ovf_env()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 96, in copy_ovf_env
raise ProtocolError("[CopyOvfEnv] Error mounting dvd: "
azurelinuxagent.common.exception.ProtocolError: [ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to mount dvd device
Inner error: [mount -o ro -t udf,iso9660 /dev/sr0 /mnt/cdrom/secure] returned 32:During handling of the above exception, another exception occurred:Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/agent.py", line 183, in main
agent.provision()
File "/usr/lib/python3/dist-packages/azurelinuxagent/agent.py", line 114, in provision
provision_handler.run()
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 103, in run
self.report_not_ready("ProvisioningFailed", ustr(e))
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 305, in report_not_ready
protocol = self.protocol_util.get_protocol()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 344, in get_protocol
protocol_name, protocol = self._detect_protocol(protocols)
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 258, in _detect_protocol
protocol = self._detect_wire_protocol() \
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 225, in _detect_wire_protocol
self.dhcp_handler.run()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/dhcp.py", line 62, in run
self.send_dhcp_req()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/dhcp.py", line 166, in send_dhcp_req
mac_addr = self.osutil.get_mac_addr()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 757, in get_mac_addr
ifname = self.get_if_name()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 1054, in get_if_name
if_name = self.get_first_if()[0]
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 821, in get_first_if
ifaces = self._get_all_interfaces()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 804, in _get_all_interfaces
ifconf_buff = buff.tostring()
AttributeError: 'array.array' object has no attribute 'tostring'[ 86.377271] apt-setup[2574]: waagent did not finish provisioning yet!
2022-01-14T11:22:06.792592Z INFO Daemon Daemon Azure Linux Agent Version:2.2.47
2022-01-14T11:22:06.794333Z INFO Daemon Daemon OS: debian 11
2022-01-14T11:22:06.795068Z INFO Daemon Daemon Python: 3.9.2
2022-01-14T11:22:06.796654Z INFO Daemon Daemon Run daemon
2022-01-14T11:22:06.797241Z INFO Daemon Daemon No RDMA handler exists for distro='Debian GNU/Linux' version='11'
2022-01-14T11:22:06.804201Z INFO Daemon Daemon Error getting cloud-init enabled status from systemctl: Command '['systemctl', 'is-enabled', 'cloud-init-local.service']' returned non-zero exit status 1.
2022-01-14T11:22:06.817019Z INFO Daemon Daemon Error getting cloud-init enabled status from service: Command '['service', 'cloud-init', 'status']' returned non-zero exit status 4.
2022-01-14T11:22:06.818129Z INFO Daemon Daemon cloud-init is enabled: False
2022-01-14T11:22:06.819565Z INFO Daemon Daemon Using waagent for provisioning
2022-01-14T11:22:06.826485Z INFO Daemon Daemon Error getting cloud-init enabled status from systemctl: Command '['systemctl', 'is-enabled', 'cloud-init-local.service']' returned non-zero exit status 1.
2022-01-14T11:22:06.837171Z INFO Daemon Daemon Error getting cloud-init enabled status from service: Command '['service', 'cloud-init', 'status']' returned non-zero exit status 4.
2022-01-14T11:22:06.838653Z INFO Daemon Daemon cloud-init is enabled: False
2022-01-14T11:22:06.839961Z INFO Daemon Daemon Activate resource disk
2022-01-14T11:22:06.841307Z INFO Daemon Daemon Searching gen1 prefix 00000000-0001 or gen2 f8b3781a-1e82-4818-a1c3-63d806ec15bb
2022-01-14T11:22:06.843295Z INFO Daemon Daemon Found device: None
2022-01-14T11:22:06.843609Z ERROR Daemon Daemon Failed to mount resource disk [ResourceDiskError] unable to detect disk topology
2022-01-14T11:22:06.845182Z ERROR Daemon Daemon Event: name=WALinuxAgent, op=ActivateResourceDisk, message=[ResourceDiskError] unable to detect disk topology, duration=0
2022-01-14T11:22:06.847109Z INFO Daemon Daemon Clean protocol and wireserver endpoint
2022-01-14T11:22:06.847844Z INFO Daemon Daemon Running default provisioning handler
2022-01-14T11:22:06.889973Z INFO Daemon Daemon Copying ovf-env.xml[ OK ] Finished Execute TrueNAS custom post-init tasks.
[ OK ] Reached target TrueNAS Target.
2022-01-14T11:22:07.130346Z WARNING Daemon Daemon Mounting dvd failed [retry 1/5, sleeping 5 sec]
[ 88.219517] device-mapper: uevent: version 1.0.3
[ 88.223643] device-mapper: ioctl: 4.43.0-ioctl (2020-10-01) initialised: dm-devel@redhat.com
2022-01-14T11:22:12.337726Z WARNING Daemon Daemon Mounting dvd failed [retry 2/5, sleeping 5 sec]
2022-01-14T11:22:17.533011Z WARNING Daemon Daemon Mounting dvd failed [retry 3/5, sleeping 5 sec]
2022-01-14T11:22:22.725107Z WARNING Daemon Daemon Mounting dvd failed [retry 4/5, sleeping 5 sec]
2022-01-14T11:22:27.917146Z WARNING Daemon Daemon Mounting dvd failed [retry 5/5, sleeping 5 sec]
2022-01-14T11:22:32.928495Z ERROR Daemon Daemon Provisioning failed: [ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to mount dvd device
Inner error: [mount -o ro -t udf,iso9660 /dev/sr0 /mnt/cdrom/secure] returned 32: (112.71s)WALinuxAgent uses the following command to mount the DVD, which behaves correctly when no disk is attached:
truenas# mount -o ro -t udf,iso9660 /dev/sr0 /mnt/cdrom/secure
mount: /mnt/cdrom/secure: no medium found on /dev/sr0.When TrueNAS-SCALE-21.06-BETA.1.iso is attached to the VM, we are able to mount the ISO as follows:
truenas# mount -o ro -t udf,iso9660 /dev/sr0 /mnt/cdrom/secure
[10228.102097] ISO 9660 Extensions: RRIP_1991A
truenas#
truenas# cd /mnt/cdrom/secure/
truenas# ls
System boot efi.img live vmlinuz
TrueNAS-SCALE.update boot.catalog initrd.img mach_kernel
truenas#However, WALinuxAgent throws following errors, since there is no configuration file (ovf-env.xml) present on the disk:
[10362.975489] apt-setup[74924]: waagent did not finish provisioning yet!
2022-01-14T14:13:23.307676Z INFO Daemon Daemon Azure Linux Agent Version:2.2.47
2022-01-14T14:13:23.309257Z INFO Daemon Daemon OS: debian 11
2022-01-14T14:13:23.310548Z INFO Daemon Daemon Python: 3.9.2
2022-01-14T14:13:23.312374Z INFO Daemon Daemon Run daemon
2022-01-14T14:13:23.314892Z INFO Daemon Daemon No RDMA handler exists for distro='Debian GNU/Linux' version='11'
2022-01-14T14:13:23.322320Z INFO Daemon Daemon Error getting cloud-init enabled status from systemctl: Command '['systemctl', 'is-enabled', 'cloud-init-local.service']' returned non-zero exit status 1.
2022-01-14T14:13:23.336032Z INFO Daemon Daemon Error getting cloud-init enabled status from service: Command '['service', 'cloud-init', 'status']' returned non-zero exit status 4.
2022-01-14T14:13:23.337715Z INFO Daemon Daemon cloud-init is enabled: False
2022-01-14T14:13:23.338957Z INFO Daemon Daemon Using waagent for provisioning
2022-01-14T14:13:23.351737Z INFO Daemon Daemon Error getting cloud-init enabled status from systemctl: Command '['systemctl', 'is-enabled', 'cloud-init-local.service']' returned non-zero exit status 1.
2022-01-14T14:13:23.362892Z INFO Daemon Daemon Error getting cloud-init enabled status from service: Command '['service', 'cloud-init', 'status']' returned non-zero exit status 4.
2022-01-14T14:13:23.364468Z INFO Daemon Daemon cloud-init is enabled: False
2022-01-14T14:13:23.365685Z INFO Daemon Daemon Activate resource disk
2022-01-14T14:13:23.366797Z INFO Daemon Daemon Searching gen1 prefix 00000000-0001 or gen2 f8b3781a-1e82-4818-a1c3-63d806ec15bb
2022-01-14T14:13:23.367750Z INFO Daemon Daemon Found device: None
2022-01-14T14:13:23.367935Z ERROR Daemon Daemon Failed to mount resource disk [ResourceDiskError] unable to detect disk topology
2022-01-14T14:13:23.369144Z ERROR Daemon Daemon Event: name=WALinuxAgent, op=ActivateResourceDisk, message=[ResourceDiskError] unable to detect disk topology, duration=0
2022-01-14T14:13:23.371333Z INFO Daemon Daemon Clean protocol and wireserver endpoint
2022-01-14T14:13:23.372835Z INFO Daemon Daemon Running default provisioning handler
2022-01-14T14:13:23.378747Z INFO Daemon Daemon Copying ovf-env.xml
2022-01-14T14:13:23.405850Z INFO Daemon Daemon /dev/sr0 is already mounted at /mnt/cdrom/secure
2022-01-14T14:13:23.410256Z ERROR Daemon Daemon Provisioning failed: [ProtocolError] [CopyOvfEnv] Error reading file /mnt/cdrom/secure/ovf-env.xml: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml' (10363.19s)
2022-01-14T14:13:23.419231Z INFO Daemon Daemon Detect protocol endpoints
2022-01-14T14:13:23.422396Z INFO Daemon Daemon Clean protocol and wireserver endpoint
2022-01-14T14:13:23.426113Z INFO Daemon Daemon WireServer endpoint is not found. Rerun dhcp handler
2022-01-14T14:13:23.430449Z INFO Daemon Daemon Test for route to 168.63.129.16
2022-01-14T14:13:23.434060Z WARNING Daemon Daemon No route exists to 168.63.129.16
2022-01-14T14:13:23.437655Z INFO Daemon Daemon Checking for dhcp lease cache
2022-01-14T14:13:23.441686Z INFO Daemon Daemon looking for leases in path [/var/lib/dhcp/dhclient.*.leases]
2022-01-14T14:13:23.446858Z INFO Daemon Daemon cached endpoint not found
2022-01-14T14:13:23.449986Z INFO Daemon Daemon Cache exists [False]
2022-01-14T14:13:23.452960Z INFO Daemon Daemon Send dhcp request
2022-01-14T14:13:23.455815Z INFO Daemon Daemon Examine /proc/net/route for primary interface
2022-01-14T14:13:23.459775Z INFO Daemon Daemon Primary interface is [eth0]
2022-01-14T14:13:23.469089Z ERROR Daemon Daemon Event: name=WALinuxAgent, op=UnhandledError, message=Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 100, in copy_ovf_env
ovfxml = fileutil.read_file(ovf_file_path_on_dvd, remove_bom=True)
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/utils/fileutil.py", line 53, in read_file
with open(filepath, mode) as in_file:
FileNotFoundError: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml'During handling of the above exception, another exception occurred:Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 78, in run
ovf_env = self.protocol_util.copy_ovf_env()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 103, in copy_ovf_env
raise ProtocolError("[CopyOvfEnv] Error reading file "
azurelinuxagent.common.exception.ProtocolError: [ProtocolError] [CopyOvfEnv] Error reading file /mnt/cdrom/secure/ovf-env.xml: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml'During handling of the above exception, another exception occurred:Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/daemon/main.py", line 84, in run
self.daemon(child_args)
File "/usr/lib/python3/dist-packages/azurelinuxagent/daemon/main.py", line 146, in daemon
self.provision_handler.run()
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 103, in run
self.report_not_ready("ProvisioningFailed", ustr(e))
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 305, in report_not_ready
protocol = self.protocol_util.get_protocol()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 344, in get_protocol
protocol_name, protocol = self._detect_protocol(protocols)
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 258, in _detect_protocol
protocol = self._detect_wire_protocol() \
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 225, in _detect_wire_protocol
self.dhcp_handler.run()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/dhcp.py", line 62, in run
self.send_dhcp_req()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/dhcp.py", line 166, in send_dhcp_req
mac_addr = self.osutil.get_mac_addr()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 757, in get_mac_addr
ifname = self.get_if_name()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 1054, in get_if_name
if_name = self.get_first_if()[0]
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 821, in get_first_if
ifaces = self._get_all_interfaces()
Fil"/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 804, in _get_all_interfaces
ifconf_buff = buff.tostring()
AttributeError: 'array.array' object has no attribute 'tostring'
, duration=0
2022-01-14T14:13:23.604941Z WARNING Daemon Daemon Daemon ended with exception -- Sleep 15 seconds and restart daemon
2022-01-14T14:13:38.625472Z INFO Daemon Daemon Run daemon
2022-01-14T14:13:38.630484Z INFO Daemon Daemon No RDMA handler exists for distro='Debian GNU/Linux' version='11'
2022-01-14T14:13:38.641847Z INFO Daemon Daemon Error getting cloud-init enabled status from systemctl: Command '['systemctl', 'is-enabled', 'cloud-init-local.service']' returned non-zero exit status 1.
2022-01-14T14:13:38.662867Z INFO Daemon Daemon Error getting cloud-init enabled status from service: Command '['service', 'cloud-init', 'status']' returned non-zero exit status 4.
2022-01-14T14:13:38.672725Z INFO Daemon Daemon cloud-init is enabled: False
2022-01-14T14:13:38.676339Z INFO Daemon Daemon Using waagent for provisioning
2022-01-14T14:13:38.685277Z INFO Daemon Daemon Error getting cloud-init enabled status from systemctl: Command '['systemctl', 'is-enabled', 'cloud-init-local.service']' returned non-zero exit status 1.
2022-01-14T14:13:38.705545Z INFO Daemon Daemon Error getting cloud-init enabled status from service: Command '['service', 'cloud-init', 'status']' returned non-zero exit status 4.
2022-01-14T14:13:38.717519Z INFO Daemon Daemon cloud-init is enabled: False
2022-01-14T14:13:38.722085Z INFO Daemon Daemon Activate resource disk
2022-01-14T14:13:38.725084Z INFO Daemon Daemon Searching gen1 prefix 00000000-0001 or gen2 f8b3781a-1e82-4818-a1c3-63d806ec15bb
2022-01-14T14:13:38.731938Z INFO Daemon Daemon Found device: None
2022-01-14T14:13:38.735449Z ERROR Daemon Daemon Failed to mount resource disk [ResourceDiskError] unable to detect disk topology
2022-01-14T14:13:38.743519Z ERROR Daemon Daemon Event: name=WALinuxAgent, op=ActivateResourceDisk, message=[ResourceDiskError] unable to detect disk topology, duration=0
2022-01-14T14:13:38.754909Z INFO Daemon Daemon Clean protocol and wireserver endpoint
2022-01-14T14:13:38.760512Z INFO Daemon Daemon Running default provisioning handler
2022-01-14T14:13:38.770388Z INFO Daemon Daemon Copying ovf-env.xml
2022-01-14T14:13:38.779961Z INFO Daemon Daemon /dev/sr0 is already mounted at /mnt/cdrom/secure
2022-01-14T14:13:38.786221Z ERROR Daemon Daemon Provisioning failed: [ProtocolError] [CopyOvfEnv] Error reading file /mnt/cdrom/secure/ovf-env.xml: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml' (10378.57s)
2022-01-14T14:13:38.797862Z INFO Daemon Daemon Detect protocol endpoints
2022-01-14T14:13:38.802781Z INFO Daemon Daemon Clean protocol and wireserver endpoint
2022-01-14T14:13:38.807256Z INFO Daemon Daemon WireServer endpoint is not found. Rerun dhcp handler
2022-01-14T14:13:38.812129Z INFO Daemon Daemon Test for route to 168.63.129.16
2022-01-14T14:13:38.816741Z WARNING Daemon Daemon No route exists to 168.63.129.16
2022-01-14T14:13:38.821978Z INFO Daemon Daemon Checking for dhcp lease cache
2022-01-14T14:13:38.826521Z INFO Daemon Daemon looking for leases in path [/var/lib/dhcp/dhclient.*.leases]
2022-01-14T14:13:38.832595Z INFO Daemon Daemon cached endpoint not found
2022-01-14T14:13:38.836628Z INFO Daemon Daemon Cache exists [False]
2022-01-14T14:13:38.840106Z INFO Daemon Daemon Send dhcp request
2022-01-14T14:13:38.843104Z INFO Daemon Daemon Examine /proc/net/route for primary interface
2022-01-14T14:13:38.847736Z INFO Daemon Daemon Primary interface is [eth0]
2022-01-14T14:13:38.855867Z ERROR Daemon Daemon Event: name=WALinuxAgent, op=UnhandledError, message=Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 100, in copy_ovf_env
ovfxml = fileutil.read_file(ovf_file_path_on_dvd, remove_bom=True)
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/utils/fileutil.py", line 53, in read_file
with open(filepath, mode) as in_file:
FileNotFoundError: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml'During handling of the above exception, another exception occurred:Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 78, in run
ovf_env = self.protocol_util.copy_ovf_env()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 103, in copy_ovf_env
raise ProtocolError("[CopyOvfEnv] Error reading file "
azurelinuxagent.common.exception.ProtocolError: [ProtocolError] [CopyOvfEnv] Error reading file /mnt/cdrom/secure/ovf-env.xml: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml'During handling of the above exception, another exception occurred:Traceback (most recent call last):
File "/usr/lib/python3/dist-packages/azurelinuxagent/daemon/main.py", line 84, in run
self.daemon(child_args)
File "/usr/lib/python3/dist-packages/azurelinuxagent/daemon/main.py", line 146, in daemon
self.provision_handler.run()
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 103, in run
self.report_not_ready("ProvisioningFailed", ustr(e))
File "/usr/lib/python3/dist-packages/azurelinuxagent/pa/provision/default.py", line 305, in report_not_ready
protocol = self.protocol_util.get_protocol()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 344, in get_protocol
protocol_name, protocol = self._detect_protocol(protocols)
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 258, in _detect_protocol
protocol = self._detect_wire_protocol() \
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/protocol/util.py", line 225, in _detect_wire_protocol
self.dhcp_handler.run()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/dhcp.py", line 62, in run
self.send_dhcp_req()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/dhcp.py", line 166, in send_dhcp_req
mac_addr = self.osutil.get_mac_addr()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 757, in get_mac_addr
ifname = self.get_if_name()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 1054, in get_if_name
if_name = self.get_first_if()[0]
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 821, in get_first_if
ifaces = self._get_all_interfaces()
File "/usr/lib/python3/dist-packages/azurelinuxagent/common/osutil/default.py", line 804, in _get_all_interfaces
ifconf_buff = buff.tostring()
AttributeError: 'array.array' object has no attribute 'tostring'
, duration=0
2022-01-14T14:13:38.993731Z WARNING Daemon Daemon Daemon ended with exception -- Sleep 15 seconds and restart daemonI was able to confirm that CD/DVD rom functionality is working properly with Hyper-V.
truenas# lshw | grep -C 100 DVD
*-pci
description: Host bridge
product: 440BX/ZX/DX - 82443BX/ZX/DX Host bridge (AGP disabled)
vendor: Intel Corporation
physical id: 100
bus info: pci@0000:00:00.0
version: 03
width: 32 bits
clock: 33MHz
*-isa
description: ISA bridge
product: 82371AB/EB/MB PIIX4 ISA
vendor: Intel Corporation
physical id: 7
bus info: pci@0000:00:07.0
version: 01
width: 32 bits
clock: 33MHz
capabilities: isa bus_master
configuration: latency=0
*-ide
description: IDE interface
product: 82371AB/EB/MB PIIX4 IDE
vendor: Intel Corporation
physical id: 7.1
bus info: pci@0000:00:07.1
logical name: scsi3
version: 01
width: 32 bits
clock: 33MHz
capabilities: ide isa_compat_mode bus_master emulated
configuration: driver=ata_piix latency=0
resources: irq:0 ioport:1f0(size=8) ioport:3f6 ioport:170(size=8) ioport:376 ioport:ffa0(size=16)
*-cdrom
description: DVD reader
product: Virtual CD/ROM
vendor: Msft
physical id: 0.0.0
bus info: scsi@3:0.0.0
logical name: /dev/cdrom
logical name: /dev/dvd
logical name: /dev/sr0
logical name: /mnt/cdrom/secure
version: 1.0
capabilities: removable audio dvd
configuration: ansiversion=5 mount.fstype=iso9660 mount.options=ro,relatime,nojoliet,check=s,map=n,blocksize=2048 state=mounted status=ready
*-medium
physical id: 0
logical name: /dev/cdrom
logical name: /mnt/cdrom/secure
capabilities: gpt-1.00 partitioned partitioned:gpt
configuration: guid=82d85ca3-9c69-47ea-922d-74c8a954c5ec mount.fstype=iso9660 mount.options=ro,relatime,nojoliet,check=s,map=n,blocksize=2048 state=mounted
*-volume:0 UNCLAIMED
description: data partition
vendor: Windows
physical id: 1
serial: 82d85ca3-9c69-47ea-922c-74c8a954c5ec
capacity: 111KiB
capabilities: precious readonly
configuration: name=Gap0
*-volume:1 UNCLAIMED
description: Windows FAT volume
vendor: MTOO4026
physical id: 2
version: FAT12
serial: 196f-d9ac
size: 15EiB
capabilities: boot precious readonly fat initialized
configuration: FATs=2 filesystem=fat name=EFI boot partition
*-volume:2 UNCLAIMED
description: Apple HFS+ partition
vendor: Mac OS X
physical id: 3
version: 4
serial: 00000000-0000-0000-0000-000000017191
size: 1478MiB
capabilities: precious readonly ro hfsplus initialized
configuration: checked=2021-06-21 12:31:22 created=2021-06-21 19:31:22 filesystem=hfsplus lastmountedby=liso modified=2021-06-21 12:31:22 name=HFSPLUS state=clean
*-volume:3 UNCLAIMED
description: data partition
vendor: Windows
physical id: 4
serial: 82d85ca3-9c69-47ea-9229-74c8a954c5ec
capacity: 299KiB
capabilities: precious readonly
configuration: name=Gap1
truenas# lsblk
NAME MAJ:MIN RM SIZE RO TYPE MOUNTPOINT
fd0 2:0 1 4K 0 disk
sda 8:0 0 10G 0 disk
├─sda1 8:1 0 1M 0 part
├─sda2 8:2 0 512M 0 part
└─sda3 8:3 0 9.5G 0 part
sr0 11:0 1 1.4G 0 rom /mnt/cdrom/secure
truenas# blkid
/dev/sda2: LABEL_FATBOOT="EFI" LABEL="EFI" UUID="099B-4C25" BLOCK_SIZE="512" TYPE="vfat" PARTUUID="ca31879a-d43c-434a-a14d-7d81ef25afd7"
/dev/sda3: LABEL="boot-pool" UUID="16524427804095936202" UUID_SUB="2155738763160627009" BLOCK_SIZE="4096" TYPE="zfs_member" PARTUUID="03139377-5898-4e03-94b2-d94663da1546"
/dev/sr0: BLOCK_SIZE="2048" UUID="2021-06-21-19-31-22-00" LABEL="ISOIMAGE" TYPE="iso9660" PTTYPE="PMBR"
/dev/sda1: PARTUUID="8f015dde-7dd5-4de9-8a6d-359792a6378f"I also found somewhat similar issues here and here that point out this issue is related to WALinuxAgent.
Complete
Details
Details
Assignee
Umer Saleem
Umer Saleem(Deactivated)Reporter
Leeroy R
Leeroy RLabels
Time remaining
0m
Fix versions
Affects versions
Priority
LowKatalon Platform
Linked Test Cases, Katalon Defect Results, Katalon Studio Test Results
Katalon Platform
Linked Test Cases, Katalon Defect Results, Katalon Studio Test Results
Created June 18, 2021 at 9:53 AM
Updated July 6, 2022 at 8:59 PM
Resolved January 19, 2022 at 4:03 PM
TrueNAS-SCALE-21.06-MASTER-20210617-212918
I have no spare system to test baremetal, so I had to use Hyper-V
When I leave DVD Drive present in VM settings I get one spam of tracebacks in syslog, which boils down to this:
Jun 18 02:34:32 truenas waagent[2205]: azurelinuxagent.common.exception.ProtocolError: [ProtocolError] [CopyOvfEnv] Error reading file /mnt/cdrom/secure/ovf-env.xml: [Errno 2] No such file or directory: '/mnt/cdrom/secure/ovf-env.xml'
If I delete DVD Drive from VM entirely, I get another spam:
Jun 18 02:31:14 truenas waagent[2164]: 2021-06-18T09:31:13.980660Z ERROR Daemon Daemon Provisioning failed: [ProtocolError] [CopyOvfEnv] Error mounting dvd: [OSUtilError] Failed to get dvd device from /dev
Jun 18 02:31:14 truenas waagent[2164]: Inner error: The following devices were found, but none matched the pattern [(sr[0-9]|hd[c-z]|cdrom[0-9]|cd[0-9])]: ...
Attaching debug archive.