Bug 406170 - added some more logging and tracing for zip access

No functional code changes except some more error logs on not closed zip
files and some more tracing for zip file handling.

Change-Id: I2c1ade45b8ca9af514aba8c60c3ef0693d172fde
Signed-off-by: Andrey Loskutov <loskutov@gmx.de>

4 files changed, 56 insertions, 18 deletions

diff --git a/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/JavaModelManager.java b/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/JavaModelManager.java
index 5aaa78f6d1..bf870ff1cc 100644
--- a/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/JavaModelManager.java
+++ b/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/JavaModelManager.java
@@ -189,36 +189,45 @@ public class JavaModelManager implements ISaveParticipant, IContentTypeChangeLis
 	 * Define a zip cache object.
 	 */
 	static class ZipCache {
-		private Map map;
+		private Map<Object, ZipFile> map;
 		Object owner;
 
 		ZipCache(Object owner) {
-			this.map = new HashMap();
+			this.map = new HashMap<>();
 			this.owner = owner;
 		}
 
 		public void flush() {
 			Thread currentThread = Thread.currentThread();
-			Iterator iterator = this.map.values().iterator();
+			Iterator<ZipFile> iterator = this.map.values().iterator();
 			while (iterator.hasNext()) {
+				ZipFile zipFile = iterator.next();
 				try {
-					ZipFile zipFile = (ZipFile)iterator.next();
 					if (JavaModelManager.ZIP_ACCESS_VERBOSE) {
-						System.out.println("(" + currentThread + ") [JavaModelManager.flushZipFiles()] Closing ZipFile on " +zipFile.getName()); //$NON-NLS-1$//$NON-NLS-2$
+						System.out.println("(" + currentThread + ") [ZipCache[" + this.owner //$NON-NLS-1$//$NON-NLS-2$
+								+ "].flush()] Closing ZipFile on " + zipFile.getName()); //$NON-NLS-1$
 					}
 					zipFile.close();
 				} catch (IOException e) {
 					// problem occured closing zip file: cannot do much more
+					JavaCore.getPlugin().getLog().log(new Status(IStatus.ERROR, JavaCore.PLUGIN_ID, "Error closing " + zipFile.getName(), e)); //$NON-NLS-1$
 				}
 			}
 		}
 
 		public ZipFile getCache(IPath path) {
-			return (ZipFile) this.map.get(path);
+			return this.map.get(path);
 		}
 
 		public void setCache(IPath path, ZipFile zipFile) {
-			this.map.put(path, zipFile);
+			ZipFile old = this.map.put(path, zipFile);
+			if(old != null) {
+				if (JavaModelManager.ZIP_ACCESS_VERBOSE) {
+					Thread currentThread = Thread.currentThread();
+					System.out.println("(" + currentThread + ") [ZipCache[" + this.owner //$NON-NLS-1$//$NON-NLS-2$
+							+ "].setCache()] leaked ZipFile on " + old.getName() + " for path: " + path); //$NON-NLS-1$ //$NON-NLS-2$
+				}
+			}
 		}
 	}
 	/**
@@ -1790,6 +1799,9 @@ public class JavaModelManager implements ISaveParticipant, IContentTypeChangeLis
 	public void closeZipFile(ZipFile zipFile) {
 		if (zipFile == null) return;
 		if (this.zipFiles.get() != null) {
+			if (JavaModelManager.ZIP_ACCESS_VERBOSE) {
+				System.out.println("(" + Thread.currentThread() + ") [JavaModelManager.closeZipFile(ZipFile)] NOT closed ZipFile (cache exist!) on " +zipFile.getName()); //$NON-NLS-1$	//$NON-NLS-2$
+			}
 			return; // zip file will be closed by call to flushZipFiles
 		}
 		try {
@@ -1799,6 +1811,7 @@ public class JavaModelManager implements ISaveParticipant, IContentTypeChangeLis
 			zipFile.close();
 		} catch (IOException e) {
 			// problem occured closing zip file: cannot do much more
+			JavaCore.getPlugin().getLog().log(new Status(IStatus.ERROR, JavaCore.PLUGIN_ID, "Error closing " + zipFile.getName(), e)); //$NON-NLS-1$
 		}
 	}
 
@@ -1983,6 +1996,9 @@ public class JavaModelManager implements ISaveParticipant, IContentTypeChangeLis
 	public void flushZipFiles(Object owner) {
 		ZipCache zipCache = (ZipCache)this.zipFiles.get();
 		if (zipCache == null) {
+			if (JavaModelManager.ZIP_ACCESS_VERBOSE) {
+				System.out.println("(" + Thread.currentThread() + ") [JavaModelManager.flushZipFiles(String)] NOT found cache for " + owner); //$NON-NLS-1$	//$NON-NLS-2$
+			}
 			return;
 		}
 		// the owner will be responsible for flushing the cache
@@ -1990,6 +2006,12 @@ public class JavaModelManager implements ISaveParticipant, IContentTypeChangeLis
 		if (zipCache.owner == owner) {
 			this.zipFiles.set(null);
 			zipCache.flush();
+		} else {
+			if (JavaModelManager.ZIP_ACCESS_VERBOSE) {
+				System.out.println("(" + Thread.currentThread() //$NON-NLS-1$
+						+ ") [JavaModelManager.flushZipFiles(String)] NOT closed cache, wrong owner, expected: " //$NON-NLS-1$
+						+ zipCache.owner + ", got: " + owner); //$NON-NLS-1$
+			}
 		}
 	}
 
diff --git a/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/builder/ClasspathJar.java b/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/builder/ClasspathJar.java
index 20fe32ff3b..54fd4c1801 100644
--- a/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/builder/ClasspathJar.java
+++ b/org.eclipse.jdt.core/model/org/eclipse/jdt/internal/core/builder/ClasspathJar.java
@@ -23,6 +23,9 @@ import java.util.zip.ZipFile;
 import org.eclipse.core.resources.IFile;
 import org.eclipse.core.runtime.CoreException;
 import org.eclipse.core.runtime.IPath;
+import org.eclipse.core.runtime.IStatus;
+import org.eclipse.core.runtime.Status;
+import org.eclipse.jdt.core.JavaCore;
 import org.eclipse.jdt.internal.compiler.classfmt.ClassFileReader;
 import org.eclipse.jdt.internal.compiler.classfmt.ClassFormatException;
 import org.eclipse.jdt.internal.compiler.classfmt.ExternalAnnotationDecorator;
@@ -141,17 +144,34 @@ public void cleanup() {
 		if (this.zipFile != null) {
 			try {
 				this.zipFile.close();
+				if (org.eclipse.jdt.internal.core.JavaModelManager.ZIP_ACCESS_VERBOSE) {
+					System.out.println("(" + Thread.currentThread() + ") [ClasspathJar.cleanup()] Closed ZipFile on " + this.zipFilename); //$NON-NLS-1$	//$NON-NLS-2$
+				}
 			} catch(IOException e) { // ignore it
+				JavaCore.getPlugin().getLog().log(new Status(IStatus.ERROR, JavaCore.PLUGIN_ID, "Error closing " + this.zipFile.getName(), e)); //$NON-NLS-1$
 			}
 			this.zipFile = null;
 		}
 		if (this.annotationZipFile != null) {
 			try {
 				this.annotationZipFile.close();
+				if (org.eclipse.jdt.internal.core.JavaModelManager.ZIP_ACCESS_VERBOSE) {
+					System.out.println("(" + Thread.currentThread() + ") [ClasspathJar.cleanup()] Closed Annotation ZipFile on " + this.zipFilename); //$NON-NLS-1$	//$NON-NLS-2$
+				}
 			} catch(IOException e) { // ignore it
+				JavaCore.getPlugin().getLog().log(new Status(IStatus.ERROR, JavaCore.PLUGIN_ID, "Error closing " + this.annotationZipFile.getName(), e)); //$NON-NLS-1$
 			}
 			this.annotationZipFile = null;
 		}
+	} else {
+		if (this.zipFile != null && org.eclipse.jdt.internal.core.JavaModelManager.ZIP_ACCESS_VERBOSE) {
+			try {
+				this.zipFile.size();
+				System.out.println("(" + Thread.currentThread() + ") [ClasspathJar.cleanup()] ZipFile NOT closed on " + this.zipFilename); //$NON-NLS-1$	//$NON-NLS-2$
+			} catch (IllegalStateException e) {
+				// OK: the file was already closed
+			}
+		}
 	}
 	this.knownPackageNames = null;
 }
diff --git a/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java b/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java
index 7dc6347a24..028c4284ed 100644
--- a/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java
+++ b/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/indexing/AddJarFileToIndex.java
@@ -141,6 +141,8 @@ class AddJarFileToIndex extends IndexRequest {
 							org.eclipse.jdt.internal.core.util.Util.verbose("-> failed to index " + location.getPath() + " because the file could not be fetched"); //$NON-NLS-1$ //$NON-NLS-2$
 						return false;
 					}
+					if (JavaModelManager.ZIP_ACCESS_VERBOSE)
+						System.out.println("(" + Thread.currentThread() + ") [AddJarFileToIndex.execute()] Creating ZipFile on " + this.containerPath); //$NON-NLS-1$	//$NON-NLS-2$
 					zip = new ZipFile(file);
 					zipFilePath = (Path) this.resource.getFullPath().makeRelative();
 					// absolute path relative to the workspace
@@ -249,19 +251,12 @@ class AddJarFileToIndex extends IndexRequest {
 			} finally {
 				if (zip != null) {
 					if (JavaModelManager.ZIP_ACCESS_VERBOSE)
-						System.out.println("(" + Thread.currentThread() + ") [AddJarFileToIndex.execute()] Closing ZipFile " + zip); //$NON-NLS-1$	//$NON-NLS-2$
+						System.out.println("(" + Thread.currentThread() + ") [AddJarFileToIndex.execute()] Closing ZipFile " + this.containerPath); //$NON-NLS-1$	//$NON-NLS-2$
 					zip.close();
 				}
 				monitor.exitWrite(); // free write lock
 			}
-		} catch (IOException e) {
-			if (JobManager.VERBOSE) {
-				org.eclipse.jdt.internal.core.util.Util.verbose("-> failed to index " + this.containerPath + " because of the following exception:"); //$NON-NLS-1$ //$NON-NLS-2$
-				e.printStackTrace();
-			}
-			this.manager.removeIndex(this.containerPath);
-			return false;
-		} catch (ZipError e) { // merge with the code above using '|' when we move to 1.7
+		} catch (IOException | ZipError e) {
 			if (JobManager.VERBOSE) {
 				org.eclipse.jdt.internal.core.util.Util.verbose("-> failed to index " + this.containerPath + " because of the following exception:"); //$NON-NLS-1$ //$NON-NLS-2$
 				e.printStackTrace();
diff --git a/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/matching/MatchLocator.java b/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/matching/MatchLocator.java
index 95ce916b27..99e193f568 100644
--- a/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/matching/MatchLocator.java
+++ b/org.eclipse.jdt.core/search/org/eclipse/jdt/internal/core/search/matching/MatchLocator.java
@@ -254,8 +254,9 @@ public static IBinaryType classFileReader(IType type) {
 		ZipFile zipFile = null;
 		try {
 			IPath zipPath = root.getPath();
-			if (JavaModelManager.ZIP_ACCESS_VERBOSE)
-				System.out.println("(" + Thread.currentThread() + ") [MatchLocator.classFileReader()] Creating ZipFile on " + zipPath); //$NON-NLS-1$	//$NON-NLS-2$
+			if (JavaModelManager.ZIP_ACCESS_VERBOSE) {
+				System.out.println("(" + Thread.currentThread() + ") [MatchLocator.classFileReader()] Requesting ZipFile on " + zipPath); //$NON-NLS-1$	//$NON-NLS-2$
+			}
 			zipFile = manager.getZipFile(zipPath);
 			String classFileName = classFile.getElementName();
 			String path = Util.concatWith(pkg.names, classFileName, '/');