Logging: how to test a web application without affecting the users

We'll think how to check internal state of a web application without affecting its behaviour. The approach is tested with Python Django web application but it is not language specific and works for web applications that execute the code on server.

Black box testing: want to know what's going inside

We test our application in the browser to see if it works but the rendered web pages do not show what's going on inside the server code: if the functions are called in the correct order, or the variables contain the expected values.

Developers debug their web applications locally to find out these things. But it has limitations:

• works safely on test servers only, can't debug on a production server because it affects all its users: the page freezes if there's a debugger breakpoint in the page code
• it's hard to debug multi-threaded code: when you check what's going on within one request, the browser makes another request and stops on another breakpoint
• some issues are hard to reproduce with debugging: if the issue occurs only for some users and data, or time specific so have to reproduce data and time conditions
• can't connect to the server with remote debugger if the server is in another private network with limited access

How to look inside without debugging

The idea is to replace debugging with output checking: add the statements in the code that output the variables state and useful messages to identify the place where it's added, example in Python:

import logging

# logger instance for the file
log = logging.getLogger(__name__)

def add_user(request, username):
    log.debug("UserManager add_user(): %s", username)

Such statement appends the message into the server log file which could be downloaded to a local computer for analysis, or checked directly on the server using Linux command line or web tool like Papertrail logging system.

Now our testing process looks like this:

1. add log statements at the points of interest to output variables with the messages that will be checked later
2. test in browser by developer, or wait till other users visit pages
3. events filtering: create file with the specific events only from the server log file
4. check the resulting file from the previous step

How to filter out lines from the log file

grep shell command on Linux or Unix-like system filters the lines from the file by criteria specified in the command arguments:

grep "UserManager add_user():" log

The command above outputs only the log file lines with the "UserManager add_user():" substring.
The command below outputs into events_log file only parts of these lines matched by expression: line substring that starts at "UserManager add_user(): " to the end of the line:

grep -o "UserManager add_user(): .*" log > events_log

Why to filter out logs? The server log contains a lot of events for every HTTP request and subsystem but we are interested in the functions and subsystems that are related to one test case only. So filtering out logs which are not produced by the test case flow significantly reduces the file size. Removing not useful line parts like event time and server name improves the log readability as well.

Tips for grep command

• Dot character matches any character.
  Example: grep "ba." command matches lines with any of substrings: bad, bag, bar, bat
  
• Escape dot to match dot itself: grep "One\. Another" filename
• Counter modificator for character or character group matches variable number of characters: * matches 0 or more characters, + matches 1 or more characters.
  Example: grep "bar.*" command matches any of these substrings: bar, bark, barrel
• -e option matches one of patterns (OR expression): grep -e pattern1 -e pattern2 filename
• Use pipeline to match all the patterns (AND expression): grep pattern1 filename| grep pattern2
• -o option outputs the matched string only instead the whole line:
  grep -o "UserManager add_user(): .*"
• -v option inverts the match: exclude the lines that match the pattern instead including them
• Character classes match group of characters:

      [:digit:] 0-9 digit
      [:alpha:] A-Z a-z letter
      [:alnum:] digit or letter
      [:space:] whitespace
      [:lower:] lower case letter
      [:upper:] upper case letter