シェルスクリプトのロギングを楽にするtips


# 背景

cronに仕込んだバッチは、echo文でログ・・・　よくある話です。
ちょっとした関数を用意しておけばログは楽に取れるので、私の手法を記録しておきます。
使っている変数のせいで、bash限定。


# log関数をつくる

## コード

たった5行のコード。
使う前に **どこかで`LOGFILE`変数を設定する必要がある。**
ログレベルみたいな便利なシロモノはない。

```bash
#!/bin/bash -
# You must set 'LOGFILE'
readonly PROCNAME=${0##*/}
function log() {
  local fname=${BASH_SOURCE[1]##*/}
  echo -e "$(date '+%Y-%m-%dT%H:%M:%S') ${PROCNAME} (${fname}:${BASH_LINENO[0]}:${FUNCNAME[1]}) $@" | tee -a ${LOGFILE}
}
```

出力フォーマットはただのecho文なので好きに直してください。`-e`オプションも不要かな・・・
`PROCNAME`変数は重複する可能性があるので、必要に応じて変えてください。


## ログのフォーマット

上記実装だとこのように出力される。

```
2015-08-27T18:58:14 libtest.sh (libtest.sh:5:main) message
```

途中の()の中身は、コロン区切りでこんな感じ。

* log関数を呼び出した **スクリプト名**
* log関数を呼び出したスクリプトの **行番号**
* log関数を呼び出した **関数名**

ホスト名は付けていないので、必要なら`${HOSTNAME}`とかを入れると良いんじゃないかと。
大元のプロセス名部分は不要だというなら、`${PROCNAME}`を削ってください。


## 使い方

echoと一緒。

```
log "message"
```


## 単一スクリプトでの実装例

先ほどのlog関数を実装したスクリプトを書いてみる。

### 実装

`LOGFILE`変数は最初に宣言している。
mainの途中に関数実装が挟まる素敵な例。

```bash_log.sh
#!/bin/bash -
readonly LOGFILE="/tmp/${0##*/}.log"

readonly PROCNAME=${0##*/}
function log() {
  local fname=${BASH_SOURCE[1]##*/}
  echo -e "$(date '+%Y-%m-%dT%H:%M:%S') ${PROCNAME} (${fname}:${BASH_LINENO[0]}:${FUNCNAME[1]}) $@" | tee -a ${LOGFILE}
}


#
# MAIN
#

log "This is test message 1"
log "Test 2"
log "Test 3"

function logtest() {
  log "test from logtest function"
}

logtest
```

### 実行

```bash
$ cd /tmp
$ ./bash_log.sh
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:13:main) This is test message 1
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:14:main) Test 2
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:15:main) Test 3
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:18:logtest) test from logtest function

$ cat bash_log.sh.log
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:13:main) This is test message 1
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:14:main) Test 2
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:15:main) Test 3
2015-08-27T15:56:23 bash_log.sh (bash_log.sh:18:logtest) test from logtest function
```

コンソールにも出力し、ログにも記録する。
プロセス名とかスクリプト名が冗長かな・・・

## ライブラリ風の実装例

今度はライブラリのように、`loglib.sh`を作成してみる。

### 実装(ライブラリ)

`LOGFILE`変数は、スクリプト毎に定義できるようにここでは定義していない。

```loglib.sh
#!/bin/bash -
# You must set 'LOGFILE'
readonly PROCNAME=${0##*/}
function log() {
  local fname=${BASH_SOURCE[1]##*/}
  echo -e "$(date '+%Y-%m-%dT%H:%M:%S') ${PROCNAME} (${fname}:${BASH_LINENO[0]}:${FUNCNAME[1]}) $@" | tee -a ${LOGFILE}
}
```

### 実装(スクリプト本体)

作った`loglib.sh`を使う`libtest.sh`を書く。
`LOGFILE`変数は、ライブラリを使う **本体スクリプト側で定義する** 例としている。 

```libtest.sh
#!/bin/bash -
LOGFILE="/tmp/test.log"
. /tmp/loglib.sh

log "test message from main"

function logtest() {
  log "test message from func"
}

logtest

. /tmp/libtest_sub.sh
sub_command
```

最後の2行で呼び出している`lib_test.sh`および`sub_commmand`の実装はこちら。

```libtest_sub.sh
#!/bin/bash -

function sub_command() {
  log "This is sub script"
}
```

うーん。試験用とはいえ、我ながらとんでもない実装だ。


### 実行

```bash
$ ./libtest.sh
2015-08-27T18:58:14 libtest.sh (libtest.sh:5:main) test message from main
2015-08-27T18:58:14 libtest.sh (libtest.sh:8:logtest) test message from func
2015-08-27T18:58:14 libtest.sh (libtest_sub.sh:4:sub_command) This is sub script

$ cat /tmp/test.log
2015-08-27T18:58:14 libtest.sh (libtest.sh:5:main) test message from main
2015-08-27T18:58:14 libtest.sh (libtest.sh:8:logtest) test message from func
2015-08-27T18:58:14 libtest.sh (libtest_sub.sh:4:sub_command) This is sub script
```

よしよし。

どのスクリプトファイルのどの位置から呼ばれたかわかるので、複数人でメンテしているようなバッチに向いている出力になったと思う。