8.6 how to test log function

  the log is a gray area. When it comes to testing, it is not obvious how to deal with it. This is a complex topic. I will divide it into the following questions:

• Should you test the log or not?
• If so, how should you test it?
• How much log is enough?
• How do you pass recorder instances?

We will use our CRM project sample as an example.

8.6.1 should you test the log?

  logging is a cross domain feature that you can ask for in any part of your code base. The following is an example of logging in a user class.

Listing 8.3 is an example of a login user

public class User {
    public void ChangeEmail(string newEmail, Company company) {
    	//Starting point of method
        _logger.Info($"Changing email for user {UserId} to {newEmail}");
        Precondition.Requires(CanChangeEmail() == null);
        if (Email == newEmail) return;
        UserType newType = company.IsEmailCorporate(newEmail) ? UserType.Employee : UserType.Customer;
        if (Type != newType) {
            int delta = newType == UserType.Employee ? 1 : -1;
            company.ChangeNumberOfEmployees(delta);
            //Change user type
            _logger.Info($"User {UserId} changed type " + $ "from {Type} to {newType}");
        }
        Email = newEmail;
        Type = newType;
        EmailChangedEvents.Add(new EmailChangedEvent(UserId, newEmail));
        //The end of the method
        _logger.Info($"Email is changed for user {UserId}");
    }
}

  the user class records each start and end of the ChangeEmail method and the change of user type in the log file. Should you test this function?
  on the one hand, logs generate important information about application behavior. On the other hand, logging can be so ubiquitous that it's unclear whether this feature is worth the extra, rather important testing effort. The answer to the question of whether to test the log can be summarized as follows. Is logging part of the observable behavior of an application, or is it an implementation detail?
  in this sense, it is no different from other functions. Logs eventually have side effects in out of process dependencies, such as text files or databases. If these side effects are intended to be observed by your customers, application customers, or others other than the developers themselves, logging is an observable behavior and must be tested. If the only audience is developers, it is an implementation detail that can be modified freely without anyone paying attention. In this case, it should not be tested.
  for example, if you write a log library, the logs generated by this library are the most important (and only) part of its observable behavior. Another example is when business personnel insist on recording key application workflow. In this case, logging also becomes a business requirement, so it must be covered by testing. However, in the latter example, you may also have separate logging for the sake of developers.
  in their book Addison Wesley professional (2009), Steve Freeman and Nat Pryce refer to these two types of logs as supporting logs and diagnostic logs.

• The information generated by the support log is for the support personnel or system administrator to track.
• Diagnostic logs help developers understand what is happening inside the application

8.6.2 how should you test logs?

  because logs involve out of process dependencies, when testing is involved, the same rules apply to other functions involving out of process dependencies. You need to use mocks to verify the interaction between your application and log storage.

Introduce the packaging at the top of ILogger
  but don't just simulate the interface of ILogger. Because supporting logging is a business requirement, it should be clearly reflected in your code base. Create a special DomainLogger class to clearly list all support logs required by the business; Use this class instead of the original ILogger to validate the interaction.
  for example, suppose a business person asks you to record all changes in User types, but the logging at the beginning and end of the method is only for debugging purposes. The next list shows the User class after introducing the DomainLogger class.

Listing 8.4 extract support logs into the DomainLogger class

public void ChangeEmail(string newEmail, Company company) {
	//Diagnostic record
    _logger.Info($"Changing email for user {UserId} to {newEmail}");
    Precondition.Requires(CanChangeEmail() == null);
    if (Email == newEmail) return;
    UserType newType = company.IsEmailCorporate(newEmail) ? UserType.Employee : UserType.Customer;
    if (Type != newType) {
        int delta = newType == UserType.Employee ? 1 : -1;
        company.ChangeNumberOfEmployees(delta);
        //Support logging
        _domainLogger.UserTypeHasChanged(UserId, Type, newType);
    }
    Email = newEmail;
    Type = newType;
    EmailChangedEvents.Add(new EmailChangedEvent(UserId, newEmail));
    //Diagnostic record
    _logger.Info($"Email is changed for user {UserId}");
}

  the diagnosis log still uses the old logger (belonging to ILogger type), but the support log now uses the new domainLogger instance of IDomainLogger type. The following list shows the implementation of IDomainLogger.

Listing 8.5 DomainLogger as a wrapper above ILogger

public class DomainLogger: IDomainLogger {
    private readonly ILogger _logger;
    public DomainLogger(ILogger logger) {
        _logger = logger;
    }
    public void UserTypeHasChanged(int userId, UserType oldType, UserType newType) {
        _logger.Info($"User {userId} changed type " + $ "from {oldType} to {newType}");
    }
}

  DomainLogger works on ILogger: it uses domain language to declare specific log entries required by the business, making it easier to understand and maintain supporting logs. In fact, this implementation is very similar to the concept of structured log. It can achieve great flexibility when it comes to post-processing and analysis of log files.

Understanding structured logging

  structured logging is a logging technology in which the capture of log data is decoupled from the presentation of the data. Traditional logging is for simple text. An image

logger.Info("User Id is " + 12);

  first form a string, and then write the string to the log storage. The problem with this method is that due to the lack of structure, the resulting log files are difficult to analyze. For example, it is not easy to see how many specific types of information there are and how many of them are related to a specific user ID. You need to use (or even write) special tools to do this.
  on the other hand, structured logging introduces a structure for your log storage. The use of structured log libraries looks similar on the surface:

logger.Info("User Id is {UserId}", 12);

  but its basic behavior is very different. Behind the scenes, the method calculates the hash value of the message template (the message itself is stored in a lookup store to improve space efficiency), and combines the hash value with the input parameters to form a set of captured data. The next step is to render the data. You can still have a flat log file, just like traditional logging, but this is only a possible rendering. You can also configure the log library to render the captured data as JSON or CSV files, which will be easier to analyze (Figure 8.12).

 
  the DomainLogger in listing 8.5 is not a structured logger in itself, but its operation spirit is the same. Take another look at this method:

public void UserTypeHasChanged(int userId, UserType oldType, UserType newType) {
    _logger.Info(
    	$"User {userId} changed type " + 
    	$"from {oldType} to {newType}");
}

  you can think of UserTypeHasChanged() as the hash value of the message template. Together with the userId, oldType and newType parameters, this hash value forms the log data. The implementation of this method renders the log data into a flat log file. You can easily create additional renderings by writing log data to JSON or CSV files.

Write tests for supporting and diagnostic records
  as I mentioned earlier, DomainLogger represents an out of process dependency - log storage. This raises a problem: the User now interacts with the dependency, thus violating the separation between business logic and communication of out of process dependencies. The use of DomainLogger makes users transition to overly complex code categories, making them more difficult to test and maintain (for more details on code categories, please refer to Chapter 7).
  this problem can be solved by notifying the external system to change the user's email: with the help of domain events (see Chapter 7 for details). You can introduce a separate domain event to track changes in user types. The controller will then translate these changes into calls to the DomainLogger, as shown in the following list.

Listing 8.6 replaces the DomainLogger in the user with a domain event

public void ChangeEmail(string newEmail, Company company) {
    _logger.Info($"Changing email for user {UserId} to {newEmail}");
    Precondition.Requires(CanChangeEmail() == null);
    if (Email == newEmail) return;
    UserType newType = company.IsEmailCorporate(newEmail) ? UserType.Employee : UserType.Customer;
    if (Type != newType) {
        int delta = newType == UserType.Employee ? 1 : -1;
        company.ChangeNumberOfEmployees(delta);
        //Use domain events instead of DomainLogger
        AddDomainEvent(new UserTypeChangedEvent(UserId, Type, newType));
    }
    Email = newEmail;
    Type = newType;
    AddDomainEvent(new EmailChangedEvent(UserId, newEmail));
    _logger.Info($"Email is changed for user {UserId}");
}

  note that there are now two areas of events. UserTypeChangedEvent and EmailChangedEvent. They all implement the same interface (IDomainEvent), so they can be stored in the same collection.
  here is what the controller looks like.

Listing 8.7 latest version of usercontroller

public string ChangeEmail(int userId, string newEmail) {
    object[] userData = _database.GetUserById(userId);
    User user = UserFactory.Create(userData);
    string error = user.CanChangeEmail();
    if (error != null) return error;
    object[] companyData = _database.GetCompany();
    Company company = CompanyFactory.Create(companyData);
    user.ChangeEmail(newEmail, company);
    _database.SaveCompany(company);
    _database.SaveUser(user);
    _eventDispatcher.Dispatch(user.DomainEvents);//Dispatch user domain events
    return "OK";
}

  EventDispatcher is a new class that converts domain events into calls to out of process dependencies:

• EmailChangedEvent to_ messageBus.SendEmailChangedMessage()
• Convert UserTypeChangedEvent to_ domainLogger.UserTypeHasChanged()

  the use of UserTypeChangedEvent restores the separation between two responsibilities: domain logic and communication with out of process dependencies. Testing support logs is now no different from testing other unmanaged dependencies, the message bus.

• The unit test should check the instance of UserTypeChangedEvent in the tested user.
• A single integration test should use a mock to ensure proper interaction with the DomainLogger.

  note that if you need to do support logging in the controller instead of in the domain class, you don't need to use domain events. As you may recall from Chapter 7, the controller coordinates the collaboration between the domain model and out of process dependencies. DomainLogger is one of such dependencies, so UserController can use the logger directly.
  at the same time, I noticed that I didn't change the way the User class does diagnostic logging. The User still uses the logger instance directly at the beginning and end of its ChangeEmail method. This is in design. Diagnostic logs are only available to developers; You don't need to unit test this function, so you don't need to put it outside the domain model.
  however, avoid using diagnostic logs in User or other domain classes when possible. I will explain why in the next section.

8.6.3 to what extent are logs sufficient?

  another important issue is about the optimal number of logs. How much logging is enough? Supporting logging is not possible here because it is a business requirement. However, you can control diagnostic logging.
  it is important not to overuse diagnostic records for the following two reasons:

• Too many logs can confuse the code. This is especially true for domain models. That's why I don't recommend using diagnostic logs in User, although from a unit testing perspective, such use is OK: it masks the code.
• The signal-to-noise ratio of log is the key. The more difficult it is to find relevant information in your log. Increase signal as much as possible; Minimize noise.

  try not to use diagnostic logs in the domain model. In most cases, you can safely transfer logging from the domain class to the controller. Even so, you can only use diagnostic logs temporarily when you need to debug. Once you've finished debugging, delete it. Ideally, you should only use diagnostic logs for unhandled exceptions.

8.6.4 how to transfer log instances?

  finally, the last question is how to pass log instances in the code. One way to resolve these instances is to use static methods, as shown in the following list.

Listing 8.8 stores ILogger in a static field

public class User {
	//ILogger is parsed through a static method and stored in a private static field
    private static readonly ILogger _logger = 
    	LogManager.GetLogger(typeof (User));
    public void ChangeEmail(string newEmail, Company company) {
        _logger.Info($"Changing email for user {UserId} to {newEmail}"); 
        /* ... */
        _logger.Info($"Email is changed for user {UserId}");
    }
}

  Steven van Deursen and Mark Seeman refer to this type of dependency acquisition as environmental context in their book Manning Publications (2018). This is an anti pattern. Their two arguments are

• Dependencies are hidden and difficult to change.
• Testing becomes more difficult

  I totally agree with this analysis. For me, however, the main disadvantage of context is that it masks potential problems in the code. If explicitly injecting a logger into a domain class becomes so inconvenient that you have to turn to the environment context, it must be a sign of a problem. You either record too much or use too many hint layers. In any case, the context of the environment is not a solution. Instead, address the root cause of the problem.
  the following list shows a way to explicitly inject logs: as method parameters. Another way is through the constructor of the class.

Listing 8.9 explicitly injects the logger

//Method injection
public void ChangeEmail(string newEmail, Company company, ILogger logger) {
    logger.Info($"Changing email for user {UserId} to {newEmail}"); 
    /* ... */
    logger.Info($"Email is changed for user {UserId}");
}