Event listeners and logging

The Laminas MVC framework describes itself as event-driven, and InterpretersOffice likewise uses – perhaps even overuses – both the Laminas and the Doctrine event systems. The use of Laminas’ event system is described elsewhere in this documentation. For example, event listeners are used to enforce user authentication and authorization. InterpretersOffice also takes advantage of Doctrine’s entity event listeners for tasks such as clearing caches following write operations, ensuring that metadata properties of certain entities are set correctly, and logging noteworthy events.

Most of our Doctrine listeners are located in module/InterpretersOffice/src/Entity/Listener Some are registered via configuration and others are registered at runtime. In the latter case, we usually register the listener in the factory class of the relevant controller(s). It would be more convenient but less efficient to do this just once in the module’s onBootstrap(), because at that stage we don’t know whether we are going to need the event listener. By way of example from the admin EventsController factory:

    public function __invoke(ContainerInterface $container, $requestedName, array $options = null)
    {
        $auth = $container->get('auth');
        $em = $container->get('entity-manager');
        $updateManager = $container->get(ScheduleUpdateManager::class);
        
        $controller = new EventsController(
            $em,
            $auth,
            $updateManager
        );

        // attach the entity listeners
        $resolver = $em->getConfiguration()->getEntityListenerResolver();
        $resolver->register($container->get(Listener\EventEntityListener::class));
        $resolver->register($container->get(Listener\UpdateListener::class)->setAuth($auth));

        $sharedEvents = $container->get('SharedEventManager');
        $sharedEvents->attach(
            EventsController::class,
            'deleteEvent',
            [$updateManager,'onDeleteEvent']
        );
        // etc
    }

The above illustrates how the $container provides access to the dependencies required by the EventsController as well as the objects we need in order to register the Doctrine entity listeners. These listeners themselves are of course produced by factories according to the mapping found in module/InterpretersOffice/config/module.config.php.

As a further example, let’s take one of the callback methods from the EventEntityListener:

/**
* preUpdate callback
*
* @param Entity\Event $entity
* @param PreUpdateEventArgs $args
*/
public function preUpdate(
   Entity\Event $entity,
   PreUpdateEventArgs $args
) {

   $fields_updated = $this->reallyModified($entity, $args);
   $user = $this->getAuthenticatedUser($args);   
   $id = $entity->getId();
   if (in_array('deleted', $fields_updated) && $entity->getDeleted()) {
       if ((string)$user->getRole() !== 'submitter') {
           $message = sprintf(
               'user %s deleted event #%d from the schedule',
               $user->getUsername(),
               $id
           );
           $this->logger->info(
               $message,
               ['entity_class' => Entity\Event::class,'entity_id' => $id,'channel' => 'scheduling', ]
           );
       }
   }
   if ($fields_updated) {
       $entity->setModified($this->now);
       $entity->setModifiedBy($user);
       $cancellation_status_changed = false;   
       /* 
       now the interesting part: guessing the criteria for resetting the 
       sent_confirmation_email property of the related InterpreterEvents;
       */
       if (count($entity->getInterpreterEvents())) {
           $this->logger->debug(sprintf("there are %d interpreter_events",count($entity->getInterpreterEvents())));
           $changeset = $args->getEntityChangeSet();
                     
           if (in_array('cancellation_reason',array_keys($changeset))) {                    
               // if it's going from null to not null or vice-versa, that's significant
               $before_and_after = $changeset['cancellation_reason'];
               if (!$before_and_after[0] or !$before_and_after[1]) {
                   $cancellation_status_changed = true;   
               }
           }
           if ($cancellation_status_changed  or in_array('date',$fields_updated) 
               or in_array('time',$fields_updated)
           ) {  // turn off sent_confirmation_email for related InterpreterEvent entities                   
               $em = $args->getEntityManager();                   
               $dql = 'UPDATE InterpretersOffice\Entity\InterpreterEvent ie 
                   SET ie.sent_confirmation_email = false WHERE ie.event = :event';
               $result = $em->createQuery($dql)->setParameters(['event'=>$entity])->getResult();
               $who = implode('; ',array_map(function($i){return "{$i->getFullname()} <{$i->getEmail()}>";},
                   $entity->getInterpreters()));
               $log_message = sprintf(
                   'user %s changed the %s of event #%d; email confirmation status set to FALSE for %d interpreter(s): %s',
                   $user->getUsername(), implode(', ',$fields_updated),$id, $result, $who
               );
               $this->logger->info($log_message,
                   ['entity_class' => Entity\Event::class,'entity_id' => $id,'channel' => 'scheduling', ]
               );
           } else {
               $this->logger->debug("found interpreters assigned, not changing confirmation status");
           }
       }           
   }        
}

Doctrine fires this callback at the preUpdate stage of its transactional database work. The first thing we have to do (at line 13) is use a helper method to work around a quirk of Doctrine that makes it think entity properties that are PHP DateTime objects have been changed when in reality they have not (this happens because the before-and-after objects are not identical, though they may be equivalent).

One of our objectives is to set the metadata properties modified and modifiedBy on the entity. The first is a PHP DateTime (which of course Doctrine converts to the appropriate database data type when the time comes), a timestamp equal to the current date and time; the second is a User entity – i.e., the User who is updating this Event.

Another task performed here is writing to the application log. In this instance, we take note of the fact that the user has (soft-)deleted this Event.

The next bit is unintelligible without a bit of background. The (human) users of InterpretersOffice like a feature that tracks whether or not an interpreter assigned to an Event has been notified via email about significant developments affecting the assignment. In their view of the schedule, a green check adjacent to an interpreter’s name means this notification has been done. When the user sends email (through InterpretersOffice) to the interpreter in regard to the assignment, the application considers which boilerplate email template is being used to decide whether set the interpreter-event entity’s email_confirmation_sent field (currently a boolean, although it would make more sense if it were a DateTime… another item for the next minor version update).

The reverse problem is knowing when to undo that setting, i.e., flag the interpreter-event as not having been notified of the latest significant modification to the event. The logic beginning at line 48 addresses this problem.

The foregoing example is just one of many throughout the application. The intention is to give some sense of how the InterpretersOffice is put together.

logging

InterpretersOffice uses the Laminas\Log\Logger component for logging. Two log writers are involved: one that writes to a disk file, another that writes to the database. The log records application errors as well as a variety of user actions including logging in and out, creating/deleting/updating entities, and sending email messages. One interesting aspect of the logging system is that where possible, it notes the entity class and the entity id as well as a textual description of what is happening. This would make it reasonably easy to create a feature – yet to be implemented – whereby users can examine log events, with hypertext links to the entities that are involved. Another field in log records is a “channel” – a simple string, not normalized in the database sense – that serves as a sort of tag that can be used for filtering records, in addition to the standard log severity levels.

The log files are stored in the data/log subdirectory and named in the format app.log.YYYY-MM-DD indicating the date. You may want to set a cron job to archive these somehow, or rotate them out periodically so they don’t consume an indefinite amount of disk space. As we observed in the section on setting up the application, this directory has to exist and be writeable by the server, or else we throw an Exception.

The database log writer is module/Admin/src/Service/Log/Writer.php. It bypasses Doctrine to execute database inserts as quickly and simply as possible, using the same PDO object wrapped by Doctrine, and it writes to the app_event_log table.