From 2cb0054b5be0bd63ddbb7859f0d6cfe6916a9c11 Mon Sep 17 00:00:00 2001 From: gmantele <gmantele@ari.uni-heidelberg.de> Date: Fri, 12 Dec 2014 20:15:10 +0100 Subject: [PATCH] [UWS,TAP] Review some log messages (in the log file but also in the error summary of a job) ; particularly stack traces are added into the error summary, but are displayed just once in the logs. --- src/tap/TAPSyncJob.java | 16 ++---- src/tap/error/DefaultTAPErrorWriter.java | 66 ++++++++++++++++++++++-- src/tap/formatter/VOTableFormat.java | 16 ++++-- src/tap/log/DefaultTAPLog.java | 31 ++++++++++- src/tap/resource/TAP.java | 13 +++-- src/uws/job/UWSJob.java | 7 ++- src/uws/service/UWSService.java | 18 +++++-- src/uws/service/UWSServlet.java | 10 ++-- src/uws/service/log/DefaultUWSLog.java | 64 +++++++++++++++++------ 9 files changed, 188 insertions(+), 53 deletions(-) diff --git a/src/tap/TAPSyncJob.java b/src/tap/TAPSyncJob.java index 81709c1..7ea795e 100644 --- a/src/tap/TAPSyncJob.java +++ b/src/tap/TAPSyncJob.java @@ -47,7 +47,7 @@ import uws.service.log.UWSLog.LogLevel; * </p> * * @author Grégory Mantelet (CDS;ARI) - * @version 2.0 (11/2014) + * @version 2.0 (12/2014) */ public class TAPSyncJob { @@ -174,13 +174,7 @@ public class TAPSyncJob { service.getLogger().logTAP(LogLevel.INFO, this, "SYNC_START", "Synchronous job " + ID + " is starting!", null); // Create the object having the knowledge about how to execute an ADQL query: - ADQLExecutor executor; - try{ - executor = service.getFactory().createADQLExecutor(); - }catch(TAPException e){ - service.getLogger().logTAP(LogLevel.ERROR, this, "SYNC_START", "An error has prevented the synchronous thread " + getID() + " to start!", e); - return false; - } + ADQLExecutor executor = service.getFactory().createADQLExecutor(); // Give to a thread which will execute the query: thread = new SyncThread(executor, ID, tapParams, response); @@ -222,14 +216,14 @@ public class TAPSyncJob { // INTERRUPTION: if (error instanceof InterruptedException){ // log the unexpected interruption (unexpected because not caused by a timeout): - service.getLogger().logTAP(LogLevel.WARNING, this, "SYNC_END", "The execution of the synchronous job " + ID + " has been unexpectedly interrupted!", error); + service.getLogger().logTAP(LogLevel.WARNING, this, "SYNC_END", "The execution of the synchronous job " + ID + " has been unexpectedly interrupted!", null); // report the unexpected interruption to the user: throw new TAPException("The execution of this synchronous job " + ID + " has been unexpectedly aborted!", UWSException.ACCEPTED_BUT_NOT_COMPLETE); } // TAP EXCEPTION: else if (error instanceof TAPException){ // log the error: - service.getLogger().logTAP(LogLevel.ERROR, this, "SYNC_END", "An error occured while executing the query of the synchronous job " + ID + ".", error); + service.getLogger().logTAP(LogLevel.ERROR, this, "SYNC_END", "An error occured while executing the query of the synchronous job " + ID + ".", null); // report the error to the user: throw (TAPException)error; } @@ -349,7 +343,7 @@ public class TAPSyncJob { executor.getLogger().logThread(LogLevel.FATAL, this, "END", "Synchronous thread \"" + ID + "\" ended with a FATAL error.", exception); else // Error: - executor.getLogger().logThread(LogLevel.ERROR, this, "END", "Synchronous thread \"" + ID + "\" ended with an error.", exception); + executor.getLogger().logThread(LogLevel.ERROR, this, "END", "Synchronous thread \"" + ID + "\" ended with an error.", null); } } diff --git a/src/tap/error/DefaultTAPErrorWriter.java b/src/tap/error/DefaultTAPErrorWriter.java index 54f5da8..d95cd71 100644 --- a/src/tap/error/DefaultTAPErrorWriter.java +++ b/src/tap/error/DefaultTAPErrorWriter.java @@ -20,10 +20,14 @@ package tap.error; * Astronomisches Rechen Institut (ARI) */ +import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.OutputStream; +import java.io.PrintStream; import java.io.PrintWriter; -import java.util.HashMap; +import java.sql.SQLException; +import java.util.LinkedHashMap; +import java.util.Map; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; @@ -185,7 +189,7 @@ public class DefaultTAPErrorWriter implements ServiceErrorWriter { response.setContentType("application/xml"); // List any additional information useful to report to the user: - HashMap<String,String> addInfos = new HashMap<String,String>(); + Map<String,String> addInfos = new LinkedHashMap<String,String>(); if (reqID != null) addInfos.put("REQ_ID", reqID); if (type != null) @@ -211,20 +215,72 @@ public class DefaultTAPErrorWriter implements ServiceErrorWriter { message = "{NO MESSAGE}"; // List any additional information useful to report to the user: - HashMap<String,String> addInfos = new HashMap<String,String>(); + Map<String,String> addInfos = new LinkedHashMap<String,String>(); + // error type: + if (error != null && error.getType() != null) + addInfos.put("ERROR_TYPE", error.getType().toString()); + // infos about the exception: + putExceptionInfos(t, addInfos); + // job ID: if (job != null){ addInfos.put("JOB_ID", job.getJobId()); if (job.getOwner() != null) addInfos.put("USER", job.getOwner().getID() + ((job.getOwner().getPseudo() == null) ? "" : " (" + job.getOwner().getPseudo() + ")")); } - if (error != null && error.getType() != null) - addInfos.put("ERROR_TYPE", error.getType().toString()); + // action running while the error occurred (only one is possible here: EXECUTING an ADQL query): addInfos.put("ACTION", "EXECUTING"); // Format the error in VOTable and write the document in the given HTTP response: getFormatter().writeError(message, addInfos, new PrintWriter(output)); } + /** + * Add all interesting additional information about the given exception inside the given map. + * + * @param t Exception whose some details must be added inside the given map. + * @param addInfos Map of all additional information. + * + * @since 2.0 + */ + protected void putExceptionInfos(final Throwable t, final Map<String,String> addInfos){ + if (t != null){ + // Browse the exception stack in order to list all exceptions' messages and to get the last cause of this error: + StringBuffer causes = new StringBuffer(); + Throwable cause = t.getCause(), lastCause = t; + int nbCauses = 0, nbStackTraces = 1; + while(cause != null){ + // new line: + causes.append('\n'); + // append the message: + causes.append("\t- ").append(cause.getMessage()); + // SQLException case: + if (cause instanceof SQLException){ + SQLException se = (SQLException)cause; + while(se.getNextException() != null){ + se = se.getNextException(); + causes.append("\n\t\t- ").append(se.getMessage()); + } + } + // go to the next message: + lastCause = cause; + cause = cause.getCause(); + nbCauses++; + nbStackTraces++; + } + + // Add the list of all causes' message: + if (causes.length() > 0) + addInfos.put("CAUSES", "\n" + nbCauses + causes.toString()); + + // Add the stack trace of the original exception ONLY IF NOT A TAP OR A UWS EXCEPTION (only unexpected error should be detailed to the users): + if (!(lastCause instanceof TAPException && lastCause instanceof UWSException)){ + ByteArrayOutputStream stackTrace = new ByteArrayOutputStream(); + lastCause.printStackTrace(new PrintStream(stackTrace)); + addInfos.put("ORIGIN_STACK_TRACE", "\n" + nbStackTraces + "\n" + stackTrace.toString()); + } + } + } + @Override public String getErrorDetailsMIMEType(){ return "application/xml"; diff --git a/src/tap/formatter/VOTableFormat.java b/src/tap/formatter/VOTableFormat.java index d039e63..2a4d1ae 100644 --- a/src/tap/formatter/VOTableFormat.java +++ b/src/tap/formatter/VOTableFormat.java @@ -84,7 +84,7 @@ import adql.db.DBType.DBDatatype; * </p> * * @author Grégory Mantelet (CDS;ARI) - * @version 2.0 (10/2014) + * @version 2.0 (12/2014) */ public class VOTableFormat implements OutputFormat { @@ -330,8 +330,18 @@ public class VOTableFormat implements OutputFormat { Iterator<Map.Entry<String,String>> it = otherInfo.entrySet().iterator(); while(it.hasNext()){ Map.Entry<String,String> entry = it.next(); - out.write("<INFO " + VOSerializer.formatAttribute("name", entry.getKey()) + VOSerializer.formatAttribute("value", entry.getValue()) + "/>"); - out.newLine(); + if (entry.getValue() != null){ + if (entry.getValue().startsWith("\n")){ + int sep = entry.getValue().substring(1).indexOf('\n'); + if (sep < 0) + sep = 0; + else + sep++; + out.write("<INFO " + VOSerializer.formatAttribute("name", entry.getKey()) + VOSerializer.formatAttribute("value", entry.getValue().substring(1, sep)) + ">\n" + entry.getValue().substring(sep + 1) + "\n</INFO>"); + }else + out.write("<INFO " + VOSerializer.formatAttribute("name", entry.getKey()) + VOSerializer.formatAttribute("value", entry.getValue()) + "/>"); + out.newLine(); + } } } diff --git a/src/tap/log/DefaultTAPLog.java b/src/tap/log/DefaultTAPLog.java index e2269bc..f8c938d 100644 --- a/src/tap/log/DefaultTAPLog.java +++ b/src/tap/log/DefaultTAPLog.java @@ -24,10 +24,12 @@ import java.io.OutputStream; import java.io.PrintWriter; import java.sql.SQLException; +import tap.TAPException; import tap.TAPExecutionReport; import tap.TAPSyncJob; import tap.db.DBConnection; import tap.parameters.TAPParameters; +import uws.UWSException; import uws.service.file.UWSFileManager; import uws.service.log.DefaultUWSLog; @@ -87,6 +89,33 @@ public class DefaultTAPLog extends DefaultUWSLog implements TAPLog { super(writer); } + @Override + protected void printException(Throwable error, final PrintWriter out){ + if (error != null){ + if (error instanceof UWSException || error instanceof TAPException || error.getClass().getPackage().getName().startsWith("adql.")){ + if (error.getCause() != null) + printException(error.getCause(), out); + else{ + out.println("Caused by a " + error.getClass().getName()); + if (error.getMessage() != null) + out.println("\t" + error.getMessage()); + } + }else if (error instanceof SQLException){ + out.println("Caused by a " + error.getClass().getName()); + out.print("\t"); + do{ + out.println(error.getMessage()); + error = ((SQLException)error).getNextException(); + if (error != null) + out.print("\t=> "); + }while(error != null); + }else{ + out.print("Caused by a "); + error.printStackTrace(out); + } + } + } + @Override public void logDB(final LogLevel level, final DBConnection connection, final String event, final String message, final Throwable error){ // log the main given error: @@ -111,7 +140,7 @@ public class DefaultTAPLog extends DefaultUWSLog implements TAPLog { if (event != null && obj != null){ if (event.equals("SYNC_INIT")) msgAppend = "QUERY=" + ((TAPParameters)obj).getQuery().replaceAll("(\t|\r?\n)+", " "); - else if (event.equals("SYNC_START")) + else if (obj instanceof TAPSyncJob) jobId = ((TAPSyncJob)obj).getID(); else if (obj instanceof TAPExecutionReport){ TAPExecutionReport report = (TAPExecutionReport)obj; diff --git a/src/tap/resource/TAP.java b/src/tap/resource/TAP.java index 3ff1789..918f211 100644 --- a/src/tap/resource/TAP.java +++ b/src/tap/resource/TAP.java @@ -660,6 +660,15 @@ public class TAP implements VOSIResource { if (request.getAttribute(UWS.REQ_ATTRIBUTE_ID) == null) request.setAttribute(UWS.REQ_ATTRIBUTE_ID, reqID); + // Extract all parameters: + if (request.getAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS) == null){ + try{ + request.setAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS, getUWS().getRequestParser().parse(request)); + }catch(UWSException ue){ + getLogger().log(LogLevel.ERROR, "REQUEST_PARSER", "Can not extract the HTTP request parameters!", ue); + } + } + // Retrieve the resource path parts: String[] resourcePath = (request.getPathInfo() == null) ? null : request.getPathInfo().split("/"); final String resourceName = (resourcePath == null || resourcePath.length < 1) ? "homePage" : resourcePath[1].trim().toLowerCase(); @@ -678,10 +687,6 @@ public class TAP implements VOSIResource { JobOwner owner = null; try{ - // Extract all parameters: - if (request.getAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS) == null) - request.setAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS, getUWS().getRequestParser().parse(request)); - // Identify the user: try{ if (service.getUserIdentifier() != null) diff --git a/src/uws/job/UWSJob.java b/src/uws/job/UWSJob.java index f0c5cf0..872b714 100644 --- a/src/uws/job/UWSJob.java +++ b/src/uws/job/UWSJob.java @@ -763,9 +763,8 @@ public class UWSJob extends SerializableUWSObject { else if (!isFinished()) this.errorSummary = errorSummary; else{ - UWSException ue = new UWSException(UWSException.NOT_ALLOWED, UWSExceptionFactory.jobModificationForbidden(jobId, getPhase(), "ERROR SUMMARY")); - getLogger().logJob(LogLevel.ERROR, this, "SET_ERROR", "Can not set an error summary when the job is finished (or not yet started)! The current phase is: " + getPhase() + " ; the summary of the error to set is: \"" + errorSummary.message + "\".", ue); - throw ue; + getLogger().logJob(LogLevel.ERROR, this, "SET_ERROR", "Can not set an error summary when the job is finished (or not yet started)! The current phase is: " + getPhase() + " ; the summary of the error to set is: \"" + errorSummary.message + "\".", null); + throw new UWSException(UWSException.NOT_ALLOWED, UWSExceptionFactory.jobModificationForbidden(jobId, getPhase(), "ERROR SUMMARY")); } } @@ -981,7 +980,7 @@ public class UWSJob extends SerializableUWSObject { public boolean addOrUpdateParameters(UWSParameters params, final JobOwner user) throws UWSException{ // The job can be modified ONLY IF in PENDING phase: if (!phase.isJobUpdatable()) - throw new UWSException(UWSException.FORBIDDEN, "Parameters modification is now forbidden for this job: it is not any more in PENDING phase!"); + throw new UWSException(UWSException.FORBIDDEN, "Forbidden parameters modification: the job is not any more in the PENDING phase!"); // Forbids the update if the user has not the required permission: if (user != null && !user.equals(owner) && !user.hasWritePermission(this)) diff --git a/src/uws/service/UWSService.java b/src/uws/service/UWSService.java index b09dddb..a2b1e74 100644 --- a/src/uws/service/UWSService.java +++ b/src/uws/service/UWSService.java @@ -1066,6 +1066,15 @@ public class UWSService implements UWS { if (request.getAttribute(UWS.REQ_ATTRIBUTE_ID) == null) request.setAttribute(UWS.REQ_ATTRIBUTE_ID, reqID); + // Extract all parameters: + if (request.getAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS) == null){ + try{ + request.setAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS, requestParser.parse(request)); + }catch(UWSException ue){ + logger.log(LogLevel.ERROR, "REQUEST_PARSER", "Can not extract the HTTP request parameters!", ue); + } + } + // Log the reception of the request: logger.logHttp(LogLevel.INFO, request, reqID, null, null); @@ -1086,10 +1095,6 @@ public class UWSService implements UWS { UWSUrl urlInterpreter = new UWSUrl(this.urlInterpreter); urlInterpreter.load(request); - // Extract all parameters: - if (request.getAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS) == null) - request.setAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS, requestParser.parse(request)); - // Identify the user: user = (userIdentifier == null) ? null : userIdentifier.extractUserId(urlInterpreter, request); @@ -1200,7 +1205,10 @@ public class UWSService implements UWS { // Write the error in the response and return the appropriate HTTP status code: errorWriter.writeError(error, response, request, reqID, user, uwsAction); // Log the error: - logger.logHttp(LogLevel.ERROR, response, reqID, user, "HTTP " + response.getStatus() + " - Can not complete the UWS action \"" + uwsAction + "\", because: " + error.getMessage(), error); + if (uwsAction == null) + logger.logHttp(LogLevel.ERROR, response, reqID, user, "HTTP " + response.getStatus() + " - Unknown UWS action!", error); + else + logger.logHttp(LogLevel.ERROR, response, reqID, user, "HTTP " + response.getStatus() + " - Can not complete the UWS action \"" + uwsAction + "\"!", error); } } diff --git a/src/uws/service/UWSServlet.java b/src/uws/service/UWSServlet.java index 2eed062..da9b7f5 100644 --- a/src/uws/service/UWSServlet.java +++ b/src/uws/service/UWSServlet.java @@ -287,6 +287,13 @@ public abstract class UWSServlet extends HttpServlet implements UWS, UWSFactory final String reqID = generateRequestID(req); req.setAttribute(UWS.REQ_ATTRIBUTE_ID, reqID); + // Extract all parameters: + try{ + req.setAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS, requestParser.parse(req)); + }catch(UWSException ue){ + logger.log(LogLevel.ERROR, "REQUEST_PARSER", "Can not extract the HTTP request parameters!", ue); + } + // Log the reception of the request: logger.logHttp(LogLevel.INFO, req, reqID, null, null); @@ -301,9 +308,6 @@ public abstract class UWSServlet extends HttpServlet implements UWS, UWSFactory UWSUrl requestUrl = new UWSUrl(this.urlInterpreter); requestUrl.load(req); - // Extract all parameters: - req.setAttribute(UWS.REQ_ATTRIBUTE_PARAMETERS, requestParser.parse(req)); - // Identify the user: user = (userIdentifier == null) ? null : userIdentifier.extractUserId(requestUrl, req); diff --git a/src/uws/service/log/DefaultUWSLog.java b/src/uws/service/log/DefaultUWSLog.java index 100f180..a1ef8b7 100644 --- a/src/uws/service/log/DefaultUWSLog.java +++ b/src/uws/service/log/DefaultUWSLog.java @@ -26,11 +26,14 @@ import java.io.PrintWriter; import java.text.DateFormat; import java.text.SimpleDateFormat; import java.util.Date; -import java.util.Enumeration; +import java.util.Map; +import java.util.Map.Entry; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; +import uws.UWSException; +import uws.UWSToolBox; import uws.job.UWSJob; import uws.job.user.JobOwner; import uws.service.UWS; @@ -212,12 +215,36 @@ public class DefaultUWSLog implements UWSLog { out.println(buf.toString()); // Print the stack trace, if any: - if (error != null) - error.printStackTrace(out); + printException(error, out); out.flush(); } + /** + * Format and print the given exception inside the given writer. + * + * @param error The exception to print. + * @param out The output in which the exception must be written. + * + * @since 4.1 + */ + protected void printException(final Throwable error, final PrintWriter out){ + if (error != null){ + if (error instanceof UWSException){ + if (error.getCause() != null) + printException(error.getCause(), out); + else{ + out.println("Caused by a " + error.getClass().getName()); + if (error.getMessage() != null) + out.println("\t" + error.getMessage()); + } + }else{ + out.print("Caused by a "); + error.printStackTrace(out); + } + } + } + @Override public void debug(String msg){ log(LogLevel.DEBUG, null, msg, null); @@ -264,7 +291,7 @@ public class DefaultUWSLog implements UWSLog { /** * <p>A message/error logged with this function will have the following format:</p> - * <pre><TIMESTAMP> <LEVEL> HTTP REQUEST_RECEIVED <REQUEST_ID> <MESSAGE> <HTTP_METHOD> at <URL> from <IP_ADDR> using <USER_AGENT> with parameters (<PARAM1>=<VAL1>&...)</pre> + * <pre><TIMESTAMP> <LEVEL> HTTP REQUEST_RECEIVED <REQUEST_ID> <MESSAGE> <HTTP_METHOD> in <CONTENT_TYPE> at <URL> from <IP_ADDR> using <USER_AGENT> with parameters (<PARAM1>=<VAL1>&...)</pre> * * @see uws.service.log.UWSLog#logHttp(uws.service.log.UWSLog.LogLevel, javax.servlet.http.HttpServletRequest, java.lang.String, java.lang.String, java.lang.Throwable) */ @@ -279,28 +306,31 @@ public class DefaultUWSLog implements UWSLog { str.append(message); str.append('\t'); - // Write the request type and the URL: - str.append(request.getMethod()).append(" at ").append(request.getRequestURL()); + // Write the request type, content type and the URL: + str.append(request.getMethod()); + str.append(" as "); + if (request.getContentType() != null){ + if (request.getContentType().indexOf(';') > 0) + str.append(request.getContentType().substring(0, request.getContentType().indexOf(';'))); + else + str.append(request.getContentType()); + } + str.append(" at ").append(request.getRequestURL()); // Write the IP address: str.append(" from ").append(request.getRemoteAddr()); // Write the user agent: - str.append(" using ").append(request.getHeader("User-Agent")); + str.append(" using ").append(request.getHeader("User-Agent") == null ? "" : request.getHeader("User-Agent")); // Write the posted parameters: str.append(" with parameters ("); - Enumeration<String> paramNames = request.getParameterNames(); - while(paramNames.hasMoreElements()){ - String param = paramNames.nextElement(); - String paramValue = request.getParameter(param); - if (paramValue != null) - paramValue = paramValue.replaceAll("[\t\n\r]", " "); - else - paramValue = ""; - str.append(param).append('=').append(paramValue); - if (paramNames.hasMoreElements()) + Map<String,String> params = UWSToolBox.getParamsMap(request); + int i = -1; + for(Entry<String,String> p : params.entrySet()){ + if (++i > 0) str.append('&'); + str.append(p.getKey()).append('=').append((p.getValue() != null) ? p.getValue().replaceAll("[\t\n\r]", " ") : ""); } str.append(')'); -- GitLab