diff --git a/docs/configuration/optional-settings.md b/docs/configuration/optional-settings.md index cbe01728c..b7ecbe94d 100644 --- a/docs/configuration/optional-settings.md +++ b/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 diff --git a/docs/release-notes/version-2.8.md b/docs/release-notes/version-2.8.md index 3088bb356..8dd4d2672 100644 --- a/docs/release-notes/version-2.8.md +++ b/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//units/` endpoint has been replaced with `/api/dcim/racks//elevation/`. diff --git a/mkdocs.yml b/mkdocs.yml index cf45b89ae..3c1733ac4 100644 --- a/mkdocs.yml +++ b/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' diff --git a/netbox/extras/reports.py b/netbox/extras/reports.py index 9027d6a4a..373acdde7 100644 --- a/netbox/extras/reports.py +++ b/netbox/extras/reports.py @@ -1,5 +1,6 @@ import importlib import inspect +import logging import pkgutil from collections import OrderedDict @@ -91,6 +92,8 @@ class Report(object): 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 @@ class Report(object): 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,6 +150,7 @@ class Report(object): 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): """ @@ -153,6 +158,7 @@ class Report(object): """ 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): """ @@ -160,6 +166,7 @@ class Report(object): """ 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): """ @@ -167,12 +174,15 @@ class Report(object): """ 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 @@ class Report(object): 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() diff --git a/netbox/extras/scripts.py b/netbox/extras/scripts.py index 97fc50ea0..fec44d039 100644 --- a/netbox/extras/scripts.py +++ b/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 BaseScript: 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 @@ class BaseScript: # 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 diff --git a/netbox/users/views.py b/netbox/users/views.py index 6a2410274..ae1345b6b 100644 --- a/netbox/users/views.py +++ b/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 @@ from .models import Token # class LoginView(View): + """ + Perform user authentication via the web UI. + """ template_name = 'login.html' @method_decorator(sensitive_post_parameters('password')) @@ -38,36 +43,51 @@ class LoginView(View): }) 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 diff --git a/netbox/utilities/api.py b/netbox/utilities/api.py index 72a5735de..43062af69 100644 --- a/netbox/utilities/api.py +++ b/netbox/utilities/api.py @@ -1,3 +1,4 @@ +import logging from collections import OrderedDict import pytz @@ -303,25 +304,35 @@ class ModelViewSet(_ModelViewSet): 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 @@ class ModelViewSet(_ModelViewSet): """ 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): """ diff --git a/netbox/utilities/views.py b/netbox/utilities/views.py index e354c4dff..d150b3680 100644 --- a/netbox/utilities/views.py +++ b/netbox/utilities/views.py @@ -1,3 +1,4 @@ +import logging import sys from copy import deepcopy @@ -219,35 +220,36 @@ class ObjectEditView(GetReturnURLMixin, View): # given some parameter from the request URL. return obj - def get(self, request, *args, **kwargs): + def dispatch(self, request, *args, **kwargs): + self.obj = self.alter_obj(self.get_object(kwargs), request, args, kwargs) - obj = self.get_object(kwargs) - obj = self.alter_obj(obj, request, args, kwargs) + return super().dispatch(request, *args, **kwargs) + + def get(self, request, *args, **kwargs): # Parse initial data manually to avoid setting field values as lists initial_data = {k: request.GET[k] for k in request.GET} - form = self.model_form(instance=obj, initial=initial_data) + form = self.model_form(instance=self.obj, initial=initial_data) return render(request, self.template_name, { - 'obj': obj, + 'obj': self.obj, 'obj_type': self.model._meta.verbose_name, 'form': form, - 'return_url': self.get_return_url(request, obj), + 'return_url': self.get_return_url(request, self.obj), }) def post(self, request, *args, **kwargs): - - obj = self.get_object(kwargs) - obj = self.alter_obj(obj, request, args, kwargs) - form = self.model_form(request.POST, request.FILES, instance=obj) + logger = logging.getLogger('netbox.views.ObjectEditView') + form = self.model_form(request.POST, request.FILES, instance=self.obj) if form.is_valid(): - obj_created = not form.instance.pk - obj = form.save() + logger.debug("Form validation was successful") + obj = form.save() msg = '{} {}'.format( - 'Created' if obj_created else 'Modified', + 'Created' if not form.instance.pk else 'Modified', self.model._meta.verbose_name ) + logger.info(f"{msg} {obj} (PK: {obj.pk})") if hasattr(obj, 'get_absolute_url'): msg = '{} {}'.format(msg, obj.get_absolute_url(), escape(obj)) else: @@ -269,11 +271,14 @@ class ObjectEditView(GetReturnURLMixin, View): else: return redirect(self.get_return_url(request, obj)) + else: + logger.debug("Form validation failed") + return render(request, self.template_name, { - 'obj': obj, + 'obj': self.obj, 'obj_type': self.model._meta.verbose_name, 'form': form, - 'return_url': self.get_return_url(request, obj), + 'return_url': self.get_return_url(request, self.obj), }) @@ -295,7 +300,6 @@ class ObjectDeleteView(GetReturnURLMixin, View): return get_object_or_404(self.model, pk=kwargs['pk']) def get(self, request, **kwargs): - obj = self.get_object(kwargs) form = ConfirmationForm(initial=request.GET) @@ -307,18 +311,22 @@ class ObjectDeleteView(GetReturnURLMixin, View): }) def post(self, request, **kwargs): - + logger = logging.getLogger('netbox.views.ObjectDeleteView') obj = self.get_object(kwargs) form = ConfirmationForm(request.POST) + if form.is_valid(): + logger.debug("Form validation was successful") try: obj.delete() except ProtectedError as e: + logger.info("Caught ProtectedError while attempting to delete object") handle_protectederror(obj, request, e) return redirect(obj.get_absolute_url()) msg = 'Deleted {} {}'.format(self.model._meta.verbose_name, obj) + logger.info(msg) messages.success(request, msg) return_url = form.cleaned_data.get('return_url') @@ -327,6 +335,9 @@ class ObjectDeleteView(GetReturnURLMixin, View): else: return redirect(self.get_return_url(request, obj)) + else: + logger.debug("Form validation failed") + return render(request, self.template_name, { 'obj': obj, 'form': form, @@ -350,7 +361,6 @@ class BulkCreateView(GetReturnURLMixin, View): template_name = None def get(self, request): - # Set initial values for visible form fields from query args initial = {} for field in getattr(self.model_form._meta, 'fields', []): @@ -368,13 +378,13 @@ class BulkCreateView(GetReturnURLMixin, View): }) def post(self, request): - + logger = logging.getLogger('netbox.views.BulkCreateView') model = self.model_form._meta.model form = self.form(request.POST) model_form = self.model_form(request.POST) if form.is_valid(): - + logger.debug("Form validation was successful") pattern = form.cleaned_data['pattern'] new_objs = [] @@ -392,6 +402,7 @@ class BulkCreateView(GetReturnURLMixin, View): # Validate each new object independently. if model_form.is_valid(): obj = model_form.save() + logger.debug(f"Created {obj} (PK: {obj.pk})") new_objs.append(obj) else: # Copy any errors on the pattern target field to the pattern form. @@ -403,6 +414,7 @@ class BulkCreateView(GetReturnURLMixin, View): # If we make it to this point, validation has succeeded on all new objects. msg = "Added {} {}".format(len(new_objs), model._meta.verbose_name_plural) + logger.info(msg) messages.success(request, msg) if '_addanother' in request.POST: @@ -412,6 +424,9 @@ class BulkCreateView(GetReturnURLMixin, View): except IntegrityError: pass + else: + logger.debug("Form validation failed") + return render(request, self.template_name, { 'form': form, 'model_form': model_form, @@ -430,7 +445,6 @@ class ObjectImportView(GetReturnURLMixin, View): template_name = 'utilities/obj_import.html' def get(self, request): - form = ImportForm() return render(request, self.template_name, { @@ -440,9 +454,11 @@ class ObjectImportView(GetReturnURLMixin, View): }) def post(self, request): - + logger = logging.getLogger('netbox.views.ObjectImportView') form = ImportForm(request.POST) + if form.is_valid(): + logger.debug("Import form validation was successful") # Initialize model form data = form.cleaned_data['data'] @@ -463,9 +479,11 @@ class ObjectImportView(GetReturnURLMixin, View): # Save the primary object obj = model_form.save() + logger.debug(f"Created {obj} (PK: {obj.pk})") # Iterate through the related object forms (if any), validating and saving each instance. for field_name, related_object_form in self.related_object_forms.items(): + logger.debug("Processing form for related objects: {related_object_form}") for i, rel_obj_data in enumerate(data.get(field_name, list())): @@ -489,7 +507,7 @@ class ObjectImportView(GetReturnURLMixin, View): pass if not model_form.errors: - + logger.info(f"Import object {obj} (PK: {obj.pk})") messages.success(request, mark_safe('Imported object: {}'.format( obj.get_absolute_url(), obj ))) @@ -504,6 +522,7 @@ class ObjectImportView(GetReturnURLMixin, View): return redirect(self.get_return_url(request, obj)) else: + logger.debug("Model form validation failed") # Replicate model form errors for display for field, errors in model_form.errors.items(): @@ -513,6 +532,9 @@ class ObjectImportView(GetReturnURLMixin, View): else: form.add_error(None, "{}: {}".format(field, err)) + else: + logger.debug("Import form validation failed") + return render(request, self.template_name, { 'form': form, 'obj_type': self.model._meta.verbose_name, @@ -560,14 +582,14 @@ class BulkImportView(GetReturnURLMixin, View): }) def post(self, request): - + logger = logging.getLogger('netbox.views.BulkImportView') new_objs = [] form = self._import_form(request.POST) if form.is_valid(): + logger.debug("Form validation was successful") try: - # Iterate through CSV data and bind each row to a new model form instance. with transaction.atomic(): for row, data in enumerate(form.cleaned_data['csv'], start=1): @@ -585,6 +607,7 @@ class BulkImportView(GetReturnURLMixin, View): if new_objs: msg = 'Imported {} {}'.format(len(new_objs), new_objs[0]._meta.verbose_name_plural) + logger.info(msg) messages.success(request, msg) return render(request, "import_success.html", { @@ -595,6 +618,9 @@ class BulkImportView(GetReturnURLMixin, View): except ValidationError: pass + else: + logger.debug("Form validation failed") + return render(request, self.template_name, { 'form': form, 'fields': self.model_form().fields, @@ -623,7 +649,7 @@ class BulkEditView(GetReturnURLMixin, View): return redirect(self.get_return_url(request)) def post(self, request, **kwargs): - + logger = logging.getLogger('netbox.views.BulkEditView') model = self.queryset.model # If we are editing *all* objects in the queryset, replace the PK list with all matched objects. @@ -636,8 +662,9 @@ class BulkEditView(GetReturnURLMixin, View): if '_apply' in request.POST: form = self.form(model, request.POST) - if form.is_valid(): + if form.is_valid(): + logger.debug("Form validation was successful") custom_fields = form.custom_fields if hasattr(form, 'custom_fields') else [] standard_fields = [ field for field in form.fields if field not in custom_fields + ['pk'] @@ -677,6 +704,7 @@ class BulkEditView(GetReturnURLMixin, View): obj.full_clean() obj.save() + logger.debug(f"Saved {obj} (PK: {obj.pk})") # Update custom fields obj_type = ContentType.objects.get_for_model(model) @@ -697,6 +725,7 @@ class BulkEditView(GetReturnURLMixin, View): ) cfv.value = form.cleaned_data[name] cfv.save() + logger.debug(f"Saved custom fields for {obj} (PK: {obj.pk})") # Add/remove tags if form.cleaned_data.get('add_tags', None): @@ -708,6 +737,7 @@ class BulkEditView(GetReturnURLMixin, View): if updated_count: msg = 'Updated {} {}'.format(updated_count, model._meta.verbose_name_plural) + logger.info(msg) messages.success(self.request, msg) return redirect(self.get_return_url(request)) @@ -715,6 +745,9 @@ class BulkEditView(GetReturnURLMixin, View): except ValidationError as e: messages.error(self.request, "{} failed validation: {}".format(obj, e)) + else: + logger.debug("Form validation failed") + else: # Include the PK list as initial data for the form initial_data = {'pk': pk_list} @@ -761,7 +794,7 @@ class BulkDeleteView(GetReturnURLMixin, View): return redirect(self.get_return_url(request)) def post(self, request, **kwargs): - + logger = logging.getLogger('netbox.views.BulkDeleteView') model = self.queryset.model # Are we deleting *all* objects in the queryset or just a selected subset? @@ -778,19 +811,25 @@ class BulkDeleteView(GetReturnURLMixin, View): if '_confirm' in request.POST: form = form_cls(request.POST) if form.is_valid(): + logger.debug("Form validation was successful") # Delete objects queryset = model.objects.filter(pk__in=pk_list) try: deleted_count = queryset.delete()[1][model._meta.label] except ProtectedError as e: + logger.info("Caught ProtectedError while attempting to delete objects") handle_protectederror(list(queryset), request, e) return redirect(self.get_return_url(request)) msg = 'Deleted {} {}'.format(deleted_count, model._meta.verbose_name_plural) + logger.info(msg) messages.success(request, msg) return redirect(self.get_return_url(request)) + else: + logger.debug("Form validation failed") + else: form = form_cls(initial={ 'pk': pk_list, @@ -814,12 +853,12 @@ class BulkDeleteView(GetReturnURLMixin, View): """ Provide a standard bulk delete form if none has been specified for the view """ - class BulkDeleteForm(ConfirmationForm): pk = ModelMultipleChoiceField(queryset=self.queryset, widget=MultipleHiddenInput) if self.form: return self.form + return BulkDeleteForm @@ -908,7 +947,7 @@ class BulkComponentCreateView(GetReturnURLMixin, View): template_name = 'utilities/obj_bulk_add_component.html' def post(self, request): - + logger = logging.getLogger('netbox.views.BulkComponentCreateView') parent_model_name = self.parent_model._meta.verbose_name_plural model_name = self.model._meta.verbose_name_plural @@ -926,10 +965,13 @@ class BulkComponentCreateView(GetReturnURLMixin, View): if '_create' in request.POST: form = self.form(request.POST) + if form.is_valid(): + logger.debug("Form validation was successful") new_components = [] data = deepcopy(form.cleaned_data) + for obj in data['pk']: names = data['name_pattern'] @@ -949,15 +991,20 @@ class BulkComponentCreateView(GetReturnURLMixin, View): if not form.errors: self.model.objects.bulk_create(new_components) - - messages.success(request, "Added {} {} to {} {}.".format( + msg = "Added {} {} to {} {}.".format( len(new_components), model_name, len(form.cleaned_data['pk']), parent_model_name - )) + ) + logger.info(msg) + messages.success(request, msg) + return redirect(self.get_return_url(request)) + else: + logger.debug("Form validation failed") + else: form = self.form(initial={'pk': pk_list})