primer commit
This commit is contained in:
George committed
1 parent
ab3c613165
commit
b2fb4e2d0a
18 files changed
+1291
-277
No files matched your search
@@ -1,175 +1,84 @@
|
||||
# Plan: logging real por sesión de usuario
|
||||
# Diseño de Logging
|
||||
|
||||
## Problema actual (diagnosticado)
|
||||
|
||||
- `main.py:32` fuerza `setup_logging(environment="debug")` siempre — el modo
|
||||
`"production"` (JSON estructurado) de `logger_config.py` nunca se activa,
|
||||
sin importar el entorno real de despliegue.
|
||||
- `core/sap.py`, `core/api_gateway.py` y `routers/auth.py` usan `print()` en
|
||||
vez del `logger` real. Esto significa:
|
||||
- No queda nada en el archivo rotativo `logs/backend.log` (solo en la
|
||||
consola / `docker compose logs`).
|
||||
- No tiene formato JSON buscable, ni `request_id` de correlación.
|
||||
- **Grave**: `routers/auth.py` imprime la contraseña (apellido) en texto
|
||||
plano dos veces:
|
||||
- línea ~27: `print(f"Contraseña (Apellido) recibida: {empLastName}")`
|
||||
- línea ~45: `print(f"Apellido en SAP: {employee_data.get('LastName')}")`
|
||||
> Nota: este documento describía originalmente un plan pendiente. Ya está
|
||||
> implementado tal como se describe abajo; se conserva el nombre del
|
||||
> archivo por los enlaces existentes desde `index.md`.
|
||||
|
||||
## Objetivo
|
||||
|
||||
Además de arreglar lo anterior, dejar un log **por sesión de usuario
|
||||
conectado**: que cada línea de log quede etiquetada con qué empleado
|
||||
(`emp_id` + nombre) hizo qué acción (`GET /Items`, `POST /BusinessPartners`,
|
||||
etc.), en JSON, para poder cargarlo después en un monitor/dashboard y buscar
|
||||
acciones por usuario.
|
||||
Cada línea de log queda etiquetada automáticamente con el `request_id` de
|
||||
la petición HTTP y con el empleado conectado que la originó (`webUser`,
|
||||
`emp_id`, `full_name`), en formato JSON, sin tener que pasar esos datos a
|
||||
mano en cada llamada a `logger.info/warning/error`.
|
||||
|
||||
## Diseño
|
||||
## Piezas
|
||||
|
||||
`context.py` ya tiene un `ContextVar` para el `request_id` que se inyecta
|
||||
automáticamente en cada log a través de `logger_config.JsonFormatter`. Se
|
||||
replica el mismo patrón para el usuario conectado, así **todo log queda
|
||||
etiquetado automáticamente sin tocar cada llamada individual**.
|
||||
### `context.py`
|
||||
|
||||
### 1. `context.py`
|
||||
Dos `ContextVar` por request (aisladas entre corrutinas concurrentes de
|
||||
FastAPI):
|
||||
|
||||
Agregar un `ContextVar` para el usuario actual, mismo patrón que
|
||||
`request_id_ctx`:
|
||||
- `request_id_ctx` — expuesta via `get_request_id()` / `set_request_id()`.
|
||||
- `current_user_ctx` — dict `{"webUser", "emp_id", "full_name"}`, expuesta
|
||||
via `get_current_user()` / `set_current_user(webUser, full_name="", emp_id="-")`.
|
||||
Por defecto ambas quedan en `"-"` cuando no hay usuario autenticado
|
||||
(por ejemplo, en el propio `POST /api/Login` antes de validar credenciales).
|
||||
|
||||
```python
|
||||
current_user_ctx: ContextVar[dict] = ContextVar(
|
||||
"current_user", default={"emp_id": "-", "username": "-"}
|
||||
)
|
||||
### `main.py`
|
||||
|
||||
def get_current_user() -> dict:
|
||||
return current_user_ctx.get()
|
||||
- `correlation_id_middleware` llama a `set_request_id()` con el header
|
||||
`X-Request-ID` entrante o un UUID generado si no viene.
|
||||
- `session_middleware`, tras validar el token con
|
||||
`validate_and_refresh_session()`, llama a
|
||||
`set_current_user(webUser, get_employee_name(webUser), get_emp_id(webUser))`
|
||||
para que el resto de la petición (incluyendo las llamadas a
|
||||
`forward_to_sapb1`) quede etiquetada con ese usuario.
|
||||
- `routers/auth.py` también llama a `set_current_user(...)` en un login
|
||||
exitoso, porque `/api/Login` no pasa por el `session_middleware`
|
||||
(todavía no hay token) y de otro modo su propio log quedaría sin usuario.
|
||||
- `LOG_ENVIRONMENT` (variable de entorno, default `"production"`) decide el
|
||||
formato de salida en `setup_logging()`.
|
||||
|
||||
def set_current_user(emp_id: str, username: str):
|
||||
current_user_ctx.set({"emp_id": emp_id, "username": username})
|
||||
```
|
||||
### `logger_config.py` — `JsonFormatter`
|
||||
|
||||
### 2. `core/session.py`
|
||||
|
||||
Agregar un helper que devuelva "Nombre Apellido" a partir de `emp_id`,
|
||||
leyendo el dict `employee_sessions` que ya existe:
|
||||
|
||||
```python
|
||||
def get_employee_name(emp_id: str) -> str:
|
||||
session = employee_sessions.get(emp_id)
|
||||
if not session:
|
||||
return "-"
|
||||
return f"{session.get('first_name', '')} {session.get('last_name', '')}".strip()
|
||||
```
|
||||
|
||||
### 3. `main.py`
|
||||
|
||||
En `session_middleware`, justo después de validar el token y obtener
|
||||
`emp_id` (donde hoy se hace `request.state.emp_id = emp_id`), setear el
|
||||
contexto de usuario:
|
||||
|
||||
```python
|
||||
from core.session import validate_and_refresh_session, get_employee_name
|
||||
from context import set_current_user
|
||||
...
|
||||
emp_id = validate_and_refresh_session(token)
|
||||
if not emp_id:
|
||||
...
|
||||
set_current_user(emp_id, get_employee_name(emp_id))
|
||||
request.state.emp_id = emp_id
|
||||
```
|
||||
|
||||
También en este archivo: dejar de forzar `"debug"` en `setup_logging`,
|
||||
leerlo de una variable de entorno nueva (por defecto `"production"`, para
|
||||
que Docker quede bien sin configurar nada extra):
|
||||
|
||||
```python
|
||||
LOG_ENVIRONMENT = os.getenv("LOG_ENVIRONMENT", "production")
|
||||
...
|
||||
@asynccontextmanager
|
||||
async def lifespan(app: FastAPI):
|
||||
setup_logging(environment=LOG_ENVIRONMENT)
|
||||
yield
|
||||
```
|
||||
|
||||
### 4. `logger_config.py`
|
||||
|
||||
Extender `JsonFormatter` para incluir `emp_id`/`username` desde el
|
||||
contexto en cada línea, y soportar campos extra estructurados
|
||||
(`http_method`, `endpoint`, `status_code`) cuando el log los trae vía
|
||||
`extra={...}`:
|
||||
|
||||
```python
|
||||
from context import get_request_id, get_current_user
|
||||
|
||||
class JsonFormatter(logging.Formatter):
|
||||
EXTRA_FIELDS = ("http_method", "endpoint", "status_code")
|
||||
|
||||
def format(self, record):
|
||||
user = get_current_user()
|
||||
log_record = {
|
||||
"timestamp": datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat(),
|
||||
"level": record.levelname,
|
||||
"request_id": get_request_id(),
|
||||
"emp_id": user["emp_id"],
|
||||
"username": user["username"],
|
||||
"message": record.getMessage(),
|
||||
"module": record.module,
|
||||
"function": record.funcName,
|
||||
"line": record.lineno,
|
||||
}
|
||||
for field in self.EXTRA_FIELDS:
|
||||
if hasattr(record, field):
|
||||
log_record[field] = getattr(record, field)
|
||||
if record.exc_info:
|
||||
log_record["exception"] = self.formatException(record.exc_info)
|
||||
return json.dumps(log_record)
|
||||
```
|
||||
|
||||
Resultado esperado por línea, por ejemplo:
|
||||
En modo `"production"` (default), cada línea de log —tanto en consola como
|
||||
en `logs/backend.log`— es un JSON con esta forma:
|
||||
|
||||
```json
|
||||
{"timestamp": "2026-08-14T...", "level": "INFO", "request_id": "...", "emp_id": "11", "username": "Juan Pérez", "http_method": "GET", "endpoint": "Items", "status_code": 200, "message": "Solicitud SAP completada", "module": "sap", "function": "forward_to_sapb1", "line": 137}
|
||||
{"timestamp": "2026-08-14T15:32:10.123456+00:00", "level": "INFO", "request_id": "3f2a...", "webUser": "jgarcia", "emp_id": "11", "full_name": "Juan García", "http_method": "GET", "endpoint": "Items", "status_code": 200, "message": "[200] GET Items", "module": "sap", "function": "forward_to_sapb1", "line": 141}
|
||||
```
|
||||
|
||||
### 5. `core/sap.py` / `core/api_gateway.py`
|
||||
Campos siempre presentes: `timestamp`, `level`, `request_id`, `webUser`,
|
||||
`emp_id`, `full_name`, `message`, `module`, `function`, `line`. Campos
|
||||
opcionales (`http_method`, `endpoint`, `status_code`) se agregan solo si el
|
||||
`logger.info/warning/error(...)` que generó la línea los pasó vía
|
||||
`extra={...}` — este es el patrón que usan `core/sap.py`,
|
||||
`core/api_gateway.py` y `routers/reports.py` para dejar trazabilidad de
|
||||
cada llamada saliente. Si el log viene de una excepción (`exc_info`), se
|
||||
agrega también `exception` con el traceback formateado.
|
||||
|
||||
Reemplazar cada `print(...)` por `logger.info/warning/error(...)`,
|
||||
agregando `extra={"http_method": method, "endpoint": endpoint_path,
|
||||
"status_code": response.status_code}` en las líneas de request/respuesta,
|
||||
para que queden como campos estructurados y no solo texto libre. Quitar la
|
||||
variable `I = " "` (indentación para prints, ya no hace falta) y los
|
||||
emojis (el nivel del log ya indica severidad).
|
||||
En cualquier otro valor de `LOG_ENVIRONMENT` (por ejemplo `"development"`),
|
||||
la consola usa un formato de texto plano legible
|
||||
(`%(asctime)s [%(levelname)s] %(module)s.%(funcName)s:%(lineno)d - %(message)s`)
|
||||
en vez de JSON — pensado para desarrollo local, no para buscar en el
|
||||
archivo. El archivo `logs/backend.log` (rotativo, 5 MB x 3 backups vía
|
||||
`RotatingFileHandler`) siempre se escribe en JSON sin importar el entorno.
|
||||
|
||||
### 6. `routers/auth.py`
|
||||
## Qué NO se loguea
|
||||
|
||||
- Agregar `logger = logging.getLogger(__name__)`.
|
||||
- Reemplazar todos los `print()` por `logger.info/warning/error(...)`.
|
||||
- **No loguear nunca `empLastName` ni `employee_data.get('LastName')`** —
|
||||
solo el `emp_id` y si el login fue exitoso o no.
|
||||
- En cuanto se confirma el empleado (login exitoso), llamar
|
||||
`set_current_user(empId, f"{first_name} {last_name}")` para que el
|
||||
propio log del login quede etiquetado también (el middleware no aplica
|
||||
a `/api/Login` porque no requiere token todavía).
|
||||
`routers/auth.py` nunca escribe `Password` / `U_WEB_PASS` en los logs, ni en
|
||||
éxito ni en fallo de login — solo el `webUser`, el `EmployeeID` y si el
|
||||
intento fue exitoso o el motivo del rechazo (`"Usuario no registrado"`,
|
||||
`"Usuario inactivo"`, contraseña incorrecta). Al auditar un cambio en el
|
||||
flujo de login, verificar que esta regla se mantenga.
|
||||
|
||||
### 7. `docker-compose.yml`
|
||||
|
||||
Agregar volumen para que el log persista en el host aunque se reconstruya
|
||||
el contenedor (si no, se perdería cada `--build`, igual que pasaba con
|
||||
`.env` antes de agregar su volumen):
|
||||
|
||||
```yaml
|
||||
backend:
|
||||
volumes:
|
||||
- ./mini-backend/menu_permissions.json:/app/menu_permissions.json:ro
|
||||
- ./mini-backend/logs:/app/logs
|
||||
```
|
||||
|
||||
## Verificación al implementar
|
||||
## Verificación
|
||||
|
||||
1. Levantar el backend (local o Docker).
|
||||
2. Loguearse con un usuario de prueba y hacer un par de llamadas reales
|
||||
(GET a algún catálogo, POST/PATCH a algo).
|
||||
3. Revisar `logs/backend.log`: cada línea debe traer `emp_id`, `username`,
|
||||
`http_method`, `endpoint`, `status_code` correctos.
|
||||
3. Revisar `logs/backend.log`: cada línea debe traer `webUser`, `emp_id`,
|
||||
`full_name`, y las líneas de proxy SAP también `http_method`,
|
||||
`endpoint`, `status_code`.
|
||||
4. `grep` de la contraseña de prueba sobre todo `logs/backend.log` (y la
|
||||
salida de consola) para confirmar que **no aparece en ningún lado**.
|
||||
5. Confirmar que `docker compose build` sigue funcionando sin errores.
|
||||
Reference in new issue
Block a user