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

TL;DR

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

元コード

再掲です。

クリックで展開する

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

問題点

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

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

この部分を

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

こういう風にしてみた。

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

test.sh

#!/bin/bash -u
while [ 1 ]
do
  date
  sleep 5
done

$ 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

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

変更トライを見てみる