JDK-8245311 : [macos] misc package tests failed due to "execution error: Finder got an error: AppleEvent timed out."
  • Type: Bug
  • Component: tools
  • Sub-Component: jpackage
  • Affected Version: 15,16
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2020-05-19
  • Updated: 2024-11-13
  • Resolved: 2020-07-22
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 b08Fixed
Related Reports
Relates :  
Relates :  
Description
The following test failed in the JDK15 CI:

tools/jpackage/share/EmptyFolderPackageTest.java

Here's a snippet from the log file:

DI_kextWaitQuiet: about to call IOServiceWaitQuiet...
DI_kextWaitQuiet: IOServiceWaitQuiet took 0.000005 seconds
2020-05-19 01:48:40.067 diskimages-helper[4843:23138260] DIHelperHDID serveImage: attaching drive
{
    autodiskmount = 1;
    "hdiagent-drive-identifier" = "E900B99F-F5F6-4952-80C1-AE135346D801";
    "unmount-timeout" = 0;
}
2020-05-19 01:48:40.069 diskimages-helper[4843:23138260] DIHelperHDID serveImage: connecting to myDrive 0x3B0F
2020-05-19 01:48:40.069 diskimages-helper[4843:23138260] DIHelperHDID serveImage: register _readBuffer 0x1137d5000
2020-05-19 01:48:40.069 diskimages-helper[4843:23138260] DIHelperHDID serveImage: activating drive port 14603
2020-05-19 01:48:40.069 diskimages-helper[4843:23138260] DIHelperHDID serveImage: set cache enabled=TRUE returned FAILURE.
2020-05-19 01:48:41.305 diskimages-helper[4843:23138260] DIHelperHDID serveImage: set on IO thread=TRUE returned SUCCESS.
2020-05-19 01:48:41.305 diskimages-helper[4843:23138260] -processKernelRequest: will sleep received
Mounting???
2020-05-19 01:48:50.680 diskimages-helper[4843:23138257] _mountDevEntries: disk1s1 aborting mountpoint postflight because disk image has no band size specified.
Finishing???
Finishing???
/dev/disk1          	GUID_partition_scheme          	
/dev/disk1s1        	Apple_HFS                      	/private/var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage11331618963992087985/images/EmptyFolderPackageTest
Running [osascript, /var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage11331618963992087985/config/EmptyFolderPackageTest-dmg-setup.scpt]
/var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage11331618963992087985/config/EmptyFolderPackageTest-dmg-setup.scpt:220:232: execution error: Finder got an error: AppleEvent timed out. (-1712)
java.io.IOException: Command [osascript, /var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage11331618963992087985/config/EmptyFolderPackageTest-dmg-setup.scpt] 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:342)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.bundle(MacDmgBundler.java:82)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacDmgBundler.execute(MacDmgBundler.java:484)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.generateBundle(Arguments.java:648)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.processArguments(Arguments.java:517)
	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)

<snip>

java.io.IOException: Command [pkgbuild, --root, /var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage13674662505527704356/images/image-12789490505410600886, --install-location, /Applications, --component-plist, /var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage13674662505527704356/config/cpl.plist, --scripts, /var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage13674662505527704356/config/scripts, --identifier, Hello, /var/folders/g_/q5lj205x373ghs_h74p6_xh80000gp/T/jdk.incubator.jpackage13674662505527704356/packages/EmptyFolderPackageTest-app.pkg] exited with 134 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.MacPkgBundler.createPKG(MacPkgBundler.java:432)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacPkgBundler.bundle(MacPkgBundler.java:131)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.MacPkgBundler.execute(MacPkgBundler.java:569)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.generateBundle(Arguments.java:648)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.processArguments(Arguments.java:517)
	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: Error: Bundler "Mac PKG Package" (pkg) failed to produce a package
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.generateBundle(Arguments.java:651)
	at jdk.incubator.jpackage/jdk.incubator.jpackage.internal.Arguments.processArguments(Arguments.java:517)
	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)
TRACE: exec: Done. Exit code: 1
ERROR: Expected [0]. Actual [1]: Check command [/mesos/work_dir/jib-master/install/jdk-15+24-1143/macosx-x64.jdk/jdk-15.jdk/Contents/Home/bin/jpackage --input ./input --dest ./output --name EmptyFolderPackageTest --type pkg --main-jar hello.jar --main-class Hello --verbose](14) exited with 0 code
[  FAILED  ] EmptyFolderPackageTest; checks=27
----------System.err:(55/3900)----------
WARNING: Using incubator modules: jdk.incubator.jpackage
WARNING: Using incubator modules: jdk.incubator.jpackage
WARNING: Using incubator modules: jdk.incubator.jpackage
java.lang.AssertionError: Expected [0]. Actual [1]: Check command [/mesos/work_dir/jib-master/install/jdk-15+24-1143/macosx-x64.jdk/jdk-15.jdk/Contents/Home/bin/jpackage --input ./input --dest ./output --name EmptyFolderPackageTest --type pkg --main-jar hello.jar --main-class Hello --verbose](14) exited with 0 code
	at jdk.jpackage.test.TKit.error(TKit.java:258)
	at jdk.jpackage.test.TKit.assertEquals(TKit.java:561)
	at jdk.jpackage.test.Executor$Result.assertExitCodeIs(Executor.java:164)
	at jdk.jpackage.test.Executor.execute(Executor.java:202)
	at jdk.jpackage.test.JPackageCommand.execute(JPackageCommand.java:633)
	at jdk.jpackage.test.PackageTest$Handler.accept(PackageTest.java:499)
	at jdk.jpackage.test.PackageTest$2.accept(PackageTest.java:428)
	at jdk.jpackage.test.PackageTest$2.accept(PackageTest.java:377)
	at jdk.jpackage.test.Functional$ThrowingConsumer.lambda$toConsumer$0(Functional.java:37)
	at java.base/java.lang.Iterable.forEach(Iterable.java:75)
	at jdk.jpackage.test.PackageTest.lambda$runActions$20(PackageTest.java:341)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1510)
	at jdk.jpackage.test.PackageTest.lambda$runActions$21(PackageTest.java:340)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1510)
	at jdk.jpackage.test.PackageTest.runActions(PackageTest.java:339)
	at jdk.jpackage.test.RunnablePackageTest.run(RunnablePackageTest.java:51)
	at EmptyFolderPackageTest.lambda$main$2(EmptyFolderPackageTest.java:58)
	at jdk.jpackage.test.TestInstance.lambda$new$1(TestInstance.java:151)
	at jdk.jpackage.test.TestInstance.run(TestInstance.java:224)
	at jdk.jpackage.test.TKit.lambda$ignoreExceptions$6(TKit.java:138)
	at jdk.jpackage.test.TKit.lambda$runTests$4(TKit.java:123)
	at java.base/java.util.AbstractList$RandomAccessSpliterator.forEachRemaining(AbstractList.java:720)
	at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
	at jdk.jpackage.test.TKit.lambda$runTests$5(TKit.java:120)
	at jdk.jpackage.test.Functional$ThrowingRunnable.lambda$toRunnable$0(Functional.java:101)
	at jdk.jpackage.test.TKit.withExtraLogStream(TKit.java:106)
	at jdk.jpackage.test.TKit.runTests(TKit.java:119)
	at jdk.jpackage.test.TKit.lambda$run$3(TKit.java:93)
	at jdk.jpackage.test.Functional$ThrowingRunnable.lambda$toRunnable$0(Functional.java:101)
	at jdk.jpackage.test.TKit.run(TKit.java:93)
	at EmptyFolderPackageTest.main(EmptyFolderPackageTest.java:47)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:832)
java.lang.RuntimeException
	at jdk.jpackage.test.TKit.run(TKit.java:96)
	at EmptyFolderPackageTest.main(EmptyFolderPackageTest.java:47)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:832)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: java.lang.RuntimeException
----------rerun:(38/6842)*----------
Comments
URL: https://hg.openjdk.java.net/jdk/jdk/rev/f25a5b35e983 User: almatvee Date: 2020-07-22 21:19:57 +0000
22-07-2020

http://cr.openjdk.java.net/~almatvee/8245311/webrev.01/ - "hdiutil detach" resource busy error is fixed in same way as JDK-8242786 by repeating detach several times. - pkgbuild timeout will be covered with JDK-8249395.
18-07-2020

I tried repro case for JDK-8236282., but running pkgbuild and issue did not reproduced.
15-07-2020

"hdiutil detach" failure very similar to JDK-8242786. After JDK-8242786 was implemented, it did not failed inside MacHelper.java. Suggested solution is to rerun detach several times from jpackage itself.
15-07-2020

pkgbuild timeout might be same root cause as JDK-8236282. Since JDK-8236282 was only reproducible for "hdiutil attach", it might be possible that it is also reproducible for other external tools we using to build DMG or PKG.
15-07-2020

Can it be somehow related to JDK-8236282?
18-06-2020

Still trying to find way to reproduce
27-05-2020