Translations
Info
All page names need to be in English.
en da  de  fr  it  ja  km  nl  ru  zh

Blueprints/Logging

From TYPO3Wiki
Jump to: navigation, search

<- Back to blueprints overview

Blueprint: Logging

Proposal Creating and implementing a new concept for logging events in TYPO3 CMS
Owner/Starter Steffen Müller
Participants/Members -
Status Draft, Discussion, Voting Phase, Accepted, Declined, Withdrawn
Current Progress Unknown, Started, Good Progress, Bad Progress, Stalled, Review Needed
Topic for Gerrit ###gerrit_topic###

Target Versions/Milestones

  • TYPO3 CMS 7.0

Goals / Motivation

A new Logging API has been introduced with TYPO CMS 6.0. This new API is different from the old API in the following ways:

  1. It is extendable for two main components: LogWriters and LogProcessors. LogWriters define the target where to write a LogRecord. LogProcessors enrich the LogRecord with additional data. LogWriters and LogProcessors can be customized and even new ones can be added.
  2. Both LogWriters and LogProcessors can be configured through $TYPO3_CONF_VARS['LOG'] without touching the PHP code itself. Each Logger has its's distinct name so it can be configured independently. Inheritance helps to keep the amount of configuration low.

The motivation for this blueprint is to describe a concept, how this API shall be used in the TYPO3 CMS core.

What could be the purposes of Logging in a CMS?

The following is a collection of use cases from the current logging implementation, as well as new ideas:

  • Monitoring the system as a whole or a specific component, for example application performance, what triggered the clearing of the cache etc.
  • Providing information for Development, for example debugging
  • Classical PHP error logging, which notices about errors, warning etc. caused by programming code
  • Tracking security incidents, policy violations, fraudulent activity, e.g. brute force login attempts
  • Process logging: who touched the content and when?
  • Learning how the system works
  • [more to add here]

Concept

Should follow the principles established by The 12-Factor App (Logs).

Part 1: Introduce a Logging Context

notice - Note

Instead of the term "Contexts" which can be misleading, we could use the term "Tags". Having predefined tags could be implemented using \TYPO3\CMS\Core\Type\Enumeration. Requires a rewrite of this section.

To structure incoming log event, we have to introduce a context variable, which allows us to set up context specific rules for writing and processing log records. Based on the context, a set of log events can be handled group-wise. This considers the concept of the current logging APIs GeneralUtility:devLog() and GeneralUtility:sysLog(), but in a more extensible and transparent way.

Contexts are optional.

The contexts are given as an array, each array item representing one context, supporting several contexts at once. The TYPO3 core will provide some default contexts which are encapsulated in the class \TYPO3\CMS\Core\Log\Context. The core is recommended to make use of these defaults. However, custom contexts can be used as well. Also extension can make use of the given default contexts.

Example scenario to demonstrate the possible solutions:

In the a Backend Authentication class
I want to log successful logins with the monitoring context,
And I want to log failed logins with the monitoring and security context,
And I want to log the proerties of the BE user with the development context.

Solution: Add context to the $data array

With the current logging API, the context can be added to the \TYPO3\CMS\Core\Log\LogRecord->data property, using context as a reserved key by convention:

API:

 \TYPO3\CMS\Core\Log\Logger::log(
   int $severity,
   string $message,
   array $additionalData = array(
     'context' => array(
       \TYPO3\CMS\Core\Log\Context::EXAMPLE_CONTEXT
     )
   )
 );

Implementation of the example scenario:

 use \TYPO3\CMS\Core\Log\Context as LogContext;

 // Get logger for the class
 $logger = GeneralUtility::makeInstance('\\TYPO3\\CMS\\Core\\Log\\LogManager')
   ->getLogger(__CLASS__);
 
 // log an event with monitoring context
 $logger->info(
   'Backend user %s logged in',
   array(
     'context' => array(LogContext::MONITORING)
   )
 );

 // log an event with monitoring and security context
 $logger->notice(
   'Failed login attempt for backend user %s',
   array(
     'context' => array(
       LogContext::MONITORING,
       LogContext::SECURITY
     )
   )
 );

 // log an event with development context
 $logger->debug(
   'Properties of logged in backend user %s',
   array(
     'userProperties' => (array)$this->user,
     'context' => array(LogContext::DEVELOPMENT)
   )
 );

Pro:

  • it keeps tha Logger::log() API simple and PSR compatible
  • it can be used seemslesly without changing the current Logging API.
  • fine grained post processing possilbe on a LogRecord basis by using LogProcessors.
  • ...

Con:

  • ...

Part 2: Logging as a dependency and how to double them in tests

Calls to the logging API have to be mocked in tests to avoid fatal errors a la "Call to a member function log() on a non-object". Therefore we need a common practice to instanciate the logger of a class.

One solution would be to add a getter API for the logger:

PHP script:
class Foo {
  /**
   * @var \Psr\Log\LoggerInterface
   */
  protected $logger = NULL;

  protected function getLogger() {
    if ($this->logger === NULL) {
      $this->logger = GeneralUtility::makeInstance('\\TYPO3\\CMS\\Core\\Log\\LogManager')->getLogger(__CLASS__);
    }

    return $this->logger;
  }

  public function bar() {
    // function logic here
    $this->getLogger->log('Interesting things happened');
    return TRUE;
  }
}

And the corresponding test for Foo::bar()

PHP script:
class FooTest {
  /**
   * @test
   */
  public function barReturnsTrue() {
    $foo = new Foo();
    $this->assertTrue($foo->bar());
  }
}

Question here are:

  • What is the prefered way to inject the dummy logger?
  • Shall we inject the dummy logger for any unit test automatically?
  • How to handle unit tests which need to assert log calls?

Part 3: [WIP] Implementation Details

What now follows is an incomplete list of use cases, ordered by context. Please add your suggestions here!

Context: Development

Database query logging

As a developer, I need to log query calls in DatabaseHandler in order to investigate database queries.

Although DBMS usually provide their own logging, application level logging could provide more convenient filtering mechanism.

Tasks:

Context: Security

Failed login attempts

As a system administrator, I want to track failed authentication attempts, to identify attacks on user accounts

Tasks:

  • Add class logger to AbstractAutentication
  • Add log calls for FE and BE-Authentication attempts

Context: Monitoring

Exceptions & Errors

As the accountable person for a stable production system (account manager, project manager, operations lead, maintenance lead), I want to log exceptions and errors to a system capable of aggregating stack traces and collecting historical data (e.g. Sentry, New Relic, Datadog), so that I have transparency about application stability, and I can be notified when application issues occur, and I can prioritize work (bug fixes) based on real numbers and logged data.

Acceptance criteria:

  • Easy integration in FE and BE
  • Exceptions, errors, warning, etc. are not consumed ("swallowed") by TYPO3 (unless explicitly configured)
  • No performance penalty

Context: Auditing

Successful logins

As a system administrator, I want to track successful authentication attempts, to monitor activity

Tasks:

  • Add class logger to AbstractAutentication
  • Add log calls for FE and BE-Authentications

Context: Data (Process logging)

Something like sys_history, maybe in a decoupled with a dedicated API?

Risks

Performance

Load caused by simply adding Loggers and log calls

Logging will cause additional load for

  • creating of the Logger instances,
  • calling the log() function

even if writing log records is completely disabled by configuration. (no LogWriters set)

Basic profiling should measure:

  • cost of a Logger initilization using the LogManager (in seconds)
  • cost of a unique log() call (in seconds)

Based on these numbers and the blueprint concept the average cost should be estimated for typical backend and frontend requests. The profiling should be done in advance to allow early discussion and decision about the concept itself.

Load caused by writing log records to a target

Additional load will be caused if additional information is added to the LogRecord and writing to a target is activated.

  • creating LogProcessor and LogWriter instances
  • adding information to LogRecord by LogProcessors
  • writing LogRecords to a target by LogWriters

Additional profiling should measure:

  • cost of instanciation of LogProcessors and LogWriters (especially IO operations of FileWriter constructor)
  • cost of calling processLogRecord() of LogProcessors (especially IntrospectionProcessor using debug_backtrace())
  • cost of writing a record to a target.

This should finaly enable us to estimate the costs of various scenarios which include logging a basic set of events by default to a predefined target (e.g. security incidents to a logfile).

Issues and reviews

Dependencies upon other Blueprints

External links for clarification of technologies