Skip to content

Feat/enhanced logging#1455

Open
mrjoshuap wants to merge 27 commits intomediacms-io:mainfrom
mrjoshuap:feat/enhanced-logging
Open

Feat/enhanced logging#1455
mrjoshuap wants to merge 27 commits intomediacms-io:mainfrom
mrjoshuap:feat/enhanced-logging

Conversation

@mrjoshuap
Copy link
Contributor

Description

This PR refreshes #1226 against latest main branch. Better late than never.

This enhances logging across the codebase to improve debugging, monitoring, and operational visibility. It introduces structured logging utilities, adds contextual exception logging throughout the application, and implements a unified log level configuration mechanism.

Key Changes:

  1. New Logging Utilities Module (cms/logging_utils.py):

    • log_operation_timing() - Context manager for timing operations with automatic start/complete/failure logging
    • log_exception_with_context() - Helper for logging exceptions with additional context
    • sanitize_path() - Utility to truncate long file paths in logs
    • sanitize_token() - Utility to mask sensitive tokens/keys in logs
  2. Enhanced Logging Configuration (cms/settings.py):

    • Implemented LOGLEVEL as primary configuration mechanism: The LOGLEVEL variable now controls log levels across all MediaCMS components
    • Default LOGLEVEL set to "ERROR": Matches current behavior and ensures production-safe defaults
    • Environment variable support: LOGLEVEL can be set via environment variable (LOGLEVEL=INFO) or overridden in local_settings.py
    • Automatic DEBUG mode override: When DEBUG=True, log level is automatically set to DEBUG for comprehensive development logging
    • Fixed logger initialization order
    • Added app-specific loggers (files, users, uploader, saml_auth, rbac, identity_providers, actions, cms) with unified log level control
    • Enhanced console handler and formatters available when DEBUG=True
    • Maintains production-safe defaults (ERROR-level file logging)
  3. Comprehensive Exception Logging:

    • Replaced generic exception messages with contextual logging across 9 files
    • All exception handlers now include relevant context (IDs, file paths, operation details)
    • Standardized exception handling using logger.exception() with specific exception types
  4. Operational Logging:

    • Added operational logging for encoding, uploads, and media lifecycle operations
    • Improved visibility into long-running tasks and critical operations
  5. Documentation:

    • Updated logging documentation (docs/admins_docs.md Section 29):
      • Documented LOGLEVEL as the primary configuration mechanism
      • Added comprehensive Celery log files documentation (celery_long.log, celery_short.log, celery_beat.log)
      • Updated all examples to show LOGLEVEL usage
      • Added environment variable configuration examples
      • Enhanced DEBUG mode documentation
      • Updated log viewing and rotation sections to include Celery logs
    • Added comprehensive logging documentation for developers (docs/developers_docs.md Section 8)

Files Modified:

  • cms/logging_utils.py (new file)
  • cms/settings.py
  • files/tasks.py
  • files/backends.py
  • files/helpers.py
  • files/methods.py
  • files/models/media.py
  • uploader/views.py
  • users/views.py
  • docs/admins_docs.md
  • docs/developers_docs.md

Steps

Pre-deploy

Post-deploy

mrjoshuap and others added 22 commits December 23, 2025 11:21
Merges PR mediacms-io#1226 logging improvements. Adds structured exception logging
to all exception handlers (tasks, views, helpers, models) while preserving
existing exception handling behavior. Enhanced logging configuration with
console handler and formatters available when DEBUG=True. Includes
comprehensive documentation for administrators and developers.

- Preserves ERROR-level file logging as default (production-safe)
- Adds logging to 9 files: tasks.py, backends.py, helpers.py, methods.py,
  models/media.py, uploader/views.py, users/views.py, manage.py, settings.py
- Adds admin docs (Section 29) and developer docs (Section 8)
- Fix logger initialization order in settings.py
- Add app-specific loggers while preserving ERROR-level file logging
- Replace generic exception messages with contextual logging
- Add operational logging for encoding, uploads, and media lifecycle
- Standardize exception handling with specific types and logger.exception()
- Create logging_utils module with helpers for structured logging

All exception handlers now include relevant context (IDs, file paths,
operation details) to improve debugging and operational monitoring.
1. Enhanced logging configuration (`cms/settings.py`)
* Improved formatters to include function name and line number
* Added separate detailed formatter for console output in DEBUG mode
* Enhanced DEBUG mode with more detailed information
2. Fixed missing logging
* `saml_auth/adapter.py`: Replaced basic logging.error() calls with proper logger calls including context; added logging for SAML authentication and role mapping
* `files/tasks.py`: Fixed bare `except:` clause in `media_init` task with proper exception handling and logging
* `cms/middleware.py`: Added logging for approval middleware blocking actions
* `files/helpers.py`: Added logging for file operations (create, delete, move, command execution)
* `files/methods.py`: Added logging for permission checks, state transitions, and notifications
* `uploader/views.py`: Enhanced upload logging with file details, size, type, and error context
3. Standardized log messages
* Converted f-string log messages to structured format with key=value pairs
* Ensured consistent format across all log messages
* Added required context variables (user_id, friendly_token, encoding_id, etc.)
4. Aligned severity levels
* Changed routine operations (like thumbnail updates) from INFO to DEBUG
* Ensured encoding failures are logged as ERROR
* Properly categorized warnings vs errors
5. Added DEBUG mode enhancements
* Added function entry/exit logging in key operations
* Added intermediate value logging in complex operations
* Added detailed object state logging for debugging
6. Removed duplicative logging
* Reviewed and optimized logging statements
- Add ENABLE_SQL_DEBUG_LOGGING setting (default: False) to control SQL query logging
- SQL queries are now opt-in even when DEBUG=True to reduce log noise
- Set celery logger to INFO level to reduce noise while keeping celery.task at DEBUG
- Suppress useless celery.utils.functional debug messages at WARNING level
- Update admin and developer documentation with new configuration options
- Add logging to media deletion API view and post_delete signal handler
- Explicitly set django.db.backends logger to ERROR when SQL debug logging is disabled
- Ensures deletion events are logged and SQL queries remain suppressed by default
…I operations

- Add login success/failure logging with IP addresses
- Log user creation, deletion, password changes, and approval actions
- Add role/permission change logging (including SAML role mapping)
- Log media updates and all bulk operations (state changes, permissions, etc.)
- Add admin management action logging (media, comments, users deletion)
- Use INFO level for auditable events, WARNING for failed auth attempts
- Add logging to user deletion signal with content counts
- Add logging to subtitle creation/update signals
- Add logging to encoding creation/update/deletion signals
- Add logging to video chapter deletion signal
- Add logging to media category m2m_changed signal
- Add logging to RBAC group category m2m_changed signal
- Add django-allauth signal handlers for password reset, email confirmation, password change, and account signup

All signal handlers use structured logging with key-value pairs for easy parsing and analysis.
…nd signal handler for consistency with django-allauth updates.
…itialization

- Move error handling from logging to business logic in post_user_create
- Remove unnecessary try/except blocks around logging in signal handlers
- Remove redundant logger initialization, use module-level logger
- Add error handling for database operations in delete_content
…eivers

- Add post_save/post_delete signal handlers with logging for Category, Tag, Comment, Playlist, Rating, Page, License, Channel, MediaAction, Identity Provider, and SAML models
- Use INFO level for creation/deletion, DEBUG for updates
- Follow structured logging patterns with key-value pairs
- Fix flake8 errors (unused variables, import ordering)
Add default values for CAN_EDIT, CAN_EDIT_MEDIA, CAN_DELETE_MEDIA,
CAN_DELETE_COMMENTS, CAN_DELETE, media_object, and current_site in
context processor. Fix templates to conditionally access optional
variables. This prevents ValueError/AttributeError/TypeError messages
from flooding debug logs when templates reference variables that aren't
always available.
Remove references to non-existent media_object.summary attribute in
media.html template. Fix crispy_custom_field.html to safely check
field/widget types without accessing non-existent attributes (input_type
on Textarea, choices on BooleanField). Prevents debug log flooding from
template resolution errors.
@mrjoshuap
Copy link
Contributor Author

This is progressing quite nicely. There are a number of rendering problems I have encountered during testing that I'm going to include here due to the fact that they are VERY noisy.

To get an idea of what it's looking like, this is the debug.log after a clean install (no db, no data, fresh checkout):

INFO 2025-12-26 14:51:33 files.models.category category_save:169 Category created - category_id=1, title=Art, user_id=None, is_global=False, is_rbac_category=False
INFO 2025-12-26 14:51:33 files.models.category category_save:169 Category created - category_id=2, title=Documentary, user_id=None, is_global=False, is_rbac_category=False
INFO 2025-12-26 14:51:33 files.models.category category_save:169 Category created - category_id=3, title=Experimental, user_id=None, is_global=False, is_rbac_category=False
INFO 2025-12-26 14:51:33 files.models.category category_save:169 Category created - category_id=4, title=Film, user_id=None, is_global=False, is_rbac_category=False
INFO 2025-12-26 14:51:33 files.models.category category_save:169 Category created - category_id=5, title=Music, user_id=None, is_global=False, is_rbac_category=False
INFO 2025-12-26 14:51:33 files.models.category category_save:169 Category created - category_id=6, title=TV, user_id=None, is_global=False, is_rbac_category=False
INFO 2025-12-26 14:51:38 users.models post_user_create:358 User registered - user_id=1, username=admin, email=admin@localhost
INFO 2025-12-26 14:51:38 users.models channel_save:323 Channel created - channel_id=1, friendly_token=McSbc126k, title=default, user_id=1, username=admin
DEBUG 2025-12-26 14:51:38 users.models channel_save:332 Channel updated - channel_id=1, friendly_token=McSbc126k, title=default, user_id=1
INFO 2025-12-26 14:52:34 users.models post_user_create:358 User registered - user_id=2, username=abcdef, email=abc@def.com
INFO 2025-12-26 14:52:34 users.models channel_save:323 Channel created - channel_id=2, friendly_token=OcZOIGFtE, title=default, user_id=2, username=abcdef
DEBUG 2025-12-26 14:52:34 users.models channel_save:332 Channel updated - channel_id=2, friendly_token=OcZOIGFtE, title=default, user_id=2
INFO 2025-12-26 14:52:34 users.models log_account_signup:446 Account signup (django-allauth) - user_id=2, username=abcdef, email=abc@def.com, ip=192.168.65.1
INFO 2025-12-26 14:52:34 users.models log_user_login:386 Login successful (django-allauth) - user_id=2, username=abcdef, ip=192.168.65.1
INFO 2025-12-26 14:52:44 uploader.views form_valid:62 Upload started - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, total_parts=2, concurrent=True, chunks_done=False
INFO 2025-12-26 14:52:44 uploader.views form_valid:62 Upload started - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, total_parts=2, concurrent=True, chunks_done=False
DEBUG 2025-12-26 14:52:44 uploader.views form_valid:122 Saving multi-part upload chunk - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, total_parts=2
DEBUG 2025-12-26 14:52:44 uploader.views form_valid:122 Saving multi-part upload chunk - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, total_parts=2
INFO 2025-12-26 14:52:44 uploader.views form_valid:62 Upload started - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, total_parts=2, concurrent=True, chunks_done=True
DEBUG 2025-12-26 14:52:44 uploader.views form_valid:83 Combining upload chunks - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, total_parts=2
DEBUG 2025-12-26 14:52:44 uploader.views form_valid:90 Chunks combined successfully - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4
DEBUG 2025-12-26 14:52:44 uploader.views form_valid:137 Creating media from uploaded file - user_id=2, filename=mediacms-admin-dashboard-smaller.mp4, file_size=2151154 bytes
INFO 2025-12-26 14:52:44 files.models.media media_save:1052 Media created - friendly_token=Dou0RUh65, user_id=2, username=abcdef, media_type=video, title=mediacms-admin-dashboard-smaller.mp4
DEBUG 2025-12-26 14:52:44 files.models.media set_media_type:416 Setting media type - friendly_token=Dou0RUh65, current_media_type=video
DEBUG 2025-12-26 14:52:44 files.models.media set_media_type:422 File type detected - friendly_token=Dou0RUh65, detected_type=video
DEBUG 2025-12-26 14:52:44 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4'], cwd=None
DEBUG 2025-12-26 14:52:44 files.helpers media_file_info:348 File size retrieved - input_file=/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4, size=2151154
DEBUG 2025-12-26 14:52:44 files.helpers run_command:245 Command executed successfully - cmd=['md5sum', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4'], cwd=None
DEBUG 2025-12-26 14:52:44 files.helpers run_command:245 Command executed successfully - cmd=['ffprobe', '-loglevel', 'error', '-show_streams', '-show_entries', 'format=format_name', '-of', 'json', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4'], cwd=None
DEBUG 2025-12-26 14:52:44 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:52:44 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpuuspuxjr.jpg, suffix=.jpg
DEBUG 2025-12-26 14:52:45 files.helpers run_command:245 Command executed successfully - cmd=['ffmpeg', '-ss', '20.7', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-vframes', '1', '-y', '/tmp/tmpuuspuxjr.jpg'], cwd=None
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpurrc90m3.jpg, suffix=.jpg
DEBUG 2025-12-26 14:52:45 files.helpers run_command:245 Command executed successfully - cmd=['ffmpeg', '-ss', '20.7', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-vframes', '1', '-y', '/tmp/tmpurrc90m3.jpg'], cwd=None
DEBUG 2025-12-26 14:52:45 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:52:45 files.helpers rm_file:146 Successfully removed file - filename=/tmp/tmpurrc90m3.jpg
DEBUG 2025-12-26 14:52:45 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:52:45 files.helpers rm_file:146 Successfully removed file - filename=/tmp/tmpuuspuxjr.jpg
DEBUG 2025-12-26 14:52:45 files.models.media encode:572 Starting encode - friendly_token=Dou0RUh65, profile_count=0, force=True, chunkize=True, video_height=720, duration=40
DEBUG 2025-12-26 14:52:45 files.models.media encode:585 Active profiles retrieved - friendly_token=Dou0RUh65, profile_count=7
INFO 2025-12-26 14:52:45 files.models.encoding encoding_file_save:155 Encoding created - friendly_token=Dou0RUh65, profile_id=23, profile_name=h264-144, status=pending, chunk=False
INFO 2025-12-26 14:52:45 files.models.encoding encoding_file_save:155 Encoding created - friendly_token=Dou0RUh65, profile_id=2, profile_name=h264-240, status=pending, chunk=False
INFO 2025-12-26 14:52:45 files.models.encoding encoding_file_save:155 Encoding created - friendly_token=Dou0RUh65, profile_id=3, profile_name=h264-360, status=pending, chunk=False
INFO 2025-12-26 14:52:45 files.models.encoding encoding_file_save:155 Encoding created - friendly_token=Dou0RUh65, profile_id=13, profile_name=h264-480, status=pending, chunk=False
INFO 2025-12-26 14:52:45 files.models.encoding encoding_file_save:155 Encoding created - friendly_token=Dou0RUh65, profile_id=10, profile_name=h264-720, status=pending, chunk=False
INFO 2025-12-26 14:52:45 files.models.encoding encoding_file_save:155 Encoding created - friendly_token=Dou0RUh65, profile_id=1, profile_name=preview, status=pending, chunk=False
DEBUG 2025-12-26 14:52:45 files.methods notify_users:200 Notification requested - friendly_token=Dou0RUh65, action=media_added
INFO 2025-12-26 14:52:45 files.methods notify_users:278 Notification email sent - action=media_added, friendly_token=Dou0RUh65, recipients=1
INFO 2025-12-26 14:52:45 files.methods notify_users:278 Notification email sent - action=media_added, friendly_token=Dou0RUh65, recipients=1
INFO 2025-12-26 14:52:45 uploader.views form_valid:147 Media uploaded successfully - user_id=2, friendly_token=Dou0RUh65, filename=mediacms-admin-dashboard-smaller.mp4, file_size=2151154 bytes
DEBUG 2025-12-26 14:52:45 files.helpers rm_file:146 Successfully removed file - filename=/home/mediacms.io/mediacms/media_files/uploads/844910f2-fcd2-40bf-9378-508664f60cdd/mediacmsadmindashboardsmaller.mp4
DEBUG 2025-12-26 14:52:45 uploader.views form_valid:158 Cleaned up upload directory - user_id=2, friendly_token=Dou0RUh65, upload_dir=uploads/844910f2-fcd2-40bf-9378-508664f60cdd
DEBUG 2025-12-26 14:52:45 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=23, status=running, chunk=False
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmp2y_dgxnb/tmpgy8rj3qd.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmp2y_dgxnb/tmpds8ofoz9.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:45 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=2, status=running, chunk=False
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpw57dyir6/tmprei5gp8l.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpw57dyir6/tmpulste9ga.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:45 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=23, status=running, chunk=False
DEBUG 2025-12-26 14:52:45 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=2, status=running, chunk=False
DEBUG 2025-12-26 14:52:45 files.backends _spawn:29 Spawning FFmpeg process - cmd=['ffmpeg', '-y', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-c:v', 'libx264', '-filter:v', 'scale=if(lt(iw\\,ih)\\,240\\,427):if(lt(iw\\,ih)\\,427\\,240):force_original_aspect_ratio=decrease:force_divisible_by=2:flags=lanczos,fps=fps=55', '-pix_fmt', 'yuv420p', '-crf', '23', '-maxrate', '450k', '-bufsize', '450k', '-force_key_frames', 'expr:gte(t,n_forced*4)', '-x264-params', 'keyint=440:keyint_min=220', '-preset', 'medium', '-profile:v', 'main', '-level', '4.2', '-strict', '-2', '/tmp/tmpw57dyir6/tmprei5gp8l.mp4']
DEBUG 2025-12-26 14:52:45 files.backends _spawn:29 Spawning FFmpeg process - cmd=['ffmpeg', '-y', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-c:v', 'libx264', '-filter:v', 'scale=if(lt(iw\\,ih)\\,144\\,256):if(lt(iw\\,ih)\\,256\\,144):force_original_aspect_ratio=decrease:force_divisible_by=2:flags=lanczos,fps=fps=55', '-pix_fmt', 'yuv420p', '-crf', '23', '-maxrate', '225k', '-bufsize', '225k', '-force_key_frames', 'expr:gte(t,n_forced*4)', '-x264-params', 'keyint=440:keyint_min=220', '-preset', 'medium', '-profile:v', 'main', '-level', '4.2', '-strict', '-2', '/tmp/tmp2y_dgxnb/tmpgy8rj3qd.mp4']
DEBUG 2025-12-26 14:52:45 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=3, status=running, chunk=False
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpi9jwc425/tmpdbpxjdhs.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:45 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpi9jwc425/tmpc7vy2ote.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:45 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=3, status=running, chunk=False
DEBUG 2025-12-26 14:52:45 files.backends _spawn:29 Spawning FFmpeg process - cmd=['ffmpeg', '-y', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-c:v', 'libx264', '-filter:v', 'scale=if(lt(iw\\,ih)\\,360\\,640):if(lt(iw\\,ih)\\,640\\,360):force_original_aspect_ratio=decrease:force_divisible_by=2:flags=lanczos,fps=fps=55', '-pix_fmt', 'yuv420p', '-crf', '23', '-maxrate', '750k', '-bufsize', '750k', '-force_key_frames', 'expr:gte(t,n_forced*4)', '-x264-params', 'keyint=440:keyint_min=220', '-preset', 'medium', '-profile:v', 'main', '-level', '4.2', '-strict', '-2', '/tmp/tmpi9jwc425/tmpdbpxjdhs.mp4']
DEBUG 2025-12-26 14:52:46 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=23, status=running, chunk=False
DEBUG 2025-12-26 14:52:47 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=2, status=running, chunk=False
DEBUG 2025-12-26 14:52:47 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=3, status=running, chunk=False
DEBUG 2025-12-26 14:52:54 files.helpers run_command:245 Command executed successfully - cmd=['ffmpeg', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-f', 'image2', '-vf', 'fps=1/10, scale=160:90', '/tmp/tmpkxurfuw6/img%03d.jpg'], cwd=None
DEBUG 2025-12-26 14:52:55 files.helpers run_command:245 Command executed successfully - cmd=['convert', '/tmp/tmpkxurfuw6/img001.jpg', '/tmp/tmpkxurfuw6/img002.jpg', '/tmp/tmpkxurfuw6/img003.jpg', '/tmp/tmpkxurfuw6/img004.jpg', '-append', '/tmp/tmpkxurfuw6/sprites.jpg'], cwd=None
DEBUG 2025-12-26 14:52:55 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:52:55 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=13, status=running, chunk=False
DEBUG 2025-12-26 14:52:55 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmprw4k2kd1/tmpnt526r1x.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:55 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmprw4k2kd1/tmp45kj5kxj.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:55 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=13, status=running, chunk=False
DEBUG 2025-12-26 14:52:55 files.backends _spawn:29 Spawning FFmpeg process - cmd=['ffmpeg', '-y', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-c:v', 'libx264', '-filter:v', 'scale=if(lt(iw\\,ih)\\,480\\,853):if(lt(iw\\,ih)\\,853\\,480):force_original_aspect_ratio=decrease:force_divisible_by=2:flags=lanczos,fps=fps=55', '-pix_fmt', 'yuv420p', '-crf', '23', '-maxrate', '1500k', '-bufsize', '1500k', '-force_key_frames', 'expr:gte(t,n_forced*4)', '-x264-params', 'keyint=440:keyint_min=220', '-preset', 'medium', '-profile:v', 'main', '-level', '4.2', '-strict', '-2', '/tmp/tmprw4k2kd1/tmpnt526r1x.mp4']
DEBUG 2025-12-26 14:52:56 files.backends encode:95 FFmpeg encoding completed successfully
DEBUG 2025-12-26 14:52:56 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/tmp/tmp2y_dgxnb/tmpgy8rj3qd.mp4'], cwd=None
DEBUG 2025-12-26 14:52:56 files.helpers media_file_info:348 File size retrieved - input_file=/tmp/tmp2y_dgxnb/tmpgy8rj3qd.mp4, size=276818
DEBUG 2025-12-26 14:52:56 files.helpers run_command:245 Command executed successfully - cmd=['md5sum', '/tmp/tmp2y_dgxnb/tmpgy8rj3qd.mp4'], cwd=None
DEBUG 2025-12-26 14:52:56 files.helpers run_command:245 Command executed successfully - cmd=['ffprobe', '-loglevel', 'error', '-show_streams', '-show_entries', 'format=format_name', '-of', 'json', '/tmp/tmp2y_dgxnb/tmpgy8rj3qd.mp4'], cwd=None
DEBUG 2025-12-26 14:52:56 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:52:56 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=23, status=success, chunk=False
INFO 2025-12-26 14:52:57 files.models.media set_encoding_status:677 Media encoding status changed - friendly_token=Dou0RUh65, old_status=pending, new_status=success
DEBUG 2025-12-26 14:52:57 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:52:57 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:52:57 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=23, status=success, chunk=False
DEBUG 2025-12-26 14:52:57 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:52:57 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=10, status=running, chunk=False
DEBUG 2025-12-26 14:52:57 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmp1aimgn5p/tmpydk1ue68.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:57 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmp1aimgn5p/tmps6djmvgg.mp4, suffix=.mp4
DEBUG 2025-12-26 14:52:57 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=10, status=running, chunk=False
DEBUG 2025-12-26 14:52:57 files.backends _spawn:29 Spawning FFmpeg process - cmd=['ffmpeg', '-y', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-c:v', 'libx264', '-filter:v', 'scale=if(lt(iw\\,ih)\\,720\\,1280):if(lt(iw\\,ih)\\,1280\\,720):force_original_aspect_ratio=decrease:force_divisible_by=2:flags=lanczos,fps=fps=55', '-pix_fmt', 'yuv420p', '-crf', '23', '-maxrate', '5250k', '-bufsize', '5250k', '-force_key_frames', 'expr:gte(t,n_forced*4)', '-x264-params', 'keyint=440:keyint_min=220', '-preset', 'medium', '-profile:v', 'main', '-level', '4.2', '-strict', '-2', '/tmp/tmp1aimgn5p/tmpydk1ue68.mp4']
DEBUG 2025-12-26 14:52:57 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=13, status=running, chunk=False
DEBUG 2025-12-26 14:52:59 files.backends encode:95 FFmpeg encoding completed successfully
DEBUG 2025-12-26 14:52:59 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/tmp/tmpw57dyir6/tmprei5gp8l.mp4'], cwd=None
DEBUG 2025-12-26 14:52:59 files.helpers media_file_info:348 File size retrieved - input_file=/tmp/tmpw57dyir6/tmprei5gp8l.mp4, size=536095
DEBUG 2025-12-26 14:52:59 files.helpers run_command:245 Command executed successfully - cmd=['md5sum', '/tmp/tmpw57dyir6/tmprei5gp8l.mp4'], cwd=None
DEBUG 2025-12-26 14:52:59 files.helpers run_command:245 Command executed successfully - cmd=['ffprobe', '-loglevel', 'error', '-show_streams', '-show_entries', 'format=format_name', '-of', 'json', '/tmp/tmpw57dyir6/tmprei5gp8l.mp4'], cwd=None
DEBUG 2025-12-26 14:52:59 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:52:59 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=2, status=success, chunk=False
INFO 2025-12-26 14:52:59 files.models.media set_encoding_status:677 Media encoding status changed - friendly_token=Dou0RUh65, old_status=pending, new_status=success
DEBUG 2025-12-26 14:52:59 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
INFO 2025-12-26 14:52:59 actions.models mediaaction_save:65 User action - action_id=1, action=watch, user_id=2, username=abcdef, media_friendly_token=Dou0RUh65, session_key=None, remote_ip=35476a338e03e65c85448bb8450bd27d
DEBUG 2025-12-26 14:53:00 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:00 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=2, status=success, chunk=False
DEBUG 2025-12-26 14:53:00 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:00 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=1, status=running, chunk=False
DEBUG 2025-12-26 14:53:00 files.helpers create_temp_file:195 Created temporary file - filename=/tmp/tmpcjzb1_gj.gif, suffix=.gif
DEBUG 2025-12-26 14:53:01 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=10, status=running, chunk=False
DEBUG 2025-12-26 14:53:08 files.backends encode:95 FFmpeg encoding completed successfully
DEBUG 2025-12-26 14:53:08 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/tmp/tmpi9jwc425/tmpdbpxjdhs.mp4'], cwd=None
DEBUG 2025-12-26 14:53:08 files.helpers media_file_info:348 File size retrieved - input_file=/tmp/tmpi9jwc425/tmpdbpxjdhs.mp4, size=882543
DEBUG 2025-12-26 14:53:08 files.helpers run_command:245 Command executed successfully - cmd=['md5sum', '/tmp/tmpi9jwc425/tmpdbpxjdhs.mp4'], cwd=None
DEBUG 2025-12-26 14:53:08 files.helpers run_command:245 Command executed successfully - cmd=['ffprobe', '-loglevel', 'error', '-show_streams', '-show_entries', 'format=format_name', '-of', 'json', '/tmp/tmpi9jwc425/tmpdbpxjdhs.mp4'], cwd=None
DEBUG 2025-12-26 14:53:08 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:08 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=3, status=success, chunk=False
INFO 2025-12-26 14:53:08 files.models.media set_encoding_status:677 Media encoding status changed - friendly_token=Dou0RUh65, old_status=pending, new_status=success
DEBUG 2025-12-26 14:53:08 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:08 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:08 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=3, status=success, chunk=False
DEBUG 2025-12-26 14:53:08 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:10 files.helpers run_command:245 Command executed successfully - cmd=['ffmpeg', '-y', '-ss', '3', '-i', '/home/mediacms.io/mediacms/media_files/original/user/abcdef/12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4', '-hide_banner', '-vf', 'scale=344:-1:flags=lanczos,fps=1', '-t', '25', '-f', 'gif', '/tmp/tmpcjzb1_gj.gif'], cwd=None
DEBUG 2025-12-26 14:53:10 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/1/abcdef/12f1302f3ef94a7e91d56a3dc7956208.tmpcjzb1_gj.gif'], cwd=None
DEBUG 2025-12-26 14:53:10 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=1, status=success, chunk=False
DEBUG 2025-12-26 14:53:10 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:10 files.helpers rm_file:146 Successfully removed file - filename=/tmp/tmpcjzb1_gj.gif
DEBUG 2025-12-26 14:53:11 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
INFO 2025-12-26 14:53:11 files.models.comment comment_save:58 Comment created - comment_id=1, user_id=2, username=abcdef, media_friendly_token=Dou0RUh65, has_parent=False
WARNING 2025-12-26 14:53:11 files.helpers run_command:283 Command failed - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], returncode=1, cwd=None
DEBUG 2025-12-26 14:53:14 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208vhrivtk2U', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:14 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208vhrivtk2U', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
DEBUG 2025-12-26 14:53:14 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208N0RpNvJCY', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:14 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208N0RpNvJCY', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
DEBUG 2025-12-26 14:53:16 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208e6Xtr39AA', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:16 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208e6Xtr39AA', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
DEBUG 2025-12-26 14:53:16 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208mu2fu3W0l', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:16 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208mu2fu3W0l', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
DEBUG 2025-12-26 14:53:22 files.backends encode:95 FFmpeg encoding completed successfully
DEBUG 2025-12-26 14:53:22 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/tmp/tmprw4k2kd1/tmpnt526r1x.mp4'], cwd=None
DEBUG 2025-12-26 14:53:22 files.helpers media_file_info:348 File size retrieved - input_file=/tmp/tmprw4k2kd1/tmpnt526r1x.mp4, size=1253439
DEBUG 2025-12-26 14:53:22 files.helpers run_command:245 Command executed successfully - cmd=['md5sum', '/tmp/tmprw4k2kd1/tmpnt526r1x.mp4'], cwd=None
DEBUG 2025-12-26 14:53:22 files.helpers run_command:245 Command executed successfully - cmd=['ffprobe', '-loglevel', 'error', '-show_streams', '-show_entries', 'format=format_name', '-of', 'json', '/tmp/tmprw4k2kd1/tmpnt526r1x.mp4'], cwd=None
DEBUG 2025-12-26 14:53:22 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/13/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:22 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=13, status=success, chunk=False
INFO 2025-12-26 14:53:23 files.models.media set_encoding_status:677 Media encoding status changed - friendly_token=Dou0RUh65, old_status=pending, new_status=success
DEBUG 2025-12-26 14:53:23 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:23 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/13/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:23 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=13, status=success, chunk=False
DEBUG 2025-12-26 14:53:23 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:24 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208HRzxlN7mp', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/13/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:24 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208Xr43tZ8ij', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/13/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:24 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208HRzxlN7mp', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
DEBUG 2025-12-26 14:53:24 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208Xr43tZ8ij', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
DEBUG 2025-12-26 14:53:32 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=10, status=running, chunk=False
DEBUG 2025-12-26 14:53:33 files.backends encode:95 FFmpeg encoding completed successfully
DEBUG 2025-12-26 14:53:33 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/tmp/tmp1aimgn5p/tmpydk1ue68.mp4'], cwd=None
DEBUG 2025-12-26 14:53:33 files.helpers media_file_info:348 File size retrieved - input_file=/tmp/tmp1aimgn5p/tmpydk1ue68.mp4, size=2020478
DEBUG 2025-12-26 14:53:33 files.helpers run_command:245 Command executed successfully - cmd=['md5sum', '/tmp/tmp1aimgn5p/tmpydk1ue68.mp4'], cwd=None
DEBUG 2025-12-26 14:53:33 files.helpers run_command:245 Command executed successfully - cmd=['ffprobe', '-loglevel', 'error', '-show_streams', '-show_entries', 'format=format_name', '-of', 'json', '/tmp/tmp1aimgn5p/tmpydk1ue68.mp4'], cwd=None
DEBUG 2025-12-26 14:53:33 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/10/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:33 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=10, status=success, chunk=False
DEBUG 2025-12-26 14:53:33 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:33 files.helpers run_command:245 Command executed successfully - cmd=['stat', '-c', '%s', '/home/mediacms.io/mediacms/media_files/encoded/10/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:33 files.models.encoding encoding_file_save:164 Encoding updated - friendly_token=Dou0RUh65, profile_id=10, status=success, chunk=False
DEBUG 2025-12-26 14:53:33 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
DEBUG 2025-12-26 14:53:34 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208vi8EWnxXC', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/13/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/10/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
DEBUG 2025-12-26 14:53:34 files.helpers run_command:245 Command executed successfully - cmd=['/home/mediacms.io/bento4/bin/mp4hls', '--segment-duration=4', '--output-dir=/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208fNgaVMw1J', '/home/mediacms.io/mediacms/media_files/encoded/2/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/3/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/13/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/10/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4', '/home/mediacms.io/mediacms/media_files/encoded/23/abcdef/12f1302f3ef94a7e91d56a3dc7956208.12f1302f3ef94a7e91d56a3dc7956208.mediacmsadmindashboardsmaller.mp4.mp4'], cwd=None
WARNING 2025-12-26 14:53:34 files.helpers run_command:283 Command failed - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208vi8EWnxXC', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], returncode=1, cwd=None
DEBUG 2025-12-26 14:53:34 files.helpers run_command:245 Command executed successfully - cmd=['cp', '-rT', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208fNgaVMw1J', '/home/mediacms.io/mediacms/media_files/hls/12f1302f3ef94a7e91d56a3dc7956208'], cwd=None
INFO 2025-12-26 14:53:34 files.models.comment comment_delete:78 Comment deleted - comment_id=1, user_id=2, username=abcdef, media_friendly_token=Dou0RUh65
DEBUG 2025-12-26 14:54:09 files.models.media media_save:1064 Media updated - friendly_token=Dou0RUh65, user_id=2
INFO 2025-12-26 14:54:09 files.models.category tag_save:203 Tag created - tag_id=1, title=testtag, user_id=2
INFO 2025-12-26 14:54:10 actions.models mediaaction_save:65 User action - action_id=2, action=watch, user_id=2, username=abcdef, media_friendly_token=Dou0RUh65, session_key=None, remote_ip=35476a338e03e65c85448bb8450bd27d
INFO 2025-12-26 14:54:59 users.models log_user_logout:398 Logout (django-allauth) - user_id=2, username=abcdef

Enhance all login paths (API, django-allauth, SAML) to capture and log
failed login attempts with consistent format. Distinguish between
user_not_found, wrong_password, user_deactivated, and user_not_approved
failure types. Include IP addresses in all failed login logs for
security monitoring.
@mrjoshuap
Copy link
Contributor Author

After inspection of the logs, I have noticed that in my setup, IP addresses are not always properly rendered. This is likely related to #1204 and suspect that my branch over there will resolve it. I'd like to leave the logic in place here and consider pulling that fix here as well.

I've added a series of signals/receivers to capture most Django events (like creates, login fails, etc), and they have already been useful for other efforts I have in flight.

Implement proxy-aware middleware and IP extraction utilities to correctly
handle client IP addresses and sessions when MediaCMS is deployed behind
reverse proxies, load balancers, or other HTTP proxies.

Features:
- Proxy-aware middleware that extracts real client IP from X-Forwarded-For
- Trusted proxy validation to prevent IP spoofing attacks
- Support for multiple proxy hops and CIDR network notation
- Configurable settings with safe defaults for backward compatibility
- Comprehensive documentation with examples for common scenarios

Fixes mediacms-io#1204
- Remove USE_X_FORWARDED_PORT and USE_X_FORWARDED_PREFIX (unused)
- Change TRUSTED_PROXIES default from example values to empty list
- Improve inline documentation for TRUSTED_PROXIES setting
@mrjoshuap
Copy link
Contributor Author

login failure w/o reverse proxy (note, I suspect I can't see the real IP due to docker on Mac networking limitations, all requests on my Mac always show the docker network gateway as client ip 192.168.65.1; this is the same behavior before and after this change)

WARNING 2025-12-27 00:11:16 users.forms clean:50 Login failed (django-allauth) - user_not_found, attempted_username_or_email=asdf, ip=192.168.65.1

login failure w/reverse proxy

WARNING 2025-12-27 00:11:56 users.forms clean:50 Login failed (django-allauth) - user_not_found, attempted_username_or_email=asdf, ip=192.168.7.208

successful login w/o reverse proxy (note same caveat as above)

INFO 2025-12-27 00:14:19 users.models log_user_login:387 Login successful (django-allauth) - user_id=1, username=admin, ip=192.168.65.1

successful login w/reverse proxy*

INFO 2025-12-27 00:17:28 users.models log_user_login:387 Login successful (django-allauth) - user_id=1, username=admin, ip=192.168.7.208

@mrjoshuap
Copy link
Contributor Author

Alright, put a fork in this one, I'm calling it done. I've got most, if not all, the important stuff properly logging now. I kept existing behavior the same, with the exception of client ip detection w/reverse proxies -- it should log the real client IP based on X-FORWARDED-FOR and/or X-REAL-IP. There were also a number of rendering errors related to model fields having no default value for frontend rendering (e.g. IS_MANAGER, IS_EDITOR...). I gave them sensible (False) defaults.

Implemented a "TRUSTED_PROXIES" configuration that will enable the behavior if the proxy is actually trusted.

I can provide additional log information or details as needed.

I've run through about 50 tests, uploads, tags, bulk actions, etc. All are properly logged and I now have a better understanding of how things work in a typical flow!

I do seem to have problems WITHOUT a reverse proxy but think it caused by Docker on Mac networking limitations -- it will likely need validation in a closer to real linux environment to be sure it's grabbing the correct remote_addr / client ip.

If you do NOT specify DEBUG=True, log levels remain at ERROR and up, however there WILL be a few new ones that were not logged properly, if at all.

I left examples for the reverse proxy setup commented in the local_settings, nginx and uwsgi configs.

Finally, I added a slew of documentation around the use for both administrators and developers. Needs validated.

Of note, a section added for SAML troubleshooting, which should now properly deliver error messages to make it easier when configuring or bug hunting.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant