trapはshにおける割込み処理関数である．基本は実行時にシェルがシグナルを受けたときに実行する手続きを指定することで行なう．最近というか以前から良くというかハマったことがある．それはロギング時のログファイルの切り替えである．通常，ロギングはsyslogd＋newsyslogで自動的にログファイルをローテートする方法を用いるが，newsyslogは指定された条件になれば実行プログラム側にシグナルを送り，その後しばらく後にログファイルをローテートする．だが，出力するファイルの切換えは実行プログラム側に任されている．したがって，同じファイルにログを出力していると新しいファイルにちゃんと出力されないことになる．とりあえず，newsyslogの環境を整えよう．まず，/etc/syslog.confにファシリティlocal5のレベルinfoで/var/log/test.logに出力することにしよう．
local5.info /var/log/test.log
で，test.logを10KBに達っしたらxzで圧縮してtest.*.xzにローテートしていくことにしよう．
/var/log/test.log 644 3 10 * X /var/run/test.pid 30
この例では3つのファイルにローテートし，ローテートの条件になったら/var/run/test.pidのPIDにシグナル30を送ることになる．ここでは/usr/local/etc/newsyslog.conf.d/test.confにコンフィグファイルを置いているので/etc/newsyslog.confに
<include> /usr/local/etc/newsyslog.conf.d/*
を忘れないように．テストモードなのでnewsyslogを1分間隔で起動しよう．
*/1 * * * * root newsyslog -v
に変更し，syslogdを再起動する．
# service syslogd restart
で，肝心のテストプログラムだが，まず，何もしないで単にログを垂れ流す場合，
#!/bin/sh
doing()
{
local __finish=false
echo -n "$1"
trap "__finish=true" 6
while true; do
if ${__finish}; then
echo -n 'done'
sleep 1
break
else
echo -n '.'
sleep 1
fi
done
tput dl
sleep 1
}
running()
{
case $1 in
start)
shift
doing "$1" &
_doing_proc_id=$!
;;
stop)
kill -6 ${_doing_proc_id}
sleep 1
;;
esac
}
echo $$ > /var/run/test.pid
trap "running stop; kill -9 $$" 2
running start "Exec process"
exec >> /var/log/test.log 2>&1
: $((n = 1))
while true; do
echo "=== Message $n"
if [ $((n % 10)) -eq 0 ]; then
sleep 1
fi
: $((n += 1))
done
running stop
簡単に説明すると，
C-cが押されたらrunningを止めてスクリプトを停止するtrapをかける
ちなみに running は何も出力されないのは寂しいので 1 秒おきに. を出力するだけの暇潰し関数 doing を制 御する関数です．running start "なんたら"で，"なんたら" を 出力してdoingをスタート，running stop で doing を停止します．この停止はシグナル 6 (ABORT) でやって ます．
テストメッセージを垂れ流す
"=== Message 番号" を出力し続けるが，10 秒おきに sleep を入れている．これがないと newsyslog がローテートチェック する時間間隔(1分)までに 10KB を遥かに超える出力をしてしまう;-(
とりあえず実行
# sh ./logrotate_bad0.sh
Exec \
process.........................................................................................................ユーザーシグナル1 \
# .....
# ............
# .........................
#
newsyslogからはちゃんとシグナル30が送られていることがわかるが，更新されたログファイルにはロギングされてないことがわかる．
# ll -h /var/log/test.log*
-rw-r--r-- 1 root wheel 75B 5月 15 23:34 /var/log/test.log
-rw-r--r-- 1 root wheel 696B 5月 15 23:34 /var/log/test.log.0.xz
# cat /var/log/test.log
May 15 23:34:00 kazu newsyslog[21662]: logfile turned over due to \
size>10K
#
なお，C-cで終了しなが，これはシグナル30が送られた時点で実行スクリプト自体が落ちてしまい，doingがゾンビプロセスになったからだ．とりあえず手動で止める．
# ps -ax|grep bad0 21723 7 S+ 0:00.00 grep bad0 21432 9 S 0:00.03 sh ./logrotate_bad0.sh # kill -6 21432 #
では次にシグナル30を拾ってログファイルに再書込みするtrapを入れよう．これはexecの前に
trap "exec >> /var/log/test.log 2>&1" 30
を入れれば良い．ではこれで実行してみよう．
# sh ./logrotate_bad1.sh
Exec \
process................................................................................................................................................................................................................................^Cdone強制終了 \
#
おっ今度はうまくいっているようだ．確かにちゃんとログファイルがローテートして入っている．
# ll -h /var/log/test.log* -rw-r--r-- 1 root wheel 3.1k 5月 16 00:11 /var/log/test.log -rw-r--r-- 1 root wheel 508B 5月 16 00:11 /var/log/test.log.0.xz -rw-r--r-- 1 root wheel 568B 5月 16 00:10 /var/log/test.log.1.xz -rw-r--r-- 1 root wheel 476B 5月 16 00:09 /var/log/test.log.2.xz #
ということで，いきなりmake buildworldに挑戦!テストプログラムの垂れ流しメッセージの部分をmake buildworldして流してみよう．
・・・ echo $$ > /var/run/test.pid trap "running stop; kill -9 $$" 2 trap "exec >> /var/log/test.log 2>&1" 30 running start "Exec process" exec >> /var/log/test.log 2>&1 cd /usr/src make buildworld running stop
# sh ./logrotate_bad2.sh
Exec \
process................................................................................................................................................................................................................................^Cdone強制終了 \
# ll -h /var/log/test.log* -rw-r--r-- 1 root wheel 74B 5月 16 00:19 /var/log/test.log -rw-r--r-- 1 root wheel 2k 5月 16 00:19 /var/log/test.log.0.xz #
あれっ？全くローテートしていない．これはmakeなどの処理では複数プロセスが生成され，各々が別々に出力するため，元プロセスのみリダイレクトし直しても新たに生成されたファイルには出力されないとうことだ．言い換えると初めに生成されたファイルのi-nodeと同じファイルに出力すれば問題は解決されることになる．これはnewsyslog自体をそのように書換えないといけないということだ．ということでnewsyslogはあっさり諦めて自前でログローテートスクリプトを作ることにする．いきなりだが，
#!/bin/sh
conv_date_fmt()
{
local __tz __time __sign __hour=0 __min=0 __arg_utc='' \
__date __src_fmt __dest_fmt
case $1 in
-u)
shift
__tz=$1
__time=`env LANG=C date -j -f "%Z" "${__tz}" "+%z"`
__sign=${__time%%[0-9]*}
__time=${__time#${__sign}}
__hour=${__time%[0-9][0-9]}
__min=${__time#[0-9][0-9]}
case ${__sign} in
+)
__sign='-'
;;
-)
__sign='+'
;;
esac
__arg_utc="-v${__sign}${__hour}H -v${__sign}${__min}M"
shift
;;
*)
;;
esac
__date=$1
__src_fmt=$2
__dest_fmt=$3
env LANG=C date ${__arg_utc} -j -f "${__src_fmt}" "${__date}" \
"+${__dest_fmt}"
}
putime()
{
local __time_now __option=$1 __key=$2 __time_start __time_end __time_int \
__sec __min __hr __time_log_file
__key=`echo "$2" | sed -Ee 's/[-.]/_/g'`
__time_now=`env LANG=C date`
case ${__option} in
-a)
conv_date_fmt "${__time_now}" '%a %b %d %T %Z %Y' '%s'
;;
-e)
eval '_time_'${__key}'_end'=`conv_date_fmt "${__time_now}" '%a %b %d %T %Z \
%Y' '%s'`
;;
-i)
eval __time_start='${_time_'${__key}'_start}'
eval __time_end='${_time_'${__key}'_end}'
: $((__time_int = __time_end - __time_start))
: $((__sec = __time_int % 60))
: $((__min = __time_int / 60 % 60))
: $((__hr = __time_int / 60 / 60 % 60))
printf "%02d:%02d:%02d\n" ${__hr} ${__min} ${__sec}
;;
-s)
eval '_time_'${__key}'_start'=`conv_date_fmt "${__time_now}" '%a %b %d %T \
%Z %Y' '%s'`
;;
-S)
case $2 in
${dkgname})
__time_log_file=${DAKEDIR}/+TIME
;;
*)
__time_log_file=${DAKEDIR}/+TIME_`echo ${2}|tr '[:lower:]' '[:upper:]'`
;;
esac
eval echo \"\${_time_${__key}_start} \${_time_${__key}_end} \
$((_time_${__key}_end - _time_${__key}_start))\" > ${__time_log_file}
;;
-T)
__time_int=$2
: $((__sec = __time_int % 60))
: $((__min = __time_int / 60 % 60))
: $((__hr = __time_int / 60 / 60 % 60))
printf "%02d:%02d:%02d\n" ${__hr} ${__min} ${__sec}
;;
*)
conv_date_fmt "${__time_now}" '%a %b %d %T %Z %Y' '%Y.%m.%d %T'
;;
esac
}
doing()
{
local __finish=false __time
echo -n "$1"
trap "__finish=true" 6
__time=1
while true; do
if ${__finish}; then
echo -n 'done'
sleep 1
break
else
echo -n '.'
sleep 1
fi
: $((__time += 1))
if [ $((__time % _log_rotate_interval)) -eq 0 ]; then
logrotate
fi
done
tput dl
sleep 1
}
running()
{
case $1 in
start)
shift
doing "$1" &
_doing_proc_id=$!
;;
stop)
kill -6 ${_doing_proc_id}
sleep 1
;;
esac
}
frotate()
{
local __logfile __logfilename __logfiledir __logfiles __n
__logfilename=`basename ${_logfile}`
__logfiledir=`dirname ${_logfile}`
__logfiles=`ls ${_logfile}.*${_logfile_sufx} 2> /dev/null | sort -r`
if [ -z "${__logfiles}" ]; then
__n=0
else
: $((__n = `echo "${__logfiles}" | wc -l`))
fi
if [ ${__n} -gt 0 -a ${__n} -lt ${_log_rotate_count} ]; then
for __logfile in ${__logfiles}; do
mv ${__logfile} ${__logfiledir}/${__logfilename}.${__n}${_logfile_sufx}
: $((__n -= 1))
done
elif [ ${__n} -eq ${_log_rotate_count} ]; then
__logfiles=`poped __logfiles`
for __logfile in ${__logfiles}; do
: $((__n -= 1))
mv ${__logfile} ${__logfiledir}/${__logfilename}.${__n}${_logfile_sufx}
done
elif [ ${__n} -gt ${_log_rotate_count} ]; then
while [ ${__n} -ge $((_log_rotate_count - 1)) ]; do
rm -f `pop __logfiles`
__logfiles=`poped __logfiles`
: $((__n -= 1))
done
for __logfile in ${__logfiles}; do
mv ${__logfile} ${__logfiledir}/${__logfilename}.${__n}${_logfile_sufx}
: $((__n -= 1))
done
fi
}
logrotate()
{
local __logfile __logtmpdir='/var/tmp' __logfilename __logfdir \
__install_options="-m ${_logfile_mode}"
__logfilename=`basename ${_logfile}`
__logdir=`dirname ${_logfile}`
if [ ! -f ${_logfile} ]; then
touch ${_logfile}
chmod ${_logfile_mode} ${_logfile}
if [ -n "${_logfile_owner}" ]; then
chown ${_logfile_owner} ${_logfile}
fi
(cd ${__logdir}; pax -r -w -l ${__logfilename} ${__logtmpdir})
else
if [ -n "${_logfile_owner}" ]; then
__install_options="${__install_options} -o ${_logfile_owner%%:*} -g \
${_logfile_owner##*:}"
fi
__logfilesize=`du -k ${_logfile} | awk '{print $1}'`
if [ ${__logfilesize} -gt ${_log_rotate_size} ]; then
install ${__install_options} ${__logtmpdir}/${__logfilename} ${_logfile}.0
printf "%-20s%12s[%d]: logfile turned over due to size>%dK\n" "`putime`" \
${dkgname} $$ ${_log_rotate_size} > ${__logtmpdir}/${__logfilename}
frotate
${_logcommpresscmd} ${_logfile}.0
fi
fi
}
get_loginfo()
{
local __mode __flags
while [ $# -gt 0 ] ; do
case $1 in
-s)
__mode=suffix
;;
-c)
__mode=ccommand
;;
*)
break
;;
esac
shift
done
__flags=$*
case ${__mode} in
suffix)
case ${__flags} in
*X*)
echo '.xz'
;;
*J*)
echo '.bz2'
;;
esac
;;
ccommand)
case ${__flags} in
*X*)
echo 'xz -z'
;;
*J*)
echo 'bzip2 -z'
;;
esac
;;
esac
}
dkgname='foo-1.0'
_log_rotate="\
# logfilename [owner:group] mode count size when flags interval
/var/log/test.log 644 7 10 \* X 1"
set -- `echo "${_log_rotate}" | egrep -e '^/'`
case $# in
8)
_logfile=$1
_logfile_owner=$2
_logfile_mode=$3
: $((_log_rotate_count = $4))
: $((_log_rotate_size = $5))
_log_rotate_when=$6
_logfile_sufx=`get_loginfo -s $7`
_logcommpresscmd=`get_loginfo -c $7`
: $((_log_rotate_interval = $8 * 60))
;;
7)
_logfile=$1
_logfile_mode=$2
: $((_log_rotate_count = $3))
: $((_log_rotate_size = $4))
_log_rotate_when=$5
_logfile_sufx=`get_loginfo -s $6`
_logcommpresscmd=`get_loginfo -c $6`
: $((_log_rotate_interval = $7 * 60))
;;
*)
error initialize "wrong logrotate specifiation"
;;
esac
echo $$ > /var/run/test.pid
trap "running stop; kill -9 $$" 2
logrotate
running start "Exec process"
exec >> /var/log/test.log 2>&1
cd /usr/src
make buildworld
簡単に説明すると，
ログローテートの条件を_log_rotateで定義する
グローバル変数_log_rotate に基本的に newsyslog.conf と同じ仕様で記述．ただし最後のフィールド (interval)にはログファイルをチェックする間隔を分単位で指 定
ロギング環境を設定する
logrotate は最初に呼出されたときにログファイルを指定さ れたオーナーとモードで生成する
running start "Exec process"
doing の中で _log_rotate_interval 毎に logrotate を起動．このときログファイルが _log_rotate_size を超えたら
それでは実行してみよう．ただし，syslog.conf，newsyslog.confおよびcrontabを元に戻しておくように．確かに
# ll -h /var/log/test.log* -rw-r--r-- 2 root wheel 60k 5月 16 02:23 /var/log/test.log -rw-r--r-- 1 root wheel 980B 5月 16 02:22 /var/log/test.log.0.xz -rw-r--r-- 1 root wheel 1.1k 5月 16 02:21 /var/log/test.log.1.xz -rw-r--r-- 1 root wheel 556B 5月 16 02:19 /var/log/test.log.2.xz -rw-r--r-- 1 root wheel 1k 5月 16 02:16 /var/log/test.log.3.xz -rw-r--r-- 1 root wheel 1.0k 5月 16 02:14 /var/log/test.log.4.xz -rw-r--r-- 1 root wheel 1k 5月 16 02:13 /var/log/test.log.5.xz -rw-r--r-- 1 root wheel 1.9k 5月 16 02:12 /var/log/test.log.6.xz #
ちゃんとローテートしている．メデタシメデタシ．