open-vm-tools toolsDeployPkg.log: Customization command failed with exitcode: 127, stderr: '' on Ubuntu Cloud image

Describe the bug

When trying to set up a virtual machines template using packer 1.12.0 in vSphere 8.0.3.00400 from Ubuntu 24.04 cloud images, I get the following vmstoold-related error in /var/log/cloud-init.log:

2025-04-25 08:12:22,015 - sources[DEBUG]: Searching for local data source in: ['DataSourceOVF']
2025-04-25 08:12:22,015 - handlers.py[DEBUG]: start: init-local/search-OVF: searching for local data from DataSourceOVF
2025-04-25 08:12:22,015 - sources[DEBUG]: Seeing if we can get any data from <class 'cloudinit.sources.DataSourceOVF.DataSourceOVF'>
2025-04-25 08:12:22,015 - sources[DEBUG]: Update datasource metadata and network config due to events: boot-new-instance
2025-04-25 08:12:22,016 - sources[DEBUG]: Detected DataSourceOVF [seed=None]
2025-04-25 08:12:22,017 - DataSourceOVF.py[DEBUG]: discovered vmware-rpctool: /usr/bin/vmware-rpctool
2025-04-25 08:12:22,017 - DataSourceOVF.py[DEBUG]: discovered vmtoolsd: /usr/bin/vmtoolsd
2025-04-25 08:12:22,017 - DataSourceOVF.py[INFO]: query guestinfo.ovfEnv with /usr/bin/vmware-rpctool
2025-04-25 08:12:22,018 - subp.py[DEBUG]: Running command ['/usr/bin/vmware-rpctool', 'info-get guestinfo.ovfEnv'] with allowed return codes [0] (shell=False, capture=True)
2025-04-25 08:12:22,021 - DataSourceOVF.py[INFO]: fallback to vmtoolsd
2025-04-25 08:12:22,022 - DataSourceOVF.py[INFO]: query guestinfo.ovfEnv with /usr/bin/vmtoolsd
2025-04-25 08:12:22,022 - subp.py[DEBUG]: Running command ['/usr/bin/vmtoolsd', '--cmd', 'info-get guestinfo.ovfEnv'] with allowed return codes [0] (shell=False, capture=True)
2025-04-25 08:12:22,140 - performance.py[DEBUG]: Running ['/usr/bin/vmtoolsd', '--cmd', 'info-get guestinfo.ovfEnv'] took 0.118 seconds
2025-04-25 08:12:22,140 - log_util.py[WARNING]: vmtoolsd failed to get guestinfo.ovfEnv: Unexpected error while running command.
Command: ['/usr/bin/vmtoolsd', '--cmd', 'info-get guestinfo.ovfEnv']
Exit code: 1
Reason: -
Stdout:
Stderr: No value found
2025-04-25 08:12:22,141 - log_util.py[DEBUG]: vmtoolsd failed to get guestinfo.ovfEnv: Unexpected error while running command.
Command: ['/usr/bin/vmtoolsd', '--cmd', 'info-get guestinfo.ovfEnv']
Exit code: 1
Reason: -
Stdout:
Stderr: No value found
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 317, in transport_vmware_guestinfo
    return query_guestinfo(rpctool, rpctool_fn)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 312, in query_guestinfo
    raise error
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 304, in query_guestinfo
    cmd, stdout, _ = rpctool_fn(rpctool, "info-get guestinfo.ovfEnv")
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 268, in exec_vmware_rpctool
    (stdout, stderr) = subp.subp(cmd)
                       ^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/cloudinit/subp.py", line 291, in subp
    raise ProcessExecutionError(
cloudinit.subp.ProcessExecutionError: Unexpected error while running command.
Command: ['/usr/bin/vmware-rpctool', 'info-get guestinfo.ovfEnv']
Exit code: 1
Reason: -
Stdout:
Stderr: No value found

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 337, in transport_vmware_guestinfo
    return query_guestinfo(vmtoolsd, exec_vmtoolsd)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 312, in query_guestinfo
    raise error
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 304, in query_guestinfo
    cmd, stdout, _ = rpctool_fn(rpctool, "info-get guestinfo.ovfEnv")
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/cloudinit/sources/DataSourceOVF.py", line 274, in exec_vmtoolsd
    (stdout, stderr) = subp.subp(cmd)
                       ^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/cloudinit/subp.py", line 291, in subp
    raise ProcessExecutionError(
cloudinit.subp.ProcessExecutionError: Unexpected error while running command.
Command: ['/usr/bin/vmtoolsd', '--cmd', 'info-get guestinfo.ovfEnv']
Exit code: 1
Reason: -
Stdout:
Stderr: No value found

I believe that this error leads to the network card remaining disconnected, which blocks packer from further provisioning the virtual machine (with ansible in this case)

Also relevant (probably related to this, but I can't be sure, because the error is really ambiguous) are the logs in /var/log/vmware-imc/toolsDeployPkg.log:

=================== Perl script log end =================
[2025-04-25T08:14:02.228Z] [   error] Customization command failed with exitcode: 127, stderr: ''.
[2025-04-25T08:14:02.228Z] [   error] Customization process returned with error.
[2025-04-25T08:14:02.228Z] [   debug] Deployment result = 127.
[2025-04-25T08:14:02.228Z] [    info] Setting 'unknown' error status in vmx.
[2025-04-25T08:14:02.230Z] [    info] Transitioning from state 'INPROGRESS' to state 'ERRORED'.
[2025-04-25T08:14:02.230Z] [    info] ENTER STATE 'ERRORED'.
[2025-04-25T08:14:02.230Z] [    info] EXIT STATE 'INPROGRESS'.
[2025-04-25T08:14:02.231Z] [   debug] Setting deploy error: 'Deployment failed.The forked off process returned error code.'.
[2025-04-25T08:14:02.231Z] [   error] Deployment failed.The forked off process returned error code.
[2025-04-25T08:14:02.231Z] [    info] Launching cleanup.
[2025-04-25T08:14:02.231Z] [   debug] Command to exec : '/bin/rm'.
[2025-04-25T08:14:02.231Z] [    info] sizeof ProcessInternal is 56
[2025-04-25T08:14:02.233Z] [    info] Returning, pending output from stdout
[2025-04-25T08:14:02.233Z] [    info] Returning, pending output from stderr
[2025-04-25T08:14:02.333Z] [    info] Process exited normally after 0 seconds, returned 0
[2025-04-25T08:14:02.333Z] [    info] No more output from stdout
[2025-04-25T08:14:02.333Z] [    info] No more output from stderr
[2025-04-25T08:14:02.333Z] [    info] Customization command output:
''.
[2025-04-25T08:14:02.333Z] [    info] sSkipReboot: 'false', forceSkipReboot 'false'.
[2025-04-25T08:14:02.333Z] [   error] Deploy error: 'Deployment failed.The forked off process returned error code.'.
[2025-04-25T08:14:02.333Z] [   error] Package deploy failed in DeployPkg_DeployPackageFromFile
[2025-04-25T08:14:02.333Z] [   debug] ## Closing log

Reproduction steps

I've downloaded the latest OVA cloud image here:

https://cloud-images.ubuntu.com/noble/20250403/ (full link is: https://cloud-images.ubuntu.com/noble/20250403/noble-server-cloudimg-amd64.ova)

And I've installed the ova template (using deploy ova) in the vSphere cluster.
I've deployed packer to create a new template based on the ova template using the following configuration (probably irrelevant here, but I'll paste it nonetheless, maybe it helps):

source "vsphere-clone" "vms-local" {
	# connection configuration
	username       = "${var.vsphere_username}"
	vcenter_server = "${var.vsphere_host}"
	password         = "${var.vsphere_password}"

	ssh_username     = "${var.ssh_username}"
	ssh_password     = "${var.ssh_password}"
	ssh_timeout      = "30m"

	# location configuration
	cluster = "${var.vsphere_cluster}"
	host = "${var.vsphere_build_host}"
	datastore = "${var.vsphere_datastore}"
	folder = "${var.vsphere_folder}"

	# vm configuration
	CPUs = 4
	RAM = 6144
	disk_size = 10240
	# already configured in the template
	# storage {
	#   disk_size             = 10000
	#   disk_thin_provisioned = true
	# }
	template = "ubuntu24-cloudimg"
	vm_name = "${var.template_name}"
	remove_cdrom = true
	network = "${var.vsphere_network}"

	vapp {
		properties = {
			hostname = "${var.playbook}"
			user-data = base64encode(var.user_data)
		}
	}
	# trying to solve vmware-tools bug which need hwclock command in ubuntu 24.04 (where it doesn't exist anymore)
	tools_sync_time = false

	ssh_private_key_file = "~/.ssh/id_ed25519"
	customize {
		linux_options {
			host_name = "${var.template_name}"
			domain = "ejobs.internal"
			hw_clock_utc = true
	}
	network_interface {
		ipv4_address = "${var.template_ip}"
		ipv4_netmask = "${var.vm_netmask}"
	}

	dns_server_list = [ "10.88.88.21", "10.88.88.22" ]
	ipv4_gateway = "${var.vm_gateway}"
	}

	convert_to_template  = true
}
# a build block invokes sources and runs provisioning steps on them. The
# documentation for build blocks can be found here:
# https://www.packer.io/docs/templates/hcl_templates/blocks/build
build {
	sources = ["source.proxmox-clone.ejobs-local", "source.vsphere-clone.ejobs-local"]

	provisioner "ansible" {
		extra_arguments = ["--extra-vars", "vmware_build=${var.vmware_build}"]
		playbook_file = "setup/${var.playbook}.yml"
		ansible_env_vars = ["ANSIBLE_HOST_KEY_CHECKING=False"]
		user = "packer"
		use_proxy = false
	}
}

The network interface card remains disconnected. If I manually connect the card (Edit Settings), packer eventually connects to the virtual machine and it works, despite the abovementioned error, which after all, I don't care about. I'm more interested in the process to just go on.

Expected behavior

I expect the network card interface to connect.

Additional context

I don't get this behaviour with an older cloud image ova which is a few months old, also on Ubuntu 24.04 (dating from 20240710)

Apr 25 '25 08:04 lethargosapatheia

Actually the /usr/bin/vmware-rpctool info-get guestinfo.ovfEnv error occurs in the 20240710 cloudimage too.

The difference lies in the toolsDeployPkg.log. In this case, it just works:

=================== Perl script log end =================
[2025-04-25T08:40:18.345Z] [    info] Wait before set enable-nics stats in vmx.
[2025-04-25T08:40:18.345Z] [   debug] Trying to connect network interfaces, attempt 1.
[2025-04-25T08:40:18.347Z] [   debug] Got VMX response 'queryNicsSupported'.
[2025-04-25T08:40:18.349Z] [   debug] Got VMX response 'disconnected'.
[2025-04-25T08:40:19.352Z] [   debug] Got VMX response 'connected'.
[2025-04-25T08:40:19.352Z] [    info] The network interfaces are connected on 1 second.
[2025-04-25T08:40:19.354Z] [    info] Transitioning from state 'INPROGRESS' to state 'Done'.
[2025-04-25T08:40:19.354Z] [    info] ENTER STATE 'Done'.
[2025-04-25T08:40:19.354Z] [    info] EXIT STATE 'INPROGRESS'.
[2025-04-25T08:40:19.354Z] [    info] Deployment succeeded.
[2025-04-25T08:40:19.354Z] [    info] Launching cleanup.
[2025-04-25T08:40:19.354Z] [   debug] Command to exec : '/bin/rm'.
[2025-04-25T08:40:19.354Z] [    info] sizeof ProcessInternal is 56
[2025-04-25T08:40:19.356Z] [    info] Returning, pending output from stdout
[2025-04-25T08:40:19.356Z] [    info] Returning, pending output from stderr
[2025-04-25T08:40:19.458Z] [    info] Process exited normally after 0 seconds, returned 0
[2025-04-25T08:40:19.458Z] [    info] No more output from stdout
[2025-04-25T08:40:19.458Z] [    info] No more output from stderr
[2025-04-25T08:40:19.458Z] [    info] Customization command output:
''.
[2025-04-25T08:40:19.458Z] [    info] sSkipReboot: 'false', forceSkipReboot 'false'.
[2025-04-25T08:40:19.458Z] [    info] Do not trigger reboot if cloud-init is executing.
[2025-04-25T08:40:19.458Z] [   debug] Command to exec : '/usr/bin/cloud-init'.
[2025-04-25T08:40:19.458Z] [    info] sizeof ProcessInternal is 56
[2025-04-25T08:40:19.460Z] [    info] Returning, pending output from stdout
[2025-04-25T08:40:19.460Z] [    info] Returning, pending output from stderr
[2025-04-25T08:40:20.175Z] [    info] Saving output from stdout
[2025-04-25T08:40:20.277Z] [    info] Process exited normally after 0 seconds, returned 2
[2025-04-25T08:40:20.278Z] [    info] No more output from stdout
[2025-04-25T08:40:20.278Z] [    info] No more output from stderr
[2025-04-25T08:40:20.278Z] [    info] Customization command output:
'status: running

So the problem is with the newer cloud image and this ambiguous error which basically say nothing:

Customization command failed with exitcode: 127, stderr: ''.

So 127 should normally mean 'command not found'. But it's unclear what actual command this is related to. So something is missing from the vmware tools scripts.

Apr 25 '25 08:04 lethargosapatheia

Hi, can you please also share the tools log /var/log/vmware-vmsvc-root.log ?

Apr 25 '25 09:04 vmwkruti1111

This is on a new VM (it's hard to keep the same one there online, but it shouldn't matter as the circumstances are the same):

[2025-04-25T10:34:00.437Z] [ message] [vmsvc] [884] VMware Tools Version: 12.4.5.49651 (build-23787635)
[2025-04-25T10:34:00.438Z] [ message] [vmsvc] [884] Guest OS details: architecture='X86' bitness='64' distroAddlVersion='24.04.2 LTS (Noble Numbat)' distroName='Ubuntu' distroVersion='24.04' familyName='Linux' kernelVersion='6.8.0-57-generic' prettyName='Ubuntu 24.04.2 LTS'
[2025-04-25T10:34:00.437Z] [ message] [vmsvc] [884] Log caching is enabled with maxCacheEntries=4096.
[2025-04-25T10:34:00.438Z] [ message] [vmsvc] [884] Core dump limit set to -1
[2025-04-25T10:34:00.476Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'hgfsServer', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'hgfsServer' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vix] [884] QueryVGAuthConfig: vgauth usage is: 1
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'vix', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'vix' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'appInfo', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'appInfo' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'componentMgr', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'componentMgr' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'deployPkg', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'deployPkg' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'gdp', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'gdp' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'guestInfo', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'guestInfo' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'guestStore', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'guestStore' initialized.
[2025-04-25T10:34:00.477Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'powerops', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.477Z] [ message] [vmtoolsd] [884] Plugin 'powerops' initialized.
[2025-04-25T10:34:00.477Z] [ message] [resolutionCommon] [884] resolutionCheckForKMS: dlopen succeeded.
[2025-04-25T10:34:00.486Z] [ message] [resolutionCommon] [884] resolutionCheckForKMS: System support available for resolutionKMS.
[2025-04-25T10:34:00.486Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'resolutionKMS', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.486Z] [ message] [vmtoolsd] [884] Plugin 'resolutionKMS' initialized.
[2025-04-25T10:34:00.486Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'timeSync', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.486Z] [ message] [vmtoolsd] [884] Plugin 'timeSync' initialized.
[2025-04-25T10:34:00.487Z] [ message] [vmsvc] [884] Cannot load message catalog for domain 'vmbackup', language 'C', catalog dir '/usr/share/open-vm-tools'.
[2025-04-25T10:34:00.487Z] [ message] [vmtoolsd] [884] Plugin 'vmbackup' initialized.
[2025-04-25T10:34:00.663Z] [ message] [vmsvc] [884] Executing script for state change 'OS_PowerOn'.
[2025-04-25T10:34:00.663Z] [ message] [powerops] [884] Executing script: '/etc/vmware-tools/poweron-vm-default'
[2025-04-25T10:34:00.906Z] [ message] [vix] [884] VixTools_ProcessVixCommand: command 62
[2025-04-25T10:34:01.352Z] [ message] [vmsvc] [884] Script exit code: 0, success = 1
[2025-04-25T10:35:42.814Z] [ warning] [deployPkg] [956] DeployPkgInGuest failed, error = 5

Apr 25 '25 10:04 lethargosapatheia

Hi @lethargosapatheia

I think the error in /var/log/cloud-init.log is NOT the culprit(I should have fixed it in cloud-init PR 5915), could you please share the entire /var/log/vmware-imc/toolsDeployPkg.log after re-connect the network adapter manually? I could find out the failure(s) which leads to [2025-04-25T08:14:02.228Z] [ error] Customization command failed with exitcode: 127, stderr: ''.

Apr 27 '25 02:04 PengpengSun

This is the full log with the network card connected:

[2025-04-27T06:40:27.205Z] [   debug] ## Starting deploy pkg operation
[2025-04-27T06:40:27.205Z] [    info] VMware Tools Version: 12.4.5.49651 (build-23787635)
[2025-04-27T06:40:27.205Z] [   debug] Deploying /var/run/160edb0d/imcf-ZBn1zd
[2025-04-27T06:40:27.205Z] [   debug] The valid [deployPkg] wait-cloudinit-timeout value range: 0 ~ 1800
[2025-04-27T06:40:27.205Z] [    info] Initializing deployment module.
[2025-04-27T06:40:27.205Z] [    info] Cleaning old state files.
[2025-04-27T06:40:27.205Z] [    info] EXIT STATE 'INPROGRESS'.
[2025-04-27T06:40:27.205Z] [   debug] Setting deploy error: 'Error removing lock '/var/log/.vmware-deploy.INPROGRESS'.(No such file or directory)'.
[2025-04-27T06:40:27.205Z] [    info] EXIT STATE 'Done'.
[2025-04-27T06:40:27.205Z] [   debug] Setting deploy error: 'Error removing lock '/var/log/.vmware-deploy.Done'.(No such file or directory)'.
[2025-04-27T06:40:27.205Z] [    info] EXIT STATE 'ERRORED'.
[2025-04-27T06:40:27.205Z] [   debug] Setting deploy error: 'Error removing lock '/var/log/.vmware-deploy.ERRORED'.(No such file or directory)'.
[2025-04-27T06:40:27.205Z] [   debug] Setting deploy error: 'Success.'.
[2025-04-27T06:40:27.205Z] [    info] Deploying cabinet file '/var/run/160edb0d/imcf-ZBn1zd'.
[2025-04-27T06:40:27.205Z] [    info] Transitioning from state '(null)' to state 'INPROGRESS'.
[2025-04-27T06:40:27.205Z] [    info] ENTER STATE 'INPROGRESS'.
[2025-04-27T06:40:27.207Z] [    info] Reading cabinet file '/var/run/160edb0d/imcf-ZBn1zd' and will extract it to '/var/run/.vmware-imgcust-dxekSpT'.
[2025-04-27T06:40:27.207Z] [    info] Flags in the header: 0.
[2025-04-27T06:40:27.207Z] [    info] Original deployment command: '/usr/bin/perl -I/tmp/.vmware/linux/deploy/scripts /tmp/.vmware/linux/deploy/scripts/Customize.pl /tmp/.vmware/linux/deploy/cust.cfg'.
[2025-04-27T06:40:27.207Z] [    info] Actual deployment command: '/usr/bin/perl -I/var/run/.vmware-imgcust-dxekSpT/scripts /var/run/.vmware-imgcust-dxekSpT/scripts/Customize.pl /var/run/.vmware-imgcust-dxekSpT/cust.cfg'.
[2025-04-27T06:40:27.207Z] [    info] Extracting package files.
[2025-04-27T06:40:27.253Z] [   debug] Command to exec : '/usr/bin/cloud-init'.
[2025-04-27T06:40:27.253Z] [    info] sizeof ProcessInternal is 56
[2025-04-27T06:40:27.255Z] [    info] Returning, pending output from stdout
[2025-04-27T06:40:27.255Z] [    info] Returning, pending output from stderr
[2025-04-27T06:40:28.362Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.462Z] [    info] Process exited normally after 1 seconds, returned 0
[2025-04-27T06:40:28.462Z] [    info] No more output from stdout
[2025-04-27T06:40:28.462Z] [    info] No more output from stderr
[2025-04-27T06:40:28.462Z] [    info] Customization command output:
'/usr/bin/cloud-init 24.4.1-0ubuntu0~24.04.2
'.
[2025-04-27T06:40:28.462Z] [    info] Cloud-init is installed.
[2025-04-27T06:40:28.462Z] [    info] Checking if cloud-init customization is enabled.
[2025-04-27T06:40:28.463Z] [    info] UseCloudInitWorkflow return: 4
[2025-04-27T06:40:28.463Z] [    info] Executing traditional GOSC workflow.
[2025-04-27T06:40:28.463Z] [   debug] Command to exec : '/usr/bin/perl'.
[2025-04-27T06:40:28.463Z] [    info] sizeof ProcessInternal is 56
[2025-04-27T06:40:28.465Z] [    info] Returning, pending output from stdout
[2025-04-27T06:40:28.465Z] [    info] Returning, pending output from stderr
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.766Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.866Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.866Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.866Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.866Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.866Z] [    info] Saving output from stdout
[2025-04-27T06:40:28.967Z] [    info] Saving output from stdout
[2025-04-27T06:40:29.971Z] [    info] Saving output from stdout
[2025-04-27T06:40:31.074Z] [    info] Saving output from stdout
[2025-04-27T06:40:32.076Z] [    info] Saving output from stdout
[2025-04-27T06:40:33.078Z] [    info] Saving output from stdout
[2025-04-27T06:40:34.081Z] [    info] Saving output from stdout
[2025-04-27T06:40:35.083Z] [    info] Saving output from stdout
[2025-04-27T06:40:36.185Z] [    info] Saving output from stdout
[2025-04-27T06:40:37.188Z] [    info] Saving output from stdout
[2025-04-27T06:40:38.190Z] [    info] Saving output from stdout
[2025-04-27T06:40:39.192Z] [    info] Saving output from stdout
[2025-04-27T06:40:39.292Z] [    info] Saving output from stdout
[2025-04-27T06:40:39.292Z] [    info] Saving output from stdout
[2025-04-27T06:40:39.393Z] [    info] Saving output from stdout
[2025-04-27T06:40:39.493Z] [    info] Saving output from stdout
[2025-04-27T06:40:39.493Z] [    info] Saving output from stdout
[2025-04-27T06:42:08.682Z] [   error] Timed out waiting for process exit, canceling...
[2025-04-27T06:42:08.782Z] [   error] Process exited abnormally after 100 sec, uncaught signal 9
[2025-04-27T06:42:08.782Z] [    info] Customization command output:
=================== Perl script log start =================
2025-04-27T06:40:28 DEBUG: Creating directory /var/lock/vmware
2025-04-27T06:40:28 DEBUG: Opening /var/lock/vmware/gosc in O_CREAT|O_EXCL|O_WRONLY mode
2025-04-27T06:40:28 INFO: Opening file name /var/run/.vmware-imgcust-dxekSpT/cust.cfg.
2025-04-27T06:40:28 DEBUG: Processing line: '[NETWORK]'
2025-04-27T06:40:28 DEBUG: FOUND CATEGORY = NETWORK
2025-04-27T06:40:28 DEBUG: Processing line: 'NETWORKING = yes'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NETWORK|NETWORKING' = 'yes'
2025-04-27T06:40:28 DEBUG: Processing line: 'BOOTPROTO = dhcp'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NETWORK|BOOTPROTO' = 'dhcp'
2025-04-27T06:40:28 DEBUG: Processing line: 'HOSTNAME = omni-ceph-template'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NETWORK|HOSTNAME' = 'omni-ceph-template'
2025-04-27T06:40:28 DEBUG: Processing line: 'DOMAINNAME = sanit.internal'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NETWORK|DOMAINNAME' = 'sanit.internal'
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: '[NIC-CONFIG]'
2025-04-27T06:40:28 DEBUG: FOUND CATEGORY = NIC-CONFIG
2025-04-27T06:40:28 DEBUG: Processing line: 'NICS = NIC1'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC-CONFIG|NICS' = 'NIC1'
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: '[NIC1]'
2025-04-27T06:40:28 DEBUG: FOUND CATEGORY = NIC1
2025-04-27T06:40:28 DEBUG: Processing line: 'MACADDR = 00:50:56:84:32:f2'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|MACADDR' = '00:50:56:84:32:f2'
2025-04-27T06:40:28 DEBUG: Processing line: 'PRIMARY = yes'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|PRIMARY' = 'yes'
2025-04-27T06:40:28 DEBUG: Processing line: 'ONBOOT = yes'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|ONBOOT' = 'yes'
2025-04-27T06:40:28 DEBUG: Processing line: 'IPv4_MODE = BACKWARDS_COMPATIBLE'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|IPv4_MODE' = 'BACKWARDS_COMPATIBLE'
2025-04-27T06:40:28 DEBUG: Processing line: 'BOOTPROTO = static'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|BOOTPROTO' = 'static'
2025-04-27T06:40:28 DEBUG: Processing line: 'IPADDR = 10.88.88.157'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|IPADDR' = '10.88.88.157'
2025-04-27T06:40:28 DEBUG: Processing line: 'NETMASK = 255.255.255.0'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|NETMASK' = '255.255.255.0'
2025-04-27T06:40:28 DEBUG: Processing line: 'GATEWAY = 10.88.88.126'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'NIC1|GATEWAY' = '10.88.88.126'
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: '[DNS]'
2025-04-27T06:40:28 DEBUG: FOUND CATEGORY = DNS
2025-04-27T06:40:28 DEBUG: Processing line: 'DNSFROMDHCP=no'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'DNS|DNSFROMDHCP' = 'no'
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: 'NAMESERVER|1 = 10.88.88.21'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'DNS|NAMESERVER|1' = '10.88.88.21'
2025-04-27T06:40:28 DEBUG: Processing line: 'NAMESERVER|2 = 10.88.88.22'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'DNS|NAMESERVER|2' = '10.88.88.22'
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: '[DATETIME]'
2025-04-27T06:40:28 DEBUG: FOUND CATEGORY = DATETIME
2025-04-27T06:40:28 DEBUG: Processing line: 'TIMEZONE = UTC'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'DATETIME|TIMEZONE' = 'UTC'
2025-04-27T06:40:28 DEBUG: Processing line: 'UTC = yes'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'DATETIME|UTC' = 'yes'
2025-04-27T06:40:28 DEBUG: Processing line: ''
2025-04-27T06:40:28 DEBUG: Empty line. Ignored.
2025-04-27T06:40:28 DEBUG: Processing line: '[CUSTOM-SOURCE]'
2025-04-27T06:40:28 DEBUG: FOUND CATEGORY = CUSTOM-SOURCE
2025-04-27T06:40:28 DEBUG: Processing line: 'CUSTOMIZATION_SOURCE=vcenter-customize'
2025-04-27T06:40:28 DEBUG: ADDED KEY-VAL :: 'CUSTOM-SOURCE|CUSTOMIZATION_SOURCE' = 'vcenter-customize'
2025-04-27T06:40:28 DEBUG: Opening file /var/run/.vmware-imgcust-dxekSpT/buildInfo.txt.
2025-04-27T06:40:28 INFO: SYSIMAGE_VERSION = 12.5.0.1415
2025-04-27T06:40:28 INFO: BUILDNUMBER = build-24231464
2025-04-27T06:40:28 INFO: /etc/vmware-tools/customization.conf doesn't exist.
2025-04-27T06:40:28 INFO: Matching guest OS by distribution flavour...
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Reading /etc/os-release file ...
2025-04-27T06:40:28 DEBUG: opening file /etc/os-release.
2025-04-27T06:40:28 DEBUG: Match found   : Line = PRETTY_NAME="Ubuntu 24.04.2 LTS"

2025-04-27T06:40:28 DEBUG: Actual String : "Ubuntu 24.04.2 LTS"
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: file content: 'Ubuntu 24.04.2 LTS \n \l

'
2025-04-27T06:40:28 DEBUG: Reading /etc/os-release file ...
2025-04-27T06:40:28 DEBUG: opening file /etc/os-release.
2025-04-27T06:40:28 DEBUG: Match found   : Line = VERSION_ID="24.04"

2025-04-27T06:40:28 DEBUG: Actual String : "24.04"
2025-04-27T06:40:28 DEBUG: ID: "24.04"
2025-04-27T06:40:28 DEBUG: opening file /etc/os-release.
2025-04-27T06:40:28 DEBUG: Match found   : Line = VERSION_ID="24.04"

2025-04-27T06:40:28 DEBUG: Actual String : "24.04"
2025-04-27T06:40:28 DEBUG: Version: "24.04"
2025-04-27T06:40:28 WARNING: Amazon Linux flavor not detected
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 WARNING: RedHat release file not available. Ignoring it.
2025-04-27T06:40:28 WARNING: Redhat flavor not detected
2025-04-27T06:40:28 DEBUG: Reading /etc/os-release file ...
2025-04-27T06:40:28 DEBUG: opening file /etc/os-release.
2025-04-27T06:40:28 DEBUG: Match found   : Line = PRETTY_NAME="Ubuntu 24.04.2 LTS"

2025-04-27T06:40:28 DEBUG: Actual String : "Ubuntu 24.04.2 LTS"
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 WARNING: RedHat release file not available. Ignoring it.
2025-04-27T06:40:28 WARNING: Redhat flavor not detected
2025-04-27T06:40:28 DEBUG: Reading /etc/os-release file ...
2025-04-27T06:40:28 DEBUG: opening file /etc/os-release.
2025-04-27T06:40:28 DEBUG: Match found   : Line = PRETTY_NAME="Ubuntu 24.04.2 LTS"

2025-04-27T06:40:28 DEBUG: Actual String : "Ubuntu 24.04.2 LTS"
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 WARNING: RedHat release file not available. Ignoring it.
2025-04-27T06:40:28 WARNING: Redhat flavor not detected
2025-04-27T06:40:28 DEBUG: Reading /etc/os-release file ...
2025-04-27T06:40:28 DEBUG: opening file /etc/os-release.
2025-04-27T06:40:28 DEBUG: Match found   : Line = PRETTY_NAME="Ubuntu 24.04.2 LTS"

2025-04-27T06:40:28 DEBUG: Actual String : "Ubuntu 24.04.2 LTS"
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 WARNING: RedHat release file not available. Ignoring it.
2025-04-27T06:40:28 WARNING: Redhat flavor not detected
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/lsb-release'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=24.04
DISTRIB_CODENAME=noble
DISTRIB_DESCRIPTION="Ubuntu 24.04.2 LTS"

2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 INFO: Detected distribution: Ubuntu 24.04
2025-04-27T06:40:28 DEBUG: Reading issue file ...
2025-04-27T06:40:28 DEBUG: Command: 'cat /etc/issue'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 DEBUG: Ubuntu 24.04.2 LTS \n \l


2025-04-27T06:40:28 INFO: Detected distribution flavour: Ubuntu 24.04
2025-04-27T06:40:28 INFO: Customization instance Ubuntu2310Customization loaded.
2025-04-27T06:40:28 INFO: Customization started
2025-04-27T06:40:28 DEBUG: Command: 'perl --version'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result:
This is perl 5, version 38, subversion 2 (v5.38.2) built for x86_64-linux-gnu-thread-multi
(with 44 registered patches, see perl -V for more detail)

Copyright 1987-2023, Larry Wall

Perl may be copied only under the terms of either the Artistic License or the
GNU General Public License, which may be found in the Perl 5 source kit.

Complete documentation for Perl, including FAQ lists, should be found on
this system using "man perl" or "perldoc perl".  If you have access to the
Internet, point your browser at https://www.perl.org/, the Perl Home Page.


2025-04-27T06:40:28 DEBUG: Command: 'hostname 2>/dev/null'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result: ubuntu

2025-04-27T06:40:28 DEBUG: TimedCommand: 'hostname -f 2>/dev/null' with timeout of 5 sec
2025-04-27T06:40:28 DEBUG: Fetching result from /tmp/timed_out_tmp_file_1145
2025-04-27T06:40:28 DEBUG: TimedResult: ubuntu

2025-04-27T06:40:28 DEBUG: opening file /etc/hostname.
2025-04-27T06:40:28 DEBUG: Match found   : Line = ubuntu

2025-04-27T06:40:28 DEBUG: Actual String : ubuntu
2025-04-27T06:40:28 INFO: OLD HOST NAME = ubuntu
2025-04-27T06:40:28 INFO: Customization source: vcenter-customize
2025-04-27T06:40:28 INFO: No need to renew machine ID.
2025-04-27T06:40:28 INFO: Marker file exists or is undefined, pre-customization is not needed
2025-04-27T06:40:28 INFO: Customizing Network settings ...
2025-04-27T06:40:28 INFO: Erasing DHCP leases
2025-04-27T06:40:28 DEBUG: Command: 'pkill dhclient'
2025-04-27T06:40:28 DEBUG: Exit Code: 1
2025-04-27T06:40:28 DEBUG: Result:
2025-04-27T06:40:28 DEBUG: Command: 'rm -rf /var/lib/dhcp/*'
2025-04-27T06:40:28 DEBUG: Exit Code: 0
2025-04-27T06:40:28 DEBUG: Result:
2025-04-27T06:40:28 DEBUG: Check if command [hostnamectl] is available
2025-04-27T06:40:28 INFO: Check if hostnamectl is available
2025-04-27T06:40:28 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:28 DEBUG: Exit Code: 1
2025-04-27T06:40:28 DEBUG: Result:
2025-04-27T06:40:28 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:29 INFO: Check if hostnamectl is available
2025-04-27T06:40:29 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:29 DEBUG: Exit Code: 1
2025-04-27T06:40:29 DEBUG: Result:
2025-04-27T06:40:29 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:30 INFO: Check if hostnamectl is available
2025-04-27T06:40:30 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:31 DEBUG: Exit Code: 1
2025-04-27T06:40:31 DEBUG: Result:
2025-04-27T06:40:31 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:32 INFO: Check if hostnamectl is available
2025-04-27T06:40:32 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:32 DEBUG: Exit Code: 1
2025-04-27T06:40:32 DEBUG: Result:
2025-04-27T06:40:32 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:33 INFO: Check if hostnamectl is available
2025-04-27T06:40:33 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:33 DEBUG: Exit Code: 1
2025-04-27T06:40:33 DEBUG: Result:
2025-04-27T06:40:33 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:34 INFO: Check if hostnamectl is available
2025-04-27T06:40:34 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:34 DEBUG: Exit Code: 1
2025-04-27T06:40:34 DEBUG: Result:
2025-04-27T06:40:34 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:35 INFO: Check if hostnamectl is available
2025-04-27T06:40:35 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:35 DEBUG: Exit Code: 1
2025-04-27T06:40:35 DEBUG: Result:
2025-04-27T06:40:35 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:36 INFO: Check if hostnamectl is available
2025-04-27T06:40:36 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:36 DEBUG: Exit Code: 1
2025-04-27T06:40:36 DEBUG: Result:
2025-04-27T06:40:36 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:37 INFO: Check if hostnamectl is available
2025-04-27T06:40:37 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:37 DEBUG: Exit Code: 1
2025-04-27T06:40:37 DEBUG: Result:
2025-04-27T06:40:37 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:38 INFO: Check if hostnamectl is available
2025-04-27T06:40:38 DEBUG: Command: 'hostnamectl status 2>/tmp/guest.customization.stderr'
2025-04-27T06:40:38 DEBUG: Exit Code: 1
2025-04-27T06:40:38 DEBUG: Result:
2025-04-27T06:40:38 DEBUG: Stderr: Failed to connect to bus: No such file or directory

2025-04-27T06:40:39 DEBUG: Host name is omni-ceph-template
2025-04-27T06:40:39 DEBUG: opening file for writing (/etc/hostname).
2025-04-27T06:40:39 DEBUG: Command: 'chmod 644 /etc/hostname'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result:
2025-04-27T06:40:39 DEBUG: Command: 'hostname omni-ceph-template'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result:
2025-04-27T06:40:39 INFO: Customizing NICS ...
2025-04-27T06:40:39 DEBUG: Command: '/bin/cp -f /etc/netplan/50-cloud-init.yaml /etc/netplan/50-cloud-init.yaml.BeforeVMwareCustomization'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result:
2025-04-27T06:40:39 INFO: Customizing NICS. { NIC1 }
2025-04-27T06:40:39 INFO: Get netplan version installed...
2025-04-27T06:40:39 DEBUG: Command: 'dpkg-query --show --showformat '${Version}' netplan.io'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result: 1.1.1-1~ubuntu24.04.1
2025-04-27T06:40:39 INFO: Netplan version is 1.1.1-1~ubuntu24.04.1
2025-04-27T06:40:39 INFO: Checking if netplan>=0.96...
2025-04-27T06:40:39 DEBUG: Command: 'dpkg --compare-versions 1.1.1-1~ubuntu24.04.1 ge 0.96'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result:
2025-04-27T06:40:39 INFO: Checking if netplan>=0.103...
2025-04-27T06:40:39 DEBUG: Command: 'dpkg --compare-versions 1.1.1-1~ubuntu24.04.1 ge 0.103'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result:
2025-04-27T06:40:39 INFO: Customizing NIC NIC1
2025-04-27T06:40:39 DEBUG: Get interface name for MAC 00:50:56:84:32:f2, via [ip addr show]
2025-04-27T06:40:39 DEBUG: Command: 'whereis ip'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result: ip: /usr/bin/ip /usr/sbin/ip /usr/share/man/man7/ip.7.gz /usr/share/man/man8/ip.8.gz

2025-04-27T06:40:39 DEBUG: Command: '/usr/bin/ip addr show 2>&1'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host noprefixroute
       valid_lft forever preferred_lft forever
2: ens192: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc mq state DOWN group default qlen 1000
    link/ether 00:50:56:84:32:f2 brd ff:ff:ff:ff:ff:ff
    altname enp11s0

2025-04-27T06:40:39 INFO: NIC suffix = ens192
2025-04-27T06:40:39 DEBUG: Checking if ens192 has static ip set in /etc/netplan/50-cloud-init.yaml
2025-04-27T06:40:39 DEBUG: opening file /etc/netplan/50-cloud-init.yaml.
2025-04-27T06:40:39 DEBUG: opening file for writing (/etc/netplan/50-cloud-init.yaml).
2025-04-27T06:40:39 INFO: Query config for ^(NIC1\|IPv6ADDR\|)
2025-04-27T06:40:39 INFO: Query config for ^(NIC1\|IPv6NETMASK\|)
2025-04-27T06:40:39 INFO: Configuring gateway from the primary NIC 'NIC1'.
2025-04-27T06:40:39 INFO: Query config for ^NIC1(\|IPv6GATEWAY\|)
2025-04-27T06:40:39 INFO: Query config for ^(DNS\|SUFFIX\|)
2025-04-27T06:40:39 INFO: Query config for ^(DNS\|NAMESERVER\|)
2025-04-27T06:40:39 DEBUG: Match Found : DNS|NAMESERVER|1
2025-04-27T06:40:39 DEBUG: 0
2025-04-27T06:40:39 DEBUG: Match Found : DNS|NAMESERVER|2
2025-04-27T06:40:39 DEBUG: 1
2025-04-27T06:40:39 DEBUG: opening file for writing (/etc/netplan/99-netcfg-vmware.yaml).
2025-04-27T06:40:39 DEBUG: Command: 'chmod 600 /etc/netplan/99-netcfg-vmware.yaml'
2025-04-27T06:40:39 DEBUG: Exit Code: 0
2025-04-27T06:40:39 DEBUG: Result:
2025-04-27T06:40:39 INFO: Apply Netplan Settings
2025-04-27T06:40:39 DEBUG: Command: '/usr/sbin/netplan apply 2>&1'

=================== Perl script log end =================
[2025-04-27T06:42:08.784Z] [   error] Customization command failed with exitcode: 127, stderr: ''.
[2025-04-27T06:42:08.784Z] [   error] Customization process returned with error.
[2025-04-27T06:42:08.784Z] [   debug] Deployment result = 127.
[2025-04-27T06:42:08.784Z] [    info] Setting 'unknown' error status in vmx.
[2025-04-27T06:42:08.786Z] [    info] Transitioning from state 'INPROGRESS' to state 'ERRORED'.
[2025-04-27T06:42:08.786Z] [    info] ENTER STATE 'ERRORED'.
[2025-04-27T06:42:08.786Z] [    info] EXIT STATE 'INPROGRESS'.
[2025-04-27T06:42:08.786Z] [   debug] Setting deploy error: 'Deployment failed.The forked off process returned error code.'.
[2025-04-27T06:42:08.786Z] [   error] Deployment failed.The forked off process returned error code.
[2025-04-27T06:42:08.786Z] [    info] Launching cleanup.
[2025-04-27T06:42:08.786Z] [   debug] Command to exec : '/bin/rm'.
[2025-04-27T06:42:08.786Z] [    info] sizeof ProcessInternal is 56
[2025-04-27T06:42:08.788Z] [    info] Returning, pending output from stdout
[2025-04-27T06:42:08.788Z] [    info] Returning, pending output from stderr
[2025-04-27T06:42:08.889Z] [    info] Process exited normally after 0 seconds, returned 0
[2025-04-27T06:42:08.889Z] [    info] No more output from stdout
[2025-04-27T06:42:08.889Z] [    info] No more output from stderr
[2025-04-27T06:42:08.889Z] [    info] Customization command output:
''.
[2025-04-27T06:42:08.889Z] [    info] sSkipReboot: 'false', forceSkipReboot 'false'.
[2025-04-27T06:42:08.889Z] [   error] Deploy error: 'Deployment failed.The forked off process returned error code.'.
[2025-04-27T06:42:08.889Z] [   error] Package deploy failed in DeployPkg_DeployPackageFromFile
[2025-04-27T06:42:08.889Z] [   debug] ## Closing log

I'm not sure where the cut-off is, meaning, I don't know what logs are generated after I connect the network card, but I'm guessing it's the last section ("Perl script log end")

If I don't connect the network card, the OS gets stuck in the booting process as show in the screenshot (in case the information helps)

Apr 27 '25 06:04 lethargosapatheia

[2025-04-27T06:40:39.493Z] [ info] Saving output from stdout [2025-04-27T06:42:08.682Z] [ error] Timed out waiting for process exit, canceling... [2025-04-27T06:42:08.782Z] [ error] Process exited abnormally after 100 sec, uncaught signal 9

The Perl script process can NOT finish within 100 seconds, it's blocked at executing /usr/sbin/netplan apply 2>&1

2025-04-27T06:40:39 INFO: Apply Netplan Settings 2025-04-27T06:40:39 DEBUG: Command: '/usr/sbin/netplan apply 2>&1' =================== Perl script log end ================= [2025-04-27T06:42:08.784Z] [ error] Customization command failed with exitcode: 127, stderr: ''. [2025-04-27T06:42:08.784Z] [ error] Customization process returned with error.

This failure leads to no network re-connection happened.

@lethargosapatheia , could you please share the yaml files (/etc/netplan/99-netcfg-vmware.yaml, /etc/netplan/50-cloud-init.yaml and etc) under /etc/netplan, we need to find out why netplan can NOT apply these network configurations.

Apr 27 '25 08:04 PengpengSun

root@omni-ceph-template:~# cat /etc/netplan/99-netcfg-vmware.yaml

# Generated by VMWare customization engine.
network:
  version: 2
  renderer: networkd
  ethernets:
    ens192:
      dhcp4: no
      dhcp6: no
      addresses:
        - 10.88.88.157/24
      routes:
        - to: default
          via: 10.88.88.126
      nameservers:
        addresses:
          - 10.88.88.21
          - 10.88.88.22

root@omni-ceph-template:~# cat /etc/netplan/50-cloud-init.yaml

network:
  version: 2
  ethernets:
    ens192:
      match:
        macaddress: "00:50:56:84:32:f2"
      dhcp4: true
      dhcp6: true
      set-name: "ens192"

root@omni-ceph-template:/etc/netplan# cat 50-cloud-init.yaml.BeforeVMwareCustomization

network:
  version: 2
  ethernets:
    ens192:
      match:
        macaddress: "00:50:56:84:32:f2"
      dhcp4: true
      dhcp6: true
      set-name: "ens192"

Apr 27 '25 10:04 lethargosapatheia

If I run netplan apply, there's no error. Everything works as expected. So I'm a little bit surprised by this. Maybe at the time netplan is run by deploypkg not all configuration files are there, although I'm guessing they are.

Apr 27 '25 14:04 lethargosapatheia

If I run netplan apply, there's no error. Everything works as expected. So I'm a little bit surprised by this. Maybe at the time netplan is run by deploypkg not all configuration files are there, although I'm guessing they are.

Yes, netplan apply could not finish at the boot time since cloud-init service blocks dbus start. I also did some tests on both http://cloud-images-archive.ubuntu.com/releases/noble/release-20240710/ and https://cloud-images.ubuntu.com/noble/20250403/

release-20240710 (netplan ver: 1.0-2ubuntu1.2) netplan apply finished with Exit Code 0, but logged Failed to connect to system bus: No such file or directory and Falling back to a hard restart of systemd-networkd.service. This means even dbus is not ready, netplan apply could finish correctly.
release-20250403 (netplan ver: 1.1.1-1~ubuntu24.04.1) netplan apply stuck.

This looks like a netplan regression to me, from https://bugs.launchpad.net/ubuntu/noble/+source/netplan.io/+bug/2077011, I see Ubuntu backported 1.1.1-1 to noble at 2025-01-08, I suggest file a bug to ubuntu team on this.

Apr 28 '25 09:04 PengpengSun

Thank you for identifying the problem with clear details. This helps. I've reported the bug here:

https://bugs.launchpad.net/ubuntu/+source/netplan.io/+bug/2109487

Apr 28 '25 09:04 lethargosapatheia

Thank you for identifying the problem with clear details. This helps. I've reported the bug here:

https://bugs.launchpad.net/ubuntu/+source/netplan.io/+bug/2109487

Sure, I've clicked the 'This bug also affects me' link to change this bug to Confirmed status.

Apr 28 '25 09:04 PengpengSun

@lethargosapatheia Although this is likely a Ubuntu netplan regression issue, Guest customization can do something to optimize netplan apply execution in such case, the change should be available in one future vSphere 8.0.3 release.

May 08 '25 07:05 PengpengSun

toolsDeployPkg.log: Customization command failed with exitcode: 127, stderr: '' on Ubuntu Cloud image - 20250403

Describe the bug

Reproduction steps

Expected behavior

Additional context