ENTRY_CREATE event not always emitted after renaming subfolder - WatchService

[pziobron]

What are you trying to do? The ENTRY_CREATE event (java.nio.file.WatchService) is not always emitted when creating subfolder in the watched directory, renaming it and copying file there. This weird behaviour was observed in the project which is using Sprint Integration library: https://github.com/pziobron/spring-integration-create-notification-bug

and initially the bug has been reported for that Spring library here: https://github.com/spring-projects/spring-integration/issues/9146

However, it turned out this is related to the JDK, not to that library...

This is only reproducible on Mac (reproduced for Temurin-17.0.9+9 and Temurin-17.0.11+9). I've tried to reproduce it also on MAC using the different version of JDK: IMPLEMENTOR="Oracle Corporation" JAVA_VERSION="17.0.4.1" JAVA_VERSION_DATE="2022-08-18" but it is working fine....

Expected behaviour: The ENTRY_CREATE should be always emitted when renaming the subfolder of the watched directory and copying file there. I haven't managed to reproduce it on Windows.

Observed behaviour:

To Reproduce

1. Configure FileReadingMessageSource in the following way: FileReadingMessageSource messageSource = new FileReadingMessageSource(); messageSource.setDirectory(new File(inputDirectory)); messageSource.setUseWatchService(true); messageSource.setWatchEvents(CREATE, MODIFY, DELETE);

2. Configure a simple flow that simply deletes the file

3. Prepare a file with minimum size of 17 KB (test.zip)

4. Configure logger for org.srpingframework.integration.file package (DEBUG level)

5. Execute the following command in the shell inside the watched directory: mkdir b1; sleep 2; mv b1 b2; sleep 3; cp /Users/patryk.ziobron/sandbox/test/test.zip b2/; sleep 2; mkdir b3; sleep 2; mv b3 b4; sleep 3; cp /Users/patryk.ziobron/sandbox/test/test.zip b4/; sleep 2; mkdir b5; sleep 2; mv b5 b6; sleep 3; cp /Users/patryk.ziobron/sandbox/test/test.zip b6/; sleep 2; mkdir b7; sleep 2; mv b7 b8; sleep 3; cp /Users/patryk.ziobron/sandbox/test/test.zip b8/; sleep 2;

6. The ENTRY_CREATE is not emitted for all files (in the example below, it is only emitted for b4 folder and missing for b2, b6 and b8): 2024-05-17 10:44:08.150 [main] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input for file events 2024-05-17 10:44:11.178 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b1] 2024-05-17 10:44:11.179 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b1 for file events 2024-05-17 10:44:13.167 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b2] 2024-05-17 10:44:13.168 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b2 for file events 2024-05-17 10:44:13.169 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_DELETE] for file [/Users/patryk.ziobron/sandbox/input/b1] 2024-05-17 10:44:17.171 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b2] 2024-05-17 10:44:19.167 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b3] 2024-05-17 10:44:19.167 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b3 for file events 2024-05-17 10:44:21.164 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b4] 2024-05-17 10:44:21.164 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b4 for file events 2024-05-17 10:44:21.165 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_DELETE] for file [/Users/patryk.ziobron/sandbox/input/b3] 2024-05-17 10:44:23.170 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b4] 2024-05-17 10:44:24.170 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b4/test.zip] 2024-05-17 10:44:24.171 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Added to queue: [/Users/patryk.ziobron/sandbox/input/b4/test.zip] 2024-05-17 10:44:24.177 [Thread_5] INFO o.s.i.handler.LoggingHandler - GenericMessage [payload=/Users/patryk.ziobron/sandbox/input/b4/test.zip, headers={sourceCountry=global, feedName=reuters, file_name=test.zip, targetPath=data, file_originalFile=/Users/patryk.ziobron/sandbox/input/b4/test.zip, source=Global_Relay, priority=5, file_relativePath=b4/test.zip, uncompress=true, sieve=true, id=ed14f9ab-335f-b547-58db-0aa4b735dac5, decrypt=false, sourcePath=/Users/patryk.ziobron/sandbox/input, remoteFeedName=reuters, timestamp=1715935464177}] 2024-05-17 10:44:25.172 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b5] 2024-05-17 10:44:25.172 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b5 for file events 2024-05-17 10:44:25.172 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b4] 2024-05-17 10:44:26.172 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_DELETE] for file [/Users/patryk.ziobron/sandbox/input/b4/test.zip] 2024-05-17 10:44:27.168 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b6] 2024-05-17 10:44:27.168 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b6 for file events 2024-05-17 10:44:27.169 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_DELETE] for file [/Users/patryk.ziobron/sandbox/input/b5] 2024-05-17 10:44:31.166 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b6] 2024-05-17 10:44:33.166 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b7] 2024-05-17 10:44:33.166 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b7 for file events 2024-05-17 10:44:35.169 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b8] 2024-05-17 10:44:35.169 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - registering: /Users/patryk.ziobron/sandbox/input/b8 for file events 2024-05-17 10:44:35.169 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_DELETE] for file [/Users/patryk.ziobron/sandbox/input/b7] 2024-05-17 10:44:39.168 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b8]

7. It seems the subfolders b2, b6 and b8 are not registered properly as when executing the following command (copying different file to these subfolders): cp /Users/patryk.ziobron/sandbox/test/test2.zip b2/ cp /Users/patryk.ziobron/sandbox/test/test2.zip b4/ cp /Users/patryk.ziobron/sandbox/test/test2.zip b6/ cp /Users/patryk.ziobron/sandbox/test/test2.zip b8/

8. The ENTRY_CREATE and ENTRY_DELETE are only emitted for the b4 subfolder: 2024-05-17 11:22:51.107 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b2] 2024-05-17 11:23:06.107 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_CREATE] for file [/Users/patryk.ziobron/sandbox/input/b4/test2.zip] 2024-05-17 11:23:06.108 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Added to queue: [/Users/patryk.ziobron/sandbox/input/b4/test2.zip] 2024-05-17 11:23:06.111 [Thread_25] INFO o.s.i.handler.LoggingHandler - GenericMessage [payload=/Users/patryk.ziobron/sandbox/input/b4/test2.zip, headers={sourceCountry=global, feedName=reuters, file_name=test2.zip, targetPath=data, file_originalFile=/Users/patryk.ziobron/sandbox/input/b4/test2.zip, source=Global_Relay, priority=5, file_relativePath=b4/test2.zip, uncompress=true, sieve=true, id=5ecc527e-1188-a57e-6afd-571d2ba75431, decrypt=false, sourcePath=/Users/patryk.ziobron/sandbox/input, remoteFeedName=reuters, timestamp=1715937786111}] 2024-05-17 11:23:07.108 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b4] 2024-05-17 11:23:08.104 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_DELETE] for file [/Users/patryk.ziobron/sandbox/input/b4/test2.zip] 2024-05-17 11:23:13.106 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b6] 2024-05-17 11:23:21.109 [scheduling-1] DEBUG o.s.i.file.FileReadingMessageSource - Watch event [ENTRY_MODIFY] for file [/Users/patryk.ziobron/sandbox/input/b8]

9. Everything works fine if the sleep is removed from command above (point 5)

Any other comments:

Sample project

https://github.com/pziobron/spring-integration-create-notification-bug

[judovana]

This is run against Oracle jdk? Even if not, osunds more like an issue for OpenJDK itself, not temurin build script: https://bugs.openjdk.org/

[pziobron]

This is run against Oracle jdk? Even if not, osunds more like an issue for OpenJDK itself, not temurin build script: https://bugs.openjdk.org/

This issue doesn't occur when running against Oracle JDK. I am going to test it against clean OpenJDK and report a bug there.

[pziobron]

FYI: I've managed to reproduce this issue for the latest Oracle JDK 17 on Mac (17.0.11+7-LTS-207). I've reported a bug for Oracle. The issue is not reproducible on Windows and Linux Red Hat Enterprise. Thus, it seems that the issue is related to the Mac-OS only...

I’ve also found this issue in the Java tracking system: https://bugs.openjdk.org/browse/JDK-8293067

"WatchService on MacOS is still implemented by the generic PollingWatchService, which continuously re-scans the directory consuming CPU, introduces large latencies to the generated WatchEvent's, and misses changes that occur faster than the re-scan interval"

It seems that explains everything now.

To sum up, the WatchService is not reliable on Mac at the moment !

[pziobron]

FYI: Oracle has officially confirmed the bug I've reported is valid, link: http://bugs.java.com/bugdatabase/view_bug?bug_id=JDK-8332530

[pziobron]

It seems the link above doesn't work properly for others, here is the direct JIRA link: https://bugs.openjdk.org/browse/JDK-8332530