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 and modulefile evaluations relies on two configuration options introduced in version 5.5:

  • logger, the command run to transmit messages to the log system

  • logged_events, list of module event to log

logger option relies on the logger command by default, which is usually available and already installed on most systems.

Following events are recognized by logged_events option:

  • requested_cmd: record module commands typed by users

  • requested_eval: record modulefile evaluations requested by users

  • auto_eval: record modulefile evaluations automatically triggered

Note that some messages can also be sent during modulefile evaluation by using the log channel of the puts command.

Compatible with Modules v5.5+

Configuration

Verify the currently defined logger command points to an installed and valid tool:

$ module config logger
Modules Release 5.5.0 (2024-11-11)

- Config. name ---------.- Value (set by if default overridden) ---------------
logger                    /usr/bin/logger -t modules

The logged_events option is empty by default, so no content is sent to logs by default.

Configure logged_events to record for instance the requested_cmd and requested_eval events:

$ module config logged_events +requested_cmd:requested_eval

With this setup, all module commands and modulefile evaluations directly asked by users will be recorded into the log system. Automatically triggered evaluations will not be recorded.

Usage example

Listing available modulefiles, then loading a bare modulefile (that sends itself a message to logs), then another one with a dependency and purging everything in the end:

$ cat /path/to/modulefiles/foo/1.0
#%Module
puts log {some message sent to log}
$ ml av
--------------- /path/to/modulefiles ---------------
bar/1.0  foo/1.0  qux/1.0
$ ml foo/1.0
$ module load bar
Loading bar/1.0
  Loading requirement: qux/1.0
$ module purge

Log entries can then be retrieved from system log files:

$ journalctl -q -t modules
Apr 29 07:47:42 hostname modules[3777797]: user="username" command="avail" arguments=""
Apr 29 07:47:51 hostname modules[3777835]: user="username" command="ml" arguments="foo/1.0"
Apr 29 07:47:51 hostname modules[3777835]: some message sent to log
Apr 29 07:47:51 hostname modules[3777835]: user="username" mode="load" module="foo/1.0" specified="foo/1.0" modulefile="/path/to/modulefiles/foo/1.0" requested="1"
Apr 29 07:48:10 hostname modules[3777876]: user="username" command="load" arguments="bar"
Apr 29 07:48:10 hostname modules[3777876]: user="username" mode="load" module="bar/1.0" specified="bar" modulefile="/path/to/modulefiles/bar/1.0" requested="1"
Apr 29 07:48:17 hostname modules[3777914]: user="username" command="purge" arguments=""
Apr 29 07:48:17 hostname modules[3777914]: user="username" mode="unload" module="bar/1.0" specified="bar/1.0" modulefile="/path/to/modulefiles/bar/1.0" requested="1"
Apr 29 07:48:17 hostname modules[3777914]: some message sent to log
Apr 29 07:48:17 hostname modules[3777914]: user="username" mode="unload" module="foo/1.0" specified="foo/1.0" modulefile="/path/to/modulefiles/foo/1.0" requested="1"

Implementation on older versions

Logging module commands is implemented by the use of a site-specific configuration that traces every call to a modulefile evaluation.

siteconfig.tcl
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.

siteconfig.tcl
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 to v5.4

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" }