Log Files

As every Web server, FIT writes several log files for monitoring, debugging and auditing:

  • access_log is the Apache access log
  • error_log is the Apache error log
  • phpfpm_access_log is the FIT access log
  • fit_engine.log is the FIT error log
  • fit_alert.log is used to record configuration errors and runtime exceptions
  • fit_request.log lists all outgoing requests to source servers

All log files are stored in /var/log/fit14.

FIT access log format

phpfpm_access_log is used to store information about all requests that are forwarded to the php-fpm process by the Web server. As the Web server may handle some static file responses itself, not every line in the access_log has a corresponding line here.

This log uses a simple key-value based format. The following example line is broken up into several lines for better readability. In a real log file, all newlines would be replaced with spaces:

VYw9JqwSM7wAAHhtNB8AAAAU [25/Jun/2015:19:40:54 +0200]
project:"developer-sevenval-com" site:"_default"
pid:"30724"
ut:"250" st:"8" rt:"260.965" it:"0" ib:"0"
req:"main" cdrid:"117826"
status:"200" ct:"text/html; charset=utf-8"

Fields

Position Field Description
1 Unique ID Unique ID generated for each request by mod_unique and passed on to the PHP process. FIT inserts the Unique ID in all log lines written for each request, such that all information regarding a request can be identified.
2 Timestamp Timestamp of the start of the request, according to the timezone settings in conf/php.ini. The strftime format is %d/%b/%Y:%H:%M:%S %z.
3 Project Name of the FIT project. Corresponds to the directory name in /var/lib/fit14/projects/ and the project configured in domains.xml.
4 Site Name of the FIT site. Corresponds to the directory name in /var/lib/fit14/projects/<project>/sites and the site configured in domains.xml.
5 PID PID (process ID) of the PHP FPM child process.
6 utime Milliseconds of CPU time spent in user mode. Most operations carried out by FIT will accumulate here. This number is important to fine-tune system limits and detect bottlenecks.
7 stime Milliseconds of CPU time spent for system calls (kernel mode). This number should be significantly lower than utime. Usually, disk I/O and in rare cases network I/O become visible here.
8 real time Milliseconds of real time spent to process the request. The clock starts when the Web server forwards the request to PHP-FPM and stops when the response is handed back. Under normal conditions, the real time should roughly equal the sum of utime, stime and in time. The difference increases when the system is under high load. Thus, this number can be helpful to investigate outages or overload situations.
9 in time Milliseconds of real time (“wall clock time”) spent waiting for source servers to respond to HTTP requests. This is the effective waiting time. If multiple resources are requested in parallel, the in time is the time of the longest request. For sequential requests, e.g. more than one request action, the in time will be summed up. This number is important to fine-tune system limits and detect bottlenecks.
10 in bytes Combined size of data requested from source servers in bytes. Local files (fit://site/public/) or cache hits are not counted towards in bytes.
11 request type The request type is main for most HTML requests or requests that are initiated directly by a user (e.g. an AJAX call). This is usually the URL in the address bar. Sub resources that are requested by the browser (JS and CSS files, fonts, images) are labelled as sub. Additional types are ap for the Active Properties Detection Page and - for other requests, like redirects or 304 responses with a Content-Type header value other than text/html.
12 CDR ID The identifier of the client matched in the built-in Client Description Repository. Most of the client-related properties in the Delivery Context are retrieved from the CDR and are associated with this ID.
13 Status code HTTP status code of the response.
14 Content type Content-type header of the outgoing HTTP response. This contains the MIME type of the processed payload and, for text media types, an optional charset declaration.

FIT request log format

fit_request.log is used to store information about all outgoing requests FIT sends to remote Web servers.

This log separates all fields with a single space character. The following example line is broken up into several lines for better readability. In a real log file, all newlines would be replaced with spaces:

2015-09-16 10:36:34+0000 VflGMrELCgrZMe1HVuScwAAAABI 
portal-mobile:_default:0 GET 
http://example.com/js/plugin.js 200 application/javascript 
2720 0.012784 proxy.local:3128 HIT main.0

Fields

Position Field Description
1 Date The date when the request was completed.
2 Time The time when the request was completed, including a time zone.
3 Unique ID Unique ID generated for each request by mod_unique and passed on to the PHP process. FIT inserts the Unique ID in all log lines written for each request, such that all information regarding a request can be identified.
4 Project and Site Name of the FIT project and site in the format <project>:<site>:0.
5 Method The HTTP method used for the Request, typically GET or POST.
6 URL The URL that was requested.
7 HTTP status The HTTP status code returned by the server. Set to 0 if the server could not be contacted or no status line was received.
8 Content Type The content-type of the response, - if none has been received.
9 Content Length The size of the (possibly compressed) response body in bytes. 0 if the body is empty. When read from the internal cache, the original response length is used.
10 Duration Real time (“wall clock time”) spent waiting for the response. The in duration is given in seconds, including a variable number of decimal places. 0 if the response was read from a FIT cache. (As one FIT request may issue multiple source requests, the duration should not be summed up to calculate waiting times. Use the in time in phpfpm_access_log instead).
11 Proxy The host name and port of the proxy used to process the request. If the internal source cache was used to satisfy the request, FIT_HTTP_Cache, FIT_Interval_Cache for the interval based cache. In all other cases - is recorded.
12 Proxy Status HIT, MISS or REFRESH if a proxy was used and has provided this information. The internal caches only record HIT. - in all other cases.
13 Request ID The identifier of the request, followed by its sequence number. Typically main.0 for the default-request or is.0 for requests executed for the image scaler. The sequence number is always 0 unless redirects is enabled for the request.
14 libcurl error code The error code returned by libcurl. See the curl documentation for a list of the possible codes, why they occur and how to fix them. This field is present only if an error occurred while processing the request.
15 … libcurl error message The error message, as indicated by the libcurl error code. The message may contain spaces. This field is present only if an error occurred while processing the request.

Summarizing log data

The fitadmin statistics command can be used to read the phpfpm_access_log and fit_request.log log files and display a summary of performance and request data.

Run fitadmin statistics -e for a list of usage examples.

Performance data

The phpfpm_access_log is enriched with performance metrics. Summarizing this log is a handy way to identify the project that eats up CPU cycles. You may be able to tell whether FIT or a backend server is the bottleneck by comparing CPU times (ut, st) with waiting time (it) and real time rt.

$ fitadmin statistics view -v /var/log/fit14/phpfpm_access_log
                Project |       time        |     ut     |     st     |     rt     |     it     |     ib     |
             myProject1    2015-06-26 15:00       379379        32032       543543            0            0
             myProject2    2015-06-26 15:00       214903         2517       378432       120920     24472810

Request data

The fit_request.log records timings for all outgoing HTTP requests. The output of statistics view in request mode helps you spot slow or buggy backends. The output is grouped by FIT project, domain of the source server and full hours. For each such aggregate, three pairs of count and cumulative duration are printed, one each for all good requests (requests), HTTP error responses like 404 (errors) and timeouts.

$  fitadmin statistics view -m request -v /var/log/fit14/fit_request.log
Starting at: 2015-06-26 15:36:53+0000
      Project |                       domain |             time |   requests |   duration |     errors |   duration |   timeouts |   duration |
 request-test      blackhole.webpagetest.org   2015-06-26 15:00            0         0.00            0         0.00            3         8.99
 request-test     fitmltest.sevenval-fit.com   2015-06-26 15:00           21         0.45            2         0.02            0         0.00

In this example, blackhole.webpagetest.org is suspicious – it looks as if it is never fast enough to answer a request.

Options

Option Description
-h, --help Print help.
-m <mode>, --mode=<mode> ‘’Mode’’ defines the type of log to be analyzed. It can be either access for phpfpm_access_log or request for fit_request.log, default is access.
-n <N>, --number=<N> Only read the last ‘’N’’ lines from the logfile.
-v, --verbose Print a header line.