Merge pull request #4315 from netbox-community/4195-application-logging

Closes #4195: Application logging
This commit is contained in:
Jeremy Stretch 2020-03-04 14:39:12 -05:00 committed by GitHub
commit 2bd3f1fcc3
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 178 additions and 39 deletions

View File

@ -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

View File

@ -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/`.

View File

@ -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'

View File

@ -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()

View File

@ -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

View File

@ -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

View File

@ -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):
"""

View File

@ -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 = '{} <a href="{}">{}</a>'.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: <a href="{}">{}</a>'.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})