From 2b709b19d9a93a1f83d4605e81509bdb38367489 Mon Sep 17 00:00:00 2001 From: Miguel Barão Date: Tue, 16 Jul 2019 16:44:02 +0100 Subject: [PATCH] fixed several errors in logging and updated messages all tornado code moved to serve.py disallowed topic restart (avoid regenerating questions) --- aprendizations/learnapp.py | 12 +++++------- aprendizations/main.py | 98 +++++++++++++++++++++++++++----------------------------------------------------------------------- aprendizations/questions.py | 6 +++--- aprendizations/serve.py | 72 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++------- aprendizations/student.py | 28 ++++++++++++++-------------- config/logger-debug.yaml | 11 ++++++++--- config/logger.yaml | 9 +++++++-- 7 files changed, 129 insertions(+), 107 deletions(-) diff --git a/aprendizations/learnapp.py b/aprendizations/learnapp.py index cf81899..244cee5 100644 --- a/aprendizations/learnapp.py +++ b/aprendizations/learnapp.py @@ -79,7 +79,7 @@ class LearnApp(object): errors = 0 for qref in self.factory: - logger.debug(f'[sanity_check_questions] Checking "{qref}"...') + logger.debug(f'checking {qref}...') try: q = self.factory[qref].generate() except Exception: @@ -208,7 +208,7 @@ class LearnApp(object): finishtime=str(q['finish_time']), student_id=uid, topic_id=topic)) - logger.debug(f'[check_answer] Saved "{q["ref"]}" into database') + logger.debug(f'db insert answer of {q["ref"]}') if knowledge.topic_has_finished(): # finished topic, save into database @@ -222,7 +222,7 @@ class LearnApp(object): .one_or_none() if a is None: # insert new studenttopic into database - logger.debug('[check_answer] Database insert studenttopic') + logger.debug('db insert studenttopic') t = s.query(Topic).get(topic) u = s.query(Student).get(uid) # association object @@ -231,14 +231,12 @@ class LearnApp(object): u.topics.append(a) else: # update studenttopic in database - logger.debug('[check_answer] Database update studenttopic') + logger.debug(f'db update studenttopic to level {level}') a.level = level a.date = date s.add(a) - logger.debug(f'[check_answer] Saved topic "{topic}" into database') - return q, action # ------------------------------------------------------------------------ @@ -347,7 +345,7 @@ class LearnApp(object): # Buils dictionary of question factories # ------------------------------------------------------------------------ def make_factory(self) -> Dict[str, QFactory]: - logger.info('Building questions factory...') + logger.info('Building questions factory:') factory = {} # {'qref': QFactory()} g = self.deps for tref in g.nodes(): diff --git a/aprendizations/main.py b/aprendizations/main.py index c238bf8..71b1557 100644 --- a/aprendizations/main.py +++ b/aprendizations/main.py @@ -4,34 +4,17 @@ import argparse import logging from os import environ, path -import signal import ssl import sys -# third party libraries -import tornado - # this project from .learnapp import LearnApp, DatabaseUnusableError -from .serve import WebApplication +from .serve import run_webserver from .tools import load_yaml from . import APP_NAME, APP_VERSION # ---------------------------------------------------------------------------- -# Signal handler to catch Ctrl-C and abort server -# ---------------------------------------------------------------------------- -def signal_handler(signal, frame): - r = input(' --> Stop webserver? (yes/no) ').lower() - if r == 'yes': - tornado.ioloop.IOLoop.current().stop() - logging.critical('Webserver stopped.') - sys.exit(0) - else: - logging.info('Abort canceled...') - - -# ---------------------------------------------------------------------------- def parse_cmdline_arguments(): argparser = argparse.ArgumentParser( description='Server for online learning. Students and topics ' @@ -91,7 +74,7 @@ def get_logger_config(debug=False): 'version': 1, 'formatters': { 'standard': { - 'format': '%(asctime)s | %(levelname)-10s | %(message)s', + 'format': '%(asctime)s | %(levelname)-8s | %(message)s', 'datefmt': '%Y-%m-%d %H:%M:%S', }, }, @@ -115,14 +98,14 @@ def get_logger_config(debug=False): 'handlers': ['default'], 'level': level, 'propagate': False, - } for module in ['learnapp', 'models', 'factory', 'questions', - 'knowledge', 'tools']}) + } for module in ['learnapp', 'models', 'factory', 'tools', 'serve', + 'questions', 'student']}) return load_yaml(config_file, default=default_config) # ---------------------------------------------------------------------------- -# Tornado web server +# Start application and webserver # ---------------------------------------------------------------------------- def main(): # --- Commandline argument parsing @@ -144,34 +127,6 @@ def main(): logging.info('====================== Start Logging ======================') - # --- start application - logging.info('Starting App...') - try: - learnapp = LearnApp(arg.conffile, prefix=arg.prefix, db=arg.db, - check=arg.check) - except DatabaseUnusableError: - logging.critical('Failed to start application.') - print('--------------------------------------------------------------') - print('Could not find a usable database. Use one of the follwing ') - print('commands to initialize: ') - print(' ') - print(' initdb-aprendizations --admin # add admin ') - print(' initdb-aprendizations -a 86 "Max Smart" # add student ') - print(' initdb-aprendizations students.csv # add many students') - print('--------------------------------------------------------------') - sys.exit(1) - except Exception: - logging.critical('Failed to start application.') - sys.exit(1) - - # --- create web application - logging.info('Starting Web App (tornado)...') - try: - webapp = WebApplication(learnapp, debug=arg.debug) - except Exception: - logging.critical('Failed to start web application.') - sys.exit(1) - # --- get SSL certificates if 'XDG_DATA_HOME' in environ: certs_dir = path.join(environ['XDG_DATA_HOME'], 'certs') @@ -197,34 +152,35 @@ def main(): print(' ') print(f' {certs_dir:<62}') print(' ') + print('(See README.md for more information) ') print('--------------------------------------------------------------') sys.exit(1) + else: + logging.info('SSL certificates loaded') - # --- create webserver + # --- start application try: - httpserver = tornado.httpserver.HTTPServer(webapp, ssl_options=ssl_ctx) - except ValueError: - logging.critical('Certificates cert.pem and privkey.pem not found') + learnapp = LearnApp(arg.conffile, prefix=arg.prefix, db=arg.db, + check=arg.check) + except DatabaseUnusableError: + logging.critical('Failed to start application.') + print('--------------------------------------------------------------') + print('Could not find a usable database. Use one of the follwing ') + print('commands to initialize: ') + print(' ') + print(' initdb-aprendizations --admin # add admin ') + print(' initdb-aprendizations -a 86 "Max Smart" # add student ') + print(' initdb-aprendizations students.csv # add many students') + print('--------------------------------------------------------------') sys.exit(1) - - try: - httpserver.listen(arg.port) - except OSError: - logging.critical(f'Cannot bind port {arg.port}. Already in use?') + except Exception: + logging.critical('Failed to start application.') sys.exit(1) + else: + logging.info('Backend application started') - logging.info(f'Listening on port {arg.port}.') - - # --- run webserver - signal.signal(signal.SIGINT, signal_handler) - logging.info('Webserver running. (Ctrl-C to stop)') - - try: - tornado.ioloop.IOLoop.current().start() # running... - except Exception: - logging.critical('Webserver stopped.') - tornado.ioloop.IOLoop.current().stop() - raise + # --- run webserver forever + run_webserver(app=learnapp, ssl=ssl_ctx, port=arg.port, debug=arg.debug) # ---------------------------------------------------------------------------- diff --git a/aprendizations/questions.py b/aprendizations/questions.py index 8ac5bec..9125696 100644 --- a/aprendizations/questions.py +++ b/aprendizations/questions.py @@ -461,7 +461,7 @@ class QFactory(object): # i.e. a question object (radio, checkbox, ...). # ----------------------------------------------------------------------- def generate(self) -> Question: - logger.debug(f'[QFactory.generate] "{self.question["ref"]}"...') + logger.debug(f'generating {self.question["ref"]}...') # Shallow copy so that script generated questions will not replace # the original generators q = self.question.copy() @@ -492,7 +492,7 @@ class QFactory(object): # ----------------------------------------------------------------------- async def generate_async(self) -> Question: - logger.debug(f'[QFactory.generate_async] "{self.question["ref"]}"...') + logger.debug(f'generating {self.question["ref"]}...') # Shallow copy so that script generated questions will not replace # the original generators q = self.question.copy() @@ -520,5 +520,5 @@ class QFactory(object): logger.error(f'Invalid type "{q["type"]}" in "{q["ref"]}"') raise else: - logger.debug(f'[generate_async] Done instance of {q["ref"]}') + logger.debug('ok') return qinstance diff --git a/aprendizations/serve.py b/aprendizations/serve.py index 2086ba0..ae97d60 100644 --- a/aprendizations/serve.py +++ b/aprendizations/serve.py @@ -6,6 +6,8 @@ import functools import logging.config import mimetypes from os import path +import signal +import sys import uuid # third party libraries @@ -16,6 +18,9 @@ from tornado.escape import to_unicode from .tools import md_to_html from . import APP_NAME +# setup logger for this module +logger = logging.getLogger(__name__) + # ---------------------------------------------------------------------------- # Decorator used to restrict access to the administrator only @@ -211,11 +216,11 @@ class FileHandler(BaseHandler): with open(filepath, 'rb') as f: data = f.read() except FileNotFoundError: - logging.error(f'File not found: {filepath}') + logger.error(f'File not found: {filepath}') except PermissionError: - logging.error(f'No permission: {filepath}') + logger.error(f'No permission: {filepath}') except Exception: - logging.error(f'Error reading: {filepath}') + logger.error(f'Error reading: {filepath}') raise else: self.set_header("Content-Type", content_type) @@ -244,7 +249,7 @@ class QuestionHandler(BaseHandler): # --- get question to render @tornado.web.authenticated def get(self): - logging.debug('[QuestionHandler.get]') + logger.debug('[QuestionHandler.get]') user = self.current_user q = self.learn.get_current_question(user) @@ -275,7 +280,7 @@ class QuestionHandler(BaseHandler): # --- post answer, returns what to do next: shake, new_question, finished @tornado.web.authenticated async def post(self) -> None: - logging.debug('[QuestionHandler.post]') + logger.debug('[QuestionHandler.post]') user = self.current_user answer = self.get_body_arguments('answer') # list @@ -283,7 +288,7 @@ class QuestionHandler(BaseHandler): answer_qid = self.get_body_arguments('qid')[0] current_qid = self.learn.get_current_question_id(user) if answer_qid != current_qid: - logging.info(f'User {user} desynchronized questions') + logger.info(f'User {user} desynchronized questions') self.write({ 'method': 'invalid', 'params': { @@ -349,6 +354,59 @@ class QuestionHandler(BaseHandler): 'tries': q['tries'], } else: - logging.error(f'Unknown action: {action}') + logger.error(f'Unknown action: {action}') self.write(response) + + +# ---------------------------------------------------------------------------- +# Signal handler to catch Ctrl-C and abort server +# ---------------------------------------------------------------------------- +def signal_handler(signal, frame): + r = input(' --> Stop webserver? (yes/no) ').lower() + if r == 'yes': + tornado.ioloop.IOLoop.current().stop() + logger.critical('Webserver stopped.') + sys.exit(0) + else: + logger.info('Abort canceled...') + + +# ---------------------------------------------------------------------------- +def run_webserver(app, ssl, port=8443, debug=False): + # --- create web application + try: + webapp = WebApplication(app, debug=debug) + except Exception: + logger.critical('Failed to start web application.') + sys.exit(1) + else: + logger.info('Web application started (tornado.web.Application)') + + # --- create tornado webserver + try: + httpserver = tornado.httpserver.HTTPServer(webapp, ssl_options=ssl) + except ValueError: + logger.critical('Certificates cert.pem and privkey.pem not found') + sys.exit(1) + else: + logger.debug('HTTP server started') + + try: + httpserver.listen(port) + except OSError: + logger.critical(f'Cannot bind port {port}. Already in use?') + sys.exit(1) + else: + logger.info(f'HTTP server listening on port {port}') + + # --- run webserver + signal.signal(signal.SIGINT, signal_handler) + logger.info('Webserver running. (Ctrl-C to stop)') + + try: + tornado.ioloop.IOLoop.current().start() # running... + except Exception: + logger.critical('Webserver stopped.') + tornado.ioloop.IOLoop.current().stop() + raise diff --git a/aprendizations/student.py b/aprendizations/student.py index 957520d..6cae165 100644 --- a/aprendizations/student.py +++ b/aprendizations/student.py @@ -63,7 +63,7 @@ class StudentState(object): 'level': 0.0, # unlocked 'date': datetime.now() } - logger.debug(f'[unlock_topics] Unlocked "{topic}".') + logger.debug(f'unlocked "{topic}"') # else: # lock this topic if deps do not satisfy min_level # del self.state[topic] @@ -73,15 +73,16 @@ class StudentState(object): # current_question: the current question to be presented # ------------------------------------------------------------------------ async def start_topic(self, topic: str): - logger.debug(f'[start_topic] topic "{topic}"') + logger.debug(f'starting "{topic}"') - # if self.current_topic == topic: - # logger.info('Restarting current topic is not allowed.') - # return + # avoid regenerating questions in the middle of the current topic + if self.current_topic == topic: + logger.info('Restarting current topic is not allowed.') + return # do not allow locked topics if self.is_locked(topic): - logger.debug(f'[start_topic] topic "{topic}" is locked') + logger.debug(f'is locked "{topic}"') return # starting new topic @@ -95,13 +96,13 @@ class StudentState(object): questions = random.sample(t['questions'], k=k) else: questions = t['questions'][:k] - logger.debug(f'[start_topic] questions: {", ".join(questions)}') + logger.debug(f'selected questions: {", ".join(questions)}') self.questions = [await self.factory[ref].generate_async() for ref in questions] n = len(self.questions) - logger.debug(f'[start_topic] generated {n} questions') + logger.debug(f'generated {n} questions') # get first question self.next_question() @@ -112,7 +113,7 @@ class StudentState(object): # The current topic is unchanged. # ------------------------------------------------------------------------ def finish_topic(self): - logger.debug(f'[finish_topic] current_topic {self.current_topic}') + logger.debug(f'finished {self.current_topic}') self.state[self.current_topic] = { 'date': datetime.now(), @@ -129,13 +130,12 @@ class StudentState(object): # - if wrong, counts number of tries. If exceeded, moves on. # ------------------------------------------------------------------------ async def check_answer(self, answer): - logger.debug('[check_answer]') - q = self.current_question q['answer'] = answer q['finish_time'] = datetime.now() + logger.debug(f'checking answer of {q["ref"]}...') await q.correct_async() - logger.debug(f'[check_answer] Grade {q["grade"]:.2} in {q["ref"]}') + logger.debug(f'grade = {q["grade"]:.2}') if q['grade'] > 0.999: self.correct_answers += 1 @@ -151,7 +151,7 @@ class StudentState(object): else: action = 'wrong' if self.current_question['append_wrong']: - logger.debug('[check_answer] Wrong, append new instance') + logger.debug('wrong answer, append new question') self.questions.append(self.factory[q['ref']].generate()) self.next_question() @@ -172,7 +172,7 @@ class StudentState(object): default_maxtries = self.deps.nodes[self.current_topic]['max_tries'] maxtries = self.current_question.get('max_tries', default_maxtries) self.current_question['tries'] = maxtries - logger.debug(f'[next_question] "{self.current_question["ref"]}"') + logger.debug(f'current_question = {self.current_question["ref"]}') return self.current_question # question or None diff --git a/config/logger-debug.yaml b/config/logger-debug.yaml index 8642783..45d6b09 100644 --- a/config/logger-debug.yaml +++ b/config/logger-debug.yaml @@ -5,8 +5,8 @@ formatters: void: format: '' standard: - format: '%(asctime)s | %(levelname)-9s | %(name)-24s | %(thread)-15d | %(message)s' - datefmt: '%H:%M:%S' + format: '%(asctime)s | %(thread)-15d | %(levelname)-8s | %(module)-10s | %(funcName)-20s | %(message)s' + # datefmt: '%H:%M:%S' handlers: default: @@ -25,7 +25,7 @@ loggers: level: 'DEBUG' propagate: false - 'aprendizations.knowledge': + 'aprendizations.student': handlers: ['default'] level: 'DEBUG' propagate: false @@ -44,3 +44,8 @@ loggers: handlers: ['default'] level: 'DEBUG' propagate: false + + 'aprendizations.serve': + handlers: ['default'] + level: 'DEBUG' + propagate: false diff --git a/config/logger.yaml b/config/logger.yaml index bf54e54..7ffcb92 100644 --- a/config/logger.yaml +++ b/config/logger.yaml @@ -5,7 +5,7 @@ formatters: void: format: '' standard: - format: '%(asctime)s | %(thread)-15d | %(levelname)-9s | %(message)s' + format: '%(asctime)s | %(levelname)-8s | %(module)-10s | %(message)s' datefmt: '%Y-%m-%d %H:%M:%S' handlers: @@ -25,7 +25,7 @@ loggers: level: 'INFO' propagate: false - 'aprendizations.knowledge': + 'aprendizations.student': handlers: ['default'] level: 'INFO' propagate: false @@ -44,3 +44,8 @@ loggers: handlers: ['default'] level: 'INFO' propagate: false + + 'aprendizations.serve': + handlers: ['default'] + level: 'INFO' + propagate: false -- libgit2 0.21.2