Deadlock in ZipFileArtifactNotifierImpl

[tbitonti]

Problem of dead lock handling file updates:

Thread 69:

at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.notifyAllListeners(ZipFileArtifactNotifier.java:791)
at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.notifyEntryChange(ZipFileArtifactNotifier.java:719)
at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.notifyAllListeners(ZipFileArtifactNotifier.java:807)
(entered lock: com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier$ListenersLock@0x00000000E0C2DBB0, entry count: 1)
at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.onChange(ZipFileArtifactNotifier.java:664)
at com/ibm/ws/kernel/filemonitor/internal/MonitorHolder.scheduledScan(MonitorHolder.java:705(Compiled Code))

private void notifyAllListeners(boolean isUpdate) { ..
synchronized( listenersLock ) { ..
for ( ArtifactListener listener : listenersEntry.getValue() ) { ..
listener.notifyEntryChange(emptyNotification, emptyNotification, registeredPaths);

'notifyAllListeners' walks downwards to forward change notification to nested entries

Thread 70:

at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.removeListener(ZipFileArtifactNotifier.java:561)
at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.updateEnclosingMonitor(ZipFileArtifactNotifier.java:355)
at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.updateMonitor(ZipFileArtifactNotifier.java:248)
at com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier.removeListener(ZipFileArtifactNotifier.java:610)
(entered lock: com/ibm/ws/artifact/zip/internal/ZipFileArtifactNotifier$ListenersLock@0x00000000E0C2DBA0, entry count: 1)
at com/ibm/ws/artifact/overlay/internal/DirectoryBasedOverlayNotifier.removeListener(DirectoryBasedOverlayNotifier.java:176)
(entered lock: com/ibm/ws/artifact/overlay/internal/DirectoryBasedOverlayNotifier@0x00000000E0C478C8, entry count: 1)
at com/ibm/ws/adaptable/module/internal/NotifierImpl.removeListener(NotifierImpl.java:87)
at com/ibm/ws/adaptable/module/internal/InterpretedNotifier.removeListener(InterpretedNotifier.java:150)
at com/ibm/ws/app/manager/internal/monitor/ApplicationMonitor$BaseApplicationListener.stop(ApplicationMonitor.java:364)

'removeListener' walks upwards to remove listeners from enclosing notifiers.

public boolean removeListener(ArtifactListener listenerToRemove) { ..
synchronized(listenersLock) { ..
updateMonitor(); ..
private void updateMonitor() { ..
updateEnclosingMonitor(); ..
private void updateEnclosingMonitor() { ..
ArtifactContainer enclosingRootContainer = entryInEnclosingContainer.getRoot();
ArtifactNotifier enclosingNotifier = enclosingRootContainer.getArtifactNotifier();
enclosingNotifier.removeListener(this);

Problem was noted when running FAT tests, with this summary:

Test claims it successfully moved app out of dropins, but in the server log the app is never stopped. Some kind of app management problem.

[07/04/2018 13:42:56:042 UTC] 001 LibertyServer restartDropinsApplication I SingletonXmlStartupApp.ear successfully moved out of dropins, waiting for message...
[07/04/2018 13:42:56:042 UTC] 001 LogMonitor getMarkOffset I mark offset=1367039
[07/04/2018 13:46:56:597 UTC] 001 Log warning W Timed out searching for CWWKZ0009I:.*SingletonXmlStartupApp in log file: /home/jazz_build/_WaEQAH98EeiACNpEFzHAag-EBC.PROD.WASRTC-74P-000-00-00/jbe/build/dev/image/output/wlp/usr/servers/com.ibm.ws.ejbcontainer.fat.BasicSessionBeanServer/logs/messages.log
[07/04/2018 13:46:56:598 UTC] 001 LogMonitor waitForStringInLogUsingMark I Started waiting for message matching regexp [ CWWKZ0009I:.*SingletonXmlStartupApp] at 1:42:56 PM UTC and finished at 1:46:56 PM UTC
[07/04/2018 13:46:56:598 UTC] 001 LogMonitor waitForStringInLogUsingMark I First line searched: [ null ]
[07/04/2018 13:46:56:598 UTC] 001 LogMonitor waitForStringInLogUsingMark I Last line searched: [ null ]
[07/04/2018 13:46:56:598 UTC] 001 LogMonitor waitForStringInLogUsingMark I Last line searching reached end of file, preceding last line was the last line of text seen.
[07/04/2018 13:47:00:598 UTC] 001 LibertyServer restartDropinsApplication I SingletonXmlStartupApp.ear successfully moved back into dropins, waiting for message...
[07/04/2018 13:47:00:598 UTC] 001 LogMonitor getMarkOffset I mark offset=1367039
[07/04/2018 13:51:01:150 UTC] 001 Log warning W Timed out searching for CWWKZ0001I:.*SingletonXmlStartupApp in log file: /home/jazz_build/_WaEQAH98EeiACNpEFzHAag-EBC.PROD.WASRTC-74P-000-00-00/jbe/build/dev/image/output/wlp/usr/servers/com.ibm.ws.ejbcontainer.fat.BasicSessionBeanServer/logs/messages.log