Difference between revisions of "Logging"

From BaseX Documentation
Jump to navigation Jump to search
(37 intermediate revisions by 4 users not shown)
Line 1: Line 1:
 +
This article is part of the [[Advanced User's Guide]]. It describes how client operations are logged by the server.
 +
The server logs can e.g. be used to get an overview of all processes executed on your server, trace any errors
 +
or compile performance statistics.
 +
 
==Introduction==
 
==Introduction==
  
The server logs give you the following advantages:
+
The server logs are written in plain text. In your [[Configuration#Database Directory|Database Directory]], you can find a folder named <code>.logs</code> in which all log files are stored with the according date. Note that, depending on your OS and configuration, files and folders beinning with a <code>.</code> may be hidden. The log directory can be changed via the {{Option|LOGPATH}} option.
 +
 
 +
If BaseX is used in a [[Web Application]], all trace output (generated via {{Code|fn:trace}}, {{Function|Profiling|prof:dump}} and similar functions) will be stored in the logs as well.
 +
 
 +
Some more notes on the logging facility:
 +
 
 +
* HTTP requests are included in the log files.
 +
* Logging can be turned on/off via the {{Option|LOG}} option.
 +
* The maximum length of logging messages can be changed via {{Option|LOGMSGMAXLEN}}.
 +
* The [[Admin Module]] provides access to the log files from XQuery.
 +
 
 +
==RESTXQ==
 +
 
 +
By default, RESTXQ code is executed with the {{Code|admin}} user. As a result, this user will be displayed in the logs for all RESTXQ requests. In a web application with a custom user management, however, the name of the actual user who has sent a request is often more relevant.
 +
 
 +
When log data is written during the processing of a RESTXQ function, the following is looked up as follows:
 +
 
 +
# The current request is checked for an {{Code|id}} attribute. The attribute can be assigned via RESTXQ and the {{Function|Request|request:set-attribute}} function, and it is the recommended approach for stateless requests as all request attributes will be dropped after the finalization of a request.
 +
# If none is found, the {{Code|id}} attribute is looked up in the current user session. The attribute can be assigned via {{Function|Session|session:set}} (see e. g. the [[DBA]] code for sessions and user handling). If the request path contains a {{Code|dba}} segment, a {{Code|dba}} session attribute will be looked up instead.
 +
# If none is found, the default path will be taken, and the user of the current database context will be included in the logs.
 +
 
 +
==Format==
 +
 
 +
; Example 1:
 +
 
 +
<syntaxhighlight>
 +
01:18:12.892  SERVER          admin  OK        Server was started (port: 1984)
 +
01:18:15.436  127.0.0.1:4722  jack    REQUEST  XQUERY for $i in 1 to 5 return random:double()
 +
01:18:15.446  127.0.0.1:4722  jack    OK        Query executed in 2.38 ms.                      2.72 ms
 +
01:18:15.447  127.0.0.1:4722  jack    REQUEST  EXIT
 +
01:18:15.447  127.0.0.1:4722  jack    OK                                                        0.39 ms
 +
</syntaxhighlight>
 +
 
 +
A server has been started and a user <code>jack</code> has connected to the server to perform a query and exit properly.
 +
 
 +
; Example 2:
 +
 
 +
<syntaxhighlight>
 +
01:23:33.251  127.0.0.1:4736  john  OK        QUERY[0] 'hi'  0.44 ms
 +
01:23:33.337  127.0.0.1:4736  john  OK        ITER[0]        1.14 ms
 +
01:23:33.338  127.0.0.1:4736  john  OK        INFO[0]        0.36 ms
 +
01:23:33.339  127.0.0.1:4736  john  OK        CLOSE[0]        0.21 ms
 +
01:23:33.359  127.0.0.1:4736  john  REQUEST  EXIT
 +
01:23:33.359  127.0.0.1:4736  john  OK                        0.14 ms
 +
</syntaxhighlight>
 +
 
 +
A user <code>john</code> has performed an iterative query, using one of the client APIs.
 +
 
 +
; Example 3:
  
# Overview about all processes executed on your server
+
<syntaxhighlight>
# Tracing of any errors thrown by BaseX
+
01:31:51.888  127.0.0.1:4803  admin  REQUEST  [GET] http://localhost:8984/rest/factbook
# Tracing of wrong modified data
+
01:31:51.892  127.0.0.1:4803  admin  200                                                  4.43 ms
# Tracing of all specific user processes
+
</syntaxhighlight>
# Tracing of time specific processes
 
  
The server logs are written in plain-text and can be opened with any editor.
+
An admin user has accessed the <code>factbook</code> database via REST.
Furthermore there are well structured to give you a perfect overview about the processes.
 
In your database folder you can find a folder named '.logs' where all log files are
 
stored with the belonging date.
 
  
==Logformat==
+
=Changelog=
  
;Example:
+
;Version 9.3
: <pre>16:00:00.094 [127.0.0.1:3920] LOGIN admin OK &#10;16:00:00.104 [127.0.0.1:3920] XQUERY 1 to 10 OK 12.36 ms&#10;16:00:00.114 [127.0.0.1:3920] LOGOUT admin OK</pre>
+
* Updated: Store trace output in database logs
: Now you can see the 'admin' user has the IP 127.0.0.1 with the socketport 3920. With this information you can identify each transaction of the corresponding user.
+
* Updated: [[#RESTXQ|RESTXQ]]: The request attributes will be checked for a user id.
  
;Example:
+
;Version 8.6
: <pre>10:06:36.498 [127.0.0.1:49990] LOGIN admin OK&#10;10:06:53.297 [127.0.0.1:49990] XQUERY 1 to 10 OK 17.89 ms&#10;10:07:03.353 [127.0.0.1:49993] LOGIN testuser OK&#10;10:07:08.259 [127.0.0.1:49993] XQUERY 1 to z Error: Stopped at line 1, column 6:  [XPDY0002] No context item set for 'z'. 9.69 ms&#10;10:07:15.505 [127.0.0.1:49990] LOGOUT admin OK&#10;10:07:19.790 [127.0.0.1:49993] LOGOUT testuser OK
+
* Added: The log directory can be changed with the {{Option|LOGPATH}} option.
: Now you can see the 'admin' user has the IP 127.0.0.1 with the socketport 49990 and the 'testuser' has the IP 127.0.0.1 with the socketport 49993. With this information you can identify each transaction of the corresponding user.
+
* Updated: Include session attributes in log data.
The 'testuser' for example executed a query which was aborted by an syntax error.
 

Revision as of 11:49, 8 July 2020

This article is part of the Advanced User's Guide. It describes how client operations are logged by the server. The server logs can e.g. be used to get an overview of all processes executed on your server, trace any errors or compile performance statistics.

Introduction

The server logs are written in plain text. In your Database Directory, you can find a folder named .logs in which all log files are stored with the according date. Note that, depending on your OS and configuration, files and folders beinning with a . may be hidden. The log directory can be changed via the LOGPATH option.

If BaseX is used in a Web Application, all trace output (generated via fn:trace, prof:dump and similar functions) will be stored in the logs as well.

Some more notes on the logging facility:

  • HTTP requests are included in the log files.
  • Logging can be turned on/off via the LOG option.
  • The maximum length of logging messages can be changed via LOGMSGMAXLEN.
  • The Admin Module provides access to the log files from XQuery.

RESTXQ

By default, RESTXQ code is executed with the admin user. As a result, this user will be displayed in the logs for all RESTXQ requests. In a web application with a custom user management, however, the name of the actual user who has sent a request is often more relevant.

When log data is written during the processing of a RESTXQ function, the following is looked up as follows:

  1. The current request is checked for an id attribute. The attribute can be assigned via RESTXQ and the request:set-attribute function, and it is the recommended approach for stateless requests as all request attributes will be dropped after the finalization of a request.
  2. If none is found, the id attribute is looked up in the current user session. The attribute can be assigned via session:set (see e. g. the DBA code for sessions and user handling). If the request path contains a dba segment, a dba session attribute will be looked up instead.
  3. If none is found, the default path will be taken, and the user of the current database context will be included in the logs.

Format

Example 1

<syntaxhighlight> 01:18:12.892 SERVER admin OK Server was started (port: 1984) 01:18:15.436 127.0.0.1:4722 jack REQUEST XQUERY for $i in 1 to 5 return random:double() 01:18:15.446 127.0.0.1:4722 jack OK Query executed in 2.38 ms. 2.72 ms 01:18:15.447 127.0.0.1:4722 jack REQUEST EXIT 01:18:15.447 127.0.0.1:4722 jack OK 0.39 ms </syntaxhighlight>

A server has been started and a user jack has connected to the server to perform a query and exit properly.

Example 2

<syntaxhighlight> 01:23:33.251 127.0.0.1:4736 john OK QUERY[0] 'hi' 0.44 ms 01:23:33.337 127.0.0.1:4736 john OK ITER[0] 1.14 ms 01:23:33.338 127.0.0.1:4736 john OK INFO[0] 0.36 ms 01:23:33.339 127.0.0.1:4736 john OK CLOSE[0] 0.21 ms 01:23:33.359 127.0.0.1:4736 john REQUEST EXIT 01:23:33.359 127.0.0.1:4736 john OK 0.14 ms </syntaxhighlight>

A user john has performed an iterative query, using one of the client APIs.

Example 3

<syntaxhighlight> 01:31:51.888 127.0.0.1:4803 admin REQUEST [GET] http://localhost:8984/rest/factbook 01:31:51.892 127.0.0.1:4803 admin 200 4.43 ms </syntaxhighlight>

An admin user has accessed the factbook database via REST.

Changelog

Version 9.3
  • Updated: Store trace output in database logs
  • Updated: RESTXQ: The request attributes will be checked for a user id.
Version 8.6
  • Added: The log directory can be changed with the LOGPATH option.
  • Updated: Include session attributes in log data.