From 15af4c5871a5b43eee08f546cf50458aaf92c39f Mon Sep 17 00:00:00 2001
From: Arie Peterson <arie@greenhost.nl>
Date: Thu, 6 Jun 2024 12:28:17 +0200
Subject: [PATCH] Fine-tune backend logging and use LOG_LEVEL env var
---
backend/app.py | 7 ++--
backend/cluster_config.py | 12 +++----
backend/config.py | 2 ++
backend/helpers/kubernetes.py | 18 +++++-----
backend/helpers/provision.py | 68 +++++++++++++++++------------------
dev.sh | 2 +-
6 files changed, 56 insertions(+), 53 deletions(-)
diff --git a/backend/app.py b/backend/app.py
index 76958441..5190cf2d 100644
--- a/backend/app.py
+++ b/backend/app.py
@@ -21,6 +21,7 @@ from areas import resources
from areas import roles
from areas import tags
from cliapp import cliapp
+import config
import helpers.kubernetes
import helpers.provision
import helpers.threads
@@ -49,6 +50,7 @@ import os
import sys
# Configure logging.
+log_level = logging.getLevelName(config.LOG_LEVEL or 'INFO')
from logging.config import dictConfig
dictConfig({
'version': 1,
@@ -59,10 +61,11 @@ dictConfig({
'class': 'logging.StreamHandler',
'stream': 'ext://flask.logging.wsgi_errors_stream',
'formatter': 'default',
+ 'level': log_level,
}},
'root': {
- 'level': 'INFO',
'handlers': ['wsgi'],
+ 'level': log_level,
},
# Loggers are created also by alembic, flask_migrate, etc. Without this
# setting, those loggers seem to be ignored.
@@ -76,8 +79,6 @@ app.config["SQLALCHEMY_DATABASE_URI"] = SQLALCHEMY_DATABASE_URI
app.config["SQLALCHEMY_ENGINE_OPTIONS"] = {'pool_pre_ping': True}
app.config["SQLALCHEMY_TRACK_MODIFICATIONS"] = SQLALCHEMY_TRACK_MODIFICATIONS
-app.logger.setLevel(logging.INFO)
-
cors = CORS(app)
db.init_app(app)
diff --git a/backend/cluster_config.py b/backend/cluster_config.py
index 4ced17f7..7934213f 100644
--- a/backend/cluster_config.py
+++ b/backend/cluster_config.py
@@ -11,7 +11,7 @@ import helpers.kubernetes as k8s
# Read in two configmaps from the cluster, which specify which apps should be
# present in the database. Returns the list of app slugs.
def populate_apps():
- logging.info("cluster_config: populating apps")
+ logging.debug("cluster_config: populating apps")
database_apps = {}
for app in App.query.all():
slug = app.slug
@@ -29,7 +29,7 @@ def _populate_apps_from(database_apps, configmap_name):
slugs = []
cm_apps = k8s.get_kubernetes_config_map_data(configmap_name, "flux-system")
if cm_apps is None:
- logging.info(f"Could not find configmap '{configmap_name}' in namespace 'flux-system'; ignoring.")
+ logging.debug(f"Could not find configmap '{configmap_name}' in namespace 'flux-system'; ignoring.")
else:
for app_slug, app_data in cm_apps.items():
logging.debug(f"configmap app: {app_slug}")
@@ -54,7 +54,7 @@ def _populate_apps_from(database_apps, configmap_name):
# Read in two configmaps from the cluster, which specify which oauthclients
# should be present in the database.
def populate_oauthclients():
- logging.info("cluster_config: populating oauthclients")
+ logging.debug("cluster_config: populating oauthclients")
database_oauthclients = {}
for client in OAuthClientApp.query.all():
id = client.oauthclient_id
@@ -69,7 +69,7 @@ def populate_oauthclients():
def _populate_oauthclients_from(database_oauthclients, configmap_name):
cm_oauthclients = k8s.get_kubernetes_config_map_data(configmap_name, "flux-system")
if cm_oauthclients is None:
- logging.info(f"Could not find configmap '{configmap_name}' in namespace 'flux-system'; ignoring.")
+ logging.debug(f"Could not find configmap '{configmap_name}' in namespace 'flux-system'; ignoring.")
else:
for client_id, client_app in cm_oauthclients.items():
logging.debug(f"configmap oauthclient: {client_id}")
@@ -96,9 +96,9 @@ def populate_scim_config(apps):
secret_name = f"stackspin-scim-{app}"
scim_config = k8s.get_kubernetes_secret_data(secret_name, "flux-system")
if scim_config is None:
- logging.info(f"Could not find secret '{secret_name}' in namespace 'flux-system'; ignoring.")
+ logging.debug(f"Could not find secret '{secret_name}' in namespace 'flux-system'; ignoring.")
continue
- logging.info(f"Processing secret stackspin-scim-{app}")
+ logging.debug(f"Processing secret stackspin-scim-{app}")
app = App.query.filter_by(slug=app).first()
if not app:
logging.error(f" could not find app with slug {app}")
diff --git a/backend/config.py b/backend/config.py
index ffa09677..2822fb86 100644
--- a/backend/config.py
+++ b/backend/config.py
@@ -1,5 +1,7 @@
import os
+LOG_LEVEL = os.environ.get("LOG_LEVEL")
+
SECRET_KEY = os.environ.get("SECRET_KEY")
HYDRA_CLIENT_ID = os.environ.get("HYDRA_CLIENT_ID")
HYDRA_CLIENT_SECRET = os.environ.get("HYDRA_CLIENT_SECRET")
diff --git a/backend/helpers/kubernetes.py b/backend/helpers/kubernetes.py
index 2c49d6ec..3aa3afbb 100644
--- a/backend/helpers/kubernetes.py
+++ b/backend/helpers/kubernetes.py
@@ -67,7 +67,7 @@ def create_variables_secret(app_slug, variables_filepath):
elif current_secret_data.keys() != new_secret_dict["data"].keys():
# Update current secret with new keys
update_secret = True
- current_app.logger.info(
+ current_app.logger.debug(
f"Secret {secret_name} in namespace {secret_namespace}"
" already exists. Merging..."
)
@@ -75,12 +75,12 @@ def create_variables_secret(app_slug, variables_filepath):
new_secret_dict["data"] |= current_secret_data
else:
# Do Nothing
- current_app.logger.info(
+ current_app.logger.debug(
f"Secret {secret_name} in namespace {secret_namespace}"
" is already in a good state, doing nothing."
)
return True
- current_app.logger.info(
+ current_app.logger.debug(
f"Storing secret {secret_name} in namespace"
f" {secret_namespace} in cluster."
)
@@ -184,9 +184,9 @@ def store_kubernetes_secret(secret_dict, namespace, update=False):
namespace=namespace
)
except FailToCreateError as ex:
- current_app.logger.info(f"Secret not created because of exception {ex}")
+ current_app.logger.warning(f"Secret not created because of exception {ex}")
raise ex
- current_app.logger.info(f"Secret {verb} with api response: {api_response}")
+ current_app.logger.debug(f"Secret {verb} with api response: {api_response}")
def store_kustomization(kustomization_template_filepath, app_slug):
@@ -212,7 +212,7 @@ def store_kustomization(kustomization_template_filepath, app_slug):
plural="kustomizations",
body=kustomization_dict)
except FailToCreateError as ex:
- current_app.logger.info(
+ current_app.logger.warning(
f"Could not create {app_slug} Kustomization because of exception {ex}")
raise ex
current_app.logger.debug(f"Kustomization created with api response: {api_response}")
@@ -244,7 +244,7 @@ def delete_kustomization(kustomization_name):
name=kustomization_name,
body=body)
except ApiException as ex:
- current_app.logger.info(
+ current_app.logger.warning(
f"Could not delete {kustomization_name} Kustomization because of exception {ex}")
raise ex
current_app.logger.debug(f"Kustomization deleted with api response: {api_response}")
@@ -453,7 +453,7 @@ def watch_dashboard_config(app, reload):
label_selector="stackspin.net/scim-config=1",
watch=True
):
- current_app.logger.info(f"{event['type']} SCIM config secret: {event['object'].metadata.name}")
+ current_app.logger.debug(f"{event['type']} SCIM config secret: {event['object'].metadata.name}")
debounced_reload()
threading.Thread(target=watch_scim_secrets).start()
def watch_dashboard_configmaps():
@@ -464,7 +464,7 @@ def watch_dashboard_config(app, reload):
label_selector="stackspin.net/dashboard-config=1",
watch=True
):
- current_app.logger.info(f"{event['type']} dashboard config configmap: {event['object'].metadata.name}")
+ current_app.logger.debug(f"{event['type']} dashboard config configmap: {event['object'].metadata.name}")
debounced_reload()
threading.Thread(target=watch_dashboard_configmaps).start()
diff --git a/backend/helpers/provision.py b/backend/helpers/provision.py
index 4c9c1599..beaba6a9 100644
--- a/backend/helpers/provision.py
+++ b/backend/helpers/provision.py
@@ -34,20 +34,20 @@ class Group:
def add_member(self, user):
if user.scim_id not in self.members:
- logging.info(f"Adding user to dict: {user.displayName} ({user.scim_id})")
+ logging.debug(f"Adding user to dict: {user.displayName} ({user.scim_id})")
self.members[user.scim_id] = user
self.modified = True
def remove_member(self, user):
if user.scim_id in self.members:
- logging.info(f"Found user to remove from dict: {user.displayName} ({user.scim_id})")
+ logging.debug(f"Found user to remove from dict: {user.displayName} ({user.scim_id})")
del self.members[user.scim_id]
self.modified = True
def debug(self):
- logging.info(f"Group {self.displayName} ({self.scim_id})")
+ logging.debug(f"Group {self.displayName} ({self.scim_id})")
for _, member in self.members.items():
- logging.info(f" with user {member.displayName} ({member.scim_id})")
+ logging.debug(f" with user {member.displayName} ({member.scim_id})")
# Read from the database which users need to be provisioned on which apps, and
# do the corresponding SCIM calls to those apps to do the actual provisioning.
@@ -96,7 +96,7 @@ class Provision:
for app_id, app in self.scim_apps.items():
existing_users[app_id] = self._get_existing_users(app)
for userId, u in existing_users[app_id].items():
- logging.info(f"Existing user in {app.slug}: {u.displayName} ({userId})")
+ logging.debug(f"Existing user in {app.slug}: {u.displayName} ({userId})")
if app.scim_group_support:
existing_groups[app_id] = self._get_existing_groups(app)
for _, g in existing_groups[app_id].items():
@@ -118,7 +118,7 @@ class Provision:
AppRole.provision_status.in_((ProvisionStatus.SyncNeeded, ProvisionStatus.ToDelete))
)
for app_role in app_roles:
- # logging.info(f"found app_role: {app_role}")
+ logging.debug(f"found app_role: {app_role}")
# Check if this app supports SCIM at all and is configured for it.
app_role.last_provision_attempt = datetime.now()
app = app_role.app
@@ -131,10 +131,10 @@ class Provision:
# pre-fetched list we got via SCIM.
existing_user = existing_users[app.id].get(app_role.user_id)
if existing_user is not None:
- logging.info(f"User {app_role.user_id} already exists in the app {app.slug}.")
+ logging.debug(f"User {app_role.user_id} already exists in the app {app.slug}.")
if app_role.role_id == Role.NO_ACCESS_ROLE_ID:
if existing_user is None:
- logging.info(f"User without access does not exist yet in {app.slug}, so nothing to do.")
+ logging.debug(f"User without access does not exist yet in {app.slug}, so nothing to do.")
# We have not provisioned this user in this app yet, so we
# don't have to do anything at this point.
app_role.provision_status = ProvisionStatus.Provisioned
@@ -142,7 +142,7 @@ class Provision:
db.session.commit()
continue
else:
- logging.info(f"User without access exists in the app {app.slug}; we continue so we can disable the user in the app.")
+ logging.debug(f"User without access exists in the app {app.slug}; we continue so we can disable the user in the app.")
try:
self._provision_user(app_role, app, existing_user, admin_group.get(app.id))
except ProvisionError as ex:
@@ -152,11 +152,11 @@ class Provision:
for app_id, app in self.scim_apps.items():
if app.scim_group_support:
if admin_group[app_id].modified:
- logging.info(f"Admin group for {app.slug} was modified, so updating it via SCIM.")
+ logging.debug(f"Admin group for {app.slug} was modified, so updating it via SCIM.")
admin_group[app_id].debug()
self._provision_group(admin_group[app_id], app)
else:
- logging.info(f"Admin group for {app.slug} was not modified.")
+ logging.debug(f"Admin group for {app.slug} was not modified.")
# Provision the user via SCIM PUT or POST, based on the user and role
# information in `app_role`, and on the existing user object in the app
@@ -164,7 +164,7 @@ class Provision:
# `admin_group` object so we may later add or remove the user to/from the
# admin group.
def _provision_user(self, app_role, app, existing_user, admin_group):
- logging.info(f"Reconciling user {app_role.user_id}")
+ logging.debug(f"Reconciling user {app_role.user_id}")
app = self.scim_apps[app.id]
scim_headers = {
'Authorization': 'Bearer ' + app.scim_token
@@ -177,7 +177,7 @@ class Provision:
logging.info(f"Deleting user {app_role.user_id} from {app.slug}")
url = f"{app.scim_url}Users/{existing_user.scim_id}"
response = requests.delete(url, headers=scim_headers)
- logging.info(f"SCIM http status: {response.status_code}")
+ logging.debug(f"SCIM http status: {response.status_code}")
if response.status_code == 204:
db.session.delete(app_role)
db.session.commit()
@@ -187,7 +187,7 @@ class Provision:
return
# Get the related user object
- logging.info(f"Getting user data from Kratos.")
+ logging.debug(f"Getting user data from Kratos.")
try:
kratos_user = KratosUser(self.kratos_identity_api, app_role.user_id)
except BackendError as e:
@@ -202,7 +202,7 @@ class Provision:
active = False
else:
active = True
- logging.info(f"Active user: {active}")
+ logging.debug(f"Active user: {active}")
data = {
'schemas': ['urn:ietf:params:scim:schemas:core:2.0:User'],
'externalId': app_role.user_id,
@@ -243,18 +243,18 @@ class Provision:
if existing_user is None:
url = f"{app.scim_url}/Users"
response = requests.post(url, headers=scim_headers, json=data)
- logging.info(f"Post SCIM user: {url} with data: {data} getting status: {response.status_code}")
+ logging.debug(f"Post SCIM user: {url} with data: {data} getting status: {response.status_code}")
else:
url = f"{app.scim_url}/Users/{existing_user.scim_id}"
response = requests.put(url, headers=scim_headers, json=data)
- logging.info(f"Put SCIM user: {url} with data: {data} getting status: {response.status_code}")
+ logging.debug(f"Put SCIM user: {url} with data: {data} getting status: {response.status_code}")
try:
response_json = response.json()
except json.decoder.JSONDecodeError as e:
logging.info("SCIM result was not json")
logging.info(response.content)
raise ProvisionError("App returned non-json data in SCIM user put/post.")
- logging.info(f"got: {response_json}")
+ logging.debug(f"got: {response_json}")
if existing_user is None:
# Because this is a new user for the app, we should read off its
# SCIM ID and store that in the Stackspin database.
@@ -263,12 +263,12 @@ class Provision:
user = User(app_role.user_id, response_json['id'], kratos_user.name)
if app.scim_group_support:
if app_role.role_id == Role.ADMIN_ROLE_ID:
- logging.info(f"Adding user to admin group: {user.displayName} ({user.kratos_id})")
+ logging.debug(f"Adding user to admin group: {user.displayName} ({user.kratos_id})")
admin_group.add_member(user)
else:
- logging.info(f"Removing user from admin group: {user.displayName} ({user.kratos_id})")
+ logging.debug(f"Removing user from admin group: {user.displayName} ({user.kratos_id})")
admin_group.remove_member(user)
- logging.info("After adding/removing user:")
+ logging.debug("After adding/removing user:")
admin_group.debug()
app_role.status = ProvisionStatus.Provisioned
@@ -277,7 +277,7 @@ class Provision:
return
def _scim_list_users(self, app):
- logging.info(f"Info: Getting list of current users from {app.slug} via SCIM.")
+ logging.debug(f"Getting list of current users from {app.slug} via SCIM.")
# SCIM prescribes a 1-based index.
startIndex = 1
# Get this many items per request. The application might further reduce
@@ -292,7 +292,7 @@ class Provision:
'Authorization': 'Bearer ' + app.scim_token
}
response = requests.get(url, headers=scim_headers)
- logging.info(f"SCIM http status: {response.status_code}")
+ logging.debug(f"SCIM http status: {response.status_code}")
try:
response_json = response.json()
except json.decoder.JSONDecodeError as e:
@@ -305,7 +305,7 @@ class Provision:
running_total = running_total + added
if running_total == response_json['totalResults'] or added == 0:
# We've got them all.
- logging.info(f"All existing users for {app.slug}: {users}")
+ logging.debug(f"All existing users for {app.slug}: {users}")
return users
else:
startIndex = startIndex + added
@@ -318,7 +318,7 @@ class Provision:
for u in scim_users:
kratos_id = u.get('externalId')
if not kratos_id:
- logging.info(f"Got user without externalId: {u}")
+ logging.debug(f"Got user without externalId: {u}")
# Users that were created just-in-time when logging in to the
# app will not have `externalId` set, so we attempt to look up
# the user from our Stackspin database based on the app ID and
@@ -328,7 +328,7 @@ class Provision:
scim_id=u['id']
).first()
if app_role is None:
- logging.info(f" SCIM ID {u['id']} not listed in database.")
+ logging.debug(f" SCIM ID {u['id']} not listed in database.")
# We can't find this app user in our Stackspin database, at
# least based on the SCIM ID. It could be that it was
# created before the introduction of SCIM, or was created
@@ -350,7 +350,7 @@ class Provision:
if kratos_user is None:
# This user is not known at all by Stackspin, so
# we'll ignore it.
- logging.info(f" SCIM user unknown, ignoring.")
+ logging.debug(f" SCIM user unknown, ignoring.")
continue
# We found the user based on email address. We'll
# store the SCIM ID for this user in the Stackspin
@@ -363,7 +363,7 @@ class Provision:
if app_role is not None:
app_role.scim_id = u['id']
db.session.commit()
- logging.info(f" Stored SCIM ID {u['id']} for user {kratos_user.uuid} for app {app.slug}")
+ logging.debug(f" Stored SCIM ID {u['id']} for user {kratos_user.uuid} for app {app.slug}")
kratos_id = kratos_user.uuid
else:
kratos_id = app_role.user_id
@@ -371,20 +371,20 @@ class Provision:
return users
def _get_existing_groups(self, app):
- logging.info(f"Info: Getting list of current groups from {app.slug} via SCIM.")
+ logging.debug(f"Getting list of current groups from {app.slug} via SCIM.")
url = f"{app.scim_url}/Groups"
scim_headers = {
'Authorization': 'Bearer ' + app.scim_token
}
response = requests.get(url, headers=scim_headers)
- logging.info(f"SCIM http status: {response.status_code}")
+ logging.debug(f"SCIM http status: {response.status_code}")
try:
response_json = response.json()
except json.decoder.JSONDecodeError as e:
logging.info("SCIM result was not json")
logging.info(response.content)
raise ProvisionError("Failed to get existing groups from {app.slug}")
- logging.info(f"got: {response_json}")
+ logging.debug(f"got: {response_json}")
groups = {}
for group in response_json['Resources']:
members = {}
@@ -395,14 +395,14 @@ class Provision:
return groups
def _provision_group(self, group, app):
- logging.info(f"Reconciling group {group.scim_id}")
+ logging.debug(f"Reconciling group {group.scim_id}")
scim_headers = {
'Authorization': 'Bearer ' + app.scim_token
}
member_data = [
{'value': member.scim_id, 'display': member.displayName, '$ref': member.ref(app.scim_url)}
for _, member in group.members.items()]
- logging.info(f"Will update admin group for {app.slug} with member data {member_data}")
+ logging.debug(f"Will update admin group for {app.slug} with member data {member_data}")
data = {
'schemas': ['urn:ietf:params:scim:schemas:core:2.0:Group'],
'displayName': group.displayName,
@@ -410,7 +410,7 @@ class Provision:
}
url = f"{app.scim_url}/Groups/{group.scim_id}"
response = requests.put(url, headers=scim_headers, json=data)
- logging.info(f"SCIM http status: {response.status_code}")
+ logging.debug(f"SCIM http status: {response.status_code}")
try:
response_json = response.json()
except json.decoder.JSONDecodeError as e:
diff --git a/dev.sh b/dev.sh
index 38591317..fdf7d7e8 100755
--- a/dev.sh
+++ b/dev.sh
@@ -103,7 +103,7 @@ runBackend() {
echo "Stopping any previous intercept for dashboard-backend..."
telepresence leave dashboard-backend
echo "Starting new intercept for dashboard-backend..."
- telepresence intercept dashboard-backend --service=dashboard-backend --port 5000:80 --mount=true --replace --env-file=./backend.env -- env TELEPRESENCE_MODE=native flask run --reload
+ telepresence intercept dashboard-backend --service=dashboard-backend --port 5000:80 --mount=true --replace --env-file=./backend.env -- env TELEPRESENCE_MODE=native FLASK_DEBUG=1 LOG_LEVEL=DEBUG flask run --reload
deactivate
popd > /dev/null
;;
--
GitLab