Q&A
Javaバージョン、Tomcatバージョンはいくつでしょう？また、それらは本番とテスト用のサーバで完全に同一ですか？また、logging.propertiesも同一ですか？
###前提・実現したいこと
前提：
CentOSで、サーバー側プログラムをJAVAで、数百本作り、iPhone端末と通信をするシステムです。
実現したいこと：
catalina.outに、JAVAの中に記述した「System.out.println("あいうえお");」を出力したいのです。
###発生している問題・エラーメッセージ
発生している問題：
・１年近く、開発時期及び、運用時期があり、その間は、System.out.println()で、大量に毎日ログの出力ができていました。
・それが、約３ヵ月前から、常に、catalina.outが、0バイトのままの状態です。
・Javaプログラム、MySQL、他のサーバー機能（WEBサービス、通信、sendmail、ファイヤーウォール．．．）は、正常動作しており、サーバーの運用を継続できている。
エラーメッセージ：
各所のログを見ましたが、「catalina.outにログ出力失敗」のようなエラーを見つけれていません。
エラーメッセージがどこに出力されているのか不明。エラーメッセージが存在するかも不明。
###該当のソースコード
System.out.println("あいうえお");
###試したこと
課題に対してアプローチしたこと：
・catalina.outのパーミッションや、所有者が変わっていないかの確認をしたが、以前のままで正常。
| ⇒ catalina.out 0 KB 2016/06/15 水 3:16:08 rw-rw-r-- tomcat
・サーバーの再起動。 ⇒ ３回行ったが、0バイトのまま。
・ログのローテーションの設定変更。⇒ 結果：ログはローテションするが、当然0バイトのまま。
・/usr/local/log/request_20160616.logには、呼び出されたAPI名や時間等が記述されています。現在も次々と。
・毎日、時間を見つけては、ネットで同じ現象を探したが、解決できていません。
・もう一台、同じ構成のサーバーを立ち上げたが（性能や容量は少ないが）、そちらでは、catalina.outに、JAVAからの出力が書きこまれる。
###補足情報(言語/FW/ツール等のバージョンなど)
より詳細な情報：
サーバープログラム側には、数カ月経っていますが、障害が未だにないので、現在は、catalina.outにログがでていなくても、調査することがないので問題が無いですが、
今後、サーバープログラムをさらに数十本追加する予定なので、万一の障害に備え、今のうちに、JAVAから、catalina.outにログを出力できるよう正常状態に戻したい。
ーーーーーーーーーーーーーーーーーーーー
# ${CATALINA_HOME}/bin/version.sh
Server version: Apache Tomcat/5.5.33
ーーーーーーーーーーーーーーーーーーーー
# java -versio
java version "1.6.0_36
ーーーーーーーーーーーーーーーーーーーー
です。
約１年で、6台のサーバーを立ち上げましたが（サーバー自体のCPU数や容量は違う）、CentOS、Java、Tomcat、他？（ウイルスチェックソフトなど）、同じパッケージをインストールしています。
尚、logging.properties は、検索していますが、未だ見つかっていません。
（ネット上の記述によると、Ver 6 から、存在するようなことが書かれていましたが、継続して、サーバー内をルートから検索処理中です）
そのへんの記載はここよりも質問文に追記してあげてください。
回答1件
0
具体的な回答ではありませんが、いくつか思いついた調査の目処を紹介させていただきます。
1.
| ⇒ catalina.out 0 KB 2016/06/15 水 3:16:08 rw-rw-r-- tomcat
とのことなので、恐らくこの時間に logrotate を実行しているのではないかと推測します。
ファイルのローテーション後、tomcat の再起動に失敗していないか、確認してみてください。
2.
以下が関係しているかもしれません。
http://www.matsuaz.com/matsumotojs/2010/12/24/1293117835413.html
3.
もしくは、サーバ上で
sh
1lsof | grep catalina.out
と実行して、catalina.out を開いているプロセスを確認してみてください。
Tomcatとは別のプロセスがファイルを掴んでしまっているかもしれません。
逆に、どのプロセスも catalina.out を開いていない場合、ロギングの設定にミスのある可能性が考えられます。
4.
また、
sh
1lsof | grep 【tomcatのプロセス名】
と実行して、tomcat が開いているファイルをリストアップしてみてください。
うっかり手動で catalina.out をリネームしてしまった場合、リネーム後のファイルに出力を続けていることがあります。
・サーバーの再起動。 ⇒ ３回行ったが、0バイトのまま。
とのことですので、可能性は低いと思いますが。
投稿2016/06/16 07:37
総合スコア4791
書きこみありがとうございます。お手数をおかけしました。
＞ 1.
＞| ⇒ catalina.out 0 KB 2016/06/15 水 3:16:08 rw-rw-r-- tomcat
＞とのことなので、恐らくこの時間に logrotate を実行しているのではないか。
＞ファイルのローテーション後、tomcat の再起動に失敗していないか。
⇒ ログのローテション後に、自動で、tomcatやサーバーの再起動処理を行っていない状態で、現在も問題なく、HTMLをブラウザから見たり、携帯端末とサーバーAPIの処理は正常に動作していますので、少なくとも、WEB関連やDB、ファイルアクセス、メールなどの、サービスが止まっていることはないです。
ただし、catalina.outへ出力する為のサービスがあるとすれば[不明ですが）、それは動いていない可能性があります。
＞ 2.以下が関係しているかもしれません。
＞http://www.matsuaz.com/matsumotojs/2010/12/24/1293117835413.html
⇒ 確認してみました。
１）Linuxでオープンできるファイル数の確認、
#cat /proc/sys/fs/file-max
1,609,258
⇒ この数が多いのか？少ないのか？の判断が難しいですが、実際に使用しているファイル数。
#cat /proc/sys/fs/file-nr
1280 0 1609258
⇒ かなり余裕と判断。
２）プロセス単位のファイル制限値は、
# ulimit -a
...
open files (-n) 1024
...
⇒ これも、この数が多いのか？少ないのか？の判断が難しいです。
＞ 3.もしくは、サーバ上で
＞ # lsof | grep catalina.out
＞ と実行して、catalina.out を開いているプロセスを確認してみてください。
＞ Tomcatとは別のプロセスがファイルを掴んでしまっているかもしれません。
⇒ 以下の２つの削除済み？ローテーション時に掴んだまま？のファイルがつかんでいるようです。
java 2153 tomcat 1w REG 8,2 484249903 41426936 ～/logs/catalina.out-20160603 (deleted)
java 2153 tomcat 2w REG 8,2 484249903 41426936 ～/logs/catalina.out-20160603 (deleted)
＞ 4.lsof | grep 【tomcatのプロセス名】
＞ と実行して、tomcat が開いているファイルをリストアップしてみてください。
⇒
# lsof | grep tomcat
・・・
～/logs/catalina.out-20160603 (deleted)
～/logs/catalina.out-20160603 (deleted)
～/logs/catalina.2016-06-12.log
・・・
catalinaと付くログファイルやテキストファイルは、上記の３つを開いています。
＞ うっかり手動で catalina.out をリネームしてしまった場合、
＞ リネーム後のファイルに出力を続けていることがあります。
最新のcatalinaとファイル名に入っているログファイルの日時は、「2016/06/16 木 3:11:28 ファイルサイズ0バイト」です。
※3カ月調べてもログが出力されない原因が分からなかったので、昨日昼間に、4:02にローテションする設定に変えたのですが．．．、なぜ？3:11:28？？(と思いましたが、何かのプロセスがこの時間に、このファイルを開いて⇒何も書かず⇒閉じたということですね)
※4:02に設定しても、実際には、4:24頃になるのを他のサーバーから理解しています（cronのログ？にも、4:02に、20min後に実行すると記録されているので。何でしょう？この20分のバッファは．．．）。
というのが、ご指示・ご指摘頂いた確認をした結果です。
⇒ tomcatが、肝心の catalina.out を開いていない。★これが問題のようです。★
従いまして、
tomcatが、肝心の catalina.out を開いて＆掴んで、ログを出力するように調べてみます。
詳細な返信、ありがとうございます。
> ・１年近く、開発時期及び、運用時期があり、その間は、System.out.println()で、大量に毎日ログの出力ができていました。
という状況と矛盾しますが、
> # lsof | grep tomcat
・・・
> ～/logs/catalina.out-20160603 (deleted)
> ～/logs/catalina.out-20160603 (deleted)
> ～/logs/catalina.2016-06-12.log
という結果から、
やはりログファイルのローテーション後に tomcat を再起動していないことが原因と思われます。
私の経験では、ログファイルをローテーションした後に tomcat を再起動してやらないと
新しいログファイルに書き込まれなかったはずです。
もっとも、改めて調べてみたところ以下のページのように再起動を行なわない設定を紹介しているサイトもありますので
tomcat のバージョンや設定によって違いがあるのかもしれません。
http://blog.katty.in/6039
logrotate の設定に
sharedscripts
postrotate
/sbin/service tomcat restart > /dev/null 2>&1 || true
endscript
などを追記して、ローテーション後に tomcat を再起動するようにしてやると、解決するかと思います。
※当然ですが、tomcat を再起動するとサービスにダウンタイムが発生します。
実施してしまって良いかどうかは該当のサービスの要件に従って判断してください。
ご回答ありがとうございます。
今の設定ですが、下記の様になっています。
--------------------------------------
/usr/local/tomcat/logs/catalina.out {
daily
rotate 30
missingok
create 644 tomcat tomcat
copytruncate
sharedscripts
postrotate
/bin/rm -f /usr/local/apache-tomcat-5.5.33/logs/`date --d '91 days ago' '+catalina.out.%Y-%m-%d.log'`
# /usr/bin/killall -HUP httpd
endscript
}
-----------------------------------------
ですので、
下記の様に修正します。
---------------------------------------------
/usr/local/tomcat/logs/catalina.out {
missingok
copytruncate
daily
sharedscripts
rotate 90
create 644 tomcat tomcat
ifempty
# dateext ← 過去のログの後ろに毎日、その日の日付が付く？ので邪魔。
postrotate
/sbin/service httpd reload > /dev/null 2>/dev/null || true
endscript
}
---------------------------------------------
> /sbin/service httpd reload > /dev/null 2>/dev/null || true
これは tomcat ではなく、Apache（httpdサーバ）を再起動しています。
tomcat の再起動コマンドは
/sbin/service tomcat restart
などのはずですが、これはお使いの環境によって異なるので、ご自分の環境で確かめてみてください。
他にも見ただけでは分からない間違いがあるかもしれませんので、サーバ上で
logrotate -dv 【上の設定を書いたファイルのパス】
と実行してみてください。
"-d"オプションはデバッグ実行モードで、実際のローテーションは行なわずにローテーションのシミュレーションのみを行ないます。
設定ファイルの構文エラー等があれば、これで分かります。
# man logrotate
-d, --debug
Turns on debug mode and implies -v. In debug mode, no changes will be made to the logs or to the logrotate state file.
ご指摘ありがとうございます。
「
postrotate
/sbin/service tomcat restart > /dev/null 2>/dev/null || true
endscript
」
に修正しました。 ※tomcatが再起動するように。
# logrotate -dv tomcat
を実行したところ、構文エラーはなく、問題なさそうです（他のサイトで、デバッグに、下記の様になれば、正常とかかれていましたので）。
-------------------------------------------------------------
# logrotate -dv tomcat
reading config file tomcat
reading config info for /usr/local/tomcat/logs/catalina.out
Handling 1 logs
rotating pattern: /usr/local/tomcat/logs/catalina.out after 1 days (30 rotations)
empty log files are rotated, old logs are removed
considering log /usr/local/tomcat/logs/catalina.out
log does not need rotating
not running postrotate script, since no logs were rotated
-------------------------------------------------------------
これで、様子をみてみます。
返信ありがとうございます。
> に修正しました。 ※apachが再起動するように。
「Tomcat が再起動するように」
の誤記でしょうか？
> これで、様子をみてみます。
問題が解決されることを祈っております。
ご指摘ありがとうございます。
誤記でしたので、修正しておきました。
後は、朝になるのを待ちます。
その後ですが、
catalina.out-20160618 0KB 2016/06/18 土 03:45:12 rw-rw-r-- tomcat
catalina.out-20160619 0KB 2016/06/19 日 03:19:09 rw-rw-r-- tomcat
catalina.out-20160620 0KB 2016/06/20 月 04:02:48 rw-rw-r-- tomcat
catalina.out 0KB 2016/06/20 月 04:02:48 rw-rw-r-- tomcat
という状態で、相変わらず、0バイトのままで System.out.println が出力されていない状態です。※ローテーションの時間が、設定通りの04:02に、休み中に代わっているもの気持ち悪いですが（金曜には、確かに、ここで教えて頂いた方法を試したり、設定したりしましたが、土日は、サーバー入っていないので、週次の何かが動いているのかもしれません。）
という相変わらずの状況ですので、継続して、ネットを調べるなり、ここで教えて頂いたことを確認するなりして、以前のようにSystem.out.println に出力されるようにします。
経過のご連絡、ありがとうございます。
> 相変わらず、0バイトのままで System.out.println が出力されていない状態です。
サーバ上で
ps -eo lstart,pid,args | grep 【tomcatのプロセス名】
と実行して、tomcat がいつから起動しているか確認してみてください。
logrotate による再起動が実行されていないはずです。
今さら気づいたのですが、先日の logrotate のデバッグ実行の結果を見ると、
設定ファイルに"ifempty"オプションを指定しているにもかかわらず
log does not need rotating
not running postrotate script, since no logs were rotated
と表示されているからです。
また、"dateext"オプションをコメントアウトしたにもかかわらず依然として
ローテート後のファイルの末尾に"-20160620"が追加されていることも説明がつきません。
恐らく、先日修正したログローテートの設定ファイルとは別の箇所で、ローテーションの設定がなされているのではありませんか？
あなたの回答
tips
プレビュー
