Instance-based Logging

The Loggable mixin provides a series of methods for creating, storing, and retrieving “instance-based” logs - that is, logs that are specific to an instance of a class incorporating Loggable. These logs can be used for anything - recording events, detailing the steps taken by a complex process, etc. Each log is created with its own name, and can be later retrieved from the instance using that name. The logs themselves are maintained as Python lists - each item in the list being a separate entry, or line, in the log. This allows them to be easily appended to over time.

When a new log is created, it becomes the “active” log for that instance - the one to which new log entries are appended. There can only be one active log on an instance at a time. If another log is active when a new log is created, it gets pushed back in the queue, and will become active again when the new log is finished. Logs must be explicitly declared “finished” in order to both re-activate previous logs and also to enable retrieving the log (unfinished logs cannot be retrieved).

The logs are stored internally on the instance. They will persist for the lifetime of that instance. No support for more persistent storage of these logs is included, but it is possible.

The methods available are:

By default, get_log() and get_last_log() retrieve logs as strings, but copies of the internal lists can be retrieved by passing raw=True to either method.

OLPMixin, used to provide advanced features to Djem’s object-level permissions system, inherits from Loggable. Keeping user-based logs of permission checks is the primary use of instance-based logging. The examples in this documentation use user-based logging in object-level permission access methods to illustrate the supported features of Loggable. While OLPMixin provides support for automatically logging permission checks, these examples assume that feature is disabled and demonstrate the basic functionality of the system.

Consider a Product model where a user may not be allowed to delete a product that is currently an actively-sold product line or if the product currently has any stock on hand. These restrictions can be imposed by an object-level access method, and a log can allow auditing why the permission was not granted:

from django.db import models

from .utils import get_quantity_in_stock


class Product(models.Model):

    code = models.CharField(max_length=20)
    name = models.CharField(max_length=100)
    active = models.BooleanField(default=True)

    def _user_can_delete_product(self, user):

        user.start_log('delete-product-{0}'.format(self.pk))

        if self.active:
            user.log('Cannot delete active product lines')
            allowed = False
        elif get_quantity_in_stock(self):
            user.log('Cannot delete products with stock on hand')
            allowed = False
        else:
            user.log('Product can be deleted')
            allowed = True

        user.end_log()

        return allowed

Nested logs

As mentioned, if a log is already active and a new log is created, the new log becomes active and the previous log will be reactivated when the new log is finished. This allows for logs to be nested without worrying about interfering with other logs.

Continuing the above Product example, deletion may also require that the user has permission to manage the inventory from the supplier in question. Thus, checking the “delete_product” permission can trigger a “manage_supplier” permission check. If both permissions perform logging, those logs are nested, but neither need to do anything special to handle it:

from django.conf import settings
from django.db import models

from .inventory import get_quantity_in_stock


class Supplier(models.Model):

    name = models.CharField(max_length=100)
    managers = models.ManyToManyField(settings.AUTH_USER_MODEL)

    def _user_can_manage_supplier(self, user):

        user.start_log('manage-supplier-{0}'.format(self.pk))

        if not self.managers.filter(pk=user.pk).exists():
            user.log('You do not have permission to manage the inventory of {0}'.format(self.name))
            allowed = False
        else:
            allowed = True

        user.end_log()

        return allowed

    class Meta:
        permissions = (
            ('manage_supplier', "Can manage inventory from this supplier")
        )


class Product(models.Model):

    code = models.CharField(max_length=20)
    name = models.CharField(max_length=100)
    active = models.BooleanField(default=True)
    supplier = models.ForeignKey(Supplier, on_delete=models.PROTECT)

    def _user_can_delete_product(self, user):

        user.start_log('delete-product-{0}'.format(self.pk))

        if self.active:
            user.log('Cannot delete active product lines')
            allowed = False
        elif get_quantity_in_stock(self):
            user.log('Cannot delete products with stock on hand')
            allowed = False
        elif not user.has_perm('inventory.manage_supplier', self.supplier):
            user.log('You do not have permission to manage the inventory of {0}'.format(self.supplier.name))
            allowed = False
        else:
            user.log('Product can be deleted')
            allowed = True

        user.end_log()

        return allowed

Of course, sometimes it is useful to explicitly handle nested logs. Instead of duplicating the same log entry in both the “manage_supplier” and “delete_product” access methods, “delete_product” can simply incorporate the log generated by “manage_supplier” into its own, using get_last_log():

def _user_can_delete_product(self, user):

    ...
    elif not user.has_perm('inventory.manage_supplier', self.supplier):
        inner_log = user.get_last_log(raw=True)
        user.log(*inner_log)
        allowed = False
    ...

Tagging log entries

In some cases, the entire log may not be relevant. For example, you may want to display a concise reason for a permission check failure, while ignoring any additional log entries (such as those added when using automatic permission check logging). In such cases, it is possible to tag individual log entries and then retrieve only those entries with a given tag.

Tagging can be done by passing the tag argument to log(). The named tag will be applied to all lines added with the same call. The lines with the tag can then be retrieved using get_log() or get_last_log(), using the tags argument. E.g.:

def some_process(user):

    user.start_log('some-process')
    user.log('Starting the process')

    result = do_something()
    if not result:
        user.log('No result!', tag='error')

    user.log('Ending the process')
    user.end_log()

    return result

After calling the above function, the log can be retrieved using:

# Full log
>>> user.get_log('some-process')
'Starting the process\nNo result!\nEnding the process'

# Only the error
>>> user.get_log('some-process', tags=['error'])
'No result!'

Note that if multiple tags are passed to get_log() or get_last_log(), lines with any of the given tags will be returned.

Duplicate names

Creating a new log with the same name as another unfinished log is not possible - it will raise a ValueError. Therefore, it is important to use sufficiently informative names. The above nested logging example uses two logs named after the permission they are checking and the object they are checking it on. If they were both to use the same generic name, e.g. 'perm-log', attempting to call one from within the other would fail.

However, it is perfectly valid to re-use a name after the log has been finished. Doing so will overwrite the previous log when the new one is finished. This allows the same process to be run multiple times within the lifetime of the Loggable instance, without causing issues. But it is important to note that only the latest version of the log will be kept.

Persistence

As noted above, logs are stored on the Loggable instance itself. This can influence the types of classes that it makes sense to incorporate Loggable into. It may not be useful to use the mixin on classes that generate short-lived or difficult-to-access instances.

A custom user model is a good choice to add Loggable to (or, even better, OLPMixin). In the typical scenario, a user instance is accessible on every incoming request, can easily (and is often required to) be passed around among various function/method calls, and persists for the entire request-response cycle.

If there is a need for a more persistent storage mechanism for these logs, there are a number of ways that can be achieved. One possible solution is to override a suitable method from Loggable. The following example uses a simple model to store logs made on a custom User model once they have been completed:

from django.contrib.auth.models import AbstractUser
from django.db import models

from djem.models import Loggable


class UserLog(models.Model):

    name = models.CharField(max_length=100)
    log = models.TextField()


class User(Loggable, AbstractUser):

    def end_log(self):

        name, log = super(User, self).end_log()

        UserLog.objects.create(
            name=name,
            log='\n'.join(log)
        )

        return name, log

Thread safety

Despite being able to be safely nested, instance-based logging is not thread safe. Due to the way the “active” log is maintained, multiple threads sharing the same Loggable instance can easily contaminate each other’s logs. In addition, if they run the same process (that uses instance-based logging), they may error out due to being unable to have multiple unfinished logs with the same name.

Multiple threads using separate instances of Loggable will only be problematic if implementing some kind of persistent storage mechanism for the logs, depending on the nature of the chosen mechanism.

When using Loggable (or OLPMixin) on a custom user model, as part of a standard request-response cycle, thread safety is not a concern as each request uses a separate user instance.