Grails 4 Audit Logging: Records being logged with the wrong user

Question

I'm using the Grails Audit Logging plugin, and some (~1.5%) of my Audit Log records are being associated with the incorrect actor (user). This API is multi-tenant, and many of these records are impossible to have been done by the actor that is being logged (since they're in a different organization). This seems to be occurring primarily on INSERT and UPDATE records.

As best I can tell, the actions being logged are from methods with @Subscriber that are called from an event publisher further up the stack.

As an example, when person submits an additionalPhoto, an event publisher calls compareToAdditionalPhoto:

    @Publisher(Event.ADDITIONAL_PHOTO_CREATED)
    @Transactional(rollbackFor = Throwable.class)
    AdditionalPhoto create(AdditionalPhoto additionalPhoto) {
        additionalPhoto.expirationDate = new Date(System.currentTimeMillis() + additionalPhoto.additionalPhotoType.timeToLive)

        additionalPhoto.validate()
        if (additionalPhoto.hasErrors())
            throw new InvalidResourceException(additionalPhoto.errors)

        deletePriorAdditionalPhotos(additionalPhoto)

        additionalPhoto.save()

        return additionalPhoto
    }

    @Transactional
    @Subscriber(Event.ADDITIONAL_PHOTO_CREATED)
    void compareToPhoto(AdditionalPhoto additionalPhoto) {
        compareFaces(additionalPhoto)
    }

    void compareFaces(AdditionalPhoto additionalPhoto, Photo photo = null) {
        log.debug("comparing faces for additionalPhoto #$additionalPhoto.id")
        if (!additionalPhoto.additionalPhotoType.enableFacialRecognition) return

        sleep(asyncDelay)
        photo = photo ?: additionalPhoto.person.currentPhoto
        additionalPhoto.facialRecognitionScore = rekognitionService.compareFaces(photoService.fetchBytes(photo), fetchBytes(additionalPhoto))
        if (additionalPhoto.facialRecognitionScore == NO_FACE_DETECTED) {
            log.error("No face detected in either Photo #$photo.id or Additional Photo #$additionalPhoto.id for $additionalPhoto.person.email")
        }
        additionalPhoto.save()
    }

The actor recorded in the audit logs belongs to another organization and couldn't possibly have initiated this method call. However, the actor was actively logged into the application at the time making other requests.

It appears that Hibernate may be piggy-backing the actions that are done by the subscriber onto another active session and incorrectly attributing the actor. Is that possible? This has been tricky to debug since most of the records are being correctly saved.

I'd really appreciate any suggestions on how to avoid this happening, and please let me know if any more detail is needed in my question. Thanks!

Answer 1

Figured this one out with some assistance over on the github repo for the Grails audit logging plugin!

The issue was being caused by the SecurityContextHolder strategy being MODE_INHERITABLETHREADLOCAL. This was the default for versions of the audit logging plugin between 3.2.1 up to 4.0.0, but is not recommended for use in pooled environments (see this discussion on the Spring Security repo). We upgraded to 4.0.1, which switched the strategy to MODE_THREADLOCAL, and this has fixed the problem.