add logging (#230)

Author: ryantanen

docker/team-sync/sync/modules/bitwarden.py

@@ -1,12 +1,14 @@
 import base64
 import hashlib
+import logging
 import os
 import subprocess
 import time
 
 import requests
 from pyotp import TOTP
 
+logger = logging.getLogger("sync.bitwarden")
 
 BITWARDEN_URL = os.environ.get("BITWARDEN_URL")
 
@@ -31,24 +33,27 @@ def sync(teams, users):
     totp = TOTP(BITWARDEN_2FA_TOKEN)
 
     # Configure bitwarden CLI
+    logger.info("Configuring Bitwarden CLI...")
     subprocess.run(["bw", "config", "server", BITWARDEN_URL])
+    logger.info("Logging in to Bitwarden...")
     subprocess.run(
         ["bw", "login", BITWARDEN_EMAIL, BITWARDEN_PASSWORD, "--code", totp.now()]
     )
     res = subprocess.run(
         ["bw", "unlock", BITWARDEN_PASSWORD, "--raw"], capture_output=True
     )
     os.environ["BW_SESSION"] = res.stdout.decode("utf-8")
-    # Add newline to logs
-    print()
 
     # Log into admin interface, invite users, and check for 2FA
+    logger.info("Logging in to admin interface...")
     session = requests.Session()
     session.post(buildURL("/admin/"), {"token": BITWARDEN_ADMIN_TOKEN})
     raw_users = session.get(buildURL("/admin/users/"))
 
     # Generate Map of email to 2FA status
     twofac = {user["Email"]: user["TwoFactorEnabled"] for user in raw_users.json()}
+    twofac_enabled = sum(1 for v in twofac.values() if v)
+    logger.info("Found %d existing user(s), %d with 2FA enabled", len(twofac), twofac_enabled)
 
     # Log into web vault
     res = session.post(
@@ -82,33 +87,37 @@ def sync(teams, users):
     body = res.json()
     if "access_token" not in body:
         # Authentication failed. Most likely due to TOTP
-        print("Bitwarden: TOTP code invalid")
+        logger.error("Authentication failed - TOTP code invalid")
         # Sleep to ensure next job uses a different TOTP code
         time.sleep(45)
         exit(1)
+    logger.info("Successfully authenticated to web vault")
     session.headers.update({"Authorization": f"Bearer {body['access_token']}"})
 
     # Generate mapping of organization to uuid
     res = session.get(buildURL("/api/sync?excludeDomains=true"))
     body = res.json()
     raw_orgs = body["Profile"]["Organizations"]
     organizations = {org["Name"]: org["Id"] for org in raw_orgs}
+    logger.info("Found %d organization(s): %s", len(organizations), ", ".join(organizations.keys()))
 
     # Grant team leads access to bitwarden organizations
     for team in teams["leads"]:
         name = team.name[:-6]  # Strip Leads
-        invite_members(organizations[name], team, users, session)
-        confirm_access(organizations[name], twofac, session)
+        logger.info("Syncing leads team '%s' -> org '%s'", team.name, name)
+        invite_members(organizations[name], name, team, users, session)
+        confirm_access(organizations[name], name, twofac, session)
 
     # Grant directors access to director organization
     for team in teams["directors"]:
         name = team.name
-        invite_members(organizations[name], team, users, session)
-        confirm_access(organizations[name], twofac, session)
+        logger.info("Syncing directors team '%s' -> org '%s'", team.name, name)
+        invite_members(organizations[name], name, team, users, session)
+        confirm_access(organizations[name], name, twofac, session)
     return
 
 
-def invite_members(organization_uuid, team, users, session):
+def invite_members(organization_uuid, org_name, team, users, session):
     """
     Given a bitwarden organization and a GitHub team, invite all members of that team
     into the organization
@@ -119,6 +128,7 @@ def invite_members(organization_uuid, team, users, session):
         gh_id = member.login.lower()
         if gh_id in users:
             email = users[gh_id]["email"]
+            logger.info("Inviting %s (%s) to org '%s'", gh_id, email, org_name)
             # Make individual requests because bw errors out if an email is already invited
             data = {
                 "emails": [email],
@@ -139,24 +149,32 @@ def invite_members(organization_uuid, team, users, session):
                     "manageUsers": False,
                 },
             }
-            session.post(
+            res = session.post(
                 buildURL(f"/api/organizations/{organization_uuid}/users/invite"),
                 json=data,
             )
+            if res.ok:
+                logger.info("  -> Invite sent successfully")
+            else:
+                logger.warning("  -> Invite returned status %d (may already be invited)", res.status_code)
+        else:
+            logger.warning("Skipping %s (not found in roster)", gh_id)
 
 
-def confirm_access(organization_uuid, twofac, session):
+def confirm_access(organization_uuid, org_name, twofac, session):
     """
     Confirm all invited users to an organization if they have enabled 2Fa
     """
     res = session.get(buildURL(f"/api/organizations/{organization_uuid}/users"))
     body = res.json()
+    logger.info("Checking %d user(s) in org '%s' for confirmation", len(body["Data"]), org_name)
     for user in body["Data"]:
         # If user has 2FA enabled, confirm access
         email = user["Email"]
         id_ = user["Id"]
         accepted = user["Status"] == 1
         if accepted and email in twofac and twofac[email]:
+            logger.info("Confirming access for %s in org '%s' (2FA enabled, invite accepted)", email, org_name)
             # I can't figure out how to reverse engineer the confirm route after a user accepts
             # an invite. I know that we encrypt an "org key" using the invited user's public key
             # however, I'm not sure what that "org key" is. Looking at the official CLI, I think
@@ -172,6 +190,8 @@ def confirm_access(organization_uuid, twofac, session):
                     organization_uuid,
                 ]
             )
+        elif accepted and email in twofac and not twofac[email]:
+            logger.warning("Skipping confirmation for %s in org '%s' (2FA not enabled)", email, org_name)
 
 
 # Crypto copied from

docker/team-sync/sync/modules/platform.py

@@ -1,7 +1,9 @@
+import logging
 import os
 
 import requests
 
+logger = logging.getLogger("sync.platform")
 
 PLATFORM_API_KEY = os.environ.get("PLATFORM_API_KEY", "")
 
@@ -25,9 +27,13 @@ def sync(teams, users):
             pennkey = users.get(gh_username, {}).get("pennkey", None)
             if pennkey:
                 content.setdefault(pennkey, []).append(slug)
+                logger.info("Granting %s (%s) -> %s", pennkey, gh_username, slug)
                 # If user is a lead of clubs, also make h@p admin
                 if slug == "penn_clubs_admin":
                     content[pennkey].append("hub_admin")
+                    logger.info("Granting %s (%s) -> hub_admin (clubs lead)", pennkey, gh_username)
+            else:
+                logger.warning("Skipping %s (not found in roster)", gh_username)
 
     # Directors are admins on all products
     for team in teams["directors"]:
@@ -36,9 +42,14 @@ def sync(teams, users):
             pennkey = users.get(gh_username, {}).get("pennkey", None)
             if pennkey:
                 content[pennkey] = team_slugs
+                logger.info("Granting %s (%s) -> all admin roles (director)", pennkey, gh_username)
+            else:
+                logger.warning("Skipping director %s (not found in roster)", gh_username)
 
+    logger.info("Syncing %d user(s) with admin permissions to platform...", len(content))
     headers = {"Authorization": f"Api-Key {PLATFORM_API_KEY}"}
-    requests.post(
+    res = requests.post(
         "https://platform.pennlabs.org/accounts/productadmin/", json=content, headers=headers
     )
+    logger.info("Platform API responded with status %d", res.status_code)
     return

docker/team-sync/sync/modules/vault.py

@@ -1,25 +1,33 @@
+import logging
 import os
 
 import boto3
 import hvac
 from jinja2 import Template
 
+logger = logging.getLogger("sync.vault")
+
 
 def sync(teams, users):
+    logger.info("Connecting to Vault via AWS IAM auth...")
     session = boto3.Session()
     credentials = session.get_credentials()
     client = hvac.Client(url=os.getenv("VAULT_ADDR"))
     client.auth.aws.iam_login(credentials.access_key, credentials.secret_key, credentials.token)
     if not client.sys.is_sealed():
+        logger.info("Vault is unsealed, proceeding with policy sync")
         # Apply normal team policies
         with open("sync/modules/user-policy.hcl.j2") as f:
             t = Template(f.read())
             for team in teams["leads"]:
                 base_team_slug = team.slug.replace("-leads", "")
                 repos = [x.name for x in team.get_repos()]
+                logger.info("Creating/updating policy '%s' with repos: %s", base_team_slug, ", ".join(repos))
                 pol = t.render(team_name=base_team_slug, repos=repos)
                 client.sys.create_or_update_policy(name=base_team_slug, policy=pol)
+                logger.info("Mapping GitHub team '%s' -> Vault policy '%s'", team.slug, base_team_slug)
                 client.auth.github.map_team(team_name=team.slug, policies=[base_team_slug])
+        logger.info("Synced policies for %d lead team(s)", len(teams["leads"]))
     else:
-        print("vault: Vault sealed. Stopping.")
+        logger.error("Vault sealed. Stopping.")
         exit(1)

docker/team-sync/sync/sync.py

@@ -1,11 +1,20 @@
 #!/usr/bin/env python
 import importlib.util
+import logging
 import os
 import pkgutil
 import yaml
 
 from github import Auth, Github
 
+logging.basicConfig(
+    level=logging.INFO,
+    format="%(asctime)s [%(levelname)s] %(name)s - %(message)s",
+    datefmt="%Y-%m-%d %H:%M:%S",
+)
+logger = logging.getLogger("sync")
+
+
 def get_user_info():
     """
     Create a dictionary of GitHub usernames to PennKeys and emails.
@@ -31,6 +40,7 @@ def run():
     g = Github(auth=Auth.Token(os.getenv("GITHUB_TOKEN")))
 
     # Generate dictionary of teams
+    logger.info("Fetching teams from pennlabs GitHub organization...")
     teams = {}
     for team in g.get_organization("pennlabs").get_teams():
         if team.name == "Alumni":  # Found an Alumni Team
@@ -42,19 +52,28 @@ def run():
         else:  # Found a Regular Team
             teams.setdefault("members", []).append(team)
 
+    for category, team_list in teams.items():
+        team_names = [t.name for t in team_list]
+        logger.info("Found %d %s team(s): %s", len(team_list), category, ", ".join(team_names))
+
     # Generate dictionary of GitHub usernames to PennKey
     users = get_user_info()
+    logger.info("Loaded %d user(s) from roster", len(users))
 
     # Dynamically find each module and run its sync method
     location = os.path.join(os.path.dirname(os.path.abspath(__file__)), "modules")
     for finder, name, _ in pkgutil.walk_packages([location]):
         try:
+            logger.info("=" * 50)
+            logger.info("Running module: %s", name)
+            logger.info("=" * 50)
             spec = finder.find_spec(name)
             module = importlib.util.module_from_spec(spec)
             spec.loader.exec_module(module)
             module.sync(teams, users)
+            logger.info("Module '%s' completed successfully", name)
         except (AttributeError, TypeError) as e:
-            print(f"Could not execute module '{name}'. The following exception occurred: {e}")
+            logger.error("Could not execute module '%s': %s", name, e)
 
 
 if __name__ == "__main__":