JDK-8238781 : [macos] jpackage tests failed due to "hdiutil: convert failed" in various ways
  • Type: Bug
  • Component: tools
  • Sub-Component: jpackage
  • Affected Version: 15,16
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2020-02-10
  • Updated: 2024-12-20
  • Resolved: 2020-12-09
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 16
16 b28Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Relates :  
Relates :  
Description
The following test failed in the JDK15 CI:

tools/jpackage/share/IconTest.java

Here's a snippet from the log file:

Creating DMG file: /mesos/work_dir/slaves/7cfa21b9-afde-4338-a459-d3e0a13ec793-S1176/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/2159a67a-de2e-46d6-a616-f98c552e821b/runs/f5083a6e-4abd-4ce2-a18c-32b75a962db4/testoutput/test-support/jtreg_open_test_jdk_tier2_part2/scratch/0/./test.3617e55e/output/IconTest-1.0.dmg.
Running [/usr/bin/hdiutil, create, -verbose, -srcfolder, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/image-16353669255289459054, -volname, IconTest, -ov, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/IconTest-tmp.dmg, -fs, HFS+, -format, UDRW]
2020-02-10 08:09:53.123 hdiutil[69407:56089714] error: unable to set up framework server.
DIHLDiskImageCreate() returned 6
(null)
hdiutil: create: returning 6
hdiutil: create failed - Device not configured
java.io.IOException: Command [/usr/bin/hdiutil, create, -verbose, -srcfolder, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/image-16353669255289459054, -volname, IconTest, -ov, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/IconTest-tmp.dmg, -fs, HFS+, -format, UDRW] exited with 1 code
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Executor.executeExpectSuccess(Executor.java:73)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.IOUtils.exec(IOUtils.java:165)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.IOUtils.exec(IOUtils.java:136)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.buildDMG(MacDmgBundler.java:299)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.bundle(MacDmgBundler.java:81)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.execute(MacDmgBundler.java:467)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.generateBundle(Arguments.java:641)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.processArguments(Arguments.java:514)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.main.Main.execute(Main.java:98)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.main.Main.main(Main.java:52)
jdk.incubator.jpackage.internal.PackagerException: java.io.IOException: Command [/usr/bin/hdiutil, create, -verbose, -srcfolder, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/image-16353669255289459054, -volname, IconTest, -ov, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/IconTest-tmp.dmg, -fs, HFS+, -format, UDRW] exited with 1 code
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.bundle(MacDmgBundler.java:86)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.execute(MacDmgBundler.java:467)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.generateBundle(Arguments.java:641)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.processArguments(Arguments.java:514)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.main.Main.execute(Main.java:98)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.main.Main.main(Main.java:52)
Caused by: java.io.IOException: Command [/usr/bin/hdiutil, create, -verbose, -srcfolder, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/image-16353669255289459054, -volname, IconTest, -ov, /var/folders/3v/cglhtd2j5f5dcxf1t9shc_bc0000gp/T/jdk.incubator.jpackage14748253831843228878/images/IconTest-tmp.dmg, -fs, HFS+, -format, UDRW] exited with 1 code
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Executor.executeExpectSuccess(Executor.java:73)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.IOUtils.exec(IOUtils.java:165)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.IOUtils.exec(IOUtils.java:136)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.buildDMG(MacDmgBundler.java:299)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.bundle(MacDmgBundler.java:81)
	... 5 more
TRACE: exec: Done. Exit code: 1
ERROR: Expected [0]. Actual [1]: Check command [/mesos/work_dir/jib-master/install/jdk-15+10-288/macosx-x64.jdk/jdk-15.jdk/Contents/Home/bin/jpackage --input ./test.3617e55e/input --dest ./test.3617e55e/output --name IconTest --type dmg --main-jar hello.jar --main-class Hello --icon /mesos/work_dir/jib-master/install/jdk-15+10-288/src.full/open/test/jdk/tools/jpackage/resources/icon.icns --runtime-image ./test.3617e55e/fake_runtime --verbose](18) exited with 0 code
[  FAILED  ] IconTest(Package, CustomIcon).test; checks=9


Since this is a Tier2 test, I'm starting this bug as a P3.
Comments
Changeset: e6b4c4d7 Author: Alexander Matveev <almatvee@openjdk.org> Date: 2020-12-09 19:02:15 +0000 URL: https://git.openjdk.java.net/jdk/commit/e6b4c4d7
09-12-2020

According to logs failure is due to "hdiutil convert" failed similar to create and detach. Our workarounds for create and detach worked fine based on logs. I will update bug summary, that convert fails and not create. [18:45:33.526] Output: hdiutil: convert: processing "/var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/IconTest-tmp.dmg" DIBackingStoreInstantiatorProbe: interface 0, score 100, CBSDBackingStore DIBackingStoreInstantiatorProbe: interface 1, score -1000, CBundleBackingStore DIBackingStoreInstantiatorProbe: interface 2, score -1000, CRAMBackingStore DIBackingStoreInstantiatorProbe: interface 3, score 100, CCarbonBackingStore DIBackingStoreInstantiatorProbe: interface 4, score -1000, CDevBackingStore DIBackingStoreInstantiatorProbe: interface 5, score -1000, CCURLBackingStore DIBackingStoreInstantiatorProbe: interface 6, score -1000, CVectoredBackingStore convert: unable to recognize "/var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/IconTest-tmp.dmg": Resource temporarily unavailable.hdiutil: convert: result: 35 hdiutil: convert failed - Resource temporarily unavailable [18:45:33.527] Returned: 1
08-12-2020

Here's a log file snippet from the jdk-16+28-1945-tier2 sighting: [18:45:14.978] Running /usr/bin/hdiutil [18:45:21.285] Command: /usr/bin/hdiutil create -verbose -srcfolder /var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/image-3069194319642620407 -volname IconTest -ov /var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/IconTest-tmp.dmg -fs HFS+ -format UDRW [18:45:21.286] Output: 2020-12-04 18:45:15.069 diskimages-helper[5113:288827198] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-04 18:45:15.069 diskimages-helper[5113:288827198] *useRealIDs******** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) Initializing??? 2020-12-04 18:45:15.070 diskimages-helper[5113:288827198] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-04 18:45:15.085 copy-helper[5114:288827199] estimating /private/var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/image-3069194319642620407 2020-12-04 18:45:16.248 diskimages-helper[5113:288827198] *useRealIDs******** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) Creating??? DIDiskImageCreatorProbe: interface 1, score -1000, CSparseBundleDiskImage DIDiskImageCreatorProbe: interface 2, score -1000, CSparseDiskImage DIDiskImageCreatorProbe: interface 3, score 1000, CRawDiskImage DIDiskImageCreatorProbe: interface 7, score -1000, CWOUDIFDiskImage DIDiskImageCreatorProbe: interface 9, score -1000, CCFPlugInDiskImage DIDiskImageCreateWithCFURL: CRawDiskImage DIFileEncodingCreatorProbe: interface 2, score -1000, CEncryptedEncoding DIBackingStoreCreatorProbe: interface 0, score 100, CBSDBackingStore DIBackingStoreCreatorProbe: interface 1, score -1000, CBundleBackingStore DIBackingStoreCreatorProbe: interface 2, score 0, CRAMBackingStore DIBackingStoreCreatorProbe: interface 3, score 300, CCarbonBackingStore DIBackingStoreCreatorProbe: interface 5, score -100, CCURLBackingStore DIBackingStoreCreateWithCFURL: CCarbonBackingStore DIBackingStoreCreateWithCFURL: creator returned 0 DIDiskImageCreateWithCFURL: creator returned 0 DI_kextWaitQuiet: about to call IOServiceWaitQuiet... DI_kextWaitQuiet: IOServiceWaitQuiet took 0.000004 seconds DI_kextWaitQuiet: about to call IOServiceWaitQuiet... DI_kextWaitQuiet: IOServiceWaitQuiet took 0.000004 seconds 2020-12-04 18:45:17.892 diskimages-helper[5113:288827221] DIHelperHDID serveImage: attaching drive { autodiskmount = 1; "hdiagent-drive-identifier" = "2A9595D9-178F-41C4-A5ED-9670950CC43B"; "skip-auto-fsck-for-system-images" = 1; "system-image" = 1; "unmount-timeout" = 0; } 2020-12-04 18:45:17.894 diskimages-helper[5113:288827221] DIHelperHDID serveImage: connecting to myDrive 0x3E1B 2020-12-04 18:45:17.894 diskimages-helper[5113:288827221] DIHelperHDID serveImage: register _readBuffer 0x107700000 2020-12-04 18:45:17.894 diskimages-helper[5113:288827221] DIHelperHDID serveImage: activating drive port 15383 2020-12-04 18:45:17.894 diskimages-helper[5113:288827221] DIHelperHDID serveImage: set cache enabled=TRUE returned FAILURE. 2020-12-04 18:45:17.903 diskimages-helper[5113:288827221] DIHelperHDID serveImage: set on IO thread=TRUE returned SUCCESS. 2020-12-04 18:45:17.904 diskimages-helper[5113:288827221] -processKernelRequest: will sleep received 2020-12-04 18:45:18.625 diskimages-helper[5113:288827198] _mountDevEntries: disk6s1 aborting mountpoint postflight because disk image has no band size specified. 2020-12-04 18:45:18.626 diskimages-helper[5113:288827198] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-04 18:45:18.655 diskimages-helper[5113:288827198] *useRealIDs******** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) Copying??? 2020-12-04 18:45:18.655 diskimages-helper[5113:288827198] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-04 18:45:18.672 copy-helper[5129:288827311] copying /private/var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/image-3069194319642620407 to /Volumes/IconTest 2020-12-04 18:45:18.672 copy-helper[5129:288827311] About to copy "/var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/image-3069194319642620407". 2020-12-04 18:45:19.054 copy-helper[5129:288827311] Copy finished. Finishing??? 2020-12-04 18:45:21.154 diskimages-helper[5113:288827221] -processKernelRequest: flush received 2020-12-04 18:45:21.171 diskimages-helper[5113:288827198] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) DIHLDiskImageCreate() returned 49168 hdiutil: create: returning 49168 hdiutil: create failed - Resource busy [18:45:21.293] Returned: 1 [18:45:21.294] java.io.IOException: Command [/usr/bin/hdiutil, create, -verbose, -srcfolder, /var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/image-3069194319642620407, -volname, IconTest, -ov, /var/folders/jl/kn2l67sd17s6k74jx39pwp_8000_dc/T/jdk.jpackage488230805885423068/images/IconTest-tmp.dmg, -fs, HFS+, -format, UDRW] exited with 1 code at jdk.jpackage/jdk.jpackage.internal.Executor.executeExpectSuccess(Executor.java:91) at jdk.jpackage/jdk.jpackage.internal.IOUtils.exec(IOUtils.java:190) at jdk.jpackage/jdk.jpackage.internal.IOUtils.exec(IOUtils.java:151) at jdk.jpackage/jdk.jpackage.internal.MacDmgBundler.buildDMG(MacDmgBundler.java:328) at jdk.jpackage/jdk.jpackage.internal.MacDmgBundler.bundle(MacDmgBundler.java:88) at jdk.jpackage/jdk.jpackage.internal.MacDmgBundler.execute(MacDmgBundler.java:534) at jdk.jpackage/jdk.jpackage.internal.Arguments.generateBundle(Arguments.java:664) at jdk.jpackage/jdk.jpackage.internal.Arguments.processArguments(Arguments.java:538) at jdk.jpackage/jdk.jpackage.main.Main.execute(Main.java:98) at jdk.jpackage/jdk.jpackage.main.Main.main(Main.java:52)
04-12-2020

Here's a log file snippet from the jdk-16+28-1916-tier2 sighting: [22:34:23.089] Running /usr/bin/hdiutil [22:34:31.436] Command: /usr/bin/hdiutil create -verbose -srcfolder /var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/image-7381036548011375259 -volname EmptyFolderPackageTest -ov /var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/EmptyFolderPackageTest-tmp.dmg -fs HFS+ -format UDRW [22:34:31.437] Output: 2020-12-03 22:34:23.245 diskimages-helper[71210:54158107] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-03 22:34:23.245 diskimages-helper[71210:54158107] *useRealIDs******** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) Initializing??? 2020-12-03 22:34:23.246 diskimages-helper[71210:54158107] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-03 22:34:23.264 copy-helper[71211:54158108] estimating /private/var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/image-7381036548011375259 2020-12-03 22:34:24.439 diskimages-helper[71210:54158107] *useRealIDs******** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) Creating??? DIDiskImageCreatorProbe: interface 1, score -1000, CSparseBundleDiskImage DIDiskImageCreatorProbe: interface 2, score -1000, CSparseDiskImage DIDiskImageCreatorProbe: interface 3, score 1000, CRawDiskImage DIDiskImageCreatorProbe: interface 7, score -1000, CWOUDIFDiskImage DIDiskImageCreatorProbe: interface 9, score -1000, CCFPlugInDiskImage DIDiskImageCreateWithCFURL: CRawDiskImage DIFileEncodingCreatorProbe: interface 2, score -1000, CEncryptedEncoding DIBackingStoreCreatorProbe: interface 0, score 100, CBSDBackingStore DIBackingStoreCreatorProbe: interface 1, score -1000, CBundleBackingStore DIBackingStoreCreatorProbe: interface 2, score 0, CRAMBackingStore DIBackingStoreCreatorProbe: interface 3, score 300, CCarbonBackingStore DIBackingStoreCreatorProbe: interface 5, score -100, CCURLBackingStore DIBackingStoreCreateWithCFURL: CCarbonBackingStore DIBackingStoreCreateWithCFURL: creator returned 0 DIDiskImageCreateWithCFURL: creator returned 0 DI_kextWaitQuiet: about to call IOServiceWaitQuiet... DI_kextWaitQuiet: IOServiceWaitQuiet took 0.000014 seconds DI_kextWaitQuiet: about to call IOServiceWaitQuiet... DI_kextWaitQuiet: IOServiceWaitQuiet took 0.000004 seconds 2020-12-03 22:34:25.784 diskimages-helper[71210:54158187] DIHelperHDID serveImage: attaching drive { autodiskmount = 1; "hdiagent-drive-identifier" = "12124356-4B10-4BB6-B7B8-6DDF8A9EC524"; "skip-auto-fsck-for-system-images" = 1; "system-image" = 1; "unmount-timeout" = 0; } 2020-12-03 22:34:25.797 diskimages-helper[71210:54158187] DIHelperHDID serveImage: connecting to myDrive 0x551B 2020-12-03 22:34:25.797 diskimages-helper[71210:54158187] DIHelperHDID serveImage: register _readBuffer 0x10c5b0000 2020-12-03 22:34:25.797 diskimages-helper[71210:54158187] DIHelperHDID serveImage: activating drive port 14371 2020-12-03 22:34:25.797 diskimages-helper[71210:54158187] DIHelperHDID serveImage: set cache enabled=TRUE returned FAILURE. 2020-12-03 22:34:25.808 diskimages-helper[71210:54158187] DIHelperHDID serveImage: set on IO thread=TRUE returned SUCCESS. 2020-12-03 22:34:25.808 diskimages-helper[71210:54158187] -processKernelRequest: will sleep received 2020-12-03 22:34:26.130 diskimages-helper[71210:54158107] _mountDevEntries: disk3s1 aborting mountpoint postflight because disk image has no band size specified. 2020-12-03 22:34:26.131 diskimages-helper[71210:54158107] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-03 22:34:26.161 diskimages-helper[71210:54158107] *useRealIDs******** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) Copying??? 2020-12-03 22:34:26.162 diskimages-helper[71210:54158107] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) 2020-12-03 22:34:26.180 copy-helper[71228:54158296] copying /private/var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/image-7381036548011375259 to /Volumes/EmptyFolderPackageTest 2020-12-03 22:34:26.180 copy-helper[71228:54158296] About to copy "/var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/image-7381036548011375259". 2020-12-03 22:34:28.756 copy-helper[71228:54158296] Copy finished. Finishing??? 2020-12-03 22:34:31.058 diskimages-helper[71210:54158187] -processKernelRequest: flush received DI_kextDriveDisconnect: could not disconnect from IOHDIXHDDrive object - 268435459 diskimages-helper: DI_kextDriveDisconnect returned 268435459 ((ipc/send) invalid destination port). 2020-12-03 22:34:31.083 diskimages-helper[71210:54158107] *useEffectiveIDs**** euid/egid changed to 10668,10668 (uid/gid is 10668,10668) DIHLDiskImageCreate() returned 49168 hdiutil: create: returning 49168 hdiutil: create failed - Resource busy [22:34:31.439] Returned: 1 [22:34:31.439] java.io.IOException: Command [/usr/bin/hdiutil, create, -verbose, -srcfolder, /var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/image-7381036548011375259, -volname, EmptyFolderPackageTest, -ov, /var/folders/93/pf04s4c922qcyb7v8xr1y5h8000_dc/T/jdk.jpackage15069277841811879546/images/EmptyFolderPackageTest-tmp.dmg, -fs, HFS+, -format, UDRW] exited with 1 code at jdk.jpackage/jdk.jpackage.internal.Executor.executeExpectSuccess(Executor.java:91) at jdk.jpackage/jdk.jpackage.internal.IOUtils.exec(IOUtils.java:190) at jdk.jpackage/jdk.jpackage.internal.IOUtils.exec(IOUtils.java:151) at jdk.jpackage/jdk.jpackage.internal.MacDmgBundler.buildDMG(MacDmgBundler.java:328) at jdk.jpackage/jdk.jpackage.internal.MacDmgBundler.bundle(MacDmgBundler.java:88) at jdk.jpackage/jdk.jpackage.internal.MacDmgBundler.execute(MacDmgBundler.java:534) at jdk.jpackage/jdk.jpackage.internal.Arguments.generateBundle(Arguments.java:664) at jdk.jpackage/jdk.jpackage.internal.Arguments.processArguments(Arguments.java:538) at jdk.jpackage/jdk.jpackage.main.Main.execute(Main.java:98) at jdk.jpackage/jdk.jpackage.main.Main.main(Main.java:52)
04-12-2020

This failure mode still happens in the JDK15 and JDK16 CIs. You might not be able to reproduce the bug outside of the CIs, but that does not mean the bug is not reproducible.
30-06-2020

intermittent and not obviously reproducible
27-05-2020