search

l3tnun / EPGStation

Mirakurun を使用した録画管理ソフト
https://twitter.com/l3tnun
MIT License
560 stars 150 forks source link

ログスイッチ後のWebUI応答停止 #268

Closed kizawa2020 closed 5 years ago

kizawa2020 commented 5 years ago

環境

Issue

日付が変わった直後からWebUIが応答しなくなる現象が発生しています。 また、日付をまたぐ番組の録画ファイルが分割されてしまう現象も発生しています。 logs/Service/system.logには以下のメッセージが表示されています。 ※ 当方ではポート80で運用していますが、他ポートに設定した際も同様でした。 ※ ローカルネットワークでIPv6は有効になっています。

[2019-05-06T00:08:29.436] [INFO] system - SocketIo Server has started. [2019-05-06T00:08:29.449] [FATAL] system - uncaughtException: Error: listen EADDRINUSE: address already in use :::80

ログスイッチ後の起動に失敗しているように見受けられます。 対処方法、あるいはpm2-logrotateでのローテーションを停止する方法をご教示いただけないでしょうか。 よろしくお願いします。

l3tnun commented 5 years ago

日付をまたぐ番組の録画ファイルが分割されてしまう現象も発生しています。

これは Operator 側が落ちていそうですね。 logs/Operator/system.log の該当部分のログを貼って頂けると助かります。

[2019-05-06T00:08:29.449] [FATAL] system - uncaughtException: Error: listen EADDRINUSE: address already in use :::80

Service 側が2重に起動してエラーが出ているのかもしれません。 おそらく Operator が落ちたときに Service は一緒に死なずに残り、その後 pm2 によって Operator が再起動したときに Service を起動させるため 2重に起動しているのだと思います。 (EPGStation は録画を司る Operator と、Webサービスを提供する Service の 2つのプロセスに別れて動作しています)

対処方法、あるいはpm2-logrotateでのローテーションを停止する方法をご教示いただけないでしょうか。

原因がはっきりしないので対処法が浮かびません。WebUI の応答を復活させたいのであれば Service 側の node プロセスを殺せば Operator 側で自動で再起動するので、それで対処してください。 プロセス id は ps auwx | grep node | grep Service で調べられると思います。

私の環境では docker を使用して動かしているため pm2-logrotateでのローテーションを停止する方法は分かりません。

kizawa2020 commented 5 years ago

logs/Operator/system.log の該当部分のログを貼って頂けると助かります。

4/30~5/1の番組を録画した際のログを以下に貼ります。

[2019-05-01T00:06:48.436] [INFO] system - ServicesDB created [2019-05-01T00:06:48.457] [INFO] system - ProgramsDB created [2019-05-01T00:06:48.467] [INFO] system - RulesDB created [2019-05-01T00:06:48.470] [INFO] system - RecordedDB created [2019-05-01T00:06:48.473] [INFO] system - EncodedDB created [2019-05-01T00:06:48.479] [INFO] system - RecordedHistoryDB created [2019-05-01T00:06:48.566] [INFO] system - start Updater pid: 19457 [2019-05-01T00:06:51.572] [INFO] system - preprec: 327360102422659 ゆく時代くる 時代~平成最後の日スペシャル~「ついに“時代越し"!」[字] [2019-05-01T00:06:51.590] [WARN] system - TunerAssignmentError programId: 327360102422659, ゆく時代くる時代~平成最後の日スペシャル~「ついに“時代越し"!」[字] [2019-05-01T00:06:52.205] [INFO] system - mirakurun -> services: 130 [2019-05-01T00:06:52.415] [INFO] system - insert Services done [2019-05-01T00:06:53.873] [INFO] system - recording: 327360102422659 ゆく時代く る時代~平成最後の日スペシャル~「ついに“時代越し"!」[字] [2019-05-01T00:06:53.903] [INFO] system - recording stream: /capture/[190430-2325][GR27][ＮＨＫ総合１・東京]ゆく時代くる時代~平成最後の日スペシャル~「ついに“時 代越し”!」字.ts [2019-05-01T00:06:53.964] [INFO] system - add recorded: 327360102422659 ゆく時代くる時代~平成最後の日スペシャル~「ついに“時代越し"!」[字] [2019-05-01T00:07:02.798] [INFO] system - mirakurun -> programs: 25909

WebUI の応答を復活させたいのであれば Service 側の node プロセスを殺せば Operator 側で自動で再起動するので、それで対処してください。

ありがとうございます。Service/ServiceExecutor.js でしょうか。 確認したところ6プロセス起動していました。

kizawa2020 commented 5 years ago

一部認識誤りしており、ログローテーションはpm2-logrotateに依存しておらずoperatorLogConfig.json、serviceLogConfig.json による標準仕様の動作でした。 こちらの動作を止めることはできるでしょうか。

l3tnun commented 5 years ago

ログの提供ありがとうございます。

[2019-05-01T00:06:48.436] [INFO] system - ServicesDB created [2019-05-01T00:06:48.457] [INFO] system - ProgramsDB created [2019-05-01T00:06:48.467] [INFO] system - RulesDB created [2019-05-01T00:06:48.470] [INFO] system - RecordedDB created [2019-05-01T00:06:48.473] [INFO] system - EncodedDB created [2019-05-01T00:06:48.479] [INFO] system - RecordedHistoryDB created

この部分が記録されているということは落ちていますね。 おそらく pm2 によって再起動しているのではないかと思います。

これより前の (4/31 23時以降) のログはありますか？ 何らかのエラーで落ちていると原因がわかるのですが。

Service/ServiceExecutor.js でしょうか。

それです。

確認したところ6プロセス起動していました。

通常1つのプロセスしか起動しないのでそれはおかしいですね。すべて殺してください。

一部認識誤りしており、ログローテーションはpm2-logrotateに依存しておらずoperatorLogConfig.json、serviceLogConfig.json による標準仕様の動作でした。 こちらの動作を止めることはできるでしょうか。

config/operatorLogConfig.json と config/serviceLogConfig.json の設定を変更すればできます。 appenders 下の system, access, stream それぞれの maxLogSize を削除すればログテーションされないはずです。

詳細は log4js-node/docs/file.md を見てください。

kizawa2020 commented 5 years ago

これより前の (4/31 23時以降) のログはありますか？

日付変更直前(23:56以降)のログを貼付しますが、特にエラーの表示はありません。 ※当該番組の録画予約は23:58に手動で行いました。

[2019-04-30T23:56:43.059] [INFO] system - clean recording [2019-04-30T23:56:43.096] [INFO] system - start Updater pid: 18694 [2019-04-30T23:56:44.605] [INFO] system - mirakurun -> services: 130 [2019-04-30T23:56:44.669] [INFO] system - insert Services done [2019-04-30T23:56:47.954] [INFO] system - mirakurun -> programs: 24172 [2019-04-30T23:56:52.899] [INFO] system - insert Programs done. [2019-04-30T23:56:52.911] [INFO] system - mirakurun -> tuners: 4 [2019-04-30T23:56:53.043] [INFO] system - updater done [2019-04-30T23:56:53.047] [INFO] system - start updateAll [2019-04-30T23:56:53.062] [INFO] system - start UpdateManualId: 1556626284226 [2019-04-30T23:56:53.068] [INFO] system - UpdateManualId: 1556626284226 done [2019-04-30T23:56:53.079] [INFO] system - start update rule: 1 [2019-04-30T23:56:53.133] [INFO] system - update rule: 1 done [2019-04-30T23:56:53.144] [INFO] system - start update rule: 2 [2019-04-30T23:56:53.199] [INFO] system - update rule: 2 done [2019-04-30T23:56:53.210] [INFO] system - start update rule: 3 [2019-04-30T23:56:53.278] [INFO] system - update rule: 3 done [2019-04-30T23:56:53.289] [INFO] system - start update rule: 4 [2019-04-30T23:56:53.513] [INFO] system - update rule: 4 done [2019-04-30T23:56:53.525] [INFO] system - start update rule: 5 [2019-04-30T23:56:53.047] [INFO] system - start updateAll [2019-04-30T23:56:53.062] [INFO] system - start UpdateManualId: 1556626284226 [2019-04-30T23:56:53.068] [INFO] system - UpdateManualId: 1556626284226 done [2019-04-30T23:56:53.079] [INFO] system - start update rule: 1 [2019-04-30T23:56:53.133] [INFO] system - update rule: 1 done [2019-04-30T23:56:53.144] [INFO] system - start update rule: 2 [2019-04-30T23:56:53.199] [INFO] system - update rule: 2 done [2019-04-30T23:56:53.210] [INFO] system - start update rule: 3 [2019-04-30T23:56:53.278] [INFO] system - update rule: 3 done [2019-04-30T23:56:53.289] [INFO] system - start update rule: 4 [2019-04-30T23:56:53.513] [INFO] system - update rule: 4 done [2019-04-30T23:56:53.525] [INFO] system - start update rule: 5 [2019-04-30T23:56:44.605] [INFO] system - mirakurun -> services: 130 [2019-04-30T23:56:44.669] [INFO] system - insert Services done [2019-04-30T23:56:47.954] [INFO] system - mirakurun -> programs: 24172 [2019-04-30T23:56:52.899] [INFO] system - insert Programs done. [2019-04-30T23:56:52.911] [INFO] system - mirakurun -> tuners: 4 [2019-04-30T23:56:53.043] [INFO] system - updater done [2019-04-30T23:56:53.047] [INFO] system - start updateAll [2019-04-30T23:56:53.062] [INFO] system - start UpdateManualId: 1556626284226 [2019-04-30T23:56:53.068] [INFO] system - UpdateManualId: 1556626284226 done [2019-04-30T23:56:53.079] [INFO] system - start update rule: 1 [2019-04-30T23:56:53.133] [INFO] system - update rule: 1 done [2019-04-30T23:56:53.144] [INFO] system - start update rule: 2 [2019-04-30T23:56:53.199] [INFO] system - update rule: 2 done [2019-04-30T23:56:53.210] [INFO] system - start update rule: 3 [2019-04-30T23:56:53.278] [INFO] system - update rule: 3 done [2019-04-30T23:56:53.289] [INFO] system - start update rule: 4 [2019-04-30T23:56:53.513] [INFO] system - update rule: 4 done [2019-04-30T23:56:53.525] [INFO] system - start update rule: 5 [2019-04-30T23:56:53.776] [INFO] system - update rule: 5 done [2019-04-30T23:56:53.787] [INFO] system - start update rule: 6 [2019-04-30T23:56:53.856] [INFO] system - update rule: 6 done [2019-04-30T23:56:53.868] [INFO] system - start update rule: 7 [2019-04-30T23:56:53.937] [INFO] system - update rule: 7 done [2019-04-30T23:56:53.948] [INFO] system - start update rule: 8 [2019-04-30T23:56:54.185] [INFO] system - update rule: 8 done [2019-04-30T23:56:54.195] [INFO] system - start update rule: 9 [2019-04-30T23:56:54.258] [INFO] system - update rule: 9 done [2019-04-30T23:56:54.270] [INFO] system - start update rule: 10 [2019-04-30T23:56:54.323] [INFO] system - update rule: 10 done [2019-04-30T23:56:54.325] [INFO] system - done updateAll [2019-04-30T23:58:48.647] [INFO] system - addReserve: 327360102422659 [2019-04-30T23:58:48.653] [INFO] system - success addReserve: 327360102422659 [2019-04-30T23:58:50.945] [INFO] system - preprec: 327360102422659 ゆく時代くる 時代~平成最後の日スペシャル~「ついに“時代越し"!」[字] [2019-04-30T23:58:52.156] [INFO] system - recording: 327360102422659 ゆく時代く る時代~平成最後の日スペシャル~「ついに“時代越し"!」[字] [2019-04-30T23:58:52.158] [INFO] system - recording stream: /capture/[190430-2325][GR27][ＮＨＫ総合１・東京]ゆく時代くる時代~平成最後の日スペシャル~「ついに“時 代越し”!」[字].ts [2019-04-30T23:58:52.170] [INFO] system - add recorded: 327360102422659 ゆく時代くる時代~平成最後の日スペシャル~「ついに“時代越し"!」[字]

appenders 下の system, access, stream それぞれの maxLogSize を削除すればログテーションされないはずです。

ありがとうございます。 本設定変更とプロセス削除で今晩様子を見ます。

kizawa2020 commented 5 years ago

config/operatorLogConfig.json と config/serviceLogConfig.json の設定を変更し、昨日・本日の動作を確認しましたが、あいにくログローテーションは引き続き行われている状態です。

日付をまたぐとWebが停止する現象も解消しておりません。 取り急ぎご報告させて頂きます。

l3tnun commented 5 years ago

config/operatorLogConfig.json と config/serviceLogConfig.json の変更後に EPGStation の再起動は行いましたか？

kizawa2020 commented 5 years ago

はい、念のためOSごと再起動しています。

l3tnun commented 5 years ago

うーん困りましたねえ。ログテーションの停止ではないですが、以下のようにするとログファイルが生成されなくなるはずです。

    "categories": {
        "default": { "appenders": [ "console", "stdout" ], "level": "info" },
        "system": { "appenders": [ "console", "stdout" ], "level": "info" },
        "access": { "appenders": [ "console", "stdout" ], "level": "info" },
        "stream": { "appenders": [ "console", "stdout" ], "level": "info" }
    }

ちなみに、web 停止時の Service/ServiceExecutor.js の node プロセスはいくつ起動していますか？

l3tnun commented 5 years ago

EPGStation を自動起動させるために pm2 を使用していると思いますが、バージョンを教えて下さい。 土日にこちらでも再現するか確認してみます。

kizawa2020 commented 5 years ago

pm2のバージョンは 3.4.0 となります。

ちなみに、web 停止時の Service/ServiceExecutor.js の node プロセスはいくつ起動していますか？

日付変更後のプロセス状態を追いまして、少し状況が掴めました。

①日付変更後（初回アクセス前） 前日から起動していたプロセスと、当日0:03に起動したプロセスの両方が存在していました。

②初回アクセス後 前日から起動していたプロセスが消滅しました。 エラーで停止したものと思います。

③pm2 restart epgstation 実行後 当日0:03に起動していたプロセスが終了し、新たなプロセスが生成されました。

日付変更後、pm2が勝手に？Serviceプロセスを追加していることが原因のように見受けられます。

なお、当方ではzabbixでポート監視を行っていますが ①初回アクセス前の状態では障害状態とならずポートは生きている ②初回アクセス後にポート応答が無くなり障害状態となる ③サービス再起動で復旧 となりますので、この状況とも一致します。

なお不便な状態ではありますが録画予約自体は成功しておりますので、急ぎご対応頂く必要はありません。時間ある際にご確認頂ければ幸いです。 よろしくお願いします。

l3tnun commented 5 years ago

pm2 側で Service プロセスは感知していないはずなので謎ですね。(Operator が勝手に起動させる) Operator が再起動した場合 pm2 の restart のカウントが増えると思いますが、どうなっていますか？

昨日、仮想環境に centos7 を入れ再現するか確認しましたが、pm2 での起動では無く手動での実行したためか再現しませんでした。 本日 pm2 で起動させ再現するか確認します。

kizawa2020 commented 5 years ago

Operator が再起動した場合 pm2 の restart のカウントが増えると思いますが、どうなっていますか？

pm2 listで表示されるrestartedのカウンタと思います。 現状 8 になっておりOS再起動後の加算と考えると毎日増えていそうですが念のため今晩再確認しご連絡します。

l3tnun commented 5 years ago

もしカウンタが増えているようであれば、

  1. 何らかの原因で Operator が死亡 (Serviceは残ったまま)

  2. pm2 による再起動処理で Operator と Service が新たに起動

こんな事が起きてそうですね。

Service 側で Operator の死活監視をして Operator が死んだら Service も死ぬように変更する事は出来そうです。

Operator 側は恐らくログにエラーを吐く間もなく死んでいると思うので、pm2 側のログで0時付近に何か残されていないか確認してもらえると助かります。

kizawa2020 commented 5 years ago

pm2側のログ(epgstation-error.log)に毎日0:03に以下のエラーが発生していることを確認しました。

Error: String '-20190327' could not be parsed as '-yyyy-MM-dd' at extractDateParts (/opt/EPGStation/node_modules/date-format/lib/index.js:114:9) at Function.parse (/opt/EPGStation/node_modules/date-format/lib/index.js:122:10) at RollingFileStream._parseFileName (/opt/EPGStation/nodemodules/streamroller/lib/RollingFileWriteStream.js:201:22) at .compact._.map.n (/opt/EPGStation/node_modules/streamroller/lib/RollingFileWriteStream.js:138:36) at arrayMap (/opt/EPGStation/node_modules/lodash/lodash.js:639:23) at Function.map (/opt/EPGStation/node_modules/lodash/lodash.js:9556:14) at fs.readdir (/opt/EPGStation/node_modules/streamroller/lib/RollingFileWriteStream.js:137:11) at go$readdir$cb (/opt/EPGStation/node_modules/graceful-fs/graceful-fs.js:162:14) at FSReqWrap.args [as oncomplete] (fs.js:140:20)

何故か日付が付与されてしまっているようです。 詳細はまだ追い切れていませんが、ひとまず連携させていただきます。

l3tnun commented 5 years ago

config/operatorLogConfig.json と config/serviceLogConfig.json の pattern を 

"pattern": "-yyyy-MM-dd"

から

"pattern": "-yyyyMMdd"

と変えるとエラーが発生しなくなるかもしれませんね。

log4js の何らかのエラーのようですが、どうしてこのようなエラーが発生するのか分からないですね。 ちなみに私の検証環境では何も問題なく可動しています。

kizawa2020 commented 5 years ago

Operator が再起動した場合 pm2 の restart のカウントが増えると思いますが、どうなっていますか？

予想どおり、日付をまたぐと増えました。 Operatorごと再起動しているようです。

前日 3/26の設定変更内容などを追いかけて改めてご報告します。

kizawa2020 commented 5 years ago

調査に時間かかりすみません。 ひとまず原因が判明し解決しましたのでご報告します。

原因は単純に logs/Operator/system.log-20190327 というファイルが存在していたことでした。 削除したところ解決しました。 なぜこのファイルがあると問題なのかまでは追跡できていませんが、これでしばらく様子見しようと思います。ありがとうございました。

l3tnun commented 5 years ago

解決したようで何よりです