User Activity Logging
Specification & Architecture
1 Introduction
This document summarizes a year long discussion between UZH and BPS about how to do Activity Logging in OLAT and describes the next steps necessary to finish the implementation.
Terminology
There will still be two different kinds of logging:
-
user activity logging for auditing and user-, group-, course-level statistics
-
technical logging for errors, warns and debugging.
This document only affects user activity logging
2 Architecture
IUserActivityLogger, ThreadLocalUserActivityLoggerInstaller and ThreadLocalUserActivityLogger
-
All logging happens via an interface IUserActivityLogger via the Method(s) log(..)
-
An UserActivityLogger can be created via ThreadLocalUserActivityLoggerInstaller
-
Also, a ThreadLocalUserActivityLogger is introduced to pass UserActivityLoggers from Controller to Controller during event handling (which is the most common use case of doing user activity logging)
-
When ThreadLocalUserActivityLogger.log() is accessed and no IUserActivityLogger is set, it falls back to the minimum set of informations available which is the user and the session.
User Activity Logging During Event Handling
-
Each Controller has an (optional) IUserActivityLogger which is initialized usually at constructor time.
PS: Controllers should set the IUserActivityLogger as early as possible when they have knowledge of olat resourceable that would be important to have for logging (incl. ForumController, CourseGroupManagementMainController). Not always are Controllers created from within an event() method
-
In the event loop where Window.event() calls Controller.event() the Framework grabs the Controller's IUserActivityLogger and sets it as the ThreadLocalUserActivityLogger. (setting the minimal IUserActivityLogger if the Controller one is null)
-
Similarly, the EventAgency.fireEvent() - through which all MultiUserEvent for both singleVM and cluster mode are passed through - sets the ThreadLocalUserActivityLogger to the Controller's IUserActivityLogger. If the listener is not a Controller then the ThreadLocalUserActivityLogger is set to null
-
This allows for any code which is executed within the scope of Controller.event() to be able to simply access the ThreadLocalUserActivityLogger.log() method to do user activity logging.
-
Similarly to Controller.event() there is a bit of logging done within the scope of Window.dispose(). The framework also sets the ThreadLocalUserActivityLogger to simplify user activity logging during dispose().
-
For cases where logging is done outside of the scope of the Controller.event()/Window.dispose() the ThreadLocalUserActivityloggerInstaller can be used to create an UserActivityLogger
-
Special care needs to be taken during multi user session event handling: There we should not pass on the UserActivityLogger object via ThreadLocal
Initialization of IUserActivityLogger
-
As a minimum fallback there will always be an IUserActivityLogger which knows about the user and the session - therefore minimal user activity logging within an event handler is always possible.
-
The goal though is to pass more specific information to the IUserActivityLogger:
-
the business path - which we should be able to retrieve via WindowControl/BusinessControl - attribute "BUSPATH"
-
and derived thereof the following (duplicate) information to simplify logging analysis later:
-
target resource (ID & Type)
-
course
-
group
-
node
-
The framework sets the IUserActivityLogger in the DefaultController to the one currently set in ThreadLocalUserActivityLogger (as part of passing IUserActivityLoggers from Controller to Controller)
Logging Targets: distributed, into OLAT DB or Separate DB
Logging is done into a database - this can either be the olat database or a separate one.
Each OLAT node logs directly into the (logging) DB - i.e. logging happens distributed. This is better performance-wise - as sending an event to a central-single-service which would then do the DB transaction is an overhead. The main reason for the RemoteAuditLogger (which did logging into a log file from a singleton service) was to make sure the log file was not garbled. With the DB this is no longer an issue and we can now log distributed. Hence the
RemoteAuditLogger will no longer be used.
Regarding logging into the OLAT DB or a separate DB: This comes down to lifecycling logging data. As this table grows constantly and rather rapidly, one needs to plan how this big logging table is handled. Two or three different concepts could be considered:
-
Logging happens into the OLAT DB - with replication configured to forward the o_loggingtable to a separate, long-term-logging-db. The latter can then do periodic compressing, normalization etc.
-
Logging happens into a separate DB which does periodic compressing, normalization etc.
-
Logging happens into a separate DB which is configured with replication and forwards its logging table to a separate, long-term-logging-db which then does compressing and normalization
The decision on which setup to implement is a deployment choice.
Logged Information
The following is the complete list of information which is logged. As shown above, the logging can happen to the usual OLAT DB or to a separate
logging DB.
Note that not all of below fields are mandatory
Technical Fields
ID
|
Type
|
Length
|
Mandatory
|
Description
|
log_id
|
bigint
|
20
|
true
|
globally unique id of this log entry
|
creationdate
|
timestamp
|
|
true
|
date and time when this log happened
|
sourceclass
|
varchar
|
512
|
true
|
the class which triggered this log
|
Session and User Fields
ID
|
Type
|
Length
|
Mandatory
|
Description
|
sessionid
|
varchar
|
255
|
true
|
JSessionID
|
user_id
|
bigint
|
20
|
false
|
o_user.user_id
|
username
|
varchar
|
255
|
false
|
|
userproperty1
|
varchar
|
255
|
false
|
customizable property 1
|
..
|
varchar
|
255
|
false
|
..
|
userproperty12
|
varchar
|
255
|
false
|
customizable property 12
|
Action
ID
|
Type
|
Length
|
Mandatory
|
Description
|
actionCRUDType
|
varchar
|
1
|
true
|
CRUD: (C)reate, (R)etrieve, (U)pdate, (D)elete, (E)xit
|
actionVerb
|
varchar
|
16
|
true
|
verb describing this action. This comes from a limited, olat-wide defined enum. e.g.:
add,remove,edit,launch,denied,move,copy,view...
|
actionObject
|
varchar
|
32
|
true
|
object of this action. usually corresponds to targetrestype but the latter might not always exist. e.g.:
course,node,editor,groupmanagement,forumthread,
owner,participant...
|
resourceadminaction
|
boolean
|
1
|
true
|
formerly known as logStream - true for ADMIN, false for USER
|
simpleDuration
|
bigint
|
20
|
true
|
-1 by default, otherwise the time between the next and this log action in this session
|
Scope
ID
|
Type
|
Length
|
Mandatory
|
Description
|
businesspath
|
varchar
|
2048
|
false
|
REST-like, full business path
|
targetrestype
|
varchar
|
32
|
false
|
target olat resourceable type (e.g. forum,wiki)
|
targetresid
|
varchar
|
64
|
false
|
target olat resourceable id
|
targetresname
|
varchar
|
256
|
false
|
target olat resourceable name
|
parentrestype
|
varchar
|
32
|
false
|
the parent olat resourceable type (e.g. node)
|
parentresid
|
varchar
|
64
|
false
|
the parent olat resourceable id
|
parentresname
|
varchar
|
256
|
false
|
the parent olat resourceable name
|
grandparentrestype
|
varchar
|
32
|
false
|
the grand parent olat resourceable type (e.g. course)
|
grandparentresid
|
varchar
|
64
|
false
|
the grand parent olat resourceable id
|
grandparentresname
|
varchar
|
256
|
false
|
the grand parent olat resourceable name
|
greatgrandparentrestype
|
varchar
|
32
|
false
|
the great grand parent olat resourceable type (e.g. course)
|
greatgrandparentresid
|
varchar
|
64
|
false
|
the great grand parent olat resourceable id
|
greatgrandparentresname
|
varchar
|
256
|
false
|
the great grand parent olat resourceable name
|
A note on olat resourceables:
-
Not all information stored in the scope/resource columns are of type OLATResourceable. Within Olat this concept of OLATResourceable is not implemented consequently - e.g. a Course Node is not an OLATResouceable, yet we want to log this information
-
Also, sometimes we want to store information which has nothing to do with an OLATResourceable, such as a user or the number of qti attempts - in short, in these cases we want to store a plain old String.
-
To support all of the above cases (a proper OLATResourceable, an almost OLAT Resourceable and a plain String) we introduce a new interface called ILoggingResourceable under which there are two concrete implementations, one for OLATResourceable and one for the rest. Hence the type and id of the above fields do not always match to something in the DB or in the filesystem and are therefore -1 in those cases
A note on target, parent, grandparent, greatgrandparent
-
The User Activity Logging framework collects ILoggingResourceables which it then stores into the DB. This collection happens at constructor creator time, is magically available during event handling and dispose via the ThreadLocal concept and can also be provided to the IUserActivityLogger at log() call time.
-
All of these resourceables are then checked against what the LoggingAction expects there to be - plus also checked against the businessPath.
-
The result - or to be precise at max 4 of them - are then stored in those target/parent/grandparent/greatgrandparent fields, starting with the most specific one, which is target.
-
Hence target should rather never be null, but greatgrandparent/greatparent are often null.
Example 'Log-Line'
*************************** 2. row ***************************
log_id: 1703939
creationdate: 2009-11-03 09:54:51
sourceclass: org.olat.course.run.navigation.NavigationHandler
sessionid: CF2F6ABEEBD1CC3112196ABB3699E07A
user_id: 229376
username: administrator
userproperty1: NULL
userproperty2: NULL
userproperty3: NULL
userproperty4: NULL
userproperty5: NULL
userproperty6: NULL
userproperty7: NULL
userproperty8: NULL
userproperty9: NULL
userproperty10: NULL
userproperty11: NULL
userproperty12: NULL
actioncrudtype: r
action: NODE_ACCESS
simpleduration: 2404
resourceadminaction: 0
businesspath: [RepositoryEntry:393222][CourseNode:70448659388630]
greatgrandparentrestype: NULL
greatgrandparentresid: NULL
greatgrandparentresname: NULL
grandparentrestype: NULL
grandparentresid: NULL
grandparentresname: NULL
parentrestype: CourseModule
parentresid: 80387775267358
parentresname: Course template small
targetrestype: st
targetresid: 70448659388630
targetresname: Course template small
Duration Estimation
In order to estimate the duration which a user spent on a particular page we can use the following algorithm:
-
initially a log entry is written to the DB with duration=-1
-
if a subsequent the above written log entry's duration value is overwritten with the measured delta value.
Note that a session timeout will set the duration of the user's last click to
session_timeout by default. This must be taken into account when doing reports. Also, large values of duration might not be useful since the user could have done something else in the meantime.
Here is a note about updating simpleDuration. With the setup @ UZH of having BLACKHOLE configured in the o_loggingtable on the Main OLAT DB those logging entries we insert directly 'disappear' (and get replicated to the logging db). That means that doing an updateObject() later would fail because hibernate does a safety check on how many rows were updated. And since it can't find the previous logging object anymore, it fails.
To work around this issue, the code now does an update manually via createQuery and executeQuery. This way we don't assume that the log row we're updating actually exists in the database. If it exists, it will update it fine. If it doesn't, nothing happens. Except that our setup with replication will still forward the update command to the slave - hence it still gets updated accordingly in the slave.