3. The AccuRev Server : Server Logging

Server Logging
The AccuRev Server maintains a log file, acserver.log, in subdirectory logs of the site_slice directory. Each log message includes a timestamp, the AccuRev username that invoked a client command, and the IP address of the client machine.
AccuRev also supports client-side logging. See Logging on page 417 of the AccuRev Online Help Guide for more information.
Time zone offset
As of AccuRev V5.4, the format of acserver.log entries has been expanded to include a time zone offset. For example:
2011/12/20 14:33:41.329-05:00 Server locale is C
where "-05:00" is the ISO-8601 TZ offset with respect to GMT.
This enables you or AccuRev Support to correlate logs from masters, replicas, and clients spread across different timezones.
Logging Levels
Logging information can be preserved at various levels of detail, as specified in acserver.cnf:
# log level 2 or 3 is recommended by AccuRev support team
LOG_LEVEL = 2
UNIX/Linux: Log File Rotation
On UNIX/Linux server machines, log file rotation keeps the log file from growing too large. Periodically, the AccuRev Server timestamps the current log file and moves it to subdirectory logs of the site_slice directory. For example, the log file might be renamed acserver-2002-01-23-04-47-29.log. The Server then creates a new acserver.log file. The log file is rotated weekly; it is also rotated whenever the AccuRev Server is restarted.
Controlling Server Log Verbosity
The verbosity of the server logs is controlled by the LOG_LEVEL entry in the acserver.cnf file:
LOG_LEVEL = 3  #enable the highest (most verbose) level of logging
At log level 1, each execution thread produces one line in the log. At log level 2, each execution thread can produce multiple log lines. Log level 3 essentially combines levels 1 and 2. At higher log levels, some of the messages detail the work of server subtasks.
Verbose Server Logging
The Server is a multi-threaded program, so it can handle several client commands concurrently. A typical AccuRev client command causes the AccuRev Server to execute a set of server subtasks. For each client command, the Server’s “master thread” creates a new “worker thread” to perform the set of subtasks for that particular command. When the worker thread has performed all the subtasks, it exits. When the LOG_LEVEL is 2 or 3, the log messages indicate many of the details of server subtask execution.
For example, a single update command can generate a set of log messages like this:
2008/02/09 16:24  connection 1076 on 00000E98 cache 0 started
2008/02/09 16:24  1076 mary *update 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary cur_wspace 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary ws_type 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary stream_top 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary check_time 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary update 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary end 00000E98 1.2.3.101
2008/02/09 16:24  connection 1076 on 00000E98 success 0.563 0 0 0 1.2.3.101 mary
These messages may or may not appear on consecutive lines of the log file. If multiple client commands are being executed concurrently by different worker threads, the log messages that the threads generate will be interleaved in the log file.
Let’s examine each message in the above example:
2008/02/09 16:24  connection 1076 on 00000E98 cache 0 started
The first message is generated at the time (2008/02/09 16:24:20) a client request is accepted by the Server’s master thread. This is connection 1076 between the client and the server). The master thread creates a new worker thread (worker thread-ID 00000E98) and hands the request off to it.
2008/02/09 16:24:20 1076 mary *update 00000E98 1.2.3.101
This message indicates the user who invoked the command (mary), the name of the command, marked with an asterisk (*update), and the IP address of the client machine (1.2.3.101).
2008/02/09 16:24  1076 mary cur_wspace 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary ws_type 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary stream_top 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary check_time 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary update 00000E98 1.2.3.101
2008/02/09 16:24  1076 mary end 00000E98 1.2.3.101
Each time the worker thread begins a particular subtask, it sends a message to the log. In the lines shown above, the client command is implemented through server subtasks cur_wspace, ws_type, stream_top, check_time, update, and end. (The last subtask is always named end.) Each message also includes the username, thread-ID, and client IP address.
... connection 1076 on 00000E98 success 0.563 0 0 0 1.2.3.101 mary
The last message is generated by the worker thread after it has completed all subtasks and is about to exit. (If the LOG_LEVEL is 1, this is the only message generated for each client command.) In addition to the username, thread-ID, and client IP address data also included in the preceding messages, this message reports summary measures, listed in boldface above:
success / failure (success in the example above): The overall result of the attempt to execute the client command.
run time (0.563): the total time, in seconds, that the worker thread took to process the entire client command.
last check (0): the time, in seconds, elapsed since last progress update from worker thread. In a success message, this value is 0. In a failure message, this value is non-zero.
time delta (0): the time difference between the clocks on the client and server machines.
exit status (0): the exit code for thread: 0 = success, non-zero = error.

Borland