Add python logging, catch unhandled exceptions, configurable virtualenv

predict.py

@@ -10,6 +10,7 @@ import math
 import sys
 import os
 import logging
+import traceback
 import calendar
 import optparse
 import subprocess
@@ -32,8 +33,9 @@ pydap.util.http.httplib2._entry_disposition = fresh
 
 # Output logger format
 log = logging.getLogger('main')
+log_formatter = logging.Formatter('%(levelname)s: %(message)s')
 console = logging.StreamHandler()
-console.setFormatter(logging.Formatter('%(levelname)s: %(message)s'))
+console.setFormatter(log_formatter)
 log.addHandler(console)
 
 progress_f = ''
@@ -45,7 +47,7 @@ progress = {
     'gfs_timestamp': '',
     'pred_running': False,
     'pred_complete': False,
-    'progress_error': '',
+    'error': '',
     }
 
 def update_progress(**kwargs):
@@ -77,6 +79,8 @@ def main():
             help='detach the process and run in the background')
     parser.add_option('--alarm', dest='alarm', action="store_true",
             help='setup an alarm for 10 minutes time to prevent hung processes')
+    parser.add_option('--log', dest='log_target',
+            help='file to log debugging messages to', metavar='FILE')
     parser.add_option('-t', '--timestamp', dest='timestamp',
         help='search for dataset covering the POSIX timestamp TIME \t[default: now]', 
         metavar='TIME', type='int',
@@ -135,6 +139,12 @@ def main():
 
     (options, args) = parser.parse_args()
 
+    # Setup log as soon as possible
+    if options.log_target:
+        log_target = logging.FileHandler(options.log_target)
+        log_target.setFormatter(log_formatter)
+        log.addHandler(log_target)
+
     # Check we got a UUID in the arguments
     if len(args) != 1:
         log.error('Exactly one positional argument should be supplied (uuid).')
@@ -219,7 +229,7 @@ def main():
     try:
         dataset = dataset_for_time(time_to_find, options.hd)
     except:
-        print('Could not locate a dataset for the requested time.')
+        log.error('Could not locate a dataset for the requested time.')
         sys.exit(1)
 
     dataset_times = map(timestamp_to_datetime, dataset.time)
@@ -254,7 +264,7 @@ def main():
     else:
         alarm_flags = []
 
-    subprocess.call([pred_binary, '-i/var/www/hab/predict/gfs/', '-v', '-o'+uuid_path+'flight_path.csv', uuid_path+'scenario.ini'] + alarm_flags)
+    subprocess.call([pred_binary, '-i/var/www/cusf-standalone-predictor/gfs/', '-v', '-o'+uuid_path+'flight_path.csv', uuid_path+'scenario.ini'] + alarm_flags)
 
     update_progress(pred_running=False, pred_complete=True)
 
@@ -350,9 +360,7 @@ def write_file(output_format, data, window, mintime, maxtime):
             downloaded_data[var] = selection
 
             log.info('   Downloaded data has shape %s...', selection.shape)
-            if len(selection.shape) != 3:
-                log.error('    Expected 3-d data.')
-                return
+            assert len(selection.shape) == 3
 
             now = datetime.datetime.now()
             time_elapsed = now - starttime
@@ -562,5 +570,18 @@ def setup_alarm():
 
 # If this is being run from the interpreter, run the main function.
 if __name__ == '__main__':
-    main()
-
+    try:
+        main()
+    except SystemExit as e:
+        log.debug("Caught: " + repr(e))
+        if e.code != 0 and progress_f:
+            update_progress(error="Unknown error exit")
+        raise
+    except Exception as e:
+        log.exception("Uncaught exception")
+        (exc_type, exc_value, discard_tb) = sys.exc_info()
+        exc_tb = traceback.format_exception_only(exc_type, exc_value)
+        info = exc_tb[-1].strip()
+        if progress_f:
+            update_progress(error="Unhandled exception: " + info)
+        raise

predict/includes/config.inc.php

@@ -8,12 +8,12 @@ define("ADMIN_EMAIL", "jon@hexoc.com");
 
 define("LOCATION_SAVE_ENABLE", true);
 
-define("DEBUG", true);
-define("AT_LOG", "/tmp/pred_log");
-
 // Path to the root of the git repo inc. trailing /
 define("ROOT", "/var/www/hab/predict/");
 
+// Path to python virtualenv to use
+// define("PYTHON", ROOT . "ENV/bin/python");
+
 // Path to prediction data dir from predict/
 define("PREDS_PATH", "preds/");
 
@@ -21,5 +21,6 @@ define("PREDS_PATH", "preds/");
 define("SCENARIO_FILE", "scenario.ini");
 define("FLIGHT_CSV", "flight_path.csv");
 define("PROGRESS_JSON", "progress.json");
+define("LOG_FILE", "py_log");
 
 ?>

predict/includes/functions.inc.php

@@ -134,12 +134,16 @@ function runPred($pred_model) {
     $predictor_lat = number_format($pred_model['lat'], 0);
     $predictor_lon = number_format($pred_model['lon'], 0);
 
-    $sh = ROOT . "/predict.py --cd=" . ROOT . " --fork --alarm -v --latdelta="
+    $log = PREDS_PATH . $pred_model['uuid'] . "/" . LOG_FILE;
+    $sh = ROOT . "/predict.py --cd=" . ROOT . " --fork --alarm --log=$log -v --latdelta="
         .$pred_model['delta_lat']." --londelta=".$pred_model['delta_lon']
         ." -p1 -f5 -t ".$pred_model['timestamp']
         ." --lat=".$predictor_lat." --lon=".$predictor_lon." " . $use_hd
         . $pred_model['uuid'];
-    file_put_contents(PREDS_PATH . $pred_model['uuid'] . "/" . LOG_FILE, "Command: " . $sh . "\n");
+    if (defined("PYTHON"))
+        $sh = PYTHON . " " . $sh;
+
+    file_put_contents($log, "Command: " . $sh . "\n");
     shell_exec($sh);
 }