SPSS Modeler ServerでDBアクセスやファイルアクセスのログを収集する

SPSS Modeler ServerでユーザーがどのDBにアクセスしたか、どのファイルにアクセスしたかのログを収集することができます。

1. 設定

Modeler Serverのログファイルの設定はlog4cxx.propertiesというファイルで行います。このファイルは、UNIXの場合は、インストール ディレクトリの configフォルダにあり、Windowsの場合は、C:\ProgramData\IBM\SPSS\Modeler Server<バージョン>\configフォルダにあります。

v18.2.2のWindows版の例：
C:\Program Files\IBM\SPSS\ModelerServer\18.2.2\config\log4cxx.properties

以下のLoggerのlevelをWARNからINFOに設定します。
・ファイルアクセス
log4j.logger.SDLDataFile
・DBアクセスとSQL
log4j.logger.SDLSqlConnection
log4j.logger.SQL.ODBC
log4j.logger.SQL.Native

# Set to INFO to log user file access and errors
log4j.logger.SDLDataFile=INFO

-------　中略　-------

# Set to INFO to log database access and errors
log4j.logger.SDLSqlConnection=INFO

# Set to INFO to log SQL as it is executed (ODBC syntax)
log4j.logger.SQL.ODBC=INFO

# Set to INFO to log SQL as it is executed (Native syntax)
log4j.logger.SQL.Native=INFO

なお、内部的に出力する一時ファイルのアクセスも記録したい場合にはlog4j.logger.SDLDataFile.TempFileのLoggerもINFOに設定します。
設定を行ったら、Modeler Serverを再起動します。

Modeler Serverは、処理の記録をserver_logging.logというログファイルに保持します。このファイルは、UNIXの場合は、インストール ディレクトリの logフォルダにあり、Windowsの場合は、C:\ProgramData\IBM\SPSS\Modeler Server<バージョン>\log フォルダにあります。

v18.2.2のWindows版の例：
C:\ProgramData\IBM\SPSS\Modeler Server\18.2.2\log\server_logging.log

2. ファイルアクセスのログ

以下のストリームを例にします。
DRUG1nというCSVファイルを読んで、集計結果をdruqcount.csvというCSVファイルを出力しています。

以下は上を実行した時のserver_logging.logからの抜粋になります。
Modelerのストリームを実行するとセッションが始まります。以下で192.168.0.190のIPアドレスからユーザーdatascientist1がセッションを始めています。セッション番号852になります。各行のタイムスタンプの後にもこのセッション番号が記録されます。

2021-01-24 22:34:08,497      852 0x000011f0 INFO  SDLSession   AEQMC0007I: Session 852 (datascientist1@::ffff:192.168.0.190.:57049) started
2021-01-24 22:34:08,497      852 0x000011f0 INFO  SDLSession   AEQMC0123I: User name: datascientist1

CSVファイルのインプットファイルやエクスポートファイルは以下のようにOpenしてCloseしています。ReadかWriteかは判別できません。

2021-01-24 22:34:23,575      852 0x000011f0 INFO  SDLDataFile  AEQMC0096I: Attempting to open/create file C:\Program Files\IBM\SPSS\ModelerServer\18.2.2\Demos\japanese_ja\DRUG1n
2021-01-24 22:34:23,575      852 0x000011f0 INFO  SDLDataFile  AEQMC0097I: File 2 (C:\Program Files\IBM\SPSS\ModelerServer\18.2.2\Demos\japanese_ja\DRUG1n) opened
2021-01-24 22:34:24,606      852 0x000011f0 INFO  SDLDataFile  AEQMC0096I: Attempting to open/create file E:\dataset\druqcount.csv
2021-01-24 22:34:24,606      852 0x000011f0 INFO  SDLDataFile  AEQMC0097I: File 3 (E:\dataset\druqcount.csv) opened
2021-01-24 22:34:28,028      852 0x000011f0 INFO  SDLDataFile  AEQMC0095I: File 2 closed
2021-01-24 22:34:28,028      852 0x000011f0 INFO  SDLDataFile  AEQMC0095I: File 3 closed

セッションが終わると以下を書き出します。

2021-01-24 22:34:36,997      852 0x000011f0 INFO  SDLSession   AEQMC0032I: Session 852 ended

ここではわかりやすくするためにストリーム実行に関係あるものだけを抜粋しましたが、実際には他のユーザーや別セッションの処理も書き出されますので、セッション番号（上の例だと852）で絞り込んで調べることになります。
また、上記以外にもファイルの存在確認やデータ型のチェックのためなどにもFile Openなどが行われそのログも記録されます。

3. DBアクセスのログ

以下のストリームを例にします。
DB2ADMIN.EMPLOYEEというテーブルを読んで、集計結果をDEPTCOUNTというテーブルに出力しています。

以下は上を実行した時のserver_logging.logからの抜粋になります。
Modelerのストリームを実行するとセッションが始まります。以下で192.168.0.190のIPアドレスからユーザーdatascientist1がセッションを始めています。セッション番号7160になります。各行のタイムスタンプの後にもこのセッション番号が記録されます。

2021-01-24 22:34:38,825     7160 0x00002264 INFO  SDLSession   AEQMC0007I: Session 7160 (datascientist1@::ffff:192.168.0.190.:57063) started
2021-01-24 22:34:38,825     7160 0x00002264 INFO  SDLSession   AEQMC0123I: User name: datascientist1

次にDBへの接続が行われています。db2sampleというデータソースに対して、DBユーザーdb2adminで接続しています。パスワードはマスキングされます。

2021-01-24 22:34:51,075     7160 0x00002264 INFO  SDLSqlConnection AEQMC0040I: Attempting connection to ODBC datasource db2sample;UID=db2admin;PWD=*****
2021-01-24 22:34:51,075     7160 0x00002264 INFO  SDLSqlConnection AEQMC0041I: Database connection 1 (db2sample;UID=db2admin;PWD=*****) opened
2021-01-24 22:34:52,200     7160 0x00002264 INFO  SDLSqlConnection AEQMC0098I: Connected to datasource, retrieved SQL_DBMS_NAME=DB2/NT64

次にCREATE TABLEが実行され、そしてDB2ADMIN.EMPLOYEEから読んでDEPTCOUNTに書き込むINSERTのSQL文が実行されています。
ODBC SQLとNative SQLで同じ処理がそれぞれ記録されていますが、実行は1回だけ行われています。

2021-01-24 22:35:06,059     7160 0x00001bcc INFO  SQL.ODBC     AEQMC0042I: ODBC SQL: CREATE TABLE DEPTCOUNT  ( WORKDEPT VARCHAR(255),"Record_Count" BIGINT ) 
2021-01-24 22:35:06,059     7160 0x00001bcc INFO  SQL.Native   AEQMC0043I: Native SQL: CREATE TABLE DEPTCOUNT  ( WORKDEPT VARCHAR(255),"Record_Count" BIGINT )
2021-01-24 22:35:07,012     7160 0x000012e4 INFO  SQL.ODBC     AEQMC0042I: ODBC SQL: INSERT INTO DEPTCOUNT (WORKDEPT,"Record_Count") SELECT T0.WORKDEPT AS C0,COUNT(*) AS C1 FROM DB2ADMIN.EMPLOYEE T0 GROUP BY T0.WORKDEPT
2021-01-24 22:35:07,012     7160 0x000012e4 INFO  SQL.Native   AEQMC0043I: Native SQL: INSERT INTO DEPTCOUNT (WORKDEPT,"Record_Count") SELECT T0.WORKDEPT AS C0,COUNT(*) AS C1 FROM DB2ADMIN.EMPLOYEE T0 GROUP BY T0.WORKDEPT

セッションが終わるとDB接続をクローズし、終了します。

2021-01-24 22:35:16,184     7160 0x00002264 INFO  SDLSqlConnection AEQMC0038I: Database connection 1 closed
2021-01-24 22:35:17,450     7160 0x00002264 INFO  SDLSession   AEQMC0032I: Session 7160 ended

ここではわかりやすくするためにストリーム実行に関係あるものだけを抜粋しましたが、実際には他のユーザーや別セッションの処理も書き出されますので、セッション番号（上の例だと7160）で絞り込んで調べることになります。
また、上記以外にもテーブルの存在確認やデータ型のチェックのためなどにもSQL実行が行われそのログも記録されます。

4. 参考

なお、セッション番号はCloseすると再利用されるので注意ください。ログは毎日切り替えるような運用だと混乱しにくくなるかと思います（参照：参考リンク）。

• SPSS Modelerの調査に必要なログについて

• SPSS Modeler のログ設定 (Undocumented) - Qiita

■テスト環境
Modeler 18.2.2 (たしかModeler 17.0から同じ動きだったと思います。)
Windows Server 2019