Logging

From Cyclos4 Wiki
Jump to: navigation, search

Any Cyclos installation uses 3 types of logging:

Error log

The error log is the highest level logging facility, and logs only unexpected errors. It can be searched by within the application by system administrators in Reports > Error logs. An error log entry is generated when a service operation or a background task fails. Each entry contains the operation that has failed, the logged user, the channel and a Java error stack trace, to help debugging the error.

External log

Besides error logs, Cyclos provides logging to an external file or database. This log can include not only errors, but also success executions.

This kind of log can be configured part in cyclos.properties and part in the system configuration page (in menu System > Configuration).

There are 2 kinds of external log:

  • Services: Logs any call to a service operation. Generally, each action the user performs in the web page or mobile app corresponds to a single service operation invocation. Some rare actions may use more than one operation, though. Enabling logging for all operations with all parameters can have a minor impact in the system throughput. Although, having them enabled can be important for tracing problems in production. As such, each system should consider their logging configuration carefully.
  • Background tasks: Logs the execution of tasks that happen in background. Cyclos performs several background tasks, such as sending e-mails / SMS messages, charging account fees, processing scheduled payments and so on.

Settings in Cyclos configuration

  • Enable tasks logging: Whether the entire background tasks logging is enabled
  • Enable services logging: Whether the entire service logging is enabled
  • Log parameters on services: When a service log is generated, should the parameter values be logged?
  • Log results on services: When a service log is generated, should the return value be logged?
  • Log services for guests: Whether to skip service logging for operations called before the user is logged-in?
  • Log writes only in services: Whether to skip service logging for operations called before the user is logged-in?

Settings in cyclos.properties

  • cyclos.log.threads: The number of threads to handle logging in an asynchronous fashion. When set to 0, responses will be held until the log is complete. Having synchronous logging has a higher impact in the system throughput but ensures that no logging is lost. When asynchronous logging is used, they are enqueued and processed by one or more threads. This queue, however, is volatile. If the server process terminates without processing all logging events, these are permanently lost.
  • cyclos.log: The log destination. Can be set to one of these: file (default), db, console or none.
    • file: Files are generated in the directory specified by cyclos.log.dir. The maximum number of files is defined with the cyclos.log.maxFiles setting, each limited in size by the cyclos.log.maxFileSize setting. The files are rotating, so, when the oldest file reaches the maximum size, it is removed and a new one is generated.
    • db: An external PostgreSQL database is used to store the log events. The same settings accepted by the basic datasource are also accepted, with the cyclos.log.datasource prefix. So, for example, cyclos.log.datasource.driverClass, cyclos.log.datasource.jdbcUrl, cyclos.log.datasource.user, cyclos.log.datasource.password and cyclos.log.datasource.maxPoolSize are valid settings.
      The greatest advantage of writing log entries to an external database is that it is much easier to query for specific events when compared to logging files. Also, more fine-grained information is generated. The database tables used on logging are the following:
      • service_logs: Stores the logging entries for the service logs. The columns are:
        • date: The logging event timestamp
        • cyclos_version: The Cyclos version that generated the event
        • remote_address: The IP address which originated the request
        • service_name: The name of the service that generated the event
        • method_name: The service operation that generated the event
        • success: Whether the service invocation succeeded (true) or failed (false)
        • time_taken: Then number of milliseconds it took for executing the service operation
        • parameters: The service parameters, stored as JSON. Only if the Log parameters on services configuration is set
        • result: The service result, stored as JSON. Only if the Log results on services configuration is set |
        • error: The exception details, stored as JSON
        • error_stack_trace: The Java stack trace of the generated exception
        • network_id: The internal identifier of the network in which the event was generated
        • network_name: The display name of the network in which the event was generated
        • configuration_id: The internal identifier of the configuration in which the event was generated
        • configuration_name: The display name of the configuration in which the event was generated
        • channel_id: The internal identifier of the channel in which the event was generated
        • channel_name: The display name of the channel in which the event was generated
        • principal_type_id: The internal identifier of the user identification method the user used for login / identification
        • principal_type_name: The display name of the user identification method the user used for login / identification
        • principal: The identification value (username, e-mail, account number, etc) the user used for login / identification
        • session_token: The identifier for the user session
        • user_id: The internal identifier for the authenticated / logged user
        • user_display: The display name for the authenticated / logged user
        • group_id: The internal identifier of the authenticated user's group
        • group_name: The display name of the authenticated user's group
        • custom_ws_id: The internal identifier of the custom web service that generated the request
      • task_logs: Stores the logging entries for the background task logs. The columns are:
        • date: The logging event timestamp
        • cyclos_version: The Cyclos version that generated the event
        • name: The name of the background task that generated the event
        • success: Whether the background operation succeeded (true) or failed (false)
        • affected_records: The number of database rows the background operation has affected
        • time_taken: Then number of milliseconds it took for executing the service operation
        • error_stack_trace: The Java stack trace of the generated exception
    • console: Instead of using an external logging file or database, writes service / task logs directly to the application server's output console. In Tomcat, this is generally <server-root>/logs/catalina.out
    • none: Completely disable both services / tasks logging.

Searching for logging events in an external database

The greatest advantage of having the external logging in an external database is that it is easier to query for events. For more useful logging it is recommended to enable both 'Log parameters on services' and 'Log results on services'.

Each operation users perform will generate one or more rows in the service_logs table (generally one). However, the greatest challenge is to figure out which service and operation maps to each action. The services are Java classes documented in the API javadocs. Each method corresponds to an operation. The next sections have a few examples.

NOTE ON PERFORMANCE: The logging tables don't have any database indexes on them by default. Depending on the type of search you need, it would be wise to create some indexes. For example, on the date, user_id or (service_name, method_name) if you often filter by these columns. Having no indexes also means higher insert throughput, because no indexes need to be updated. Finally, there is no built-in mechanism for purging old log rows. It would be good to remove from the live logging table very old rows, to improve the query performance. This depends on each system's policies. For example, it might be desirable to keep log entries for 3 months, and then remove them. Of course, in this case having a backup would be wise, in case some old incident need to be investigated.

Finding out when a specific user has logged in

We can find out that the LoginService.login() method is used to login the user. The HTTP BASIC authentication is passed to identify the logged user, and then a session is created.

Supposing we have a user with login name '12345'. The first thing to do is to find out the user's id in the main Cyclos database:

select id from users where username = '12345';
 id 
----
  99
(1 row)

In this case, the id is 99. Then, to find out when the user has logged in, as well as the remote IP addresses, we can run the following SQL in the log database:

select date, remote_address from service_logs where user_id = '12345' order by date;
            date            | remote_address  
----------------------------+-----------------
 2020-02-12 13:37:36.755783 | 187.107.56.127
 2020-02-25 18:02:27.924425 | 187.107.56.119
 2020-02-26 09:12:13.331676 | 187.107.56.119
(3 rows)

Finding out which administrators have saved the configuration

We can find out that the ConfigurationService inherits the save() method from CRUDService (this happens with many services).

To find out the dates, ids, names of administrators, as well as which configurations were saved, we can run the following SQL in the log database:

select date, remote_address, user_id, user_display, parameters->>'id' as configuration_id from service_logs where service_name = 'ConfigurationService' and method_name = 'save' order by date;
            date            | remote_address  | user_id |     user_display     | configuration_id 
----------------------------+-----------------+---------+----------------------+------------------
 2020-02-03 08:12:42.874792 | 187.107.56.127  |       1 | System Administrator | 4
 2020-02-10 10:32:13.404823 | 187.107.56.127  |       1 | System Administrator | 1
 2020-02-10 10:29:57.203312 | 187.107.56.129  |       2 | Second Administrator | 4
 2020-02-12 15:12:08.346181 | 187.107.56.129  |       2 | Second Administrator | 4
 2020-02-13 11:28:34.231136 | 187.107.56.129  |       2 | Second Administrator | 1
(5 rows)

Similarly, if searching for product changes, just change the service_name column 'ProductService' in the query.

Console log

There are miscellaneous places where unhandled errors are logged to the application server's console. Also, the setting cyclos.dumpAllErrors can be set to true to log to console every error that happen on any service invocation. This helps debugging but is not recommended for production, as too much noise can be generated. For example, every failed login attempt, or invalid form submission will generate an error log in the console.