JDK-8174819 : java/nio/file/WatchService/LotsOfEvents.java fails intermittently
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.nio
  • Affected Version: 9,12,15,16,17
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2017-02-13
  • Updated: 2022-11-17
  • Resolved: 2021-09-28
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 11 JDK 17 JDK 18
11.0.14Fixed 17.0.2Fixed 18 b17Fixed
Related Reports
Relates :  
JDK-8297188 - java/nio/file/WatchService/LotsOfEvents.java fails intermittently
Relates :  
JDK-8293067 - (fs) Implement WatchService using system library (macOS)
Relates :  
JDK-8175115 - Improve instrumentation of java/nio/file/WatchService/LotsOfEvents.java
Relates :  
JDK-8250651 - java/nio/file/WatchService/SensitivityModifier.java fails with missing ENTRY_MODIFY event
Description
java/nio/file/WatchService/LotsOfEvents.java fails intermittently, observed at OSX platform.

----------System.err:(14/829)----------
java.lang.RuntimeException: Insufficient events
	at LotsOfEvents.drainAndCheckOverflowEvents(LotsOfEvents.java:127)
	at LotsOfEvents.testOverflowEvent(LotsOfEvents.java:73)
	at LotsOfEvents.main(LotsOfEvents.java:46)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:543)
	at com.sun.javatest.regtest.agent.MainActionHelper$SameVMRunnable.run(MainActionHelper.java:230)
	at java.base/java.lang.Thread.run(Thread.java:844)
Comments
verified
13-04-2022
Fix request [11u] I backport this for parity with 11.0.15-oracle. No risk, only a test change. Clean backport. Test passes.
11-11-2021
17u fix request: Please approve this fix for backport to 17u. The patch applies clean, and test passes on all platforms.
15-10-2021
Changeset: 633eab23 Author: Jaikiran Pai <jpai@openjdk.org> Date: 2021-09-28 04:54:58 +0000 URL: https://git.openjdk.java.net/jdk/commit/633eab23f0c5cadac06e37b9d6eeef5696ca3d22
28-09-2021
There are some interesting bits in all the logs available in this issue so far. Each failure is in "testOverflowEvent" (that's the obvious part). The interesting part is these logs: (from one of those runs): > Retrieved key with 1 events after 5511153205 ns (from a different run): > Retrieved key with 1 events after 2437085064 ns This log message is part of the diagnostic output where an additional polling of events is done (with a 15 second timeout), after the test has failed. This useful diagnostic logs were added as part of https://bugs.openjdk.java.net/browse/JDK-8175115. The interesting part in the above diagnostic log is that this is consistently returning 1 single event, which IMO is highly likely that it's an OVERFLOW event (since apparently it won't be retrieved with other event kinds). The 2437085064 ns and 5511153205 ns translate to 2 and 5 seconds each. This implies that if the "while" loop in the actual test, which currently waits for just 2 seconds, had instead waited for a few more seconds, then it would have received these events. This matches with what Alan already noted in this issue: > It's likely the sleep in the test isn't long enough for the polling implementation to accumulate and overflow. I'll open a PR with a proposed change that might help fix this intermittent failure.
25-09-2021
Here's a log file snippet from the jdk-17+6-315-tier2 sighting: java/nio/file/WatchService/LotsOfEvents.java ----------System.err:(16/1249)---------- Test directory /scratch/mesos/slaves/0f76e7b4-d512-4e9f-a839-a1d961774dea-S24175/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/848f09a1-f9c9-4847-9565-2a3ccb589531/runs/7fdb3724-272c-40ba-bd71-4c927534707f/testoutput/test-support/jtreg_open_test_jdk_tier2_part2/tmp/name15026216390491237227 contains 1024 files Retrieved key with 1 events after 2437085064 ns java.lang.RuntimeException: Insufficient ENTRY_CREATE events: expected 1024, received 488 at LotsOfEvents.drainAndCheckOverflowEvents(LotsOfEvents.java:146) at LotsOfEvents.testOverflowEvent(LotsOfEvents.java:76) at LotsOfEvents.main(LotsOfEvents.java:49) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298) at java.base/java.lang.Thread.run(Thread.java:831) JavaTest Message: Test threw exception: java.lang.RuntimeException JavaTest Message: shutting down test ----------System.out:(1/48)---------- Seed from RandomFactory = -8300919819018459583L result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Insufficient ENTRY_CREATE events: expected 1024, received 488 test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Insufficient ENTRY_CREATE events: expected 1024, received 488
16-01-2021
Here's a snippet from the log file from the jdk-16+5-151-tier2 CI job set failure: ----------System.err:(16/1244)---------- Test directory /mesos/work_dir/slaves/4728e7c1-7e67-490e-be0f-6bbf2a2f33db-S324/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/5b82adbd-f594-4567-b962-b9a07267cb66/runs/a94c5a04-aab3-436a-ac03-b2d136cb45a6/testoutput/test-support/jtreg_open_test_jdk_tier2_part2/tmp/name7152667754384086269 contains 0 files Retrieved key with 1 events after 5511153205 ns java.lang.RuntimeException: Insufficient ENTRY_DELETE events: expected 1024, received 495 at LotsOfEvents.drainAndCheckOverflowEvents(LotsOfEvents.java:146) at LotsOfEvents.testOverflowEvent(LotsOfEvents.java:87) at LotsOfEvents.main(LotsOfEvents.java:49) 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.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298) at java.base/java.lang.Thread.run(Thread.java:832) JavaTest Message: Test threw exception: java.lang.RuntimeException JavaTest Message: shutting down test ----------System.out:(1/47)---------- Seed from RandomFactory = 6205956148904838769L result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Insufficient ENTRY_DELETE events: expected 1024, received 495 test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Insufficient ENTRY_DELETE events: expected 1024, received 495
07-07-2020
We don't have a native implementation of WatchService on macOS so it's using the polling implementation. It's likely the sleep in the test isn't long enough for the polling implementation to accumulate and overflow.
12-09-2018
Since this is a tier2 failure, I'm bumping the priority from P4 -> P3. Also added the 'intermittent' label.
12-09-2018
Spotted again: Test directory /var/folders/db/32zz3v4j141_887zr71kxzbc0000mv/T/name3731228544592730827 contains 1024 files Retrieved key with 1 events after 2929315238 ns java.lang.RuntimeException: Insufficient ENTRY_CREATE events: expected 1024, received 305 at LotsOfEvents.drainAndCheckOverflowEvents(LotsOfEvents.java:146) at LotsOfEvents.testOverflowEvent(LotsOfEvents.java:76) at LotsOfEvents.main(LotsOfEvents.java:49) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:246) at java.base/java.lang.Thread.run(Thread.java:834)
12-09-2018
Note that the 2001 and 2010 failures are different: 2001 java.lang.RuntimeException: Unexpected event 'ENTRY_CREATE' at LotsOfEvents.drainAndCheckOverflowEvents(LotsOfEvents.java:117) at LotsOfEvents.testOverflowEvent(LotsOfEvents.java:84) at LotsOfEvents.main(LotsOfEvents.java:46) 2010 java.lang.RuntimeException: Insufficient events at LotsOfEvents.drainAndCheckOverflowEvents(LotsOfEvents.java:127) at LotsOfEvents.testOverflowEvent(LotsOfEvents.java:84) at LotsOfEvents.main(LotsOfEvents.java:46)
22-02-2017