Linuxのマルチプロセスの標準出力でバッティングするのかteeが機能しない時がある

www.itmedia.co.jp

⇧ 職場で復旧できないほどの軋轢が生じていたということでしょうかね...

Linuxのマルチプロセスの標準出力でバッティングするのかteeが機能しない時がある

『あ…ありのまま今　起こった事を話すぜ！』

『な…　何を言ってるのか　わからねーと思うがおれも何をされたのかわからなかった…　頭がどうにかなりそうだった…』

とは、漫画「ジョジョの奇妙な冒険第三部」の登場人物ジャン＝ピエール・ポルナレフの台詞として有名ですが、まさに、そんな状況に遭遇したけど、ネット上でこれといった情報を発見できずのため、問題のあった部分をコメントアウトとして残しておきます。

■/home/ts0818/work/test_progress/test_progress.sh

#!/bin/bash
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
# ■  @title テスト用処理
# ■  @description
# ■    test_progress.sh
# ■    進捗を記録する処理を検証するための処理
# ■  @author ts0818
# ■  @version 1.0 2023-11-23
# ■  @since GNU/Linux 5.15.133.1-microsoft-standard-WSL2 x86_64
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■

# ログファイル
LOG=test_progress.log

# 処理開始日時
START_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
#echo "[${START_DATE_TIME}][start]test_progress.sh" | tee -a ${LOG}
echo "[${START_DATE_TIME}][start]test_progress.sh" >> ${LOG}
#echo "[${START_DATE_TIME}][start]test_progress.sh" 2>&1 | tee -a ${LOG}


# 開始時間
start=0

# 終了時間
end=10

# 終了時間になるまで繰り返し
while [[ "${start}" -le "${end}" ]];
do
  # 1秒スリーブ
  sleep 1
  
  # 開始時間に、1加算（1秒経過を表現）
  start=$(($start+1))
  
  # 経過時間をログファイルに記録
  #echo "passed ${start} seconds." | tee -a ${LOG}
  echo "passed ${start} seconds." >> ${LOG}
  #echo "passed ${start} seconds." 2>&1 | tee -a ${LOG}

done

# 処理終了日時
FINISH_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
#echo "[${FINISH_DATE_TIME}][finished]test_progress.sh" | tee -a ${LOG}
echo "[${FINISH_DATE_TIME}][finished]test_progress.sh" >> ${LOG}
#echo "[${FINISH_DATE_TIME}][finished]test_progress.sh" 2>&1 | tee -a ${LOG}

■/home/ts0818/work/test_progress/test_progress_02.sh

#!/bin/bash
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
# ■  @title テスト用処理
# ■  @description
# ■    test_progress_02.sh
# ■    進捗を記録する処理を検証するための処理
# ■  @author ts0818
# ■  @version 1.0 2023-11-30
# ■  @since GNU/Linux 5.15.133.1-microsoft-standard-WSL2 x86_64
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■

# ログファイル
LOG=test_progress_02.log

# 処理開始日時
START_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
#echo "[${START_DATE_TIME}][start]test_progress_02.sh" | tee -a ${LOG}
echo "[${START_DATE_TIME}][start]test_progress_02.sh" >> ${LOG}

# 開始時間
start=0

# 終了時間
end=10

# 終了時間になるまで繰り返し
while [[ "${start}" -le "${end}" ]];
do
  # 1秒スリーブ
  sleep 1
  
  # 開始時間に、1加算（1秒経過を表現）
  start=$(($start+1))
  
  # 経過時間をログファイルに記録
  #echo "passed ${start} seconds." | tee -a ${LOG}
  echo "passed ${start} seconds." >> ${LOG}

done

# 処理終了日時
FINISH_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
#echo "[${FINISH_DATE_TIME}][finished]test_progress_02.sh" | tee -a ${LOG}
echo "[${FINISH_DATE_TIME}][finished]test_progress_02.sh" >> ${LOG}

■/home/ts0818/work/test_progress/test_progress_03.sh

#!/bin/bash
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
# ■  @title テスト用処理
# ■  @description
# ■    test_progress_03.sh
# ■    進捗を記録する処理を検証するための処理
# ■  @author ts0818
# ■  @version 1.0 2023-11-30
# ■  @since GNU/Linux 5.15.133.1-microsoft-standard-WSL2 x86_64
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■

# ログファイル
LOG=test_progress_03.log

# 処理開始日時
START_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
#echo "[${START_DATE_TIME}][start]test_progress_03.sh" | tee -a ${LOG}
echo "[${START_DATE_TIME}][start]test_progress_03.sh" >> ${LOG}

# 開始時間
start=0

# 終了時間
end=10

# 終了時間になるまで繰り返し
while [[ "${start}" -le "${end}" ]];
do
  # 1秒スリーブ
  sleep 1
  
  # 開始時間に、1加算（1秒経過を表現）
  start=$(($start+1))
  
  # 経過時間をログファイルに記録
  #echo "passed ${start} seconds." | tee -a ${LOG}
  echo "passed ${start} seconds." >> ${LOG}

done

# 処理終了日時
FINISH_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
#echo "[${FINISH_DATE_TIME}][finished]test_progress_03.sh" | tee -a ${LOG}
echo "[${FINISH_DATE_TIME}][finished]test_progress_03.sh" >> ${LOG}

■/home/ts0818/work/test_progress/progress_echo.sh

#!/bin/bash
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
# ■  @title 進捗記録処理
# ■  @description
# ■    progress_echo.sh
# ■    進捗を記録する処理を実行する関数
# ■  @author ts0818
# ■  @version 1.0 2023-11-23
# ■  @since GNU/Linux 5.15.133.1-microsoft-standard-WSL2 x86_64
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■

function progress_echo() {
  target_pid="$1"
  local _processing=""
  # 経過時間用
  local start=0
  # タイムアウト
  local time_out=120
  
  local _LF=$'\n'

  local _LENGTH_LIMIT_ONE_LINE=32
  
  echo 'args ${target_pid}'"${target_pid}"
  
  # 対象の処理のプロセスが終了するまで繰り返し
  while [ -n "${target_pid}" ];
  do
    # プロセスが終了していないか確認
    if [ -n "${target_pid}" ]; then
      target_pid=$(ps -p "${target_pid}" | awk 'NR!=1{print $1}')
    fi
    
    progress="..."
    #echo 'update ${target_pid}'"${target_pid}"

    _processing+="${progress}"
    
#    if [[ "${#_processing}" -eq "${#progress}" ]]; then
#      _processing+="${_processing}${_LF}"
#      printf "${_processing}";
#    fi

    if [[ "${#_processing}" -gt "${_LENGTH_LIMIT_ONE_LINE}" ]]; then
      _processing+="${_processing}${_LF}"
      printf "${_processing}";
      _processing=""
    
    else
      printf "${_processing}";
    
    fi

    sleep 1
    
    # 開始時間に、1加算（1秒経過を表現）
    start=$(($start+1))
    
    # 処理の経過時間が、タイムアウトの時間を超過した場合
    if [ "${start}" -gt "${time_out}" ]; then
      echo "timeout. Finished in the middle of progress_echo.sh"
      繰り返しを抜ける
      break;
    fi

  done

}

■/home/ts0818/work/test_progress/test_main.sh

#!/bin/bash
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
# ■  @title メイン処理
# ■  @description
# ■    test_main.sh
# ■    進捗を記録する処理を実行する
# ■  @author ts0818
# ■  @version 1.0 2023-11-23
# ■  @since GNU/Linux 5.15.133.1-microsoft-standard-WSL2 x86_64
# ■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■

# 外部のシェルスクリプトのファイルを読み込み
source ./progress_echo.sh

readonly LF=$'\n'

# 処理開始日時
START_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "[${START_DATE_TIME}][start]main.sh"

# 進捗を記録するファイル
RESULT_PROGRESS_TXT=result_progress.txt

echo "before start test_progress.sh and progress_echo.sh" | tee -a "${RESULT_PROGRESS_TXT}"

PROCESSING_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "[${PROCESSING_TIME}][start]test_progress.sh" | tee -a "${RESULT_PROGRESS_TXT}"
# 進捗を記録したい処理の開始し、進捗を記録する
bash test_progress.sh | 
  ps axf | grep "test_progress" | grep -v grep | awk '{print $1}' | 
  { read pid; progress_echo "$pid"; } | tee -a "${RESULT_PROGRESS_TXT}"

PROCESSING_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "${LF}[${PROCESSING_TIME}][finished]test_progress.sh" | tee -a "${RESULT_PROGRESS_TXT}"

PROCESSING_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "[${PROCESSING_TIME}][start]test_progress_02.sh" | tee -a "${RESULT_PROGRESS_TXT}"
bash test_progress_02.sh | 
  ps axf | grep "test_progress_02" | grep -v grep | awk '{print $1}' | 
  { read pid; progress_echo "$pid"; } | tee -a "${RESULT_PROGRESS_TXT}"

PROCESSING_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "${LF}[${PROCESSING_TIME}][finished]test_progress_02.sh" | tee -a "${RESULT_PROGRESS_TXT}"

PROCESSING_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "[${PROCESSING_TIME}][start]test_progress_03.sh" | tee -a "${RESULT_PROGRESS_TXT}"
bash test_progress_03.sh | 
  ps axf | grep "test_progress_03" | grep -v grep | awk '{print $1}' | 
  { read pid; progress_echo "$pid"; } | tee -a "${RESULT_PROGRESS_TXT}"

PROCESSING_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "${LF}[${PROCESSING_TIME}][finished]test_progress_03.sh" | tee -a "${RESULT_PROGRESS_TXT}"

echo "after finished test_progress.sh and progress_echo.sh" | tee -a "${RESULT_PROGRESS_TXT}"

# 処理終了日時
FINISH_DATE_TIME=$(date +"%Y-%m-%d %H:%M:%S.%3N")
echo "[${FINISH_DATE_TIME}][finished]main.sh" | tee -a "${RESULT_PROGRESS_TXT}"

⇧ という感じで、灰色にした部分が、ファイルへの書き込みをしてくれなかったという話。マルチプロセスで標準出力がブロッキングされるのか謎なんだけど、ファイル書き込みだけにすると、書き込めたんで、標準出力を同時に利用できないってことなんかね？

仕組みが分からんから、何とも言えん...

ちなみに、

sgyatto.hatenablog.com

ここでのポイント1つ目は、ファイルディスクリプタはプロセスごとに管理しているということです。

パイプの仕組みを図で説明してみる - sgyatto's blog

⇧ ファイルディスクリプタはプロセスごとに独立してるってことかと。

Wikipediaさんの説明を見てみたけど、

Unix系オペレーティングシステムのパイプ(pipe)、もしくはパイプライン (pipeline) とは、複数のプログラムの入出力をつなぐための仕組み（プロセス間通信）の一つである。

パイプ (コンピュータ) - Wikipedia