ssh 呼び出しのバッチが動かないトラブルを調べた話【vol.1.5】

[ssh 呼び出しのバッチが動かないトラブルを調べた話【vol.1】](https://qiita.com/terra_yucco/items/b688bb613184ab89d34e) の中で書いた `remoteexe` スクリプトをちょっと改良したいのですが、思うようにうまくいかないので、ヘルプを求めつつ記事にしてみる。

# TL;DR

- ssh でリモートプロセスを呼び出します
- リモートプロセスはだらだらと stdout　にナニカを垂れ流します
- そのナニカをリアルタイムでタイムスタンプ付きで、呼び出し元側サーバにあるログに保存したいです
- ssh 終了時にはその終了コードをログに保存したいです

# 元コード

再掲です。
<details><summary>クリックで展開する</summary><div>

```bash:remoteexe
#!/bin/bash -u
log_path=/tmp/$( date +'%Y%m%d' )_remoteexe.log

function log()
{
  echo "[$( date +'%Y-%m-%d %H:%M:%S' )][$$] $@" >> ${log_path}
}

parameters="$@"
log "START,-,${parameters}"

function validate()
{
  error_code=10
  if [ $# -lt 2 ]; then
    log "usage: remoteexe target script [parameters]"
    log "e.g.) remoteexe host_sum_batch01 /path/to/starting_sh/sum.sh"
    log "e.g.) remoteexe host_user_batch02 "/path/to/starting_sh/user_log.sh action"
    log "END,${error_code},${parameters}"
    exit ${error_code}
  fi
}

validate $@
host=${1}
shift

command="ssh -i /path/to/key root@${host} ${@}"
log "command,${command}"
output=$( ${command} 2>&1 )
rc=$?

while read line
do
  log "${line}"
done << EOS
${output}
EOS

log "END,${rc},${parameters}"
```

</div>

## 問題点

stdout/stderr を一度変数に落とし `ssh` が終わったタイミングで全部出力しているので、実際に出力された時間とタイムスタンプがズレます。
元の出力に時間を示すものがあればいいのですが、無い場合結構致命的。

## 改善してみようと頑張ったメモ

この部分を

```bash
command="ssh -i /path/to/key root@${host} ${@}"
log "command,${command}"
output=$( ${command} 2>&1 )
rc=$?

while read line
do
  log "${line}"
done << EOS
${output}
EOS
```

こういう風にしてみた。

```bash
command="ssh -i /path/to/key root@${host} ${@}"
log "command,${command}"
${command} 2>&1 | awk -v shpid="$$" '{ print "[" strftime("%Y-%m-%d %H:%M:%S") "][" shpid "] " $0 } { fflush() }' >> ${log_path}
rc=$?
```

### できたこと

出力がリアルタイムに、現在日時と PID 付きでログファイルに append される。

テスト用 sh

```bash:test.sh
#!/bin/bash -u
while [ 1 ]
do
  date
  sleep 5
done
```

```terminal
$ tail -f /tmp/test.log
[2019-06-26 18:05:00][1899] START,-,host_hoge /tmp/test.sh
[2019-06-26 18:05:00][1899] command,ssh -i /path/to/key root@host_hoge /tmp/test.sh
[2019-06-26 18:05:00][1899] Warning: Permanently added 'host_hoge,xxx.xxx.xxx.xxx' (RSA) to the list of known hosts.
[2019-06-26 18:05:00][1899] 2019年  6月 26日 水曜日 18:05:00 JST
[2019-06-26 18:05:05][1899] 2019年  6月 26日 水曜日 18:05:05 JST
[2019-06-26 18:05:10][1899] 2019年  6月 26日 水曜日 18:05:10 JST
[2019-06-26 18:05:15][1899] 2019年  6月 26日 水曜日 18:05:15 JST
[2019-06-26 18:05:20][1899] 2019年  6月 26日 水曜日 18:05:20 JST
[2019-06-26 18:05:25][1899] END,0,host_hoge /tmp/test.sh
```

### できなかったこと

見たらわかるように、テスト用の sh は無限ループなので、動作を確認したあとに kill で落としたのですが、その場合にログされる終了コードが 0 になってしまいました。
(kill は 143 がログされてほしい)

おそらくパイプを噛ませていることで awk の戻り値になっちゃったのかな？

# Conclusion

リアルタイムでリモートプロセスの出力する stdout/stderr をタイムスタンプ付きでログすることはできましたが、終了時に ssh の結果コードをログするのがうまくできていない気がしています。
TL;DR にも書いたように、この要求を両立させる方法、探してます。m(__)m

----
# Appendix

テスト用スクリプトを変更したりしてみたけど、ダメッポイ。

<details><summary>変更トライを見てみる</summary><div>

テスト用 sh

```bash:test.sh
#!/bin/bash -u
i=0
while [ $i -lt 3 ]
do
  date
  i=$(( i + 1 ))
  sleep 5
done

exit 2
```

お手製 remoteexe からの実行

```terminal
$ remoteexe host_hoge /tmp/test.sh
$
$ cat /tmp/test.log
[2019-06-26 20:17:42][4932] START,-,host_hoge/tmp/test.sh
[2019-06-26 20:17:42][4932] command,ssh -i /path/to/key root@host_hoge/tmp/test.sh
[2019-06-26 20:17:42][4932] Warning: Permanently added 'host_hoge,xxx.xxx.xxx.xxx' (RSA) to the list of known hosts.
[2019-06-26 20:17:42][4932] 2019年  6月 26日 水曜日 20:17:42 JST
[2019-06-26 20:17:47][4932] 2019年  6月 26日 水曜日 20:17:47 JST
[2019-06-26 20:17:52][4932] 2019年  6月 26日 水曜日 20:17:52 JST
[2019-06-26 20:17:57][4932] END,0,host_hoge/tmp/test.sh
$
```

ssh からの直実行

```terminal
$ ssh -i /path/to/key root@host_hoge /tmp/test.sh
Warning: Permanently added 'host_hoge,xxx.xxx.xxx.xxx' (RSA) to the list of known hosts.
2019年  6月 26日 水曜日 20:20:18 JST
2019年  6月 26日 水曜日 20:20:23 JST
2019年  6月 26日 水曜日 20:20:28 JST
$ echo $?
2
$
```

</div>