Logging and Exception handling - Pyosch/powertac-server GitHub Wiki

up

The Power TAC simulation server is a complex software system intended to support a variety of research agendas. To be an effective research tool, its operation must be as transparent as possible. The logging scheme is designed to promote that transparency. When the server runs, it generates two log files for each simulation session: a "state" log, and a "trace" log; the state log is named "powertac-xxx.state", and the trace log is named "powertac-xxx.trace". The state log records all changes to the internal state of the server in a standard format, suitable for automated post-session analysis. The trace log is a record of server activity, intended to help understand detailed server behavior.

Entries in the state log represent method calls that modify the state of the simulation. Examples include creation of a new TariffSpecification, a change in the cash position of a broker, creation of a TariffTransaction that represents power consumption by a customer, etc. There are two types of entries in the state log corresponding to object creation and method calls. Classes that are annotated with @Domain have their constructor calls logged, and methods annotated with @StateChange generate log entries when they are called.

Each line in the state log has a standard format:

    ms:classname::id::method::arg...

where

• ms is the time in milliseconds from the beginning of the simulation process,
• classname is the Java type of the object being created or modified,
• id is the integer id value of the object being modified,
• method is the name of the method that was invoked (constructors are called new), and
• arg is an argument to the method.

The format of method arguments depends on type. If the type of a method argument is a domain object, then its id value is given; times are given in UTC time format; primitive values (number, booleans, etc.) are printed in their standard forms; enumeration values (such as Tariff states) are given as defined in the code.

To interpret the content of the state log, it is necessary to understand the simulation domain model, which is documented in the javadoc. As an example, here are three lines from near the beginning of a state log, generated by the balancing market:

32073:org.powertac.common.BalancingTransaction::1309::new::1::2009-10-25T00:00:00.000Z::-29238.753000000008::1461.9376500000005
32073:org.powertac.common.DistributionTransaction::1310::new::1::2009-10-25T00:00:00.000Z::29238.753000000008::-633.9811943285854
32074:org.powertac.common.DistributionTransaction::1311::new::598::2009-10-25T00:00:00.000Z::-0.0::0.0

The first line is a new BalancingTransaction, id 1309. The constructor takes 4 arguments: a Broker (id 1, the default broker), an Instant (when the transaction was created), a double representing the energy imbalance in kwh, and a double representing the charge for this transaction.

The trace log is intended to provide a record of server activity that is useful for server developers or those trying to understand server behavior. Each line has the format

    ms level abbrev-classname: message

where ms is the time in milliseconds since the simulator process was started, level is an indicator of the type of message (one of ERROR, WARN, INFO, DEBUG), abbrev-classname is the class where the message was generated, except that the package string is abbreviated to just its last component, and message is whatever message the developer thought was useful to produce at that point in the code. Because the state log and trace logs are generated in the same process, it is relatively easy to align them by matching up the ms values.

In addition to normal behavior, the trace log also records interesting or unusual circumstances, including errors. An initial validation of a game is to ensure that the string ERROR does not appear in the trace log. In general, Exceptions are used only when an error is detected that prevents further progress in some section of code, and either it makes sense to abort the server at this point, or the current stack context is prepared to intercept an exception and recover somehow (in other words, there is a catch block on the stack that will intercept and deal appropriately with the exception that is raised.