Merge pull request netbox-community#4315 from netbox-community/4195-a…

…pplication-logging

Closes netbox-community#4195: Application logging

docs/configuration/optional-settings.md

@@ -183,6 +183,14 @@ LOGGING = {
 }
 ```
 
+### Available Loggers
+
+* `netbox.auth.*` - Authentication events
+* `netbox.api.views.*` - Views which handle business logic for the REST API
+* `netbox.reports.*` - Report execution (`module.name`)
+* `netbox.scripts.*` - Custom script execution (`module.name`)
+* `netbox.views.*` - Views which handle business logic for the web UI
+
 ---
 
 ## LOGIN_REQUIRED

docs/release-notes/version-2.8.md

@@ -1,5 +1,9 @@
 # v2.8.0 (FUTURE)
 
+## Enhancements
+
+* [#4195](https://github.com/netbox-community/netbox/issues/4195) - Enabled application logging (see [logging configuration](../configuration/optional-settings.md#logging))
+
 ## API Changes
 
 * dcim.Rack: The `/api/dcim/racks/<pk>/units/` endpoint has been replaced with `/api/dcim/racks/<pk>/elevation/`.

mkdocs.yml

@@ -63,6 +63,7 @@ nav:
         - Release Checklist: 'development/release-checklist.md'
         - Squashing Migrations: 'development/squashing-migrations.md'
     - Release Notes:
+        - Version 2.8: 'release-notes/version-2.8.md'
         - Version 2.7: 'release-notes/version-2.7.md'
         - Version 2.6: 'release-notes/version-2.6.md'
         - Version 2.5: 'release-notes/version-2.5.md'

netbox/extras/reports.py

@@ -1,5 +1,6 @@
 import importlib
 import inspect
+import logging
 import pkgutil
 from collections import OrderedDict
 
@@ -91,6 +92,8 @@ def __init__(self):
         self.active_test = None
         self.failed = False
 
+        self.logger = logging.getLogger(f"netbox.reports.{self.module}.{self.name}")
+
         # Compile test methods and initialize results skeleton
         test_methods = []
         for method in dir(self):
@@ -138,6 +141,7 @@ def log(self, message):
         Log a message which is not associated with a particular object.
         """
         self._log(None, message, level=LOG_DEFAULT)
+        self.logger.info(message)
 
     def log_success(self, obj, message=None):
         """
@@ -146,33 +150,39 @@ def log_success(self, obj, message=None):
         if message:
             self._log(obj, message, level=LOG_SUCCESS)
         self._results[self.active_test]['success'] += 1
+        self.logger.info(f"Success | {obj}: {message}")
 
     def log_info(self, obj, message):
         """
         Log an informational message.
         """
         self._log(obj, message, level=LOG_INFO)
         self._results[self.active_test]['info'] += 1
+        self.logger.info(f"Info | {obj}: {message}")
 
     def log_warning(self, obj, message):
         """
         Log a warning.
         """
         self._log(obj, message, level=LOG_WARNING)
         self._results[self.active_test]['warning'] += 1
+        self.logger.info(f"Warning | {obj}: {message}")
 
     def log_failure(self, obj, message):
         """
         Log a failure. Calling this method will automatically mark the report as failed.
         """
         self._log(obj, message, level=LOG_FAILURE)
         self._results[self.active_test]['failure'] += 1
+        self.logger.info(f"Failure | {obj}: {message}")
         self.failed = True
 
     def run(self):
         """
         Run the report and return its results. Each test method will be executed in order.
         """
+        self.logger.info(f"Running report")
+
         for method_name in self.test_methods:
             self.active_test = method_name
             test_method = getattr(self, method_name)
@@ -184,6 +194,11 @@ def run(self):
         result.save()
         self.result = result
 
+        if self.failed:
+            self.logger.warning("Report failed")
+        else:
+            self.logger.info("Report completed successfully")
+
         # Perform any post-run tasks
         self.post_run()
 

netbox/extras/scripts.py

@@ -1,5 +1,6 @@
 import inspect
 import json
+import logging
 import os
 import pkgutil
 import time
@@ -254,6 +255,7 @@ class Meta:
     def __init__(self):
 
         # Initiate the log
+        self.logger = logging.getLogger(f"netbox.scripts.{self.module()}.{self.__class__.__name__}")
         self.log = []
 
         # Declare the placeholder for the current request
@@ -301,18 +303,23 @@ def as_form(self, data=None, files=None, initial=None):
     # Logging
 
     def log_debug(self, message):
+        self.logger.log(logging.DEBUG, message)
         self.log.append((LOG_DEFAULT, message))
 
     def log_success(self, message):
+        self.logger.log(logging.INFO, message)  # No syslog equivalent for SUCCESS
         self.log.append((LOG_SUCCESS, message))
 
     def log_info(self, message):
+        self.logger.log(logging.INFO, message)
         self.log.append((LOG_INFO, message))
 
     def log_warning(self, message):
+        self.logger.log(logging.WARNING, message)
         self.log.append((LOG_WARNING, message))
 
     def log_failure(self, message):
+        self.logger.log(logging.ERROR, message)
         self.log.append((LOG_FAILURE, message))
 
     # Convenience functions
@@ -375,6 +382,10 @@ def run_script(script, data, request, commit=True):
     start_time = None
     end_time = None
 
+    script_name = script.__class__.__name__
+    logger = logging.getLogger(f"netbox.scripts.{script.module()}.{script_name}")
+    logger.info(f"Running script (commit={commit})")
+
     # Add files to form data
     files = request.FILES
     for field_name, fileobj in files.items():
@@ -404,6 +415,7 @@ def run_script(script, data, request, commit=True):
         script.log_failure(
             "An exception occurred: `{}: {}`\n```\n{}\n```".format(type(e).__name__, e, stacktrace)
         )
+        logger.error(f"Exception raised during script execution: {e}")
         commit = False
     finally:
         if not commit:
@@ -416,6 +428,7 @@ def run_script(script, data, request, commit=True):
     # Calculate execution time
     if end_time is not None:
         execution_time = end_time - start_time
+        logger.info(f"Script completed in {execution_time:.4f} seconds")
     else:
         execution_time = None
 

netbox/users/views.py

@@ -1,3 +1,5 @@
+import logging
+
 from django.conf import settings
 from django.contrib import messages
 from django.contrib.auth import login as auth_login, logout as auth_logout, update_session_auth_hash
@@ -24,6 +26,9 @@
 #
 
 class LoginView(View):
+    """
+    Perform user authentication via the web UI.
+    """
     template_name = 'login.html'
 
     @method_decorator(sensitive_post_parameters('password'))
@@ -38,36 +43,51 @@ def get(self, request):
         })
 
     def post(self, request):
+        logger = logging.getLogger('netbox.auth.login')
         form = LoginForm(request, data=request.POST)
+
         if form.is_valid():
+            logger.debug("Login form validation was successful")
 
             # Determine where to direct user after successful login
-            redirect_to = request.POST.get('next', '')
-            if not is_safe_url(url=redirect_to, allowed_hosts=request.get_host()):
+            redirect_to = request.POST.get('next')
+            if redirect_to and not is_safe_url(url=redirect_to, allowed_hosts=request.get_host()):
+                logger.warning(f"Ignoring unsafe 'next' URL passed to login form: {redirect_to}")
                 redirect_to = reverse('home')
 
             # If maintenance mode is enabled, assume the database is read-only, and disable updating the user's
             # last_login time upon authentication.
             if settings.MAINTENANCE_MODE:
+                logger.warning("Maintenance mode enabled: disabling update of most recent login time")
                 user_logged_in.disconnect(update_last_login, dispatch_uid='update_last_login')
 
             # Authenticate user
             auth_login(request, form.get_user())
+            logger.info(f"User {request.user} successfully authenticated")
             messages.info(request, "Logged in as {}.".format(request.user))
 
+            logger.debug(f"Redirecting user to {redirect_to}")
             return HttpResponseRedirect(redirect_to)
 
+        else:
+            logger.debug("Login form validation failed")
+
         return render(request, self.template_name, {
             'form': form,
         })
 
 
 class LogoutView(View):
-
+    """
+    Deauthenticate a web user.
+    """
     def get(self, request):
+        logger = logging.getLogger('netbox.auth.logout')
 
         # Log out the user
+        username = request.user
         auth_logout(request)
+        logger.info(f"User {username} has logged out")
         messages.info(request, "You have logged out.")
 
         # Delete session key cookie (if set) upon logout

netbox/utilities/api.py

@@ -1,3 +1,4 @@
+import logging
 from collections import OrderedDict
 
 import pytz
@@ -303,25 +304,35 @@ def get_serializer(self, *args, **kwargs):
         return super().get_serializer(*args, **kwargs)
 
     def get_serializer_class(self):
+        logger = logging.getLogger('netbox.api.views.ModelViewSet')
 
         # If 'brief' has been passed as a query param, find and return the nested serializer for this model, if one
         # exists
         request = self.get_serializer_context()['request']
-        if request.query_params.get('brief', False):
+        if request.query_params.get('brief'):
+            logger.debug("Request is for 'brief' format; initializing nested serializer")
             try:
-                return get_serializer_for_model(self.queryset.model, prefix='Nested')
+                serializer = get_serializer_for_model(self.queryset.model, prefix='Nested')
+                logger.debug(f"Using serializer {serializer}")
+                return serializer
             except SerializerNotFound:
                 pass
 
         # Fall back to the hard-coded serializer class
+        logger.debug(f"Using serializer {self.serializer_class}")
         return self.serializer_class
 
     def dispatch(self, request, *args, **kwargs):
+        logger = logging.getLogger('netbox.api.views.ModelViewSet')
+
         try:
             return super().dispatch(request, *args, **kwargs)
         except ProtectedError as e:
-            models = ['{} ({})'.format(o, o._meta) for o in e.protected_objects.all()]
+            models = [
+                '{} ({})'.format(o, o._meta) for o in e.protected_objects.all()
+            ]
             msg = 'Unable to delete object. The following dependent objects were found: {}'.format(', '.join(models))
+            logger.warning(msg)
             return self.finalize_response(
                 request,
                 Response({'detail': msg}, status=409),
@@ -341,6 +352,26 @@ def retrieve(self, *args, **kwargs):
         """
         return super().retrieve(*args, **kwargs)
 
+    #
+    # Logging
+    #
+
+    def perform_create(self, serializer):
+        model = serializer.child.Meta.model if hasattr(serializer, 'many') else serializer.Meta.model
+        logger = logging.getLogger('netbox.api.views.ModelViewSet')
+        logger.info(f"Creating new {model._meta.verbose_name}")
+        return super().perform_create(serializer)
+
+    def perform_update(self, serializer):
+        logger = logging.getLogger('netbox.api.views.ModelViewSet')
+        logger.info(f"Updating {serializer.instance} (PK: {serializer.instance.pk})")
+        return super().perform_update(serializer)
+
+    def perform_destroy(self, instance):
+        logger = logging.getLogger('netbox.api.views.ModelViewSet')
+        logger.info(f"Deleting {instance} (PK: {instance.pk})")
+        return super().perform_destroy(instance)
+
 
 class FieldChoicesViewSet(ViewSet):
     """