Adds logging configuration and use.

Author: wilkie

README.md

@@ -20,6 +20,11 @@ starting point. Then set the `OPENAI_API_KEY` variable to a valid OpenAI API key
 enable that service. Or, otherwise set that variable the appropriate way when
 deploying the service.
 
+To control the logging information, use the `LOG_LEVEL` configuration parameter. Set
+to `DEBUG`, `INFO`, `WARNING`, `ERROR`, or `CRITICAL`. The `DEBUG` setting is the
+most permissive and shows all logging text. The `CRITICAL` prevents most logging
+from happening. Most logging happens at `INFO`, which is the default setting.
+
 ## Local Development
 
 All of our server code is written using [Flask](https://flask.palletsprojects.com/en/2.3.x/).

config.txt.sample

@@ -1 +1,2 @@
 OPENAI_API_KEY=
+LOG_LEVEL=INFO

lib/assessment/assess.py

@@ -4,6 +4,7 @@
 import concurrent.futures
 import io
 import json
+import logging
 
 # Import our support classes
 from lib.assessment.config import SUPPORTED_MODELS, VALID_GRADES
@@ -32,10 +33,10 @@ def grade(code, prompt, rubric, api_key='', llm_model='gpt-4', num_responses=1,
   if OPENAI_API_KEY:
     os.environ['OPENAI_API_KEY'] = OPENAI_API_KEY
   elif not 'OPENAI_API_KEY' in os.environ:
-    print("Must set OPENAI_API_KEY!")
+    logging.error("Must set OPENAI_API_KEY!")
     return {}
   else:
-    print("Using set OPENAI_API_KEY")
+    logging.info("Using set OPENAI_API_KEY")
 
   grade = Grade()
   return grade.grade_student_work(

lib/assessment/grade.py

@@ -3,6 +3,7 @@
 import csv
 import time
 import requests
+import logging
 
 from typing import List, Dict, Any
 from lib.assessment.config import VALID_GRADES
@@ -42,18 +43,18 @@ def grade_student_work(self, prompt, rubric, student_code, student_id, examples=
         try:
             response = requests.post(api_url, headers=headers, json=data, timeout=120)
         except requests.exceptions.ReadTimeout:
-            print(f"{student_id} request timed out in {(time.time() - start_time):.0f} seconds.")
+            logging.error(f"{student_id} request timed out in {(time.time() - start_time):.0f} seconds.")
             return None
 
         if response.status_code != 200:
-            print(f"{student_id} Error calling the API: {response.status_code}")
-            print(f"{student_id} Response body: {response.text}")
+            logging.error(f"{student_id} Error calling the API: {response.status_code}")
+            logging.info(f"{student_id} Response body: {response.text}")
             return None
 
         info = response.json()
         tokens = info['usage']['total_tokens']
         elapsed = time.time() - start_time
-        print(f"{student_id} request succeeded in {elapsed:.0f} seconds. {tokens} tokens used.")
+        logging.info(f"{student_id} request succeeded in {elapsed:.0f} seconds. {tokens} tokens used.")
 
         tsv_data_choices = [self.get_tsv_data_if_valid(choice['message']['content'], rubric, student_id, choice_index=index) for index, choice in enumerate(info['choices']) if choice['message']['content']]
         tsv_data_choices = [choice for choice in tsv_data_choices if choice]
@@ -107,7 +108,7 @@ def compute_messages(self, prompt, rubric, student_code, examples=[]):
     def get_tsv_data_if_valid(self, response_text, rubric, student_id, choice_index=None):
         choice_text = f"Choice {choice_index}: " if choice_index is not None else ''
         if not response_text:
-            print(f"{student_id} {choice_text} Invalid response: empty response")
+            logging.error(f"{student_id} {choice_text} Invalid response: empty response")
             return None
         text = response_text.strip()
 
@@ -131,12 +132,12 @@ def get_tsv_data_if_valid(self, response_text, rubric, student_id, choice_index=
                 lines = text.split('\n')
                 lines = list(filter(lambda x: "---" not in x, lines))
                 text = "\n".join(lines)
-                print("response was markdown and not tsv, delimiting by '|'")
+                logging.info("response was markdown and not tsv, delimiting by '|'")
 
                 tsv_data = list(csv.DictReader(StringIO(text), delimiter='|'))
             else:
                 # Let's assume it is CSV
-                print("response had no tabs so is not tsv, delimiting by ','")
+                logging.info("response had no tabs so is not tsv, delimiting by ','")
                 tsv_data = list(csv.DictReader(StringIO(text), delimiter=','))
         else:
             # Let's assume it is TSV
@@ -147,7 +148,7 @@ def get_tsv_data_if_valid(self, response_text, rubric, student_id, choice_index=
             self.validate_server_response(tsv_data, rubric)
             return [row for row in tsv_data]
         except InvalidResponseError as e:
-            print(f"{student_id} {choice_text} Invalid response: {str(e)}\n{response_text}")
+            logging.error(f"{student_id} {choice_text} Invalid response: {str(e)}\n{response_text}")
             return None
 
     def parse_tsv(self, tsv_text):
@@ -210,7 +211,7 @@ def get_consensus_response(self, choices, student_id):
             majority_grade = Counter(grades).most_common(1)[0][0]
             key_concept_to_majority_grade[key_concept] = majority_grade
             if majority_grade != grades[0]:
-                print(f"outvoted {student_id} Key Concept: {key_concept} first grade: {grades[0]} majority grade: {majority_grade}")
+                logging.info(f"outvoted {student_id} Key Concept: {key_concept} first grade: {grades[0]} majority grade: {majority_grade}")
 
         key_concept_to_observations = {}
         key_concept_to_reason = {}

lib/assessment/rubric_tester.py

@@ -9,6 +9,7 @@
 from multiprocessing import Pool
 import concurrent.futures
 import io
+import logging
 
 from lib.assessment.config import SUPPORTED_MODELS, VALID_GRADES
 from lib.assessment.grade import Grade
@@ -194,7 +195,7 @@ def main():
     report.generate_html_output(
         output_file, prompt, rubric, overall_accuracy, actual_grades, expected_grades, options.passing_grades, accuracy_by_criteria, errors, command_line
     )
-    print(f"main finished in {int(time.time() - main_start_time)} seconds")
+    logging.info(f"main finished in {int(time.time() - main_start_time)} seconds")
 
     os.system(f"open {output_file}")
 

src/__init__.py

@@ -1,5 +1,8 @@
 # Main imports
-import os
+import os, sys
+
+# Logging
+import logging
 
 # Our modules
 from src.test import test_routes
@@ -33,6 +36,12 @@ def create_app(test_config=None):
     except OSError:
         pass
 
+    # Set up logging
+    log_level = os.getenv('LOG_LEVEL', 'INFO')
+    logging.basicConfig(format='%(asctime)s: %(name)s:%(message)s', level=log_level)
+    logging.log(100, f"Setting up application. Logging level={log_level}")
+    logging.basicConfig(format='%(asctime)s: %(levelname)s:%(name)s:%(message)s', level=log_level)
+
     # Index (a simple HTML response that will always succeed)
     @app.route('/')
     def root():