Merge pull request #1089 from rcordovano/ingest-analysis-error-logging

Ingest logging improvements, minor bug fix

Core/src/org/sleuthkit/autopsy/ingest/DataSourceIngestJob.java

@@ -119,7 +119,7 @@ final class DataSourceIngestJob {
     private volatile boolean currentDataSourceIngestModuleCancelled;
     private volatile boolean cancelled;
     private final List<String> cancelledDataSourceIngestModules = new CopyOnWriteArrayList<>();
-        
+
     /**
      * A data source ingest job uses the task scheduler singleton to create and
      * queue the ingest tasks that make up the job.
@@ -346,8 +346,10 @@ final class DataSourceIngestJob {
         List<IngestModuleError> errors = startUpIngestPipelines();
         if (errors.isEmpty()) {
             if (this.hasFirstStageDataSourceIngestPipeline() || this.hasFileIngestPipeline()) {
+                logger.log(Level.INFO, "Starting first stage analysis for {0} (jobId={1})", new Object[]{dataSource.getName(), this.id});
                 this.startFirstStage();
             } else if (this.hasSecondStageDataSourceIngestPipeline()) {
+                logger.log(Level.INFO, "Starting second stage analysis for {0} (jobId={1}), no first stage configured", new Object[]{dataSource.getName(), this.id});
                 this.startSecondStage();
             }
         }
@@ -432,10 +434,13 @@ final class DataSourceIngestJob {
          * Schedule the first stage tasks.
          */
         if (this.hasFirstStageDataSourceIngestPipeline() && this.hasFileIngestPipeline()) {
+            logger.log(Level.INFO, "Scheduling first stage data source and file level analysis tasks for {0} (jobId={1})", new Object[]{dataSource.getName(), this.id});
             DataSourceIngestJob.taskScheduler.scheduleIngestTasks(this);
         } else if (this.hasFirstStageDataSourceIngestPipeline()) {
+            logger.log(Level.INFO, "Scheduling first stage data source level analysis tasks for {0} (jobId={1}), no file level analysis configured", new Object[]{dataSource.getName(), this.id});
             DataSourceIngestJob.taskScheduler.scheduleDataSourceIngestTask(this);
         } else {
+            logger.log(Level.INFO, "Scheduling file level analysis tasks for {0} (jobId={1}), no first stage data source level analysis configured", new Object[]{dataSource.getName(), this.id});
             DataSourceIngestJob.taskScheduler.scheduleFileIngestTasks(this);
 
             /**
@@ -454,6 +459,7 @@ final class DataSourceIngestJob {
      * Starts the second stage of this ingest job.
      */
     private void startSecondStage() {
+        logger.log(Level.INFO, "Starting second stage analysis for {0} (jobId={1})", new Object[]{dataSource.getName(), this.id});
         this.stage = DataSourceIngestJob.Stages.SECOND;
         if (this.runInteractively) {
             this.startDataSourceIngestProgressBar();
@@ -461,6 +467,7 @@ final class DataSourceIngestJob {
         synchronized (this.dataSourceIngestPipelineLock) {
             this.currentDataSourceIngestPipeline = this.secondStageDataSourceIngestPipeline;
         }
+        logger.log(Level.INFO, "Scheduling second stage data source level analysis tasks for {0} (jobId={1})", new Object[]{dataSource.getName(), this.id});
         DataSourceIngestJob.taskScheduler.scheduleDataSourceIngestTask(this);
     }
 
@@ -549,6 +556,8 @@ final class DataSourceIngestJob {
      * job and starts the second stage, if appropriate.
      */
     private void finishFirstStage() {
+        logger.log(Level.INFO, "Finished first stage analysis for {0} (jobId={1})", new Object[]{dataSource.getName(), this.id});
+
         // Shut down the file ingest pipelines. Note that no shut down is
         // required for the data source ingest pipeline because data source 
         // ingest modules do not have a shutdown() method.
@@ -595,6 +604,7 @@ final class DataSourceIngestJob {
      * Shuts down the ingest pipelines and progress bars for this job.
      */
     private void finish() {
+        logger.log(Level.INFO, "Finished analysis for {0} (jobId={1})", new Object[]{dataSource.getName(), this.id});
         this.stage = DataSourceIngestJob.Stages.FINALIZATION;
 
         if (this.runInteractively) {
@@ -845,7 +855,7 @@ final class DataSourceIngestJob {
     /**
      * Rescind a temporary cancellation of data source level ingest that was
      * used to stop a single data source level ingest module for this job.
-     * 
+     *
      * @param moduleDisplayName The display name of the module that was stopped.
      */
     void currentDataSourceIngestModuleCancellationCompleted(String moduleDisplayName) {
@@ -954,7 +964,7 @@ final class DataSourceIngestJob {
      */
     private void logIngestModuleErrors(List<IngestModuleError> errors) {
         for (IngestModuleError error : errors) {
-            DataSourceIngestJob.logger.log(Level.SEVERE, error.getModuleDisplayName() + " experienced an error", error.getModuleError()); //NON-NLS
+            DataSourceIngestJob.logger.log(Level.SEVERE, String.format("%s experienced an error analyzing %s (jobId=%d)", error.getModuleDisplayName(), dataSource.getName(), this.id), error.getModuleError()); //NON-NLS
         }
     }
 
@@ -1132,13 +1142,13 @@ final class DataSourceIngestJob {
         boolean isCancelled() {
             return this.jobCancelled;
         }
-        
+
         /**
-         * Gets a list of the display names of any canceled data source level ingest
+         * Gets a list of the display names of any canceled data source level
-         * modules
+         * ingest modules
          *
-         * @return A list of canceled data source level ingest module display names,
+         * @return A list of canceled data source level ingest module display
-         * possibly empty.
+         * names, possibly empty.
          */
         List<String> getCancelledDataSourceIngestModules() {
             return Collections.unmodifiableList(this.cancelledDataSourceModules);

Core/src/org/sleuthkit/autopsy/ingest/DataSourceIngestPipeline.java

@@ -21,7 +21,9 @@ package org.sleuthkit.autopsy.ingest;
 import java.util.ArrayList;
 import java.util.Date;
 import java.util.List;
+import java.util.logging.Level;
 import org.openide.util.NbBundle;
+import org.sleuthkit.autopsy.coreutils.Logger;
 import org.sleuthkit.datamodel.Content;
 
 /**
@@ -34,6 +36,7 @@ import org.sleuthkit.datamodel.Content;
 final class DataSourceIngestPipeline {
 
     private static final IngestManager ingestManager = IngestManager.getInstance();
+    private static final Logger logger = Logger.getLogger(DataSourceIngestPipeline.class.getName());    
     private final DataSourceIngestJob job;
     private final List<PipelineModule> modules = new ArrayList<>();
     private volatile PipelineModule currentModule;
@@ -102,7 +105,9 @@ final class DataSourceIngestPipeline {
                 this.job.updateDataSourceIngestProgressBarDisplayName(displayName);
                 this.job.switchDataSourceIngestProgressBarToIndeterminate();
                 DataSourceIngestPipeline.ingestManager.setIngestTaskProgress(task, module.getDisplayName());
+                logger.log(Level.INFO, "{0} analysis of {1} (jobId={2}) starting", new Object[]{module.getDisplayName(), this.job.getDataSource().getName(), this.job.getDataSource().getId()});
                 module.process(dataSource, new DataSourceIngestModuleProgress(this.job));
+                logger.log(Level.INFO, "{0} analysis of {1} (jobId={2}) finished", new Object[]{module.getDisplayName(), this.job.getDataSource().getName(), this.job.getDataSource().getId()});
             } catch (Throwable ex) { // Catch-all exception firewall
                 errors.add(new IngestModuleError(module.getDisplayName(), ex));
             }

Core/src/org/sleuthkit/autopsy/ingest/IngestJob.java

@@ -1,7 +1,7 @@
 /*
  * Autopsy Forensic Browser
  * 
- * Copyright 2014 Basis Technology Corp.
+ * Copyright 2014-2015 Basis Technology Corp.
  * Contact: carrier <at> sleuthkit <dot> org
  * 
  * Licensed under the Apache License, Version 2.0 (the "License");
@@ -41,6 +41,7 @@ public final class IngestJob {
     private final long id;
     private final Map<Long, DataSourceIngestJob> dataSourceJobs;
     private final AtomicInteger incompleteJobsCount;
+    private boolean started;  // Guarded by this
     private volatile boolean cancelled;
 
     /**
@@ -92,8 +93,14 @@ public final class IngestJob {
      *
      * @return A collection of ingest module start up errors, empty on success.
      */
-    List<IngestModuleError> start() {
+    synchronized List<IngestModuleError> start() {
-        List<IngestModuleError> errors = new ArrayList<>();
+        List<IngestModuleError> errors = new ArrayList<>();        
+        if (started) {
+            errors.add(new IngestModuleError("IngestJob", new IllegalStateException("Job already started")));
+            return errors;
+        }
+        started = true;
+                
         for (DataSourceIngestJob dataSourceJob : this.dataSourceJobs.values()) {
             errors.addAll(dataSourceJob.start());
             if (!errors.isEmpty()) {
@@ -117,7 +124,7 @@ public final class IngestJob {
 
         return errors;
     }
-
+    
     /**
      * Gets a snapshot of the progress of this ingest job.
      *

Core/src/org/sleuthkit/autopsy/ingest/IngestManager.java

@@ -367,7 +367,6 @@ public class IngestManager {
         if (this.jobCreationIsEnabled) {
             IngestJob job = new IngestJob(dataSources, settings, this.runInteractively);
             if (job.hasIngestPipeline()) {
-                this.jobsById.put(job.getId(), job);
                 long taskId = nextThreadId.incrementAndGet();
                 Future<Void> task = startIngestJobsThreadPool.submit(new IngestJobStarter(taskId, job));
                 ingestJobStarters.put(taskId, task);
@@ -386,7 +385,6 @@ public class IngestManager {
         if (this.jobCreationIsEnabled) {
             IngestJob job = new IngestJob(dataSources, settings, this.runInteractively);
             if (job.hasIngestPipeline()) {
-                this.jobsById.put(job.getId(), job);
                 if (this.startIngestJob(job)) {
                     return job;
                 }
@@ -403,9 +401,11 @@ public class IngestManager {
      */
     private boolean startIngestJob(IngestJob job) {
         boolean success = false;
-
         if (this.jobCreationIsEnabled) {
-            if (runInteractively && jobsById.isEmpty()) {
+            /**
+             * TODO: This is not really reliable.
+             */
+            if (runInteractively && jobsById.size() == 1) {
                 clearIngestMessageBox();
             }
 
@@ -413,6 +413,13 @@ public class IngestManager {
                 ingestMonitor.start();
             }
 
+            /**
+             * Add the job to the jobs map now so that isIngestRunning() will
+             * return true while the modules read global settings during start
+             * up. This works because the core global settings panels restrict
+             * changes while analysis is in progress.
+             */
+            this.jobsById.put(job.getId(), job);
             List<IngestModuleError> errors = job.start();
             if (errors.isEmpty()) {
                 this.fireIngestJobStarted(job.getId());
@@ -420,6 +427,9 @@ public class IngestManager {
                 success = true;
             } else {
                 this.jobsById.remove(job.getId());
+                for (IngestModuleError error : errors) {
+                    logger.log(Level.SEVERE, String.format("Error starting %s ingest module", error.getModuleDisplayName()), error.getModuleError()); //NON-NLS
+                }
                 IngestManager.logger.log(Level.INFO, "Ingest job {0} could not be started", job.getId()); //NON-NLS
                 if (this.runInteractively) {
                     EventQueue.invokeLater(new Runnable() {
@@ -452,8 +462,6 @@ public class IngestManager {
                     });
                 }
             }
-        } else {
-            this.jobsById.remove(job.getId());
         }
         return success;
     }
@@ -488,7 +496,9 @@ public class IngestManager {
             handle.cancel(true);
         }
 
-        // Cancel all the jobs already created.
+        // Cancel all the jobs already created. Force a stack trace for the log
+        // message.
+        logger.log(Level.INFO, "Cancelling all ingest jobs", new Exception("Cancelling all ingest jobs"));
         for (IngestJob job : this.jobsById.values()) {
             job.cancel();
         }