[LLSC-51] Fix logging within backend (#14)

## Notion ticket link
<!-- Please replace with your ticket's URL -->
[Add startup Logs (Fix logging) for
backend](https://www.notion.so/uwblueprintexecs/Startup-logs-14e10f3fb1dc8015a1c5c65e9dcd2c55?pvs=4)


<!-- Give a quick summary of the implementation details, provide design
justifications if necessary -->
## Implementation description
* We were having issues troubleshooting where some people may have
startup issues, since errors weren't being emitted to the console
(through standard error). After deep diving, we realized that the
`alembic.ini` config was taking control over logging configurations and
suppressing other loggers. Given that going without the `alembic.ini`
config doesn't seem viable at the moment, I've stuck to basing all
loggers in the API off of one sublogger, and using a function to create
child loggers for more context.


<!-- What should the reviewer do to verify your changes? Describe
expected results and include screenshots when appropriate -->
## Steps to test
1. Run `pdm run dev`
2. Add a new logger using the instructions in the README to another
service, ie.
To add a logger to a new service or file, use the `LOGGER_NAME` function
in `app/utilities/constants.py`

```python
from app.utilities.constants import LOGGER_NAME

log = logging.getLogger(LOGGER_NAME("my_service"))
```

<!-- Draw attention to the substantial parts of your PR or anything
you'd like a second opinion on -->
## What should reviewers focus on?
* Whether logging works


## Checklist
- [x] My PR name is descriptive and in imperative tense
- [x] My commit messages are descriptive and in imperative tense. My
commits are atomic and trivial commits are squashed or fixup'd into
non-trivial commits
- [x] I have run the appropriate linter(s)
- [x] I have requested a review from the PL, as well as other devs who
have background knowledge on this PR or who will be building on top of
this PR

---------

Co-authored-by: Evan Wu <[email protected]>

Author: mslwang

README.md

@@ -243,6 +243,18 @@ pdm run ruff format .
 
 All code needs to pass ruff formatting and linting before it can be merged.
 
+### Logging
+
+To add a logger to a new service or file, use the `LOGGER_NAME` function in `app/utilities/constants.py`
+
+```python
+from app.utilities.constants import LOGGER_NAME
+
+log = logging.getLogger(LOGGER_NAME("my_service"))
+```
+
+If you'd like to create a new logger name in the hierarchy, you'll need to add it to `alembic.ini` under the logger section. Following the pre-existing examples for `logger_uvicorn` for example.
+
 ### Frontend
 
 #### Prettier

backend/README.md

@@ -136,3 +136,15 @@ To apply the migration, run the following command:
 ```bash
 pdm run alembic upgrade head
 ```
+
+### Logging
+
+To add a logger to a new service or file, use the `LOGGER_NAME` function in `app/utilities/constants.py`
+
+```python
+from app.utilities.constants import LOGGER_NAME
+
+log = logging.getLogger(LOGGER_NAME("my_service"))
+```
+
+If you'd like to create a new logger name in the hierarchy, you'll need to add it to `alembic.ini` under the logger section. Following the pre-existing examples for `logger_uvicorn` for example.

backend/alembic.ini

@@ -62,7 +62,7 @@ version_path_separator = os  # Use os.pathsep. Default configuration used for ne
 # output_encoding = utf-8
 
 # Updated in env.py using the POSTGRES_DATABASE_URL environment variable
-# sqlalchemy.url = 
+# sqlalchemy.url =
 
 
 [post_write_hooks]
@@ -83,8 +83,10 @@ ruff.executable = %(here)s/.venv/bin/ruff
 ruff.options = check --fix REVISION_SCRIPT_FILENAME
 
 # Logging configuration
+# Every time you want to define a new sub-logger, you need to add it to loggers or it won't show up.
+# Would recommend just using uvicorn."name of area you want to log" to identify a smaller scope
 [loggers]
-keys = root,sqlalchemy,alembic
+keys = root,sqlalchemy,alembic,uvicorn
 
 [handlers]
 keys = console
@@ -107,12 +109,17 @@ level = INFO
 handlers =
 qualname = alembic
 
+[logger_uvicorn]
+level = INFO
+handlers =
+qualname = uvicorn
+
 [handler_console]
 class = StreamHandler
 args = (sys.stderr,)
 level = NOTSET
 formatter = generic
 
 [formatter_generic]
-format = %(levelname)-5.5s [%(name)s] %(message)s
+format = %(levelname)-5.5s     [%(name)s]      %(message)s
 datefmt = %H:%M:%S

backend/app/models/__init__.py

@@ -1,6 +1,10 @@
+import logging
+
 from alembic import command
 from alembic.config import Config
 
+from app.utilities.constants import LOGGER_NAME
+
 # Make sure all models are here to reflect all current models
 # when autogenerating new migration
 from .Base import Base
@@ -10,8 +14,12 @@
 # Used to avoid import errors for the models
 __all__ = ["Base", "User", "Role"]
 
+log = logging.getLogger(LOGGER_NAME("models"))
+
 
 def run_migrations():
+    log.info("Running run_migrations in models/__init__ on server startup")
+
     alembic_cfg = Config("alembic.ini")
     # Emulates `alembic upgrade head` to migrate up to latest revision
     command.upgrade(alembic_cfg, "head")

backend/app/server.py

@@ -2,18 +2,18 @@
 from contextlib import asynccontextmanager
 from typing import Union
 
-from backend.app.routes import send_email
 from dotenv import load_dotenv
 from fastapi import FastAPI
 
+from . import models
+from .routes import send_email, user
+from .utilities.constants import LOGGER_NAME
+from .utilities.firebase_init import initialize_firebase
+
 load_dotenv()
 
-# we need to load env variables before initialization code runs
-from . import models  # noqa: E402
-from .routes import user  # noqa: E402
-from .utilities.firebase_init import initialize_firebase  # noqa: E402
 
-log = logging.getLogger("uvicorn")
+log = logging.getLogger(LOGGER_NAME("server"))
 
 
 @asynccontextmanager

backend/app/services/implementations/user_service.py

@@ -12,12 +12,13 @@
     UserCreateResponse,
     UserRole,
 )
+from app.utilities.constants import LOGGER_NAME
 
 
 class UserService(IUserService):
     def __init__(self, db: Session):
         self.db = db
-        self.logger = logging.getLogger(__name__)
+        self.logger = logging.getLogger(LOGGER_NAME("user_service"))
 
     async def create_user(self, user: UserCreateRequest) -> UserCreateResponse:
         firebase_user = None

backend/app/utilities/constants.py

@@ -0,0 +1,5 @@
+SERVER_LOGGER_NAME = "uvicorn"
+
+
+def LOGGER_NAME(name: str):
+    return f"{SERVER_LOGGER_NAME}.{name}"

backend/app/utilities/firebase_init.py

@@ -1,11 +1,19 @@
+import logging
 import os
 
 import firebase_admin
 from firebase_admin import credentials
 
+from app.utilities.constants import LOGGER_NAME
+
+log = logging.getLogger(LOGGER_NAME("firebase_init"))
+
 
 def initialize_firebase():
+    log.info("Running initialize_firebase")
     cwd = os.getcwd()
     service_account_path = os.path.join(cwd, "serviceAccountKey.json")
     cred = credentials.Certificate(service_account_path)
+
     firebase_admin.initialize_app(cred)
+    log.info("Finished initializing firebase")

backend/migrations/env.py

@@ -1,3 +1,4 @@
+import logging
 import os
 from logging.config import fileConfig
 
@@ -9,27 +10,33 @@
 
 load_dotenv()
 
+log = logging.getLogger("alembic")
+log.info("Entering env.py for alembic migration")
 # this is the Alembic Config object, which provides
 # access to the values within the .ini file in use.
 config = context.config
+log.info("Finished setting up alembic config object")
 
 # Interpret the config file for Python logging.
 # This line sets up loggers basically.
 if config.config_file_name is not None:
-    fileConfig(config.config_file_name)
+    fileConfig(config.config_file_name, disable_existing_loggers=False)
 
 # add your model's MetaData object here
 # for 'autogenerate' support
 # from myapp import mymodel
 # target_metadata = mymodel.Base.metadata
 
+log.info("Pulling model metadata")
+
 target_metadata = Base.metadata
 
 # other values from the config, defined by the needs of env.py,
 # can be acquired:
 # my_important_option = config.get_main_option("my_important_option")
 # ... etc.
 config.set_main_option("sqlalchemy.url", os.environ["POSTGRES_DATABASE_URL"])
+log.info("Finished migration env config setup")
 
 
 def run_migrations_offline() -> None:
@@ -69,13 +76,19 @@ def run_migrations_online() -> None:
         prefix="sqlalchemy.",
         poolclass=pool.NullPool,
     )
+    try:
+        log.info("Established database connection")
+        with connectable.connect() as connection:
+            context.configure(connection=connection, target_metadata=target_metadata)
 
-    with connectable.connect() as connection:
-        context.configure(connection=connection, target_metadata=target_metadata)
+            with context.begin_transaction():
+                context.run_migrations()
+        log.info("Finished running migrations in alembic env")
+    except Exception as e:
+        log.error(e)
 
-        with context.begin_transaction():
-            context.run_migrations()
 
+log.info("Starting up migration env")
 
 if context.is_offline_mode():
     run_migrations_offline()

backend/pyproject.toml

@@ -30,6 +30,10 @@ distribution = false
 dev = "fastapi dev app/server.py"
 precommit = "pre-commit run"
 precommit-install = "pre-commit install"
+dc-down = "docker-compose down -v"
+dc-up = "docker-compose up -d"
+docker-db = {composite = ["dc-down", "dc-up"]}
+db-dev = {composite = ["docker-db", "dev"]}
 revision = "alembic revision --autogenerate"
 upgrade = "alembic upgrade head"