debug(snapshot): Add comprehensive logging for rollback troubleshooting

Problem 1: Apply affects all entities (should only affect changed ones)
Problem 2: Reject rollback not working (entity stays at new value)

Added detailed logging:
- Snapshot creation: JSON test result, field count
- Frontend update: metadata keys, entity_snapshot presence
- Reject: metadata parsing, entity_snapshot detection
- Rollback: entity data, operation type, old_values
- _rollback_update: Before/after values, UPDATE query result
- Verify: Post-rollback database state

This will help identify:
- Is snapshot being created?
- Is metadata being saved to database?
- Is metadata being parsed during reject?
- Is rollback function being called?
- Is UPDATE query executing?
- What are the actual values being restored?

Log locations to check:
kubectl logs deployment/haproxy-openmanager-backend -n haproxy-openmanager | grep 'SNAPSHOT\|ROLLBACK\|REJECT'
This commit is contained in:
taylanbakircioglu
2025-11-13 21:04:43 +03:00
parent 84916db872
commit f9ca700352
3 changed files with 47 additions and 4 deletions
+12
View File
@@ -4316,11 +4316,23 @@ async def reject_all_pending_changes(cluster_id: int, authorization: str = Heade
# Parse metadata
metadata = json_module.loads(version['metadata']) if version['metadata'] else {}
logger.info(f"REJECT DEBUG: Version {version['version_name']} - metadata exists={version['metadata'] is not None}")
logger.info(f"REJECT DEBUG: Parsed metadata keys={list(metadata.keys()) if metadata else 'EMPTY'}")
# Check for single entity snapshot
entity_snapshot = metadata.get('entity_snapshot')
logger.info(f"REJECT DEBUG: entity_snapshot exists={entity_snapshot is not None}")
if entity_snapshot:
# Single entity rollback
logger.info(f"REJECT DEBUG: Calling rollback for {entity_snapshot.get('entity_type')} {entity_snapshot.get('entity_id')}")
logger.info(f"REJECT DEBUG: old_values exists={('old_values' in entity_snapshot)}")
logger.info(f"REJECT DEBUG: operation={entity_snapshot.get('operation')}")
success = await rollback_entity_from_snapshot(conn, entity_snapshot)
logger.info(f"REJECT DEBUG: Rollback result={success}")
if success:
rollback_success_count += 1
logger.info(f"REJECT ROLLBACK: Rolled back {entity_snapshot['entity_type']} {entity_snapshot['entity_id']}")
+6
View File
@@ -752,6 +752,9 @@ async def update_frontend(frontend_id: int, frontend: FrontendConfig, request: R
operation="UPDATE"
)
logger.info(f"FRONTEND UPDATE DEBUG: entity_snapshot_metadata keys={list(entity_snapshot_metadata.keys()) if entity_snapshot_metadata else 'EMPTY'}")
logger.info(f"FRONTEND UPDATE DEBUG: entity_snapshot exists={('entity_snapshot' in entity_snapshot_metadata) if entity_snapshot_metadata else False}")
# Get pre-apply snapshot (for diff viewer)
old_config = await conn.fetchval("""
SELECT config_content FROM config_versions
@@ -765,6 +768,9 @@ async def update_frontend(frontend_id: int, frontend: FrontendConfig, request: R
**entity_snapshot_metadata # For rollback
}
logger.info(f"FRONTEND UPDATE DEBUG: Final metadata keys={list(metadata.keys())}")
logger.info(f"FRONTEND UPDATE DEBUG: metadata has entity_snapshot={'entity_snapshot' in metadata}")
# Try with status field first, fallback to old behavior if field doesn't exist
try:
config_version_id = await conn.fetchval("""
+29 -4
View File
@@ -159,6 +159,17 @@ async def save_entity_snapshot(
f"SNAPSHOT: Created for {entity_type} {entity_id} "
f"(operation={operation}, changed_fields={len(changed_fields)})"
)
logger.info(f"SNAPSHOT DEBUG: old_values keys={list(serializable_old_values.keys())[:10]}")
logger.info(f"SNAPSHOT DEBUG: Serializable check - can serialize to JSON: {len(serializable_old_values)} fields")
# Test if snapshot is JSON serializable
try:
import json as json_final_test
json_final_test.dumps(snapshot)
logger.info(f"SNAPSHOT DEBUG: Final JSON test PASSED for {entity_type} {entity_id}")
except Exception as json_err:
logger.error(f"SNAPSHOT DEBUG: Final JSON test FAILED for {entity_type} {entity_id}: {json_err}")
return {}
return {"entity_snapshot": snapshot}
@@ -194,7 +205,7 @@ async def rollback_entity_from_snapshot(
logger.warning("Rollback failed")
"""
if not ENTITY_SNAPSHOT_ENABLED:
logger.debug("Entity snapshot disabled, skipping rollback")
logger.warning("ROLLBACK DEBUG: Entity snapshot disabled by feature flag, skipping rollback")
return False
entity_type = entity_snapshot.get("entity_type")
@@ -202,14 +213,19 @@ async def rollback_entity_from_snapshot(
operation = entity_snapshot.get("operation")
old_values = entity_snapshot.get("old_values")
logger.info(f"ROLLBACK DEBUG: entity_type={entity_type}, entity_id={entity_id}, operation={operation}")
logger.info(f"ROLLBACK DEBUG: old_values exists={old_values is not None}, old_values length={len(old_values) if old_values else 0}")
if not all([entity_type, entity_id, operation, old_values]):
logger.warning(f"ROLLBACK: Invalid snapshot data, skipping rollback")
logger.warning(f"ROLLBACK: Invalid snapshot data, skipping rollback (missing: {[k for k in ['entity_type', 'entity_id', 'operation', 'old_values'] if not entity_snapshot.get(k)]})")
return False
try:
if operation in ["UPDATE", "UPDATE_RESTORE"]:
# Entity'yi eski değerlerine geri yükle
logger.info(f"ROLLBACK DEBUG: Calling _rollback_update for {entity_type} {entity_id}")
success = await _rollback_update(conn, entity_type, entity_id, old_values)
logger.info(f"ROLLBACK DEBUG: _rollback_update returned {success}")
return success
elif operation == "CREATE":
@@ -257,7 +273,10 @@ async def _rollback_update(
try:
if entity_type == "frontend":
# Frontend'i eski değerlerine geri yükle
await conn.execute("""
logger.info(f"ROLLBACK UPDATE DEBUG: Frontend {entity_id} - restoring bind_port={old_values.get('bind_port')}")
logger.info(f"ROLLBACK UPDATE DEBUG: old_values sample: name={old_values.get('name')}, bind_port={old_values.get('bind_port')}, ssl_enabled={old_values.get('ssl_enabled')}")
result = await conn.execute("""
UPDATE frontends SET
name = $1, bind_address = $2, bind_port = $3,
default_backend = $4, mode = $5, ssl_enabled = $6,
@@ -301,7 +320,13 @@ async def _rollback_update(
old_values.get('updated_at'),
entity_id
)
logger.info(f"ROLLBACK UPDATE: Frontend {entity_id} restored to previous state")
logger.info(f"ROLLBACK UPDATE: Frontend {entity_id} restored to previous state (UPDATE query result={result})")
# Verify rollback
verify = await conn.fetchrow("SELECT bind_port, last_config_status FROM frontends WHERE id = $1", entity_id)
logger.info(f"ROLLBACK UPDATE VERIFY: Frontend {entity_id} after rollback - bind_port={verify['bind_port']}, status={verify['last_config_status']}")
return True
elif entity_type == "backend":