Add proper logging to QDoc bot

Change-Id: Ibf6374c5ebd0dd4fa8445f7bcd6092dbda442143
Reviewed-by: Frederik Gladhorn <frederik.gladhorn@digia.com>

git-hooks/qdoc-bot.py

@@ -27,6 +27,7 @@ import os
 import subprocess
 import sys
 import datetime
+import logging
 
 config = None # configuration object, it is initialized in main and passed to every worker process created by multiprocessing.Pool
 
@@ -95,7 +96,7 @@ def post_review(event, message, score):
     if len(message) > 0:
         command += "--message", "\"" + message + "\"",
     command += sha1,
-    print(command)
+    logging.debug(command)
     #if (event["change"]["number"] == '33219' or event["change"]["number"] == '33224'):
     subprocess.check_call(command)
 
@@ -105,7 +106,7 @@ def remove_moved_doc_errors(fixes, errors):
         if pos >= 0:
             begin = "+" + fix[1:pos]
             end = fix[fix.find(":", pos+1):]
-            print end
+            logging.debug(end)
             for i in range(len(errors)):
                 if errors[i].startswith(begin) and errors[i].endswith(end):
                     del errors[i]
@@ -124,10 +125,10 @@ def review_output(event, output_no_patch, output_with_patch):
         subject = event["change"]["subject"]
         new_error_count = output_with_patch.count("\n") - output_no_patch.count("\n")
         if new_error_count == 0:
-            print "NO DOC ERRORS: ", subject, url
+            logging.info("NO DOC ERRORS: %s, %s", subject, url)
             #post_review(event, "", 1)
             return 0
-        print "DIFF for:", subject, url
+        logging.debug("DIFF for %s: %s", subject, url)
         message = ""
         score = 0
         if new_error_count == 1:
@@ -159,11 +160,11 @@ def review_output(event, output_no_patch, output_with_patch):
             message += "New qdoc warnings:\n \n "
             message += new_errors
         message += "\n\nThis comment was generated by the qtdoc bot.\n\nPlease contact Jedrzej Nowacki (nierob) or Frederik Gladhorn (fregl) if you have questions or think the script gives you false positives."
-        print "Review result: " + message
+        logging.debug("Review result: %s", message)
         post_review(event, message, score)
         return score
     except:
-        print "Unexpected error:", sys.exc_info()
+        logging.error("Unexpected error: %s", sys.exc_info())
 
 
 def fetch_change(project, patch_set, change_number):
@@ -181,14 +182,14 @@ def fetch_change(project, patch_set, change_number):
             except subprocess.CalledProcessError, e:
                 # Try to fetch again - one problem is that running git fetch will fail if run simultaneously
                 num_tries += 1
-                print "Fetching subprocess failed, trying again: ", e
+                logging.warn("Fetching subprocess failed, trying again: %s", e)
                 import time
                 time.sleep(30)
                 if num_tries > 11:
                     raise e
 
     except subprocess.CalledProcessError, e:
-        print "Fetching subprocess failed too many times: ", e
+        logging.error("Fetching subprocess failed too many times: %s", e)
         return -1
 
 
@@ -204,8 +205,7 @@ def process_event(event_string):
     try:
         event = json.loads(event_string)
     except ValueError, e:
-        print event_string
-        print "JSON loading problem:", e
+        logging.error("JSON loading problem: %s\nJSON data: %s", e, event_string)
         return -1
 
     if event["type"] != "patchset-created":
@@ -218,17 +218,17 @@ def process_event(event_string):
 
     module_name = project.split('/')[-1]
     if module_name != "qtbase": # TODO for now we care only about qtbase
-        print "IGNORED MODULE: ", module_name, patch_set, datetime.datetime.now().isoformat()
+        logging.info("IGNORED MODULE: %s %s", module_name, patch_set)
         return 0
 
-    print "MODULE NAME:", module_name, patch_set, datetime.datetime.now().isoformat()
+    logging.info("MODULE NAME: %s %s", module_name, patch_set)
 
     source_path = config.watcher_working_dir + "/" + project
     try:
         os.chdir(source_path)
     except OSError, e:
-        print "Unknown project, TODO write code to initialize it, error message:", e #TODO for know you need to have qt/qtbase checkout ready
-        print "Current dir was:", os.getcwd()
+        logging.error("Unknown project, TODO write code to initialize it, error message: %s", e) #TODO for know you need to have qt/qtbase checkout ready
+        logging.debug("Current dir was: %s", os.getcwd())
         return -1
 
     if fetch_change(project, patch_set, change_number) != 0:
@@ -237,7 +237,7 @@ def process_event(event_string):
     try:
         #make own copy
         tmp_dir = tempfile.mkdtemp(prefix="qdoc_")
-        print("CREATING TMP DIR:", tmp_dir)
+        logging.info("CREATING TMP DIR: %s", tmp_dir)
         try:
             os.chdir(tmp_dir)
 
@@ -259,16 +259,16 @@ def process_event(event_string):
 
             output_no_patch = run_qdoc(module_name)
 
-            print "DONE RUNNING QDOC"
+            logging.info("DONE RUNNING QDOC")
             return review_output(event, output_no_patch, output_with_patch)
 
         finally:
             # TODO reuse tmp dir
-            print "REMOVING TMP DIR " + tmp_dir
+            logging.info("REMOVING TMP DIR: %s", tmp_dir)
             shutil.rmtree(tmp_dir)
-            print "WORKER EXECUTION TIME: ", time.time() - start_time
+            logging.debug("WORKER EXECUTION TIME: %s", time.time() - start_time)
     except subprocess.CalledProcessError, e:
-        print("QDoc sanity failed because of an internal error:", str(e))
+        logging.error("QDoc sanity failed because of an internal error: %s", e)
         return -1
 
 
@@ -277,7 +277,7 @@ def watcher():
         try:
             ssh = subprocess.Popen(["ssh", config.gerrit_address, "gerrit", "stream-events"], stdout=subprocess.PIPE)
             import multiprocessing
-            print "WATCHER " + datetime.datetime.now().isoformat()
+            logging.info("STARTING WATCHER")
             def multiprocess_config_assign(c):
                 config = c
             processPool = multiprocessing.Pool(processes=config.workers_count,
@@ -295,7 +295,7 @@ def watcher():
                 event_string = ssh.stdout.readline()
         except:
             # an error occured let's restart in 15 sec
-            print "WATCHER RESTART" + datetime.datetime.now().isoformat(), sys.exc_info()
+            logging.critical("WATCHER RESTART because of: %s", sys.exc_info())
             import time
             time.sleep(15)
 
@@ -324,5 +324,13 @@ if __name__== "__main__":
                    metavar="/home/user/dev/qdoc-watcher",
                    required=True,
                    help='Set working directory which contains all neccessery checkouts')
+    parser.add_argument('--log-level',
+                   type=str,
+                   dest="logging_level",
+                   choices=["debug", "info", "warning", "error", "critical"],
+                   default="INFO",
+                   help='Set verbose level')
+
     args = parser.parse_args(namespace=config)
+    logging.basicConfig(format='(PID: %(process)d) %(asctime)s %(levelname)s: %(message)s', level=getattr(logging, config.logging_level.upper(), None))
     watcher()