Cloud Pak for DataのJob (Notebook) でログファイルを出力する

Cloud Pak for Data (以下CP4D) の分析プロジェクトで、Notebookから作成したJobを実行した時のログを生成する方法です。

背景として、CP4D v3.0時点ではJob実行ログに任意のログメッセージを含めることができません。（将来機能改善されるはず）
<details><summary>詳細：Job実行ログ</summary><div>

分析プロジェクトのジョブを開き、実行結果であるタイムスタンプ部分をクリックすると、

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/397277/28767d0a-eec4-09af-d3f9-b36b9c71ed14.png)

実行ログが表示されます。しかしこのログはJob (Notebook) を実行したときのPython環境に関するもののみ記録されており、ここに任意のログメッセージを書き込むことができません。（2020/6/11 CP4D v3.0LA時点)
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/397277/a26e54df-3fe5-bbf4-a18e-9eb06f2bf2cd.png)

</div></details>

回避策として、Notebook内からログをファイルに出力し、それを分析プロジェクトのデータ資産 (Data Assets) として登録する方法を作成しました。

# ログファイルを出力するNotebook例
Python標準のLoggerを使って、コンソール(Notebook内のoutput)とログファイルの両方にログを出力します。
ログファイルはproject_libを使って、分析プロジェクトのデータ資産に登録します。
ログ設定に関しては[こちらの記事](https://qiita.com/fltwtn/items/d615f19e338cbfbfd4d6)を参考にさせていただいております。

```python:これはNotebookの先頭に書く
from pytz import timezone
from datetime import datetime

# logger設定
logger = logging.getLogger("mylogger")
logger.setLevel(logging.DEBUG)

# ログフォーマット設定
def customTime(*args):
    return datetime.now(timezone('Asia/Tokyo')).timetuple()
formatter = logging.Formatter(
    fmt='%(asctime)s.%(msecs)-3d %(levelname)s : %(message)s',
    datefmt="%Y-%m-%d %H:%M:%S"
)
formatter.converter = customTime

# コンソールへのログ出力用ハンドラ設定(Notebook内表示用。レベルはDEBUGに指定)
sh = logging.StreamHandler()
sh.setLevel(logging.DEBUG)
sh.setFormatter(formatter)
logger.addHandler(sh)

# ファイルへのログ出力用ハンドラ設定(Job実行用。レベルはINFOに指定。ログファイルはカレントディレクトリに出力し後ほどData Assetに登録する)
logfilename = "mylog_" + datetime.now(timezone('Asia/Tokyo')).strftime('%Y%m%d%H%M%S') + ".log"
fh = logging.FileHandler(logfilename)
fh.setLevel(logging.INFO)
fh.setFormatter(formatter)
logger.addHandler(fh)

# Data Asset登録用ライブラリ
import io
from project_lib import Project
project = Project.access()
```

使い方の例です。

```python
try:
    logger.info('%s', '処理スタート started')
    # やりたい処理をここに書く
    
    # 随時ログメッセージを出力
    logger.debug('%s', 'dummy debug message')
    logger.info('%s', 'dummy info message')
    
    # わざとエラーを発生させる(0除算)
    test = 1/0
    
except Exception as e:
    logger.exception('%s', str(repr(e)))
    # ログファイルのData Assetへの書き出し(エラー発生時)
    with open(logfilename, 'rb') as z:
        data = io.BytesIO(z.read())
        project.save_data(logfilename, data, set_project_asset=True, overwrite=True)

# ログファイルのData Assetへの書き出し(正常終了時)
with open(logfilename, 'rb') as z:
    data = io.BytesIO(z.read())
    project.save_data(logfilename, data, set_project_asset=True, overwrite=True)
```

# 実行結果
Notebook内で実行してみると、以下のようにログがoutputとして得られ、ログファイルがデータ資産に生成されます。

```python:Notebook内で実行時のoutput
2020-06-11 07:43:12.383 INFO : 処理スタート started
2020-06-11 07:43:12.388 INFO : dummy info message
2020-06-11 07:43:12.389 ERROR : ZeroDivisionError('division by zero',)
Traceback (most recent call last):
  File "<ipython-input-7-0b7d7ffe66e9>", line 10, in <module>
    test = 1/0
ZeroDivisionError: division by zero
```

また、Notebookをバージョン保存してJobを作成して、Jobを実行すると、ログファイルがデータ資産に生成されます。

生成されたログファイルはこんな感じです。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/397277/2417cea1-4926-df48-9dc0-b5875fa1c1f8.png)
ダウンロードして中身を確認してみます。ログファイルはレベルをINFOにしたのでDEBUGメッセージは含まれてません。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/397277/dea16cd3-2460-1049-0181-7d3f147f07a3.png)

# ログファイル名に関する考察
データ資産がログファイルで埋まっていくのは、データ資産の本来の用途を考えると気持ちいいものではありません。なので、ログファイルは1つとして常に上書きしていく方法が考えられます。
しかし、CP4DはOpenShift(Kubernates)なので、JobのPython環境はPodとして実行時に生成され終了したら消滅します。なので、1つのファイル名の場合、最新のJob実行分のみがログファイルに記録され、過去履歴は上書きで消えてしまいます。
そのため、上の例ではログファイル名にタイムスタンプを含めて、履歴を残すようにしてみました。
このあたりは、用途に応じて調整していただければ。

以上、データ資産がログで埋まるのはイマイチですが、本来のJobログに任意のログ出力ができるようになるまでは、しばらくこれで凌ぐしか無いです。他には、DBテーブルにログを記録していくという方法も考えられます。