Log module command
It is sometimes desired to better understand the module
usage on the
system we manage. Especially to determine what are the modulefiles most used
and what are those never used that could be removed. This recipe describes a
way to track the module
usage by logging each request made.
Implementation
Logging module commands is implemented by the use of a site-specific configuration that traces every call to a modulefile evaluation.
26proc logModfileInterp {cmdstring code result op} {
27 # parse context
28 lassign $cmdstring cmdname modfile modname
29 set mode [currentState mode]
30 if {[info level] > 1} {
31 set caller [lindex [info level -1] 0]
32 } else {
33 set caller {}
34 }
35
36 # only log load and unload modulefile evaluation
37 if {$mode in {load unload}} {
38
39 # add info on load mode to know if module is auto-loaded or not
40 if {$mode eq {load} && $caller eq {cmdModuleLoad}} {
41 upvar 1 uasked uasked
42 set extra ", \"auto\": [expr {$uasked ? {false} : {true}}]"
43 } else {
44 set extra {}
45 }
46
47 # produced log entry (formatted as a JSON record)
48 execLogger "{ \"user\": \"[get-env USER]\", \"mode\": \"$mode\",\
49 \"module\": \"$modname\"${extra} }"
50 }
51}
52
53# run log procedure after each modulefile interpretation call
54trace add execution execute-modulefile leave logModfileInterp
This code defines a logModfileInterp
procedure which is set to be
evaluated after each evaluation of the execute-modulefile
procedure with
the trace Tcl command. Thanks to the trace
mechanism
logModfileInterp
receives the arguments passed to execute-modulefile
.
The logModfileInterp
procedure applies filter to only log load and
unload modulefile evaluations. It may be extended to the other evaluation
modes (help, display, test, whatis and refresh) by adapting the
following line:
36 # only log load and unload modulefile evaluation
37 if {$mode in {load unload}} {
In the proposed code, log entries are formatted as a JSON record which is convenient to push these logs in a search and analytics engine like Elasticsearch or Splunk. Such tools help to globally monitor the whole set of log entries produced from thousands of computing nodes.
47 # produced log entry (formatted as a JSON record)
48 execLogger "{ \"user\": \"[get-env USER]\", \"mode\": \"$mode\",\
49 \"module\": \"$modname\"${extra} }"
The logger command is run to generate the log message. This is done
through a specific execLogger
procedure ensuring that the current user
environment does not confuse logger with unexpected version of the
libraries it requires.
13proc execLogger {msg} {
14 # ensure logger command is executed with system libs
15 if {[info exists ::env(LD_LIBRARY_PATH)]} {
16 set ORIG_LD_LIBRARY_PATH $::env(LD_LIBRARY_PATH)
17 unset ::env(LD_LIBRARY_PATH)
18 }
19 exec logger -t module $msg
20 # restore current user lib setup
21 if {[info exists ORIG_LD_LIBRARY_PATH]} {
22 set ::env(LD_LIBRARY_PATH) $ORIG_LD_LIBRARY_PATH
23 }
24}
Example code also defines a logModuleCmd
procedure which is set to be
evaluated after each evaluation of the module
and the ml
procedures
with trace Tcl command.
56proc logModuleCmd {cmdstring code result op} {
57 # parse context
58 set args [lassign $cmdstring cmdname]
59 if {[info level] > 1} {
60 set caller [lindex [info level -1] 0]
61 } else {
62 set caller {}
63 }
64
65 # skip duplicate log entry when ml command calls module
66 if {$cmdname ne {module} || $caller ne {ml}} {
67
68 # produced log entry (formatted as a JSON record)
69 execLogger "{ \"user\": \"[get-env USER]\", \"cmd\": \"$cmdname\",\
70 \"args\": \"$args\" }"
71 }
72}
73
74# run log procedure after each module or ml command
75trace add execution module leave logModuleCmd
76trace add execution ml leave logModuleCmd
Note
This code example may be extended to log for instance additional
information in each message. The upvar Tcl command may be used to
retrieve variables from the calling context. However beware that the
internal code of Modules may change, so if you rely on internal variables
please re-check the code in the siteconfig.tcl
file deployed after
each upgrade of Modules.
Compatible with Modules v4.2+
Installation
Create site-specific configuration directory if it does not exist yet:
$ mkdir /etc/environment-modules
Then copy there the site-specific configuration script of this recipe:
$ cp example/log-module-commands/siteconfig.tcl /etc/environment-modules/
Note
Defined location for the site-specific configuration script may vary from
one installation to another. To determine the expected location for this
file on your setup, check the value of the siteconfig
option on Modules
version 4.3 or above:
$ module config siteconfig
On older version of Modules, check the modulecmd.tcl
script:
$ grep '^set g_siteconfig ' $MODULES_CMD
Usage example
Listing available modulefiles, then loading a bare modulefile, then another one with a dependency and purging everything in the end:
$ ml av --------------- /path/to/modulefiles --------------- bar/1.0 foo/1.0 qux/1.0 $ ml foo $ module load bar Loading bar/1.0 Loading requirement: qux/1.0 $ module purge
A log entry can then be retrieved from system log files:
$ journalctl -q -t module
Sep 12 20:24:01 hostname module[9925]: { "user": "username", "cmd": "ml", "args": "av" }
Sep 12 20:24:02 hostname module[9925]: { "user": "username", "mode": "load", "module": "foo/1.0", "auto": false }
Sep 12 20:24:02 hostname module[9925]: { "user": "username", "cmd": "ml", "args": "foo" }
Sep 12 20:24:03 hostname module[9925]: { "user": "username", "mode": "load", "module": "qux/1.0", "auto": true }
Sep 12 20:24:03 hostname module[9925]: { "user": "username", "mode": "load", "module": "bar/1.0", "auto": false }
Sep 12 20:24:03 hostname module[9925]: { "user": "username", "cmd": "module", "args": "load bar" }
Sep 12 20:24:04 hostname module[9925]: { "user": "username", "mode": "unload", "module": "bar/1.0" }
Sep 12 20:24:04 hostname module[9925]: { "user": "username", "mode": "unload", "module": "qux/1.0" }
Sep 12 20:24:04 hostname module[9925]: { "user": "username", "mode": "unload", "module": "foo/1.0" }
Sep 12 20:24:04 hostname module[9925]: { "user": "username", "cmd": "module", "args": "purge" }