This is an automated email from the ASF dual-hosted git repository.
jsedding pushed a commit to branch jsedding/additional-logging-for-race-analysis
in repository
https://gitbox.apache.org/repos/asf/sling-org-apache-sling-scripting-jsp.git
commit bd4091925f8f8e170e21a2ce17832c655951f039
Author: Julian Sedding <(none)>
AuthorDate: Thu Jul 25 18:04:29 2024 +0200
additional logging to analyze possible race-condition
---
.../scripting/jsp/JspScriptEngineFactory.java | 2 ++
.../sling/scripting/jsp/SlingIOProvider.java | 2 ++
.../jsp/jasper/JspCompilationContext.java | 14 ++++++------
.../scripting/jsp/jasper/compiler/Compiler.java | 25 ++++++----------------
.../scripting/jsp/jasper/compiler/SmapUtil.java | 24 ++++++++++++++++++++-
.../jsp/jasper/servlet/JspServletWrapper.java | 9 +++++++-
6 files changed, 49 insertions(+), 27 deletions(-)
diff --git
a/src/main/java/org/apache/sling/scripting/jsp/JspScriptEngineFactory.java
b/src/main/java/org/apache/sling/scripting/jsp/JspScriptEngineFactory.java
index 2b3fc8c..e3a98d6 100644
--- a/src/main/java/org/apache/sling/scripting/jsp/JspScriptEngineFactory.java
+++ b/src/main/java/org/apache/sling/scripting/jsp/JspScriptEngineFactory.java
@@ -479,6 +479,7 @@ public class JspScriptEngineFactory
}
ResourceResolver resolver =
scriptingResourceResolverProvider.getRequestScopedResourceResolver();
if ( resolver == null ) {
+ logger.info("No request-scoped ResourceResolver found, falling
back to the script-resource ResourceResolver");
resolver =
scriptHelper.getScript().getScriptResource().getResourceResolver();
}
final SlingIOProvider io = ioProvider;
@@ -489,6 +490,7 @@ public class JspScriptEngineFactory
scriptHelper.getScript().getScriptResource().getPath());
}
+ logger.info("Setting IOProvider ResourceResolver with user {}",
resolver.getUserID());
final ResourceResolver oldResolver =
io.setRequestResourceResolver(resolver);
jspfh.incUsage();
try {
diff --git a/src/main/java/org/apache/sling/scripting/jsp/SlingIOProvider.java
b/src/main/java/org/apache/sling/scripting/jsp/SlingIOProvider.java
index 49deeee..8e2d66b 100644
--- a/src/main/java/org/apache/sling/scripting/jsp/SlingIOProvider.java
+++ b/src/main/java/org/apache/sling/scripting/jsp/SlingIOProvider.java
@@ -22,6 +22,7 @@ import java.io.InputStream;
import java.io.OutputStream;
import java.net.MalformedURLException;
import java.net.URL;
+import java.time.Instant;
import java.util.HashSet;
import java.util.Iterator;
import java.util.Set;
@@ -121,6 +122,7 @@ class SlingIOProvider implements IOProvider {
if (resource != null) {
ResourceMetadata meta = resource.getResourceMetadata();
long modTime = meta.getModificationTime();
+ log.info("Raw last modified date for resource " +
resource.getPath() + " is " + Instant.ofEpochMilli(modTime));
return (modTime > 0) ? modTime : 0;
}
} catch (final SlingException se) {
diff --git
a/src/main/java/org/apache/sling/scripting/jsp/jasper/JspCompilationContext.java
b/src/main/java/org/apache/sling/scripting/jsp/jasper/JspCompilationContext.java
index d414312..90f55ea 100644
---
a/src/main/java/org/apache/sling/scripting/jsp/jasper/JspCompilationContext.java
+++
b/src/main/java/org/apache/sling/scripting/jsp/jasper/JspCompilationContext.java
@@ -53,6 +53,9 @@ import
org.apache.sling.scripting.jsp.jasper.compiler.ServletWriter;
*/
public class JspCompilationContext {
+ private final org.apache.juli.logging.Log LOG =
+ org.apache.juli.logging.LogFactory.getLog(Compiler.class);
+
private final Map<String, URL> tagFileJarUrls;
private volatile String className;
@@ -511,20 +514,17 @@ public class JspCompilationContext {
public JasperException compile() {
final Compiler c = createCompiler();
try {
+ if (LOG.isInfoEnabled()) {
+ LOG.info("Removing generated files before compiling " +
this.jspUri);
+ }
c.removeGeneratedFiles();
c.compile(true, false);
} catch (final JasperException ex) {
return ex;
- } catch (final IOException ioe) {
- final JasperException je = new JasperException(
- Localizer.getMessage("jsp.error.unable.compile"),
- ioe);
- return je;
} catch (final Exception ex) {
- JasperException je = new JasperException(
+ return new JasperException(
Localizer.getMessage("jsp.error.unable.compile"),
ex);
- return je;
} finally {
c.clean();
}
diff --git
a/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/Compiler.java
b/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/Compiler.java
index ce23b30..6dcdaf1 100644
--- a/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/Compiler.java
+++ b/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/Compiler.java
@@ -344,28 +344,17 @@ public abstract class Compiler {
* Remove generated files
*/
public void removeGeneratedFiles() {
- this.removeGeneratedClassFiles();
- try {
- String javaFileName = ctxt.getServletJavaFileName();
- if (javaFileName != null) {
- if (log.isDebugEnabled()) {
- log.debug("Deleting " + javaFileName);
- }
- ctxt.delete(javaFileName);
- }
- } catch (Exception e) {
- // Remove as much as possible, ignore possible exceptions
- }
+ removeFile(ctxt.getClassFileName());
+ removeFile(ctxt.getServletJavaFileName());
}
- public void removeGeneratedClassFiles() {
+ private void removeFile(String filePath) {
try {
- String classFileName = ctxt.getClassFileName();
- if (classFileName != null) {
- if (log.isDebugEnabled()) {
- log.debug("Deleting " + classFileName);
+ if (filePath != null) {
+ if (log.isInfoEnabled()) {
+ log.info("Deleting " + filePath);
}
- ctxt.delete(classFileName);
+ ctxt.delete(filePath);
}
} catch (Exception e) {
// Remove as much as possible, ignore possible exceptions
diff --git
a/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/SmapUtil.java
b/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/SmapUtil.java
index b0c3dd2..2ea6da3 100644
--- a/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/SmapUtil.java
+++ b/src/main/java/org/apache/sling/scripting/jsp/jasper/compiler/SmapUtil.java
@@ -18,12 +18,14 @@
package org.apache.sling.scripting.jsp.jasper.compiler;
import java.io.ByteArrayOutputStream;
+import java.io.FileNotFoundException;
import java.io.IOException;
import java.io.InputStream;
import java.io.OutputStream;
import java.io.OutputStreamWriter;
import java.io.PrintWriter;
import java.io.UnsupportedEncodingException;
+import java.nio.file.NoSuchFileException;
import java.util.HashMap;
import java.util.Iterator;
import java.util.Map;
@@ -191,7 +193,7 @@ public class SmapUtil {
// Installation logic (from Robert Field, JSR-045 spec lead)
private static class SDEInstaller {
- private org.apache.juli.logging.Log log=
+ private static final org.apache.juli.logging.Log log =
org.apache.juli.logging.LogFactory.getLog( SDEInstaller.class
);
static final String nameSDE = "SourceDebugExtension";
@@ -241,14 +243,34 @@ public class SmapUtil {
static void install(JspCompilationContext ctxt, String classFile,
byte[] smap) throws IOException {
String tmpFile = classFile + "tmp";
new SDEInstaller(ctxt, classFile, smap, tmpFile);
+ if (log.isInfoEnabled()) {
+ String existence = existence(ctxt, classFile);
+ log.info("Trying to delete previous class file, which " +
existence + " before smap installation" + classFile);
+ }
if (!ctxt.delete(classFile)) {
throw new IOException("classFile.delete() failed");
}
if (!ctxt.rename(tmpFile, classFile)) {
+ if (log.isInfoEnabled()) {
+ log.info("Failed to rename tmp class file "
+ + tmpFile + " (which " + existence(ctxt, tmpFile)
+ ") to "
+ + classFile+ " (which " + existence(ctxt,
classFile) + ")");
+ }
throw new IOException("tmpFile.renameTo(classFile) failed (" +
tmpFile + " -> " + classFile + ")");
}
}
+ private static String existence(JspCompilationContext ctxt, String
classFile) throws IOException {
+ boolean exists;
+ try {
+ ctxt.getInputStream(classFile); // should throw FNFE if the
file does not exist
+ exists = true;
+ } catch (FileNotFoundException | NoSuchFileException e) {
+ exists = false;
+ }
+ return exists ? "exists" : "does not exist";
+ }
+
SDEInstaller(JspCompilationContext ctxt, String inClassFile, byte[]
sdeAttr, String outClassFile)
throws IOException {
// if (!inClassFile.exists()) {
diff --git
a/src/main/java/org/apache/sling/scripting/jsp/jasper/servlet/JspServletWrapper.java
b/src/main/java/org/apache/sling/scripting/jsp/jasper/servlet/JspServletWrapper.java
index 49640f0..24db180 100644
---
a/src/main/java/org/apache/sling/scripting/jsp/jasper/servlet/JspServletWrapper.java
+++
b/src/main/java/org/apache/sling/scripting/jsp/jasper/servlet/JspServletWrapper.java
@@ -23,8 +23,8 @@ import java.io.LineNumberReader;
import java.io.OutputStream;
import java.io.OutputStreamWriter;
import java.net.URL;
+import java.time.Instant;
import java.util.ArrayList;
-import java.util.Arrays;
import java.util.Collections;
import java.util.Iterator;
import java.util.List;
@@ -386,6 +386,9 @@ public class JspServletWrapper {
// check if class file exists
final String targetFile = ctxt.getClassFileName();
final long targetLastModified =
ctxt.getRuntimeContext().getIOProvider().lastModified(targetFile);
+ if (log.isInfoEnabled()) {
+ log.info("Last modified date for " + targetFile + " is " +
Instant.ofEpochMilli(targetLastModified));
+ }
if (targetLastModified < 0) {
return true;
}
@@ -393,6 +396,9 @@ public class JspServletWrapper {
// compare jsp time stamp with class file time stamp
final String jsp = ctxt.getJspFile();
final long jspRealLastModified =
ctxt.getRuntimeContext().getIOProvider().lastModified(jsp);
+ if (log.isInfoEnabled()) {
+ log.info("Last modified date for JSP " + jsp + " is " +
Instant.ofEpochMilli(jspRealLastModified));
+ }
if (targetLastModified < jspRealLastModified) {
if (log.isDebugEnabled()) {
log.debug("Compiler: outdated: " + targetFile + " "
@@ -412,6 +418,7 @@ public class JspServletWrapper {
continue;
}
final long includeLastModified =
ctxt.getRuntimeContext().getIOProvider().lastModified(include);
+ log.info("Last modified date for include " + include + " is "
+ Instant.ofEpochMilli(includeLastModified));
if (includeLastModified > targetLastModified) {
if (log.isDebugEnabled()) {
