From 45d7e2c62e34f4eac7a55a180266129f6c2357d2 Mon Sep 17 00:00:00 2001 From: forest Date: Tue, 27 Jul 2021 14:28:42 -0500 Subject: [PATCH 1/4] breaking up after abusive relationship with logger --- .gitignore | 1 + capsulflask/__init__.py | 50 +++++++++++-------------------- capsulflask/admin.py | 4 +-- capsulflask/auth.py | 1 + capsulflask/cli.py | 28 ++++++++--------- capsulflask/console.py | 17 ++++++----- capsulflask/db.py | 22 +++++++------- capsulflask/db_model.py | 4 +-- capsulflask/http_client.py | 6 ++-- capsulflask/hub_api.py | 18 +++++------ capsulflask/hub_model.py | 16 +++++----- capsulflask/landing.py | 1 + capsulflask/metrics.py | 3 +- capsulflask/payment.py | 22 +++++++------- capsulflask/shared.py | 30 +++++++++++++++++-- capsulflask/spoke_api.py | 42 +++++++++++++------------- capsulflask/spoke_model.py | 20 ++++++------- capsulflask/tests/test_console.py | 4 ++- capsulflask/tests_base.py | 8 ++--- 19 files changed, 158 insertions(+), 139 deletions(-) diff --git a/.gitignore b/.gitignore index c9bb7c2..0a82cef 100644 --- a/.gitignore +++ b/.gitignore @@ -17,3 +17,4 @@ build/ *.egg-info/ .venv +unittest-output.log \ No newline at end of file diff --git a/capsulflask/__init__.py b/capsulflask/__init__.py index f685bf8..ddf18cf 100644 --- a/capsulflask/__init__.py +++ b/capsulflask/__init__.py @@ -18,7 +18,7 @@ from flask import current_app from apscheduler.schedulers.background import BackgroundScheduler -from capsulflask.shared import my_exec_info_message +from capsulflask.shared import * from capsulflask import hub_model, spoke_model, cli from capsulflask.btcpay import client as btcpay from capsulflask.http_client import MyHTTPClient @@ -50,7 +50,7 @@ def create_app(): app = Flask(__name__) app.config.from_mapping( - TESTING=config.get("TESTING", False), + TESTING=config.get("TESTING", "False").lower() in ['true', '1', 't', 'y', 'yes'], BASE_URL=config.get("BASE_URL", "http://localhost:5000"), SECRET_KEY=config.get("SECRET_KEY", "dev"), HUB_MODE_ENABLED=config.get("HUB_MODE_ENABLED", "True").lower() in ['true', '1', 't', 'y', 'yes'], @@ -96,28 +96,21 @@ def create_app(): app.config['HUB_URL'] = config.get("HUB_URL", app.config['BASE_URL']) - log_filters = { - 'setLogLevelToDebugForHeartbeatRelatedMessages': { - '()': SetLogLevelToDebugForHeartbeatRelatedMessagesFilter, - } - } - if app.config['TESTING'] != False: - log_filters['captureLogOutputDuringTests'] = { - '()': CaptureLogOutputDuringTestsFilter, - } - - logging_dict_config({ 'version': 1, 'formatters': {'default': { 'format': '[%(asctime)s] %(levelname)s in %(module)s: %(message)s', }}, - 'filters': log_filters, + 'filters': { + 'setLogLevelToDebugForHeartbeatRelatedMessages': { + '()': SetLogLevelToDebugForHeartbeatRelatedMessagesFilter, + } + }, 'handlers': {'wsgi': { 'class': 'logging.StreamHandler', 'stream': 'ext://flask.logging.wsgi_errors_stream', 'formatter': 'default', - 'filters': list(log_filters.keys()) + 'filters': ['setLogLevelToDebugForHeartbeatRelatedMessages'] }}, 'root': { 'level': app.config['LOG_LEVEL'], @@ -125,11 +118,11 @@ def create_app(): } }) - # app.logger.critical("critical") - # app.logger.error("error") - # app.logger.warning("warning") - # app.logger.info("info") - # app.logger.debug("debug") + # mylog_critical(app, "critical") + # mylog_error(app, "error") + # mylog_warning(app, "warning") + # mylog_info(app, "info") + # mylog_debug(app, "debug") stripe.api_key = app.config['STRIPE_SECRET_KEY'] stripe.api_version = app.config['STRIPE_API_VERSION'] @@ -137,7 +130,7 @@ def create_app(): if app.config['MAIL_SERVER'] != "": app.config['FLASK_MAIL_INSTANCE'] = Mail(app) else: - app.logger.warning("No MAIL_SERVER configured. capsul will simply print emails to stdout.") + mylog_warning(app, "No MAIL_SERVER configured. capsul will simply print emails to stdout.") app.config['FLASK_MAIL_INSTANCE'] = StdoutMockFlaskMail() app.config['HTTP_CLIENT'] = MyHTTPClient(timeout_seconds=int(app.config['INTERNAL_HTTP_TIMEOUT_SECONDS'])) @@ -148,7 +141,7 @@ def create_app(): app.config['BTCPAY_CLIENT'] = btcpay.Client(api_uri=app.config['BTCPAY_URL'], pem=app.config['BTCPAY_PRIVATE_KEY']) app.config['BTCPAY_ENABLED'] = True except: - app.logger.warning("unable to create btcpay client. Capsul will work fine except cryptocurrency payments will not work. The error was: " + my_exec_info_message(sys.exc_info())) + mylog_warning(app, "unable to create btcpay client. Capsul will work fine except cryptocurrency payments will not work. The error was: " + my_exec_info_message(sys.exc_info())) # only start the scheduler and attempt to migrate the database if we are running the app. # otherwise we are running a CLI command. @@ -159,7 +152,7 @@ def create_app(): ('test' in command_line) ) - app.logger.info(f"is_running_server: {is_running_server}") + mylog_info(app, f"is_running_server: {is_running_server}") if app.config['HUB_MODE_ENABLED']: if app.config['HUB_MODEL'] == "capsul-flask": @@ -252,7 +245,7 @@ def url_for_with_cache_bust(endpoint, **values): class StdoutMockFlaskMail: def send(self, message: Message): - current_app.logger.info(f"Email would have been sent if configured:\n\nto: {','.join(message.recipients)}\nsubject: {message.subject}\nbody:\n\n{message.body}\n\n") + mylog_info(current_app, f"Email would have been sent if configured:\n\nto: {','.join(message.recipients)}\nsubject: {message.subject}\nbody:\n\n{message.body}\n\n") class SetLogLevelToDebugForHeartbeatRelatedMessagesFilter(logging.Filter): def isHeartbeatRelatedString(self, thing): @@ -279,13 +272,4 @@ class SetLogLevelToDebugForHeartbeatRelatedMessagesFilter(logging.Filter): return True -class CaptureLogOutputDuringTestsFilter(logging.Filter): - def filter(self, record): - file_object = open('unittest-output.log', 'a') - file_object.write("%s" % record.msg) - for arg in record.args: - file_object.write("%s" % arg) - file_object.write("\n") - file_object.close() - return True diff --git a/capsulflask/admin.py b/capsulflask/admin.py index 50cc61e..f183a58 100644 --- a/capsulflask/admin.py +++ b/capsulflask/admin.py @@ -10,7 +10,7 @@ from nanoid import generate from capsulflask.metrics import durations as metric_durations from capsulflask.auth import admin_account_required from capsulflask.db import get_model -from capsulflask.shared import my_exec_info_message +from capsulflask.shared import * bp = Blueprint("admin", __name__, url_prefix="/admin") @@ -58,7 +58,7 @@ def index(): ) network['allocations'].append(allocation) else: - current_app.logger.warning(f"/admin: capsul {vm['id']} has public_ipv4 {vm['public_ipv4']} which is out of range for its host network {host_id} {network['network_name']} {network['public_ipv4_cidr_block']}") + mylog_warning(current_app, f"/admin: capsul {vm['id']} has public_ipv4 {vm['public_ipv4']} which is out of range for its host network {host_id} {network['network_name']} {network['public_ipv4_cidr_block']}") display_hosts.append(display_host) diff --git a/capsulflask/auth.py b/capsulflask/auth.py index 6e4caa1..2621620 100644 --- a/capsulflask/auth.py +++ b/capsulflask/auth.py @@ -16,6 +16,7 @@ from flask_mail import Message from werkzeug.exceptions import abort from capsulflask.db import get_model +from capsulflask.shared import * bp = Blueprint("auth", __name__, url_prefix="/auth") diff --git a/capsulflask/cli.py b/capsulflask/cli.py index f13c304..c3f29cc 100644 --- a/capsulflask/cli.py +++ b/capsulflask/cli.py @@ -12,7 +12,7 @@ from psycopg2 import ProgrammingError from flask_mail import Message from capsulflask.db import get_model -from capsulflask.shared import my_exec_info_message +from capsulflask.shared import * from capsulflask.console import get_account_balance bp = Blueprint('cli', __name__) @@ -68,19 +68,19 @@ def sql_script(f, c): def cron_task(): # make sure btcpay payments get completed (in case we miss a webhook), otherwise invalidate the payment - current_app.logger.info("cron_task: starting clean_up_unresolved_btcpay_invoices") + mylog_info(current_app, "cron_task: starting clean_up_unresolved_btcpay_invoices") clean_up_unresolved_btcpay_invoices() - current_app.logger.info("cron_task: finished clean_up_unresolved_btcpay_invoices") + mylog_info(current_app, "cron_task: finished clean_up_unresolved_btcpay_invoices") # notify when funds run out - current_app.logger.info("cron_task: starting notify_users_about_account_balance") + mylog_info(current_app, "cron_task: starting notify_users_about_account_balance") notify_users_about_account_balance() - current_app.logger.info("cron_task: finished notify_users_about_account_balance") + mylog_info(current_app, "cron_task: finished notify_users_about_account_balance") # make sure vm system and DB are synced - current_app.logger.info("cron_task: starting ensure_vms_and_db_are_synced") + mylog_info(current_app, "cron_task: starting ensure_vms_and_db_are_synced") ensure_vms_and_db_are_synced() - current_app.logger.info("cron_task: finished ensure_vms_and_db_are_synced") + mylog_info(current_app, "cron_task: finished ensure_vms_and_db_are_synced") @@ -92,7 +92,7 @@ def clean_up_unresolved_btcpay_invoices(): try: btcpay_invoice = current_app.config['BTCPAY_CLIENT'].get_invoice(invoice_id) except: - current_app.logger.error(f""" + mylog_error(current_app, f""" error was thrown when contacting btcpay server for invoice {invoice_id}: {my_exec_info_message(sys.exc_info())}""" ) @@ -101,13 +101,13 @@ def clean_up_unresolved_btcpay_invoices(): days = float((datetime.now() - unresolved_invoice['created']).total_seconds())/float(60*60*24) if btcpay_invoice['status'] == "complete": - current_app.logger.info( + mylog_info(current_app, f"resolving btcpay invoice {invoice_id} " f"({unresolved_invoice['email']}, ${unresolved_invoice['dollars']}) as completed " ) get_model().btcpay_invoice_resolved(invoice_id, True) elif days >= 1: - current_app.logger.info( + mylog_info(current_app, f"resolving btcpay invoice {invoice_id} " f"({unresolved_invoice['email']}, ${unresolved_invoice['dollars']}) as invalidated, " f"btcpay server invoice status: {btcpay_invoice['status']}" @@ -236,7 +236,7 @@ def notify_users_about_account_balance(): index_to_send = i if index_to_send > -1: - current_app.logger.info(f"cron_task: sending {warnings[index_to_send]['id']} warning email to {account['email']}.") + mylog_info(current_app, f"cron_task: sending {warnings[index_to_send]['id']} warning email to {account['email']}.") get_body = warnings[index_to_send]['get_body'] get_subject = warnings[index_to_send]['get_subject'] current_app.config["FLASK_MAIL_INSTANCE"].send( @@ -250,7 +250,7 @@ def notify_users_about_account_balance(): get_model().set_account_balance_warning(account['email'], warnings[index_to_send]['id']) if index_to_send == len(warnings)-1: for vm in vms: - current_app.logger.warning(f"cron_task: deleting {vm['id']} ( {account['email']} ) due to negative account balance.") + mylog_warning(current_app, f"cron_task: deleting {vm['id']} ( {account['email']} ) due to negative account balance.") current_app.config["HUB_MODEL"].destroy(email=account["email"], id=vm['id']) get_model().delete_vm(email=account["email"], id=vm['id']) @@ -282,9 +282,9 @@ def ensure_vms_and_db_are_synced(): email_addresses_raw = current_app.config['ADMIN_EMAIL_ADDRESSES'].split(",") email_addresses = list(filter(lambda x: len(x) > 6, map(lambda x: x.strip(), email_addresses_raw ) )) - current_app.logger.info(f"cron_task: sending inconsistency warning email to {','.join(email_addresses)}:") + mylog_info(current_app, f"cron_task: sending inconsistency warning email to {','.join(email_addresses)}:") for error in errors: - current_app.logger.info(f"cron_task: {error}.") + mylog_info(current_app, f"cron_task: {error}.") current_app.config["FLASK_MAIL_INSTANCE"].send( Message( diff --git a/capsulflask/console.py b/capsulflask/console.py index b1168fb..e49fe9c 100644 --- a/capsulflask/console.py +++ b/capsulflask/console.py @@ -17,7 +17,7 @@ from nanoid import generate from capsulflask.metrics import durations as metric_durations from capsulflask.auth import account_required from capsulflask.db import get_model -from capsulflask.shared import my_exec_info_message +from capsulflask.shared import * from capsulflask.payment import poll_btcpay_session from capsulflask import cli @@ -37,7 +37,7 @@ def double_check_capsul_address(id, ipv4, get_ssh_host_keys): if result != None and result.ssh_host_keys != None and get_ssh_host_keys: get_model().update_vm_ssh_host_keys(email=session["account"], id=id, ssh_host_keys=result.ssh_host_keys) except: - current_app.logger.error(f""" + mylog_error(current_app, f""" the virtualization model threw an error in double_check_capsul_address of {id}: {my_exec_info_message(sys.exc_info())}""" ) @@ -135,7 +135,7 @@ def detail(id): delete=True ) else: - current_app.logger.info(f"deleting {vm['id']} per user request ({session['account']})") + mylog_info(current_app, f"deleting {vm['id']} per user request ({session['account']})") current_app.config["HUB_MODEL"].destroy(email=session['account'], id=id) get_model().delete_vm(email=session['account'], id=id) @@ -149,7 +149,7 @@ def detail(id): force_stop=True, ) else: - current_app.logger.info(f"force stopping {vm['id']} per user request ({session['account']})") + mylog_info(current_app, f"force stopping {vm['id']} per user request ({session['account']})") current_app.config["HUB_MODEL"].vm_state_command(email=session['account'], id=id, command="force-stop") vm["state"] = "stopped" @@ -193,9 +193,12 @@ def detail(id): @account_required def create(): - raise "console.create()!" + #raise "console.create()!" + # file_object = open('unittest-output.log', 'a') + # file_object.write("console.create()!\n") + # file_object.close() - current_app.logger.error("console.create()!") + mylog_error(current_app, "console.create()!") vm_sizes = get_model().vm_sizes_dict() operating_systems = get_model().operating_systems_dict() @@ -279,7 +282,7 @@ def create(): flash(error) if not capacity_avaliable: - current_app.logger.warning(f"when capsul capacity is restored, send an email to {session['account']}") + mylog_warning(current_app, f"when capsul capacity is restored, send an email to {session['account']}") return render_template( "create-capsul.html", diff --git a/capsulflask/db.py b/capsulflask/db.py index 5f3eaa1..a39bd66 100644 --- a/capsulflask/db.py +++ b/capsulflask/db.py @@ -8,7 +8,7 @@ from flask import current_app from flask import g from capsulflask.db_model import DBModel -from capsulflask.shared import my_exec_info_message +from capsulflask.shared import * def init_app(app, is_running_server): @@ -28,11 +28,11 @@ def init_app(app, is_running_server): schemaMigrations = {} schemaMigrationsPath = join(app.root_path, 'schema_migrations') - app.logger.info("loading schema migration scripts from {}".format(schemaMigrationsPath)) + mylog_info(app, "loading schema migration scripts from {}".format(schemaMigrationsPath)) for filename in listdir(schemaMigrationsPath): result = re.search(r"^\d+_(up|down)", filename) if not result: - app.logger.error(f"schemaVersion {filename} must match ^\\d+_(up|down). exiting.") + mylog_error(app, f"schemaVersion {filename} must match ^\\d+_(up|down). exiting.") exit(1) key = result.group() with open(join(schemaMigrationsPath, filename), 'rb') as file: @@ -57,12 +57,12 @@ def init_app(app, is_running_server): hasSchemaVersionTable = True if hasSchemaVersionTable == False: - app.logger.info("no table named schemaversion found in the {} schema. running migration 01_up".format(app.config['DATABASE_SCHEMA'])) + mylog_info(app, "no table named schemaversion found in the {} schema. running migration 01_up".format(app.config['DATABASE_SCHEMA'])) try: cursor.execute(schemaMigrations["01_up"]) connection.commit() except: - app.logger.error("unable to create the schemaversion table because: {}".format(my_exec_info_message(sys.exc_info()))) + mylog_error(app, "unable to create the schemaversion table because: {}".format(my_exec_info_message(sys.exc_info()))) exit(1) actionWasTaken = True @@ -70,24 +70,24 @@ def init_app(app, is_running_server): schemaVersion = cursor.fetchall()[0][0] if schemaVersion > desiredSchemaVersion: - app.logger.critical("schemaVersion ({}) > desiredSchemaVersion ({}). schema downgrades are not supported yet. exiting.".format( + mylog_critical(app, "schemaVersion ({}) > desiredSchemaVersion ({}). schema downgrades are not supported yet. exiting.".format( schemaVersion, desiredSchemaVersion )) exit(1) while schemaVersion < desiredSchemaVersion: migrationKey = "%02d_up" % (schemaVersion+1) - app.logger.info("schemaVersion ({}) < desiredSchemaVersion ({}). running migration {}".format( + mylog_info(app, "schemaVersion ({}) < desiredSchemaVersion ({}). running migration {}".format( schemaVersion, desiredSchemaVersion, migrationKey )) try: cursor.execute(schemaMigrations[migrationKey]) connection.commit() except KeyError: - app.logger.critical("missing schema migration script: {}_xyz.sql".format(migrationKey)) + mylog_critical(app, "missing schema migration script: {}_xyz.sql".format(migrationKey)) exit(1) except: - app.logger.critical("unable to execute the schema migration {} because: {}".format(migrationKey, my_exec_info_message(sys.exc_info()))) + mylog_critical(app, "unable to execute the schema migration {} because: {}".format(migrationKey, my_exec_info_message(sys.exc_info()))) exit(1) actionWasTaken = True @@ -96,7 +96,7 @@ def init_app(app, is_running_server): versionFromDatabase = cursor.fetchall()[0][0] if schemaVersion != versionFromDatabase: - app.logger.critical("incorrect schema version value \"{}\" after running migration {}, expected \"{}\". exiting.".format( + mylog_critical(app, "incorrect schema version value \"{}\" after running migration {}, expected \"{}\". exiting.".format( versionFromDatabase, migrationKey, schemaVersion @@ -107,7 +107,7 @@ def init_app(app, is_running_server): app.config['PSYCOPG2_CONNECTION_POOL'].putconn(connection) - app.logger.info("{} current schemaVersion: \"{}\"".format( + mylog_info(app, "{} current schemaVersion: \"{}\"".format( ("schema migration completed." if actionWasTaken else "schema is already up to date. "), schemaVersion )) diff --git a/capsulflask/db_model.py b/capsulflask/db_model.py index 9d31aba..bcf955e 100644 --- a/capsulflask/db_model.py +++ b/capsulflask/db_model.py @@ -7,7 +7,7 @@ from nanoid import generate from flask import current_app from typing import List -from capsulflask.shared import OnlineHost +from capsulflask.shared import * class DBModel: @@ -270,7 +270,7 @@ class DBModel: row = self.cursor.fetchone() if row: if int(row[1]) != int(dollars): - current_app.logger.warning(f""" + mylog_warning(current_app, f""" {payment_type} gave us a completed payment session with a different dollar amount than what we had recorded!! id: {id} account: {row[0]} diff --git a/capsulflask/http_client.py b/capsulflask/http_client.py index 201a392..98c1c33 100644 --- a/capsulflask/http_client.py +++ b/capsulflask/http_client.py @@ -8,7 +8,7 @@ import threading import aiohttp import asyncio from flask import current_app -from capsulflask.shared import OnlineHost, my_exec_info_message +from capsulflask.shared import * from typing import List class HTTPResult: @@ -33,7 +33,7 @@ class MyHTTPClient: toReturn = [] for individualResult in fromOtherThread: if individualResult.error != None and individualResult.error != "": - current_app.logger.error(individualResult.error) + mylog_error(current_app, individualResult.error) toReturn.append(individualResult.http_result) return toReturn @@ -42,7 +42,7 @@ class MyHTTPClient: future = run_coroutine(self.do_http(method=method, url=url, body=body, authorization_header=authorization_header)) fromOtherThread = future.result() if fromOtherThread.error != None and fromOtherThread.error != "": - current_app.logger.error(fromOtherThread.error) + mylog_error(current_app, fromOtherThread.error) return fromOtherThread.http_result def get_client_session(self): diff --git a/capsulflask/hub_api.py b/capsulflask/hub_api.py index 634ec21..feeccbc 100644 --- a/capsulflask/hub_api.py +++ b/capsulflask/hub_api.py @@ -7,7 +7,7 @@ from flask import request, make_response from werkzeug.exceptions import abort from capsulflask.db import get_model -from capsulflask.shared import my_exec_info_message, authorized_as_hub +from capsulflask.shared import * bp = Blueprint("hub", __name__, url_prefix="/hub") @@ -21,19 +21,19 @@ def authorized_for_host(id): def ping_all_hosts_task(): if authorized_as_hub(request.headers): all_hosts = get_model().get_all_hosts() - current_app.logger.debug(f"pinging {len(all_hosts)} hosts...") + mylog_debug(current_app, f"pinging {len(all_hosts)} hosts...") authorization_header = f"Bearer {current_app.config['HUB_TOKEN']}" results = current_app.config["HTTP_CLIENT"].do_multi_http_sync(all_hosts, "/spoke/heartbeat", None, authorization_header=authorization_header) for i in range(len(all_hosts)): host = all_hosts[i] result = results[i] - current_app.logger.debug(f"response from {host.id} ({host.url}): {result.status_code} {result.body}") + mylog_debug(current_app, f"response from {host.id} ({host.url}): {result.status_code} {result.body}") if result.status_code == 200: get_model().host_heartbeat(host.id) return "ok" else: - current_app.logger.warning(f"/hub/heartbeat-task returned 401: invalid hub token") + mylog_warning(current_app, f"/hub/heartbeat-task returned 401: invalid hub token") return abort(401, "invalid hub token") @@ -42,7 +42,7 @@ def heartbeat(host_id): if authorized_for_host(host_id): return "ok" else: - current_app.logger.warning(f"/hub/heartbeat/{host_id} returned 401: invalid token") + mylog_warning(current_app, f"/hub/heartbeat/{host_id} returned 401: invalid token") return abort(401, "invalid host id or token") @bp.route("/claim-operation//", methods=("POST",)) @@ -51,7 +51,7 @@ def claim_operation(operation_id: int, host_id: str): payload_json = get_model().get_payload_json_from_host_operation(operation_id, host_id) if payload_json is None: error_message = f"{host_id} can't claim operation {operation_id} because host_operation row not found" - current_app.logger.error(error_message) + mylog_error(current_app, error_message) return abort(404, error_message) # right now if there is a can_claim_handler there needs to be a corresponding on_claimed_handler. @@ -84,7 +84,7 @@ def claim_operation(operation_id: int, host_id: str): if error_message != "": error_message = f"{host_id} can't claim operation {operation_id} because {error_message}" - current_app.logger.error(error_message) + mylog_error(current_app, error_message) return abort(400, error_message) # we will only return this payload as json if claiming succeeds, so might as well do this now... @@ -97,7 +97,7 @@ def claim_operation(operation_id: int, host_id: str): if error_message != "": error_message = f"{host_id} can't claim operation {operation_id} because {error_message}" - current_app.logger.error(error_message) + mylog_error(current_app, error_message) return abort(400, error_message) claimed = get_model().claim_operation(operation_id, host_id) @@ -113,7 +113,7 @@ def claim_operation(operation_id: int, host_id: str): else: return abort(409, f"operation was already assigned to another host") else: - current_app.logger.warning(f"/hub/claim-operation/{operation_id}/{host_id} returned 401: invalid token") + mylog_warning(current_app, f"/hub/claim-operation/{operation_id}/{host_id} returned 401: invalid token") return abort(401, "invalid host id or token") def can_claim_create(payload, host_id) -> (str, str): diff --git a/capsulflask/hub_model.py b/capsulflask/hub_model.py index a20f00b..5ed5cf9 100644 --- a/capsulflask/hub_model.py +++ b/capsulflask/hub_model.py @@ -14,7 +14,7 @@ from subprocess import run from capsulflask.db import get_model from capsulflask.http_client import HTTPResult -from capsulflask.shared import VirtualizationInterface, VirtualMachine, OnlineHost, validate_capsul_id, my_exec_info_message +from capsulflask.shared import * class MockHub(VirtualizationInterface): def __init__(self): @@ -42,7 +42,7 @@ class MockHub(VirtualizationInterface): def create(self, email: str, id: str, os: str, size: str, template_image_file_name: str, vcpus: int, memory_mb: int, ssh_authorized_keys: list): validate_capsul_id(id) - current_app.logger.info(f"mock create: {id} for {email}") + mylog_info(current_app, f"mock create: {id} for {email}") sleep(1) get_model().create_vm( email=email, @@ -56,10 +56,10 @@ class MockHub(VirtualizationInterface): ) def destroy(self, email: str, id: str): - current_app.logger.info(f"mock destroy: {id} for {email}") + mylog_info(current_app, f"mock destroy: {id} for {email}") def vm_state_command(self, email: str, id: str, command: str): - current_app.logger.info(f"mock {command}: {id} for {email}") + mylog_info(current_app, f"mock {command}: {id} for {email}") class CapsulFlaskHub(VirtualizationInterface): @@ -119,7 +119,7 @@ class CapsulFlaskHub(VirtualizationInterface): operation_desc = "" if operation_id: operation_desc = f"for operation {operation_id}" - current_app.logger.error(f"""error reading assignment_status {operation_desc} from host {host.id}: + mylog_error(current_app, f"""error reading assignment_status {operation_desc} from host {host.id}: result_is_json: {result_is_json} result_is_dict: {result_is_dict} result_has_status: {result_has_status} @@ -183,10 +183,10 @@ class CapsulFlaskHub(VirtualizationInterface): except: all_valid = False if not all_valid: - current_app.logger.error(f"""error reading ids for list_ids operation, host {host.id}""") + mylog_error(current_app, f"""error reading ids for list_ids operation, host {host.id}""") else: result_json_string = json.dumps({"error_message": "invalid response, missing 'ids' list"}) - current_app.logger.error(f"""missing 'ids' list for list_ids operation, host {host.id}""") + mylog_error(current_app, f"""missing 'ids' list for list_ids operation, host {host.id}""") except: # no need to do anything here since if it cant be parsed then generic_operation will handle it. pass @@ -196,7 +196,7 @@ class CapsulFlaskHub(VirtualizationInterface): def create(self, email: str, id: str, os: str, size: str, template_image_file_name: str, vcpus: int, memory_mb: int, ssh_authorized_keys: list): validate_capsul_id(id) online_hosts = get_model().get_online_hosts() - current_app.logger.debug(f"hub_model.create(): ${len(online_hosts)} hosts") + mylog_debug(current_app, f"hub_model.create(): ${len(online_hosts)} hosts") payload = json.dumps(dict( type="create", email=email, diff --git a/capsulflask/landing.py b/capsulflask/landing.py index 8161352..2c59387 100644 --- a/capsulflask/landing.py +++ b/capsulflask/landing.py @@ -3,6 +3,7 @@ from flask import render_template from flask import current_app from capsulflask.db import get_model +from capsulflask.shared import * bp = Blueprint("landing", __name__, url_prefix="/") diff --git a/capsulflask/metrics.py b/capsulflask/metrics.py index 9d345b6..264ffcc 100644 --- a/capsulflask/metrics.py +++ b/capsulflask/metrics.py @@ -15,6 +15,7 @@ from werkzeug.exceptions import abort from capsulflask.db import get_model from capsulflask.auth import account_required +from capsulflask.shared import * mutex = Lock() bp = Blueprint("metrics", __name__, url_prefix="/metrics") @@ -143,7 +144,7 @@ def get_plot_bytes(metric, capsulid, duration, size): def draw_plot_png_bytes(data, scale, size_x=3, size_y=1): - #current_app.logger.info(json.dumps(data, indent=4, default=str)) + #mylog_info(current_app, json.dumps(data, indent=4, default=str)) pyplot.style.use("seaborn-dark") fig, my_plot = pyplot.subplots(figsize=(size_x, size_y)) diff --git a/capsulflask/payment.py b/capsulflask/payment.py index 3c41cd9..1aefa65 100644 --- a/capsulflask/payment.py +++ b/capsulflask/payment.py @@ -21,7 +21,7 @@ from werkzeug.exceptions import abort from capsulflask.auth import account_required from capsulflask.db import get_model -from capsulflask.shared import my_exec_info_message +from capsulflask.shared import * bp = Blueprint("payment", __name__, url_prefix="/payment") @@ -67,11 +67,11 @@ def btcpay_payment(): notificationURL=f"{current_app.config['BASE_URL']}/payment/btcpay/webhook" )) - current_app.logger.info(f"created btcpay invoice: {invoice}") + mylog_info(current_app, f"created btcpay invoice: {invoice}") # print(invoice) - current_app.logger.info(f"created btcpay invoice_id={invoice['id']} ( {session['account']}, ${dollars} )") + mylog_info(current_app, f"created btcpay invoice_id={invoice['id']} ( {session['account']}, ${dollars} )") get_model().create_payment_session("btcpay", invoice["id"], session["account"], dollars) @@ -89,7 +89,7 @@ def poll_btcpay_session(invoice_id): try: invoice = current_app.config['BTCPAY_CLIENT'].get_invoice(invoice_id) except: - current_app.logger.error(f""" + mylog_error(current_app, f""" error was thrown when contacting btcpay server: {my_exec_info_message(sys.exc_info())}""" ) @@ -101,13 +101,13 @@ def poll_btcpay_session(invoice_id): dollars = invoice['price'] - current_app.logger.info(f"poll_btcpay_session invoice_id={invoice_id}, status={invoice['status']} dollars={dollars}") + mylog_info(current_app, f"poll_btcpay_session invoice_id={invoice_id}, status={invoice['status']} dollars={dollars}") if invoice['status'] == "paid" or invoice['status'] == "confirmed" or invoice['status'] == "complete": success_account = get_model().consume_payment_session("btcpay", invoice_id, dollars) if success_account: - current_app.logger.info(f"{success_account} paid ${dollars} successfully (btcpay_invoice_id={invoice_id})") + mylog_info(current_app, f"{success_account} paid ${dollars} successfully (btcpay_invoice_id={invoice_id})") if invoice['status'] == "complete": get_model().btcpay_invoice_resolved(invoice_id, True) @@ -120,7 +120,7 @@ def poll_btcpay_session(invoice_id): @bp.route("/btcpay/webhook", methods=("POST",)) def btcpay_webhook(): - current_app.logger.info(f"got btcpay webhook") + mylog_info(current_app, f"got btcpay webhook") # IMPORTANT! there is no signature or credential to authenticate the data sent into this webhook :facepalm: # its just a notification, thats all. @@ -148,7 +148,7 @@ def stripe_payment(): if len(errors) == 0: - current_app.logger.info(f"creating stripe checkout session for {session['account']}, ${dollars}") + mylog_info(current_app, f"creating stripe checkout session for {session['account']}, ${dollars}") checkout_session = stripe.checkout.Session.create( success_url=current_app.config['BASE_URL'] + "/payment/stripe/success?session_id={CHECKOUT_SESSION_ID}", @@ -167,7 +167,7 @@ def stripe_payment(): ) stripe_checkout_session_id = checkout_session['id'] - current_app.logger.info(f"stripe_checkout_session_id={stripe_checkout_session_id} ( {session['account']}, ${dollars} )") + mylog_info(current_app, f"stripe_checkout_session_id={stripe_checkout_session_id} ( {session['account']}, ${dollars} )") get_model().create_payment_session("stripe", stripe_checkout_session_id, session["account"], dollars) @@ -251,13 +251,13 @@ def validate_stripe_checkout_session(stripe_checkout_session_id): def success(): stripe_checkout_session_id = request.args.get('session_id') if not stripe_checkout_session_id: - current_app.logger.info("/payment/stripe/success returned 400: missing required URL parameter session_id") + mylog_info(current_app, "/payment/stripe/success returned 400: missing required URL parameter session_id") abort(400, "missing required URL parameter session_id") else: for _ in range(0, 5): paid = validate_stripe_checkout_session(stripe_checkout_session_id) if paid: - current_app.logger.info(f"{paid['email']} paid ${paid['dollars']} successfully (stripe_checkout_session_id={stripe_checkout_session_id})") + mylog_info(current_app, f"{paid['email']} paid ${paid['dollars']} successfully (stripe_checkout_session_id={stripe_checkout_session_id})") return redirect(url_for("console.account_balance")) else: sleep(1) diff --git a/capsulflask/shared.py b/capsulflask/shared.py index ba72900..92e8485 100644 --- a/capsulflask/shared.py +++ b/capsulflask/shared.py @@ -1,6 +1,6 @@ import re -from flask import current_app +from flask import current_app, Flask from typing import List class OnlineHost: @@ -54,4 +54,30 @@ def authorized_as_hub(headers): return False def my_exec_info_message(exec_info): - return "{}: {}".format(".".join([exec_info[0].__module__, exec_info[0].__name__]), exec_info[1]) \ No newline at end of file + return "{}: {}".format(".".join([exec_info[0].__module__, exec_info[0].__name__]), exec_info[1]) + +def log_output_for_tests(app: Flask, message: str): + if app.config['TESTING'] != False: + file_object = open('unittest-log-output.log', 'a') + file_object.write(message) + file_object.close() + +def mylog_debug(app: Flask, message: str): + log_output_for_tests(app, f"DEBUG: {message}\n") + app.logger.debug(message) + +def mylog_info(app: Flask, message: str): + log_output_for_tests(app, f"INFO: {message}\n") + app.logger.info(message) + +def mylog_warning(app: Flask, message: str): + log_output_for_tests(app, f"WARNING: {message}\n") + app.logger.warning(message) + +def mylog_error(app: Flask, message: str): + log_output_for_tests(app, f"ERROR: {message}\n") + app.logger.error(message) + +def mylog_critical(app: Flask, message: str): + log_output_for_tests(app, f"CRITICAL: {message}\n") + app.logger.critical(message) \ No newline at end of file diff --git a/capsulflask/spoke_api.py b/capsulflask/spoke_api.py index 3ca86bc..79b81ff 100644 --- a/capsulflask/spoke_api.py +++ b/capsulflask/spoke_api.py @@ -8,7 +8,7 @@ from flask import request from flask.json import jsonify from werkzeug.exceptions import abort -from capsulflask.shared import my_exec_info_message, authorized_as_hub +from capsulflask.shared import * bp = Blueprint("spoke", __name__, url_prefix="/spoke") @@ -19,18 +19,18 @@ def heartbeat(): authorization_header = f"Bearer {current_app.config['SPOKE_HOST_TOKEN']}" result = current_app.config['HTTP_CLIENT'].do_http_sync(url, body=None, authorization_header=authorization_header) if result.status_code == -1: - current_app.logger.info(f"/spoke/heartbeat returned 503: hub at {url} timed out or cannot be reached") + mylog_info(current_app, f"/spoke/heartbeat returned 503: hub at {url} timed out or cannot be reached") return abort(503, "Service Unavailable: hub timed out or cannot be reached") if result.status_code == 401: - current_app.logger.info(f"/spoke/heartbeat returned 502: hub at {url} rejected our token") + mylog_info(current_app, f"/spoke/heartbeat returned 502: hub at {url} rejected our token") return abort(502, "hub rejected our token") if result.status_code != 200: - current_app.logger.info(f"/spoke/heartbeat returned 502: hub at {url} returned {result.status_code}") + mylog_info(current_app, f"/spoke/heartbeat returned 502: hub at {url} returned {result.status_code}") return abort(502, "Bad Gateway: hub did not return 200") return "OK" else: - current_app.logger.info(f"/spoke/heartbeat returned 401: invalid hub token") + mylog_info(current_app, f"/spoke/heartbeat returned 401: invalid hub token") return abort(401, "invalid hub token") @bp.route("/operation/", methods=("POST",)) @@ -45,7 +45,7 @@ def operation_impl(operation_id: int): if authorized_as_hub(request.headers): request_body_json = request.json request_body = json.loads(request_body_json) - #current_app.logger.info(f"request.json: {request_body}") + #mylog_info(current_app, f"request.json: {request_body}") handlers = { "capacity_avaliable": handle_capacity_avaliable, "get": handle_get, @@ -63,7 +63,7 @@ def operation_impl(operation_id: int): return handlers[request_body['type']](operation_id, request_body) except: error_message = my_exec_info_message(sys.exc_info()) - current_app.logger.error(f"unhandled exception in {request_body['type']} handler: {error_message}") + mylog_error(current_app, f"unhandled exception in {request_body['type']} handler: {error_message}") return jsonify(dict(error_message=error_message)) else: error_message = f"'type' must be one of {types_csv}" @@ -71,15 +71,15 @@ def operation_impl(operation_id: int): error_message = "'type' json property is required" if error_message != "": - current_app.logger.error(f"/hosts/operation returned 400: {error_message}") + mylog_error(current_app, f"/hosts/operation returned 400: {error_message}") return abort(400, f"bad request; {error_message}") else: - current_app.logger.warning(f"/hosts/operation returned 401: invalid hub token") + mylog_warning(current_app, f"/hosts/operation returned 401: invalid hub token") return abort(401, "invalid hub token") def handle_capacity_avaliable(operation_id, request_body): if 'additional_ram_bytes' not in request_body: - current_app.logger.error(f"/hosts/operation returned 400: additional_ram_bytes is required for capacity_avaliable") + mylog_error(current_app, f"/hosts/operation returned 400: additional_ram_bytes is required for capacity_avaliable") return abort(400, f"bad request; additional_ram_bytes is required for capacity_avaliable") has_capacity = current_app.config['SPOKE_MODEL'].capacity_avaliable(request_body['additional_ram_bytes']) @@ -87,7 +87,7 @@ def handle_capacity_avaliable(operation_id, request_body): def handle_get(operation_id, request_body): if 'id' not in request_body: - current_app.logger.error(f"/hosts/operation returned 400: id is required for get") + mylog_error(current_app, f"/hosts/operation returned 400: id is required for get") return abort(400, f"bad request; id is required for get") vm = current_app.config['SPOKE_MODEL'].get(request_body['id'], request_body['get_ssh_host_keys']) @@ -101,7 +101,7 @@ def handle_list_ids(operation_id, request_body): def handle_create(operation_id, request_body): if not operation_id: - current_app.logger.error(f"/hosts/operation returned 400: operation_id is required for create ") + mylog_error(current_app, f"/hosts/operation returned 400: operation_id is required for create ") return abort(400, f"bad request; operation_id is required. try POST /spoke/operation/") parameters = ["email", "id", "os", "size", "template_image_file_name", "vcpus", "memory_mb", "ssh_authorized_keys"] @@ -111,7 +111,7 @@ def handle_create(operation_id, request_body): error_message = f"{error_message}\n{parameter} is required for create" if error_message != "": - current_app.logger.error(f"/hosts/operation returned 400: {error_message}") + mylog_error(current_app, f"/hosts/operation returned 400: {error_message}") return abort(400, f"bad request; {error_message}") # only one host should create the vm, so we first race to assign this create operation to ourselves. @@ -140,7 +140,7 @@ def handle_create(operation_id, request_body): elif result.status_code == 409: assignment_status = "assigned_to_other_host" else: - current_app.logger.error(f"{url} returned {result.status_code}: {result.body}") + mylog_error(current_app, f"{url} returned {result.status_code}: {result.body}") return abort(503, f"hub did not cleanly handle our request to claim the create operation") if assignment_status == "assigned": @@ -166,7 +166,7 @@ def handle_create(operation_id, request_body): params= f"{params} network_name='{request_body['network_name'] if 'network_name' in request_body else 'KeyError'}', " params= f"{params} public_ipv4='{request_body['public_ipv4'] if 'public_ipv4' in request_body else 'KeyError'}', " - current_app.logger.error(f"spoke_model.create({params}) failed: {error_message}") + mylog_error(current_app, f"spoke_model.create({params}) failed: {error_message}") return jsonify(dict(assignment_status=assignment_status, error_message=error_message)) @@ -174,11 +174,11 @@ def handle_create(operation_id, request_body): def handle_destroy(operation_id, request_body): if 'id' not in request_body: - current_app.logger.error(f"/hosts/operation returned 400: id is required for destroy") + mylog_error(current_app, f"/hosts/operation returned 400: id is required for destroy") return abort(400, f"bad request; id is required for destroy") if 'email' not in request_body: - current_app.logger.error(f"/hosts/operation returned 400: email is required for destroy") + mylog_error(current_app, f"/hosts/operation returned 400: email is required for destroy") return abort(400, f"bad request; email is required for destroy") try: @@ -187,7 +187,7 @@ def handle_destroy(operation_id, request_body): error_message = my_exec_info_message(sys.exc_info()) params = f"email='{request_body['email'] if 'email' in request_body else 'KeyError'}', " params= f"{params} id='{request_body['id'] if 'id' in request_body else 'KeyError'}', " - current_app.logger.error(f"current_app.config['SPOKE_MODEL'].destroy({params}) failed: {error_message}") + mylog_error(current_app, f"current_app.config['SPOKE_MODEL'].destroy({params}) failed: {error_message}") return jsonify(dict(assignment_status="assigned", status="error", error_message=error_message)) return jsonify(dict(assignment_status="assigned", status="success")) @@ -198,11 +198,11 @@ def handle_vm_state_command(operation_id, request_body): required_properties = ['id', 'email', 'command'] for required_property in required_properties: if required_property not in request_body: - current_app.logger.error(f"/hosts/operation returned 400: {required_property} is required for vm_state_command") + mylog_error(current_app, f"/hosts/operation returned 400: {required_property} is required for vm_state_command") return abort(400, f"bad request; {required_property} is required for vm_state_command") if request_body['command'] not in ["stop", "force-stop", "start", "restart"]: - current_app.logger.error(f"/hosts/operation returned 400: command ({request_body['command']}) must be one of stop, force-stop, start, or restart") + mylog_error(current_app, f"/hosts/operation returned 400: command ({request_body['command']}) must be one of stop, force-stop, start, or restart") return abort(400, f"bad request; command ({request_body['command']}) must be one of stop, force-stop, start, or restart") try: @@ -212,7 +212,7 @@ def handle_vm_state_command(operation_id, request_body): params = f"email='{request_body['email'] if 'email' in request_body else 'KeyError'}', " params= f"{params} id='{request_body['id'] if 'id' in request_body else 'KeyError'}', " params= f"{params} command='{request_body['command'] if 'command' in request_body else 'KeyError'}', " - current_app.logger.error(f"current_app.config['SPOKE_MODEL'].vm_state_command({params}) failed: {error_message}") + mylog_error(current_app, f"current_app.config['SPOKE_MODEL'].vm_state_command({params}) failed: {error_message}") return jsonify(dict(assignment_status="assigned", status="error", error_message=error_message)) return jsonify(dict(assignment_status="assigned", status="success")) \ No newline at end of file diff --git a/capsulflask/spoke_model.py b/capsulflask/spoke_model.py index 9ab0d3a..1c93c59 100644 --- a/capsulflask/spoke_model.py +++ b/capsulflask/spoke_model.py @@ -10,7 +10,7 @@ from subprocess import run from capsulflask.db import get_model -from capsulflask.shared import VirtualizationInterface, VirtualMachine, validate_capsul_id, my_exec_info_message +from capsulflask.shared import * class MockSpoke(VirtualizationInterface): @@ -43,15 +43,15 @@ class MockSpoke(VirtualizationInterface): def create(self, email: str, id: str, template_image_file_name: str, vcpus: int, memory_mb: int, ssh_authorized_keys: list, network_name: str, public_ipv4: str): validate_capsul_id(id) - current_app.logger.info(f"mock create: {id} for {email}") + mylog_info(current_app, f"mock create: {id} for {email}") self.capsuls[id] = dict(email=email, id=id, network_name=network_name, public_ipv4=public_ipv4) sleep(1) def destroy(self, email: str, id: str): - current_app.logger.info(f"mock destroy: {id} for {email}") + mylog_info(current_app, f"mock destroy: {id} for {email}") def vm_state_command(self, email: str, id: str, command: str): - current_app.logger.info(f"mock {command}: {id} for {email}") + mylog_info(current_app, f"mock {command}: {id} for {email}") class ShellScriptSpoke(VirtualizationInterface): @@ -73,7 +73,7 @@ class ShellScriptSpoke(VirtualizationInterface): completedProcess = run(my_args, capture_output=True) if completedProcess.returncode != 0: - current_app.logger.error(f""" + mylog_error(current_app, f""" capacity-avaliable.sh exited {completedProcess.returncode} with stdout: {completedProcess.stdout} @@ -85,7 +85,7 @@ class ShellScriptSpoke(VirtualizationInterface): lines = completedProcess.stdout.splitlines() output = lines[len(lines)-1] if not output == b"yes": - current_app.logger.error(f"capacity-avaliable.sh exited 0 and returned {output} but did not return \"yes\" ") + mylog_error(current_app, f"capacity-avaliable.sh exited 0 and returned {output} but did not return \"yes\" ") return False return True @@ -96,14 +96,14 @@ class ShellScriptSpoke(VirtualizationInterface): self.validate_completed_process(completedProcess) lines = completedProcess.stdout.splitlines() if len(lines) == 0: - current_app.logger.warning("shell_scripts/get.sh returned zero lines!") + mylog_warning(current_app, "shell_scripts/get.sh returned zero lines!") return None result_string = lines[0].decode("utf-8") fields = result_string.split(" ") if fields[0] != "true": - current_app.logger.warning(f"shell_scripts/get.sh was called for {id} which libvirt says does not exist.") + mylog_warning(current_app, f"shell_scripts/get.sh was called for {id} which libvirt says does not exist.") return None if len(fields) < 2: @@ -126,7 +126,7 @@ class ShellScriptSpoke(VirtualizationInterface): ssh_host_keys = json.loads(completedProcess2.stdout.decode("utf-8")) return VirtualMachine(id, current_app.config["SPOKE_HOST_ID"], state=state, ipv4=ipaddr, ssh_host_keys=ssh_host_keys) except: - current_app.logger.warning(f""" + mylog_warning(current_app, f""" failed to ssh-keyscan {id} at {ipaddr}: {my_exec_info_message(sys.exc_info())}""" ) @@ -218,5 +218,5 @@ class ShellScriptSpoke(VirtualizationInterface): completedProcess = run([join(current_app.root_path, f"shell_scripts/{command}.sh"), id], capture_output=True) self.validate_completed_process(completedProcess, email) returned_string = completedProcess.stdout.decode("utf-8") - current_app.logger.info(f"{command} vm {id} for {email} returned: {returned_string}") + mylog_info(current_app, f"{command} vm {id} for {email} returned: {returned_string}") diff --git a/capsulflask/tests/test_console.py b/capsulflask/tests/test_console.py index fee1178..be27438 100644 --- a/capsulflask/tests/test_console.py +++ b/capsulflask/tests/test_console.py @@ -58,6 +58,7 @@ class ConsoleTests(BaseTestCase): def test_create_fails_capacity(self): with self.client as client: + client.get(url_for("console.create")) csrf_token = self.get_context_variable('csrf_token') @@ -82,7 +83,7 @@ class ConsoleTests(BaseTestCase): len(get_model().list_vms_for_account('test@example.com')), 0 ) - + file_object = open('unittest-output.log', 'a') file_object.write(f"{self.id()} captured output:\n{self.logs_from_test.getvalue()}\n") file_object.close() @@ -207,3 +208,4 @@ class ConsoleTests(BaseTestCase): get_model().cursor.execute("DELETE FROM vms") get_model().cursor.execute("DELETE FROM payments") get_model().cursor.connection.commit() + diff --git a/capsulflask/tests_base.py b/capsulflask/tests_base.py index 60eebb0..085d739 100644 --- a/capsulflask/tests_base.py +++ b/capsulflask/tests_base.py @@ -9,12 +9,13 @@ from flask import current_app from capsulflask import create_app from capsulflask.db import get_model +from capsulflask.shared import * class BaseTestCase(TestCase): def create_app(self): # Use default connection paramaters os.environ['POSTGRES_CONNECTION_PARAMETERS'] = "host=localhost port=5432 user=postgres password=dev dbname=capsulflask_test" - os.environ['TESTING'] = '1' + os.environ['TESTING'] = 'True' os.environ['LOG_LEVEL'] = 'DEBUG' os.environ['SPOKE_MODEL'] = 'mock' os.environ['HUB_MODEL'] = 'capsul-flask' @@ -22,14 +23,13 @@ class BaseTestCase(TestCase): return self.app def setUp(self): - pass + mylog_info(self.app, f"setting up {self.id()}") def tearDown(self): - pass + mylog_info(self.app, f"tearing down {self.id()}") def _login(self, user_email): get_model().login(user_email) with self.client.session_transaction() as session: session['account'] = user_email session['csrf-token'] = generate() - -- 2.45.2 From f5640a1d01cc12e863a7531c1c420a8fc8e4487f Mon Sep 17 00:00:00 2001 From: forest Date: Tue, 27 Jul 2021 14:44:10 -0500 Subject: [PATCH 2/4] getting unit tests to log properly --- .gitignore | 2 +- capsulflask/shared.py | 24 +++++++++++++++++------- capsulflask/tests_base.py | 4 ++-- 3 files changed, 20 insertions(+), 10 deletions(-) diff --git a/.gitignore b/.gitignore index 0a82cef..b343e04 100644 --- a/.gitignore +++ b/.gitignore @@ -17,4 +17,4 @@ build/ *.egg-info/ .venv -unittest-output.log \ No newline at end of file +unittest-log-output.log \ No newline at end of file diff --git a/capsulflask/shared.py b/capsulflask/shared.py index 92e8485..68af334 100644 --- a/capsulflask/shared.py +++ b/capsulflask/shared.py @@ -56,28 +56,38 @@ def authorized_as_hub(headers): def my_exec_info_message(exec_info): return "{}: {}".format(".".join([exec_info[0].__module__, exec_info[0].__name__]), exec_info[1]) + + +mylog_current_test_id_container = { + 'value': '', +} +def set_mylog_test_id(test_id): + mylog_current_test_id_container['value'] = ".".join(test_id.split(".")[-2:]) + + def log_output_for_tests(app: Flask, message: str): - if app.config['TESTING'] != False: + if app.config['TESTING'] and mylog_current_test_id_container['value'] != "": file_object = open('unittest-log-output.log', 'a') - file_object.write(message) + file_object.write(f"{mylog_current_test_id_container['value']}: {message}\n") file_object.close() + def mylog_debug(app: Flask, message: str): - log_output_for_tests(app, f"DEBUG: {message}\n") + log_output_for_tests(app, f"DEBUG: {message}") app.logger.debug(message) def mylog_info(app: Flask, message: str): - log_output_for_tests(app, f"INFO: {message}\n") + log_output_for_tests(app, f"INFO: {message}") app.logger.info(message) def mylog_warning(app: Flask, message: str): - log_output_for_tests(app, f"WARNING: {message}\n") + log_output_for_tests(app, f"WARNING: {message}") app.logger.warning(message) def mylog_error(app: Flask, message: str): - log_output_for_tests(app, f"ERROR: {message}\n") + log_output_for_tests(app, f"ERROR: {message}") app.logger.error(message) def mylog_critical(app: Flask, message: str): - log_output_for_tests(app, f"CRITICAL: {message}\n") + log_output_for_tests(app, f"CRITICAL: {message}") app.logger.critical(message) \ No newline at end of file diff --git a/capsulflask/tests_base.py b/capsulflask/tests_base.py index 085d739..9a3f93e 100644 --- a/capsulflask/tests_base.py +++ b/capsulflask/tests_base.py @@ -23,10 +23,10 @@ class BaseTestCase(TestCase): return self.app def setUp(self): - mylog_info(self.app, f"setting up {self.id()}") + set_mylog_test_id(self.id()) def tearDown(self): - mylog_info(self.app, f"tearing down {self.id()}") + set_mylog_test_id("") def _login(self, user_email): get_model().login(user_email) -- 2.45.2 From 6d52f56d27af251615c3ca00a88f2895073d434f Mon Sep 17 00:00:00 2001 From: forest Date: Tue, 27 Jul 2021 14:49:10 -0500 Subject: [PATCH 3/4] documenting the janky tests logs situation --- docs/testing.md | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/docs/testing.md b/docs/testing.md index 42de70f..c29e5ee 100644 --- a/docs/testing.md +++ b/docs/testing.md @@ -6,7 +6,9 @@ To run tests: 1. create a Postgres database called `capsulflask_test` - e.g.: `docker exec -it 98e1ddfbbffb createdb -U postgres -O postgres capsulflask_test` - (`98e1ddfbbffb` is the docker container ID of the postgres container) -2. run `python3 -m unittest` +2. run `python3 -m unittest && cat unittest-log-output.log && rm unittest-log-output.log` + +**NOTE** that right now we can't figure out how to get the tests to properly output the log messages that happened when they failed, (or passed), so for now we have hacked it to write to a file. ### Architecture -- 2.45.2 From c0bc65ed3daaff27a2fbc9b805c1c15f6cda3cce Mon Sep 17 00:00:00 2001 From: forest Date: Sat, 31 Jul 2021 15:28:42 -0500 Subject: [PATCH 4/4] create TestHTTPClient that uses werkzueg test client, tests are passing --- app.py | 3 +- capsulflask/__init__.py | 11 ++-- capsulflask/console.py | 7 --- capsulflask/hub_model.py | 1 - capsulflask/shared.py | 6 ++- capsulflask/spoke_api.py | 7 +-- capsulflask/tests/test_console.py | 44 +++++++++------- capsulflask/tests_base.py | 88 ++++++++++++++++++++++++++++++- docs/testing.md | 2 +- 9 files changed, 130 insertions(+), 39 deletions(-) diff --git a/app.py b/app.py index ba485a4..3e3e415 100644 --- a/app.py +++ b/app.py @@ -1,4 +1,5 @@ from capsulflask import create_app +from capsulflask.http_client import MyHTTPClient -app = create_app() +app = create_app(lambda timeout_seconds: MyHTTPClient(timeout_seconds=timeout_seconds)) diff --git a/capsulflask/__init__.py b/capsulflask/__init__.py index ddf18cf..c5396ae 100644 --- a/capsulflask/__init__.py +++ b/capsulflask/__init__.py @@ -21,11 +21,9 @@ from apscheduler.schedulers.background import BackgroundScheduler from capsulflask.shared import * from capsulflask import hub_model, spoke_model, cli from capsulflask.btcpay import client as btcpay -from capsulflask.http_client import MyHTTPClient - -def create_app(): +def create_app(http_client_factory): for var_name in [ "SPOKE_HOST_TOKEN", "HUB_TOKEN", "STRIPE_SECRET_KEY", "BTCPAY_PRIVATE_KEY", "MAIL_PASSWORD" @@ -133,7 +131,10 @@ def create_app(): mylog_warning(app, "No MAIL_SERVER configured. capsul will simply print emails to stdout.") app.config['FLASK_MAIL_INSTANCE'] = StdoutMockFlaskMail() - app.config['HTTP_CLIENT'] = MyHTTPClient(timeout_seconds=int(app.config['INTERNAL_HTTP_TIMEOUT_SECONDS'])) + # allow a mock http client to be injected by the test code. + app.config['HTTP_CLIENT'] = http_client_factory(int(app.config['INTERNAL_HTTP_TIMEOUT_SECONDS'])) + + app.config['BTCPAY_ENABLED'] = False if app.config['BTCPAY_URL'] != "": @@ -160,7 +161,7 @@ def create_app(): # debug mode (flask reloader) runs two copies of the app. When running in debug mode, # we only want to start the scheduler one time. - if is_running_server and (not app.debug or config.get('WERKZEUG_RUN_MAIN') == 'true'): + if is_running_server and not app.config['TESTING'] and (not app.debug or config.get('WERKZEUG_RUN_MAIN') == 'true'): scheduler = BackgroundScheduler() heartbeat_task_url = f"{app.config['HUB_URL']}/hub/heartbeat-task" heartbeat_task_headers = {'Authorization': f"Bearer {app.config['HUB_TOKEN']}"} diff --git a/capsulflask/console.py b/capsulflask/console.py index e49fe9c..d05ffbf 100644 --- a/capsulflask/console.py +++ b/capsulflask/console.py @@ -193,13 +193,6 @@ def detail(id): @account_required def create(): - #raise "console.create()!" - # file_object = open('unittest-output.log', 'a') - # file_object.write("console.create()!\n") - # file_object.close() - - mylog_error(current_app, "console.create()!") - vm_sizes = get_model().vm_sizes_dict() operating_systems = get_model().operating_systems_dict() public_keys_for_account = get_model().list_ssh_public_keys_for_account(session["account"]) diff --git a/capsulflask/hub_model.py b/capsulflask/hub_model.py index 5ed5cf9..689e540 100644 --- a/capsulflask/hub_model.py +++ b/capsulflask/hub_model.py @@ -196,7 +196,6 @@ class CapsulFlaskHub(VirtualizationInterface): def create(self, email: str, id: str, os: str, size: str, template_image_file_name: str, vcpus: int, memory_mb: int, ssh_authorized_keys: list): validate_capsul_id(id) online_hosts = get_model().get_online_hosts() - mylog_debug(current_app, f"hub_model.create(): ${len(online_hosts)} hosts") payload = json.dumps(dict( type="create", email=email, diff --git a/capsulflask/shared.py b/capsulflask/shared.py index 68af334..9ca62cb 100644 --- a/capsulflask/shared.py +++ b/capsulflask/shared.py @@ -2,6 +2,7 @@ import re from flask import current_app, Flask from typing import List +from threading import Lock class OnlineHost: def __init__(self, id: str, url: str): @@ -58,8 +59,10 @@ def my_exec_info_message(exec_info): + mylog_current_test_id_container = { 'value': '', + 'mutex': Lock() } def set_mylog_test_id(test_id): mylog_current_test_id_container['value'] = ".".join(test_id.split(".")[-2:]) @@ -67,10 +70,11 @@ def set_mylog_test_id(test_id): def log_output_for_tests(app: Flask, message: str): if app.config['TESTING'] and mylog_current_test_id_container['value'] != "": + mylog_current_test_id_container['mutex'].acquire() file_object = open('unittest-log-output.log', 'a') file_object.write(f"{mylog_current_test_id_container['value']}: {message}\n") file_object.close() - + mylog_current_test_id_container['mutex'].release() def mylog_debug(app: Flask, message: str): log_output_for_tests(app, f"DEBUG: {message}") diff --git a/capsulflask/spoke_api.py b/capsulflask/spoke_api.py index 79b81ff..d218556 100644 --- a/capsulflask/spoke_api.py +++ b/capsulflask/spoke_api.py @@ -43,9 +43,10 @@ def operation_without_id(): def operation_impl(operation_id: int): if authorized_as_hub(request.headers): - request_body_json = request.json - request_body = json.loads(request_body_json) - #mylog_info(current_app, f"request.json: {request_body}") + request_body = request.json + if not isinstance(request.json, dict) and not isinstance(request.json, list): + request_body = json.loads(request.json) + handlers = { "capacity_avaliable": handle_capacity_avaliable, "get": handle_get, diff --git a/capsulflask/tests/test_console.py b/capsulflask/tests/test_console.py index be27438..a02997a 100644 --- a/capsulflask/tests/test_console.py +++ b/capsulflask/tests/test_console.py @@ -8,6 +8,7 @@ from flask import url_for from capsulflask.db import get_model from capsulflask.tests_base import BaseTestCase +from capsulflask.shared import * from capsulflask.spoke_model import MockSpoke @@ -25,6 +26,30 @@ class ConsoleTests(BaseTestCase): "content": "ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABgQDntq1t8Ddsa2q4p+PM7W4CLYYmxakokRRVLlf7AQlsTJFPsgBe9u0zuoOaKDMkBr0dlnuLm4Eub1Mj+BrdqAokto0YDiAnxUKRuYQKuHySKK8bLkisi2k47jGBDikx/jihgiuFTawo1mYsJJepC7PPwZGsoCImJEgq1L+ug0p3Zrj3QkUx4h25MpCSs2yvfgWjDyN8hEC76O42P+4ETezYrzrd1Kj26hdzHRnrxygvIUOtfau+5ydlaz8xQBEPrEY6/+pKDuwtXg1pBL7GmoUxBXVfHQSgq5s9jIJH+G0CR0ZoHMB25Ln4X/bsCQbLOu21+IGYKSDVM5TIMLtkKUkERQMVWvnpOp1LZKir4dC0m7SW74wpA8+2b1IsURIr9ARYGJpCEv1Q1Wz/X3yTf6Mfey7992MjUc9HcgjgU01/+kYomoXHprzolk+22Gjfgo3a4dRIoTY82GO8kkUKiaWHvDkkVURCY5dpteLA05sk3Z9aRMYsNXPLeOOPfzTlDA0=" } + def setUp(self): + super().setUp() + + + get_model().cursor.execute("DELETE FROM host_operation") + get_model().cursor.execute("DELETE FROM operations") + get_model().cursor.execute("DELETE FROM vm_ssh_host_key") + get_model().cursor.execute("DELETE FROM vm_ssh_authorized_key") + get_model().cursor.execute("DELETE FROM ssh_public_keys") + get_model().cursor.execute("DELETE FROM login_tokens") + get_model().cursor.execute("DELETE FROM vms") + get_model().cursor.execute("DELETE FROM payments") + get_model().cursor.connection.commit() + + self._login('test@example.com') + get_model().create_ssh_public_key('test@example.com', 'key', 'foo') + + # heartbeat all the spokes so that the hub <--> spoke communication can work as normal. + host_ids = get_model().list_hosts_with_networks(None).keys() + for host_id in host_ids: + get_model().host_heartbeat(host_id) + + + def test_index(self): self._login('test@example.com') with self.client as client: @@ -84,10 +109,6 @@ class ConsoleTests(BaseTestCase): 0 ) - file_object = open('unittest-output.log', 'a') - file_object.write(f"{self.id()} captured output:\n{self.logs_from_test.getvalue()}\n") - file_object.close() - def test_create_fails_invalid(self): with self.client as client: client.get(url_for("console.create")) @@ -121,9 +142,8 @@ class ConsoleTests(BaseTestCase): response = client.post(url_for("console.create"), data=data) - + # mylog_info(self.app, get_model().list_all_operations()) - self.assertEqual( len(get_model().list_all_operations()), 1 @@ -196,16 +216,4 @@ class ConsoleTests(BaseTestCase): category='message' ) - def setUp(self): - super().setUp() - self._login('test@example.com') - get_model().create_ssh_public_key('test@example.com', 'key', 'foo') - - def tearDown(self): - super().tearDown() - get_model().cursor.execute("DELETE FROM ssh_public_keys") - get_model().cursor.execute("DELETE FROM login_tokens") - get_model().cursor.execute("DELETE FROM vms") - get_model().cursor.execute("DELETE FROM payments") - get_model().cursor.connection.commit() diff --git a/capsulflask/tests_base.py b/capsulflask/tests_base.py index 9a3f93e..ac0f241 100644 --- a/capsulflask/tests_base.py +++ b/capsulflask/tests_base.py @@ -1,14 +1,26 @@ -from io import StringIO + import logging import unittest import os +import sys +import json +import itertools +import time +import threading +import asyncio +import traceback + +from urllib.parse import urlparse +from typing import List from nanoid import generate +from concurrent.futures import ThreadPoolExecutor from flask_testing import TestCase from flask import current_app from capsulflask import create_app from capsulflask.db import get_model +from capsulflask.http_client import * from capsulflask.shared import * class BaseTestCase(TestCase): @@ -19,7 +31,9 @@ class BaseTestCase(TestCase): os.environ['LOG_LEVEL'] = 'DEBUG' os.environ['SPOKE_MODEL'] = 'mock' os.environ['HUB_MODEL'] = 'capsul-flask' - self.app = create_app() + self1 = self + get_app = lambda: self1.app + self.app = create_app(lambda timeout_seconds: TestHTTPClient(get_app, timeout_seconds)) return self.app def setUp(self): @@ -33,3 +47,73 @@ class BaseTestCase(TestCase): with self.client.session_transaction() as session: session['account'] = user_email session['csrf-token'] = generate() + +class TestHTTPClient: + def __init__(self, get_app, timeout_seconds = 5): + self.timeout_seconds = timeout_seconds + self.get_app = get_app + self.executor = ThreadPoolExecutor() + + + def do_multi_http_sync(self, online_hosts: List[OnlineHost], url_suffix: str, body: str, authorization_header=None) -> List[HTTPResult]: + future = run_coroutine(self.do_multi_http(online_hosts=online_hosts, url_suffix=url_suffix, body=body, authorization_header=authorization_header)) + fromOtherThread = future.result() + toReturn = [] + for individualResult in fromOtherThread: + if individualResult.error != None and individualResult.error != "": + mylog_error(self.get_app(), individualResult.error) + toReturn.append(individualResult.http_result) + + return toReturn + + def do_http_sync(self, url: str, body: str, method="POST", authorization_header=None) -> HTTPResult: + future = run_coroutine(self.do_http(method=method, url=url, body=body, authorization_header=authorization_header)) + fromOtherThread = future.result() + if fromOtherThread.error != None and fromOtherThread.error != "": + mylog_error(self.get_app(), fromOtherThread.error) + return fromOtherThread.http_result + + async def do_http(self, url: str, body: str, method="POST", authorization_header=None) -> InterThreadResult: + path = urlparse(url).path + + headers = {} + if authorization_header != None: + headers['Authorization'] = authorization_header + if body: + headers['Content-Type'] = "application/json" + + #mylog_info(self.get_app(), f"path, data=body, headers=headers: {path}, {body}, {headers}") + + do_request = None + if method == "POST": + do_request = lambda: self.get_app().test_client().post(path, data=body, headers=headers) + if method == "GET": + do_request = lambda: self.get_app().test_client().get(path, headers=headers) + + response = None + try: + response = await get_event_loop().run_in_executor(self.executor, do_request) + except: + traceback.print_exc() + error_message = my_exec_info_message(sys.exc_info()) + response_body = json.dumps({"error_message": f"do_http (HTTP {method} {url}) {error_message}"}) + + return InterThreadResult( + HTTPResult(-1, response_body), + f"""do_http (HTTP {method} {url}) failed with: {error_message}""" + ) + + return InterThreadResult(HTTPResult(response.status_code, response.get_data()), None) + + async def do_multi_http(self, online_hosts: List[OnlineHost], url_suffix: str, body: str, authorization_header=None) -> List[InterThreadResult]: + tasks = [] + # append to tasks in the same order as online_hosts + for host in online_hosts: + tasks.append( + self.do_http(url=f"{host.url}{url_suffix}", body=body, authorization_header=authorization_header) + ) + # gather is like Promise.all from javascript, it returns a future which resolves to an array of results + # in the same order as the tasks that we passed in -- which were in the same order as online_hosts + results = await asyncio.gather(*tasks) + + return results \ No newline at end of file diff --git a/docs/testing.md b/docs/testing.md index c29e5ee..3ae9a6a 100644 --- a/docs/testing.md +++ b/docs/testing.md @@ -6,7 +6,7 @@ To run tests: 1. create a Postgres database called `capsulflask_test` - e.g.: `docker exec -it 98e1ddfbbffb createdb -U postgres -O postgres capsulflask_test` - (`98e1ddfbbffb` is the docker container ID of the postgres container) -2. run `python3 -m unittest && cat unittest-log-output.log && rm unittest-log-output.log` +2. run `python3 -m unittest; cat unittest-log-output.log; rm unittest-log-output.log` **NOTE** that right now we can't figure out how to get the tests to properly output the log messages that happened when they failed, (or passed), so for now we have hacked it to write to a file. -- 2.45.2