[UWS,TAP] Errors and log management improvements. Particularly, now TAP and... (998d11f5) · Commits · Sonia Zorba / vollt

src/tap/ADQLExecutor.java

+45 −30

Original line number	Diff line number	Diff line
		@@ -16,7 +16,7 @@ package tap;
		* You should have received a copy of the GNU Lesser General Public License
		* along with TAPLibrary. If not, see <http://www.gnu.org/licenses/>.
		*
		* Copyright 2012-2014 - UDS/Centre de Données astronomiques de Strasbourg (CDS),
		* Copyright 2012-2015 - UDS/Centre de Données astronomiques de Strasbourg (CDS),
		* Astronomisches Rechen Institut (ARI)
		*/

		@@ -104,7 +104,7 @@ import adql.query.ADQLQuery;
		* </p>
		*
		* @author Grégory Mantelet (CDS;ARI)
		* @version 2.0 (12/2014)
		* @version 2.0 (04/2015)
		*/
		public class ADQLExecutor {

		@@ -223,6 +223,8 @@ public class ADQLExecutor {

		try{
		return start();
		}catch(IOException ioe){
		throw new UWSException(ioe);
		}catch(TAPException te){
		throw new UWSException(te.getHttpErrorCode(), te);
		}
		@@ -260,11 +262,12 @@ public class ADQLExecutor {
		* @return The resulting execution report.
		*
		* @throws TAPException If any error occurs while executing the ADQL query.
		* @throws IOException If any error occurs while writing the result in the given {@link HttpServletResponse}.
		* @throws InterruptedException If the job has been interrupted (by the user or a time-out).
		*
		* @see #start()
		*/
		public final TAPExecutionReport start(final Thread thread, final String jobId, final TAPParameters params, final HttpServletResponse response) throws TAPException, InterruptedException{
		public final TAPExecutionReport start(final Thread thread, final String jobId, final TAPParameters params, final HttpServletResponse response) throws TAPException, IOException, InterruptedException{
		if (this.thread != null \|\| this.report != null)
		throw new TAPException("This ADQLExecutor has already been executed!");

		@@ -305,9 +308,14 @@ public class ADQLExecutor {
		*
		* @throws TAPException If any error occurs while executing the ADQL query.
		* @throws UWSException If any error occurs while executing the ADQL query.
		* @throws IOException If an error happens while writing the result in the specified {@link HttpServletResponse}.
		* <i>That kind of error can be thrown only in synchronous mode.
		* In asynchronous, the error is stored as job error report and is never propagated.</i>
		* @throws InterruptedException If the job has been interrupted (by the user or a time-out).
		*/
		protected final TAPExecutionReport start() throws TAPException, UWSException, InterruptedException{
		protected final TAPExecutionReport start() throws TAPException, UWSException, IOException, InterruptedException{
		logger.logTAP(LogLevel.INFO, report, "START_EXEC", (report.synchronous ? "Synchronous" : "Asynchronous") + " execution of an ADQL query STARTED.", null);

		// Save the start time (for reporting usage):
		long start = System.currentTimeMillis();

		@@ -356,9 +364,6 @@ public class ADQLExecutor {

		// 4. WRITE RESULT:
		startStep(ExecutionProgression.WRITING_RESULT);
		if (response != null && response.isCommitted())
		getLogger().logTAP(LogLevel.WARNING, report, "WRITING_RESULT", "HTTP request canceled/timeout! The result can not have been returned to the user.", null);
		else
		writeResult(queryResult);
		endStep();

		@@ -366,6 +371,12 @@ public class ADQLExecutor {
		tapParams.remove(TAPJob.PARAM_PROGRESSION);
		report.success = true;

		// Set the total duration in the report:
		report.setTotalDuration(System.currentTimeMillis() - start);

		// Log and report the end of this execution:
		logger.logTAP(LogLevel.INFO, report, "END_EXEC", "ADQL query execution finished.", null);

		return report;
		}finally{
		// Close the result if any:
		@@ -373,7 +384,7 @@ public class ADQLExecutor {
		try{
		queryResult.close();
		}catch(DataReadException dre){
		logger.logTAP(LogLevel.ERROR, report, "END_EXEC", "Can not close the database query result!", dre);
		logger.logTAP(LogLevel.WARNING, report, "END_EXEC", "Can not close the database query result!", dre);
		}
		}

		@@ -381,7 +392,7 @@ public class ADQLExecutor {
		try{
		dropUploadedTables();
		}catch(TAPException e){
		logger.logTAP(LogLevel.ERROR, report, "END_EXEC", "Can not drop the uploaded tables from the database!", e);
		logger.logTAP(LogLevel.WARNING, report, "END_EXEC", "Can not drop the uploaded tables from the database!", e);
		}

		// Free the connection (so that giving it back to a pool, if any, otherwise, just free resources):
		@@ -389,12 +400,6 @@ public class ADQLExecutor {
		service.getFactory().freeConnection(dbConn);
		dbConn = null;
		}

		// Set the total duration in the report:
		report.setTotalDuration(System.currentTimeMillis() - start);

		// Log and report the end of this execution:
		logger.logTAP(LogLevel.INFO, report, "END_EXEC", "ADQL query execution finished.", null);
		}
		}

		@@ -549,7 +554,7 @@ public class ADQLExecutor {
		*/
		protected TableIterator executeADQL(final ADQLQuery adql) throws InterruptedException, TAPException{
		// Log the start of execution:
		logger.logTAP(LogLevel.INFO, report, "EXECUTING", "Executing ADQL: " + adql.toADQL().replaceAll("(\t\|\r?\n)+", " "), null);
		logger.logTAP(LogLevel.INFO, report, "START_DB_EXECUTION", "ADQL query: " + adql.toADQL().replaceAll("(\t\|\r?\n)+", " "), null);

		// Set the fetch size, if any:
		if (service.getFetchSize() != null && service.getFetchSize().length >= 1){
		@@ -564,9 +569,10 @@ public class ADQLExecutor {

		// Log the success or failure:
		if (result == null)
		logger.logTAP(LogLevel.INFO, report, "END_QUERY", "Query execution aborted after " + (System.currentTimeMillis() - startStep) + "ms!", null);
		logger.logTAP(LogLevel.INFO, report, "END_DB_EXECUTION", "Query execution aborted after " + (System.currentTimeMillis() - startStep) + "ms!", null);
		else
		logger.logTAP(LogLevel.INFO, report, "END_QUERY", "Query successfully executed in " + (System.currentTimeMillis() - startStep) + "ms!", null);
		logger.logTAP(LogLevel.INFO, report, "END_DB_EXECUTION", "Query successfully executed in " + (System.currentTimeMillis() - startStep) + "ms!", null);

		return result;
		}

		@@ -582,12 +588,15 @@ public class ADQLExecutor {
		* @param queryResult The result of the query execution in database.
		*
		* @throws InterruptedException If the thread has been interrupted.
		* @throws IOException If an error happens while writing the result in the {@link HttpServletResponse}.
		* <i>That kind of error can be thrown only in synchronous mode.
		* In asynchronous, the error is stored as job error report and is never propagated.</i>
		* @throws TAPException If an error occurs while getting the appropriate formatter or while formatting or writing (synchronous execution) the result.
		* @throws UWSException If an error occurs while getting the output stream or while writing (asynchronous execution) the result.
		*
		* @see #writeResult(TableIterator, OutputFormat, OutputStream)
		*/
		protected final void writeResult(final TableIterator queryResult) throws InterruptedException, TAPException, UWSException{
		protected final void writeResult(final TableIterator queryResult) throws InterruptedException, IOException, TAPException, UWSException{
		// Log the start of the writing:
		logger.logTAP(LogLevel.INFO, report, "WRITING_RESULT", "Writing the query result", null);

		@@ -596,19 +605,20 @@ public class ADQLExecutor {

		// CASE SYNCHRONOUS:
		if (response != null){
		try{
		long start = -1;

		// Set the HTTP content type to the MIME type of the result format:
		response.setContentType(formatter.getMimeType());

		// Write the formatted result in the HTTP response output:
		start = System.currentTimeMillis();
		writeResult(queryResult, formatter, response.getOutputStream());

		}catch(IOException ioe){
		throw new TAPException("Impossible to get the HTTP response, so the result of the job " + report.jobID + " can not be written!", ioe, UWSException.INTERNAL_SERVER_ERROR);
		}
		logger.logTAP(LogLevel.INFO, report, "RESULT_WRITTEN", "Result formatted (in " + formatter.getMimeType() + " ; " + (report.nbRows < 0 ? "?" : report.nbRows) + " rows ; " + ((report.resultingColumns == null) ? "?" : report.resultingColumns.length) + " columns) in " + ((start <= 0) ? "?" : (System.currentTimeMillis() - start)) + "ms!", null);
		}
		// CASE ASYNCHRONOUS:
		else{
		long start = -1, end = -1;
		try{
		// Create a UWS Result object to store the result
		// (the result will be stored in a file and this object is the association between the job and the result file):
		@@ -619,7 +629,9 @@ public class ADQLExecutor {
		result.setMimeType(formatter.getMimeType());

		// Write the formatted result in the file output:
		start = System.currentTimeMillis();
		writeResult(queryResult, formatter, jobThread.getResultOutput(result));
		end = System.currentTimeMillis();

		// Set the size (in bytes) of the result in the result description:
		result.setSize(jobThread.getResultSize(result));
		@@ -627,8 +639,10 @@ public class ADQLExecutor {
		// Add the result description and link in the job description:
		jobThread.publishResult(result);

		logger.logTAP(LogLevel.INFO, report, "RESULT_WRITTEN", "Result formatted (in " + formatter.getMimeType() + " ; " + (report.nbRows < 0 ? "?" : report.nbRows) + " rows ; " + ((report.resultingColumns == null) ? "?" : report.resultingColumns.length) + " columns) in " + ((start <= 0 \|\| end <= 0) ? "?" : (end - start)) + "ms!", null);

		}catch(IOException ioe){
		throw new UWSException(UWSException.INTERNAL_SERVER_ERROR, ioe, "Impossible to access the file into the result of the job " + report.jobID + " must be written!");
		throw new UWSException(UWSException.INTERNAL_SERVER_ERROR, ioe, "Impossible to write in the file into the result of the job " + report.jobID + " must be written!");
		}
		}
		}
		@@ -648,9 +662,10 @@ public class ADQLExecutor {
		* @param output The stream in which the result must be written.
		*
		* @throws InterruptedException If the thread has been interrupted.
		* @throws IOException If there is an error while writing the result in the given stream.
		* @throws TAPException If there is an error while formatting the result.
		*/
		protected void writeResult(TableIterator queryResult, OutputFormat formatter, OutputStream output) throws InterruptedException, TAPException{
		protected void writeResult(TableIterator queryResult, OutputFormat formatter, OutputStream output) throws InterruptedException, IOException, TAPException{
		formatter.writeResult(queryResult, output, report, thread);
		}

src/tap/TAPExecutionReport.java

+6 −2

Original line number	Diff line number	Diff line
		@@ -16,7 +16,7 @@ package tap;
		* You should have received a copy of the GNU Lesser General Public License
		* along with TAPLibrary. If not, see <http://www.gnu.org/licenses/>.
		*
		* Copyright 2012,2014 - UDS/Centre de Données astronomiques de Strasbourg (CDS),
		* Copyright 2012-2015 - UDS/Centre de Données astronomiques de Strasbourg (CDS),
		* Astronomisches Rechen Institut (ARI)
		*/

		@@ -31,7 +31,7 @@ import adql.db.DBColumn;
		* <p>This report is completely filled by {@link ADQLExecutor}, and aims to be used/read only at the end of the job or when it is definitely finished.</p>
		*
		* @author Grégory Mantelet (CDS;ARI)
		* @version 2.0 (07/2014)
		* @version 2.0 (04/2015)
		*/
		public class TAPExecutionReport {

		@@ -47,6 +47,10 @@ public class TAPExecutionReport {
		/** List of all resulting columns. <i>Empty array, if not yet known.</i> */
		public DBColumn[] resultingColumns = new DBColumn[0];

		/** Total number of written rows.
		* @since 2.0 */
		public long nbRows = -1;

		/** Duration of all execution steps. <i>For the moment only 4 steps (in the order): uploading, parsing, executing and writing.</i> */
		protected final long[] durations = new long[]{-1,-1,-1,-1};

src/tap/TAPJob.java

+3 −3

Original line number	Diff line number	Diff line
		@@ -16,7 +16,7 @@ package tap;
		* You should have received a copy of the GNU Lesser General Public License
		* along with TAPLibrary. If not, see <http://www.gnu.org/licenses/>.
		*
		* Copyright 2012,2014 - UDS/Centre de Données astronomiques de Strasbourg (CDS),
		* Copyright 2012-2015 - UDS/Centre de Données astronomiques de Strasbourg (CDS),
		* Astronomisches Rechen Institut (ARI)
		*/

		@@ -45,7 +45,7 @@ import uws.service.log.UWSLog.LogLevel;
		* </p>
		*
		* @author Grégory Mantelet (CDS;ARI)
		* @version 2.0 (12/2014)
		* @version 2.0 (04/2015)
		*/
		public class TAPJob extends UWSJob {
		private static final long serialVersionUID = 1L;
		@@ -253,7 +253,7 @@ public class TAPJob extends UWSJob {
		* @throws UWSException If this job has never been restored and is not running.
		*/
		public final void setExecReport(final TAPExecutionReport execReport) throws UWSException{
		if (getRestorationDate() == null && !isRunning())
		if (getRestorationDate() == null && (thread == null \|\| thread.isFinished()))
		throw new UWSException("Impossible to set an execution report if the job is not in the EXECUTING phase ! Here, the job \"" + jobId + "\" is in the phase " + getPhase());
		this.execReport = execReport;
		}

src/tap/TAPSyncJob.java

+25 −16

Original line number	Diff line number	Diff line
		@@ -20,6 +20,7 @@ package tap;
		* Astronomisches Rechen Institut (ARI)
		*/

		import java.io.IOException;
		import java.util.Date;

		import javax.servlet.http.HttpServletResponse;
		@@ -162,16 +163,17 @@ public class TAPSyncJob {
		* @return <i>true</i> if the execution was successful, <i>false</i> otherwise.
		*
		* @throws IllegalStateException If this synchronous job has already been started before.
		* @throws IOException If any error occurs while writing the query result in the given {@link HttpServletResponse}.
		* @throws TAPException If any error occurs while executing the ADQL query.
		*
		* @see SyncThread
		*/
		public synchronized boolean start(final HttpServletResponse response) throws IllegalStateException, TAPException{
		public synchronized boolean start(final HttpServletResponse response) throws IllegalStateException, IOException, TAPException{
		if (startedAt != null)
		throw new IllegalStateException("Impossible to restart a synchronous TAP query!");

		// Log the start of this sync job:
		service.getLogger().logTAP(LogLevel.INFO, this, "SYNC_START", "Synchronous job " + ID + " is starting!", null);
		service.getLogger().logTAP(LogLevel.INFO, this, "START", "Synchronous job " + ID + " is starting!", null);

		// Create the object having the knowledge about how to execute an ADQL query:
		ADQLExecutor executor = service.getFactory().createADQLExecutor();
		@@ -179,7 +181,7 @@ public class TAPSyncJob {
		executor.initDBConnection(ID);
		}catch(TAPException te){
		service.getLogger().logDB(LogLevel.ERROR, null, "CONNECTION_LACK", "No more database connection available for the moment!", te);
		service.getLogger().logTAP(LogLevel.ERROR, this, "END_EXEC", "Synchronous job " + ID + " execution aborted: no database connection available!", null);
		service.getLogger().logTAP(LogLevel.ERROR, this, "END", "Synchronous job " + ID + " execution aborted: no database connection available!", null);
		throw new TAPException("TAP service too busy! No connection available for the moment. You should try later or create an asynchronous query (which will be executed when enough resources will be available again).", UWSException.SERVICE_UNAVAILABLE);
		}

		@@ -211,9 +213,9 @@ public class TAPSyncJob {
		if (timeout && error != null && error instanceof InterruptedException){
		// Log the timeout:
		if (thread.isAlive())
		service.getLogger().logTAP(LogLevel.WARNING, this, "SYNC_TIME_OUT", "Time out (after " + tapParams.getExecutionDuration() + "ms) for the synchonous job " + ID + ", but the thread can not be interrupted!", null);
		service.getLogger().logTAP(LogLevel.WARNING, this, "TIME_OUT", "Time out (after " + tapParams.getExecutionDuration() + "ms) for the synchonous job " + ID + ", but the thread can not be interrupted!", null);
		else
		service.getLogger().logTAP(LogLevel.INFO, this, "SYNC_TIME_OUT", "Time out (after " + tapParams.getExecutionDuration() + "ms) for the synchonous job " + ID + ".", null);
		service.getLogger().logTAP(LogLevel.INFO, this, "TIME_OUT", "Time out (after " + tapParams.getExecutionDuration() + "ms) for the synchonous job " + ID + ".", null);

		// Report the timeout to the user:
		throw new TAPException("Time out! The execution of this synchronous TAP query was limited to " + tapParams.getExecutionDuration() + "ms. You should try again but in asynchronous execution.", UWSException.ACCEPTED_BUT_NOT_COMPLETE);
		@@ -223,21 +225,28 @@ 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!", null);
		service.getLogger().logTAP(LogLevel.ERROR, this, "END", "The execution of the synchronous job " + ID + " has been unexpectedly interrupted!", error);
		// 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);
		}
		// REQUEST ABORTION:
		else if (error instanceof IOException){
		// log the unexpected interruption (unexpected because not caused by a timeout):
		service.getLogger().logTAP(LogLevel.INFO, this, "END", "Abortion of the synchronous job " + ID + "! Cause: connection with the HTTP client unexpectedly closed.", null);
		// throw the error until the TAP instance to notify it about the abortion:
		throw (IOException)error;
		}
		// 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 + ".", null);
		service.getLogger().logTAP(LogLevel.ERROR, this, "END", "The following error interrupted the execution of the synchronous job " + ID + ".", error);
		// report the error to the user:
		throw (TAPException)error;
		}
		// ANY OTHER EXCEPTION:
		else{
		// log the error:
		service.getLogger().logTAP(LogLevel.FATAL, this, "SYNC_END", "An unexpected error has stopped the execution of the synchronous job " + ID + ".", error);
		service.getLogger().logTAP(LogLevel.FATAL, this, "END", "The following GRAVE error interrupted the execution of the synchronous job " + ID + ".", error);
		// report the error to the user:
		if (error instanceof Error)
		throw (Error)error;
		@@ -245,7 +254,7 @@ public class TAPSyncJob {
		throw new TAPException(error);
		}
		}else
		service.getLogger().logTAP(LogLevel.INFO, this, "SYNC_END", "The synchronous job " + ID + " successfully ended.", null);
		service.getLogger().logTAP(LogLevel.INFO, this, "END", "Success of the synchronous job " + ID + ".", null);

		return thread.isSuccess();
		}
		@@ -259,7 +268,7 @@ public class TAPSyncJob {
		* </p>
		*
		* @author Grégory Mantelet (CDS;ARI)
		* @version 2.0 (09/2014)
		* @version 2.0 (04/2015)
		*/
		protected class SyncThread extends Thread {

		@@ -342,15 +351,15 @@ public class TAPSyncJob {
		exception = e;

		// Log the end of the job:
		if (e instanceof InterruptedException)
		if (e instanceof InterruptedException \|\| e instanceof IOException)
		// Abortion:
		executor.getLogger().logThread(LogLevel.INFO, this, "END", "Synchronous thread \"" + ID + "\" cancelled.", null);
		else if (e instanceof Error)
		// GRAVE error:
		executor.getLogger().logThread(LogLevel.FATAL, this, "END", "Synchronous thread \"" + ID + "\" ended with a FATAL error.", exception);
		else
		else if (e instanceof TAPException)
		// Error:
		executor.getLogger().logThread(LogLevel.ERROR, this, "END", "Synchronous thread \"" + ID + "\" ended with an error.", null);
		else
		// GRAVE error:
		executor.getLogger().logThread(LogLevel.FATAL, this, "END", "Synchronous thread \"" + ID + "\" ended with a FATAL error.", null);
		}
		}

src/tap/db/JDBCConnection.java

+5 −5

Original line number	Diff line number	Diff line
		@@ -435,27 +435,27 @@ public class JDBCConnection implements DBConnection {
		// 3. Execute the SQL query:
		result = stmt.executeQuery(sql);
		if (logger != null)
		logger.logDB(LogLevel.INFO, this, "EXECUTE", "Executing translated query: " + sql.replaceAll("(\t\|\r?\n)+", " "), null);
		logger.logDB(LogLevel.INFO, this, "EXECUTE", "SQL query: " + sql.replaceAll("(\t\|\r?\n)+", " "), null);

		// 4. Return the result through a TableIterator object:
		if (logger != null)
		logger.logDB(LogLevel.INFO, this, "RESULT", "Returning result", null);
		logger.logDB(LogLevel.INFO, this, "RESULT", "Returning result (" + (supportsFetchSize ? "fetch size = " + fetchSize : "all in once") + ").", null);
		return createTableIterator(result, adqlQuery.getResultingColumns());

		}catch(SQLException se){
		close(result);
		if (logger != null)
		logger.logDB(LogLevel.ERROR, this, "EXECUTE", "Unexpected error while EXECUTING SQL query!", se);
		logger.logDB(LogLevel.ERROR, this, "EXECUTE", "Unexpected error while EXECUTING SQL query!", null);
		throw new DBException("Unexpected error while executing a SQL query: " + se.getMessage(), se);
		}catch(TranslationException te){
		close(result);
		if (logger != null)
		logger.logDB(LogLevel.ERROR, this, "TRANSLATE", "Unexpected error while TRANSLATING ADQL into SQL!", te);
		logger.logDB(LogLevel.ERROR, this, "TRANSLATE", "Unexpected error while TRANSLATING ADQL into SQL!", null);
		throw new DBException("Unexpected error while translating ADQL into SQL: " + te.getMessage(), te);
		}catch(DataReadException dre){
		close(result);
		if (logger != null)
		logger.logDB(LogLevel.ERROR, this, "RESULT", "Unexpected error while reading the query result!", dre);
		logger.logDB(LogLevel.ERROR, this, "RESULT", "Unexpected error while reading the query result!", null);
		throw new DBException("Impossible to read the query result, because: " + dre.getMessage(), dre);
		}
		}