- use logging instead of print

- updated correction code to use recommended subprocess.run() from python 3.5 - remove exit() calls so that the server will not terminate

- use logging instead of print
- updated correction code to use recommended subprocess.run() from python 3.5 - remove exit() calls so that the server will not terminate
Miguel Barão
1 parent acf93255
Showing 1 changed file with 98 additions and 77 deletions Show diff stats
questions.py
@@ -32,10 +32,32 @@ import yaml
 import random
 import re
 import subprocess
-import sys
 import os.path
+import logging
+qlogger = logging.getLogger('Questions')
+qlogger.setLevel(logging.INFO)
+
+fh = logging.FileHandler('question.log')
+ch = logging.StreamHandler()
+ch.setLevel(logging.INFO)
+
+formatter = logging.Formatter('%(asctime)s | %(name)s | %(levelname)s | %(message)s')
+fh.setFormatter(formatter)
+ch.setFormatter(formatter)
+
+qlogger.addHandler(fh)
+qlogger.addHandler(ch)
+
+# if an error occurs in a question, the question is replaced by this message
+qerror = {
+    'filename': 'questions.py',
+    'ref': '__error__',
+    'type': 'warning',
+    'text': 'An error occurred while generating this question.'
+    }
+
 # ===========================================================================
 class QuestionsPool(dict):
     '''This class contains base questions read from files, but which are
@@ -46,43 +68,42 @@ class QuestionsPool(dict):
         # add some defaults if missing from sources
         for i, q in enumerate(questions):
             if not isinstance(q, dict):
-                print('[ WARNG ]  Question with index {0} in file {1} is not a dict. Ignoring...'.format(i, filename))
+                qlogger.error('Question index {0} from file {1} is not a dictionary. Skipped...'.format(i, filename))
                 continue
             if q['ref'] in self:
-                print('[ ERROR ]  Duplicate question "{0}" in files "{1}" and "{2}".'.format(q['ref'], filename, self[q['ref']]['filename']))
-                sys.exit(1)
-
-            # filename and index (number in the file, 0 based)
-            q['filename'] = filename
-            q['path'] = path
-            q['index'] = i
-
-            # ref  (if missing, add 'filename.yaml:3')
-            q['ref'] = str(q.get('ref', filename + ':' + str(i)))
-
-            # type  (default type is 'information')
-            q['type'] = str(q.get('type', 'information'))
+                qlogger.error('Duplicate question "{0}" in files "{1}" and "{2}". Skipped...'.format(q['ref'], filename, self[q['ref']]['filename']))
+                continue
-            # optional title (default empty string)
-            q['title'] = str(q.get('title', ''))
+            # index is the position in the questions file, 0 based
+            q.update({
+                'filename': filename,
+                'path': path,
+                'index': i
+                })
+            q.setdefault('ref', filename + ':' + str(i)) # 'filename.yaml:3'
+            q.setdefault('type', 'information')
             # add question to the pool
             self[q['ref']] = q
+            qlogger.debug('Added question "{0}" to the pool.'.format(q['ref']))
     #------------------------------------------------------------------------
     def add_from_files(self, files, path='.'):
+        '''Given a list of YAML files, reads them all and tries to add
+        questions to the pool.'''
         for filename in files:
             try:
                 with open(os.path.normpath(os.path.join(path, filename)), 'r', encoding='utf-8') as f:
                     questions = yaml.load(f)
             except(FileNotFoundError):
-                print('[ ERROR ]  Questions file "{0}" not found.'.format(filename))
+                qlogger.error('Questions file "{0}" not found. Skipping this one.'.format(filename))
                 continue
             except(yaml.parser.ParserError):
-                print('[ ERROR ] Error loading questions in YAML file "{0}".'.format(filename))
+                qlogger.error('Error loading questions from YAML file "{0}". Skipping this one.'.format(filename))
                 continue
             self.add(questions, filename, path)
+            qlogger.info('Added {0} questions from "{1}" to the pool.'.format(len(questions), filename))
 #============================================================================
@@ -97,13 +118,6 @@ def create_question(q):
     The remaing keys depend on the type of question.
     '''
-    # If `q` is of a question generator type, an external program will be run
-    # and expected to print a valid question in yaml format to stdout. This
-    # output is then converted to a dictionary and `q` becomes that dict.
-    if q['type'] == 'generator':
-        q.update(question_generator(q))
-    # At this point the generator question was replaced by an actual question.
-
     # Depending on the type of question, a different question class is
     # instantiated. All these classes derive from the base class `Question`.
     types = {
@@ -111,28 +125,33 @@ def create_question(q):
         'checkbox'  : QuestionCheckbox,
         'text'      : QuestionText,
         'text_regex': QuestionTextRegex,
-        # 'text-regex': QuestionTextRegex,
-        # 'regex'     : QuestionTextRegex,
         'textarea'  : QuestionTextArea,
         'information': QuestionInformation,
         'warning'   : QuestionInformation,
-        # 'info'      : QuestionInformation,
-        # ''          : QuestionInformation,  # default
     }
+
+    # If `q` is of a question generator type, an external program will be run
+    # and expected to print a valid question in yaml format to stdout. This
+    # output is then converted to a dictionary and `q` becomes that dict.
+    if q['type'] == 'generator':
+        qlogger.debug('Generating question "{0}"...'.format(q['ref']))
+        q.update(question_generator(q))
+    # At this point the generator question was replaced by an actual question.
+
     # Get the correct question class for the declared question type
     try:
         questiontype = types[q['type']]
     except KeyError:
-        print('[ ERROR ]  Unsupported question type "{0}" in "{1}:{2}".'.format(q['type'], q['filename'], q['ref']))
-        questiontype = Question
+        qlogger.error('Unsupported question type "{0}" in "{1}:{2}".'.format(q['type'], q['filename'], q['ref']))
+        questiontype, q = QuestionWarning, qerror
     # Create question instance and return
     try:
         qinstance = questiontype(q)
     except:
-        print('[ ERROR ]  Creating question "{0}" from file "{1}".'.format(q['ref'], q['filename']))
-        # FIXME if here, then no qinstance is defined to return...
+        qlogger.error('Could not create question "{0}" from file "{1}".'.format(q['ref'], q['filename']))
+        qinstance = QuestionInformation(qerror)
     return qinstance
@@ -142,35 +161,47 @@ def question_generator(q):
     '''Run an external program that will generate a question in yaml format.
     This function will return the yaml converted back to a dict.'''
-    q['arg'] = q.get('arg', '')  # send this string to stdin
+    q.setdefault('arg', '')   # will be sent to stdin
     script = os.path.abspath(os.path.normpath(os.path.join(q['path'], q['script'])))
     try:
         p = subprocess.Popen([script], stdout=subprocess.PIPE, stdin=subprocess.PIPE, stderr=subprocess.STDOUT)
     except FileNotFoundError:
-        print('[ ERROR ]  Script "{0}" of question "{2}:{1}" not found'.format(script, q['ref'], q['filename']))
-        sys.exit(1)
+        qlogger.error('Script "{0}" of question "{2}:{1}" not found'.format(script, q['ref'], q['filename']))
+        return qerror
     except PermissionError:
-        print('[ ERROR ]  Script "{0}" of question "{2}:{1}" has wrong permissions. Is it executable?'.format(script, q['ref'], q['filename']))
-        sys.exit(1)
+        qlogger.error('Script "{0}" has wrong permissions. Is it executable?'.format(script, q['ref'], q['filename']))
+        return qerror
     try:
         qyaml = p.communicate(input=q['arg'].encode('utf-8'), timeout=5)[0].decode('utf-8')
     except subprocess.TimeoutExpired:
         p.kill()
-        print('[ ERROR ]  Timeout on script "{0}" of question "{2}:{1}"'.format(script, q['ref'], q['filename']))
-        sys.exit(1)
+        qlogger.error('Timeout on script "{0}" of question "{2}:{1}"'.format(script, q['ref'], q['filename']))
+        return qerror
     return yaml.load(qyaml)
 # ===========================================================================
+# Questions derived from Question are already instantiated and ready to be
+# presented to students.
+# ===========================================================================
 class Question(dict):
     '''
     Classes derived from this base class are meant to instantiate a question
     to a student.
     Instances can shuffle options, or automatically generate questions.
     '''
+    def __init__(self, q):
+        super().__init__(q)
+
+        # these are mandatory for any question:
+        self.set_defaults({
+            'title': '',
+            'answer': None,
+            })
+
     def correct(self):
         self['grade'] = 0.0
         return 0.0
@@ -204,7 +235,6 @@ class QuestionRadio(Question):
             'correct': 0,
             'shuffle': True,
             'discount': True,
-            'answer': None,
             })
         n = len(self['options'])
@@ -215,7 +245,7 @@ class QuestionRadio(Question):
             self['correct'] = [1.0 if x==self['correct'] else 0.0 for x in range(n)]
         if len(self['correct']) != n:
-            print('[ ERROR ]  Options and correct mismatch in "{1}", file "{0}".'.format(self['filename'], self['ref']))
+            qlogger.error('Options and correct mismatch in "{1}", file "{0}".'.format(self['filename'], self['ref']))
         # generate random permutation, e.g. [2,1,4,0,3]
         # and apply to `options` and `correct`
@@ -266,11 +296,10 @@ class QuestionCheckbox(Question):
             'correct': [0.0] * n,     # useful for questionaries
             'shuffle': True,
             'discount': True,
-            'answer': None,
             })
         if len(self['correct']) != n:
-            print('[ ERROR ]  Options and correct mismatch in "{1}", file "{0}".'.format(self['filename'], self['ref']))
+            qlogger.error('Options and correct mismatch in "{1}", file "{0}".'.format(self['filename'], self['ref']))
         # generate random permutation, e.g. [2,1,4,0,3]
         # and apply to `options` and `correct`
@@ -280,7 +309,6 @@ class QuestionCheckbox(Question):
             self['options'] = [ str(self['options'][i]) for i in perm ]
             self['correct'] = [ float(self['correct'][i]) for i in perm ]
-
     #------------------------------------------------------------------------
     # can return negative values for wrong answers
     def correct(self):
@@ -325,7 +353,6 @@ class QuestionText(Question):
         self.set_defaults({
             'text': '',
             'correct': [],
-            'answer': None,
             })
         # make sure its always a list of possible correct answers
@@ -365,7 +392,6 @@ class QuestionTextRegex(Question):
         self.set_defaults({
             'text': '',
             'correct': '$.^',   # will always return false
-            'answer': None,
             })
     #------------------------------------------------------------------------
@@ -398,8 +424,8 @@ class QuestionTextArea(Question):
         self.set_defaults({
             'text': '',
-            'answer': None,
             'lines': 8,
+            'timeout': 5,  # seconds
             })
         self['correct'] = os.path.abspath(os.path.normpath(os.path.join(self['path'], self['correct'])))
@@ -412,37 +438,32 @@ class QuestionTextArea(Question):
             self['grade'] = 0.0
         else:
             # answered
-
-            # The correction program expects data from stdin and prints the result to stdout.
-            # The result should be a string that can be parsed to a float.
             try:
-                p = subprocess.Popen([self['correct']],
+                p = subprocess.run([self['correct']],
+                    input=self['answer'],
                     stdout=subprocess.PIPE,
-                    stdin=subprocess.PIPE,
-                    stderr=subprocess.STDOUT)
-            except FileNotFoundError as e:
-                print('[ ERROR ]  Script "{0}" defined in question "{1}" of file "{2}" could not be found'.format(self['correct'], self['ref'], self['filename']))
-                raise e
-            except PermissionError as e:
-                print('[ ERROR ]  Script "{0}" has wrong permissions. Is it executable?'.format(self['correct']))
-                raise e
-
-            try:
-                value = p.communicate(input=self['answer'].encode('utf-8'), timeout=5)[0].decode('utf-8')
+                    stderr=subprocess.STDOUT,
+                    universal_newlines=True,
+                    timeout=self['timeout'],
+                    )
+            except FileNotFoundError:
+                qlogger.error('Script "{0}" defined in question "{1}" of file "{2}" could not be found.'.format(self['correct'], self['ref'], self['filename']))
+                self['grade'] = 0.0
+            except PermissionError:
+                qlogger.error('Script "{0}" has wrong permissions. Is it executable?'.format(self['correct']))
+                self['grade'] = 0.0
             except subprocess.TimeoutExpired:
-                p.kill()
-                value = 0.0  # student gets a zero if timout occurs
-                print('[ WARNG ]  Timeout in correction script "{0}"'.format(self['correct']))
+                qlogger.warning('Timeout {1}s exceeded while running "{0}"'.format(self['correct'], self['timeout']))
+                self['grade'] = 0.0  # student gets a zero if timout occurs
+            else:
+                if p.returncode != 0:
+                    qlogger.warning('Script "{0}" returned error code {1}.'.format(self['correct'], p.returncode))
-            # In case the correction program returns a non float value, we assume an error
-            # has occurred (for instance, invalid input). We just assume its the student's
-            # fault and give him Zero.
-            try:
-                self['grade'] = float(value)
-            except ValueError as e:
-                self['grade'] = 0.0
-                print('[ ERROR ]  Correction of question "{0}" returned nonfloat:\n{1}\n'.format(self['ref'], value))
-                raise e
+                try:
+                    self['grade'] = float(p.stdout)
+                except ValueError:
+                    qlogger.error('Correction script of "{0}" returned nonfloat:\n{1}\n'.format(self['ref'], p.stdout))
+                    self['grade'] = 0.0
         return self['grade']
@@ -468,5 +489,5 @@ class QuestionInformation(Question):
     #------------------------------------------------------------------------
     # can return negative values for wrong answers
     def correct(self):
-        self['grade'] = 0.0  # always "correct" but points should be zero!
+        self['grade'] = 1.0  # always "correct" but points should be zero!
         return self['grade']