録画の強制終了について

totemoyoi commented 3 years ago

機能提案ですので省略いたします。

環境

Version of EPGStation: x.x.x
Version of Mirakurun: x.x.x
Version of Node: x.x.x
Version of NPM: x.x.x
OS:
Architecture: x64

Issue

ありがとうございます。いつも便利に使わせていただいております。録画終了してファイルが作成されていても、何故か「録画中」に番組が残っていることが時々あります。また、長時間番組で保存したい部分はすでに放送済みなので途中で手動で録画をストップしたい場合もございます。録画中の番組を選択し、強制録画終了させるようにはできないでしょうか？「delete」を選択したら録画済みのファイルも消えてしまうため、途中で録画を終了させたい場合に困っております。

hikuma3 commented 3 years ago

ルールは、有効なもの12、無効にしてあるもの5です。

予約件数は、48,71,25,99,1,5,4,4,41,0,7,2です。「予約数があまりに多い」とは、何件ぐらいの数量でしょうか？

l3tnun commented 3 years ago

連絡ありがとうございます。予約数が1000,2000件くらいを想定していましたが、そこまで多くないですね。何かバグがありそうですので調べてみます。

hikuma3 commented 3 years ago

気がついたことがあります。・手動録画で、フィードバックまで数秒かかる。・数秒かかった上に、エラーで予約できない時もある。・エラーが起きたにもかかわらず、予約がされてしまうこともたまにある。という状況は、以前からあり、不思議に思っていました。

私のルールの特徴としては、・タイトルで正規表現を使う。・除外ワードもタイトルに対する正規表現で指示している・正規表現は少し長め(1つのルールで、10〜15位のキーワード指定：例ガンダム|ジョジョ|ソードアート ... ) というところです。

ご参考になれば。

l3tnun commented 3 years ago

手動予約でフィードバックが返ってこない、帰ってくるまでに時間がかかるのはおかしいですね。手動予約で指定された番組の放映時間と重複する予約を取り出して競合しないかチェックしているだけですので、通常であれば1秒とかからないです。

DB の読み書きが異常に遅いのかもしれません。なにか調べる方法があればハッキリするのですが… 予約が一切ない時刻帯で予約しても同様の現象だったりするのでしょうか?

・エラーが起きたにもかかわらず、予約がされてしまうこともたまにある。

こちらは Service が Operator から応答が受け取れずタイムアウトになった事が原因ですかね。処理をキャンセルする手立てがないため、タイムアウト後も処理が走り続け予約に至ったと思われます。

hikuma3 commented 3 years ago

毎回じゃないんですよ。機嫌のいい時は、あっという間に処理終了します。今も試してみましたが、１番組録画中で予約/削除は瞬時でした。

hikuma3 commented 2 years ago

本日、Premature closeはなかったのですが、00:06くらいから、get execution error: 1が出続けていました。録画結果を見ると、0:00は3本の録画が終了するタイミングで、2本の録画が始まるタイミングです。

[2021-09-15T00:03:23.749] [INFO] system - recording finish reserveId: 253, recordedId: 59, 0:00終了の１時間番組の録画終了が、3分以上かかって終了しているところも気になります。何か、録画終了が遅いことにより、エラーが発生している可能性はありますか？

[2021-09-14T23:50:38.003] [INFO] system - all reservation update finish [2021-09-14T23:59:45.002] [INFO] system - preprec: 182 [2021-09-14T23:59:45.007] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-14T23:59:45.028] [INFO] system - preprec: 254 [2021-09-14T23:59:45.052] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-14T23:59:45.052] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-14T23:59:45.065] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-15T00:00:00.498] [INFO] system - recording: 254 /app/recordedTemp/古代の宇宙人S11 #133 ダ・ヴィンチ禁断の暗号[二] [202109150000-ヒストリーチャンネル]B.ts [2021-09-15T00:00:00.503] [INFO] system - add recorded 254 /app/recordedTemp/古代の宇宙人S11 #133 ダ・ヴィンチ禁断の暗号[二] [202109150000-ヒストリーチャンネル]B.ts [2021-09-15T00:00:00.523] [INFO] system - recording added reserveId: 254, recordedId: 60 [2021-09-15T00:00:00.523] [INFO] system - create video file: 古代の宇宙人S11 #133 ダ・ヴィンチ禁断の暗号[二] [202109150000-ヒストリーチャンネル]B.ts [2021-09-15T00:00:00.535] [INFO] system - set stream.finished: reserveId: 254 recordedId: 60 [2021-09-15T00:00:00.537] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-15T00:00:00.561] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-15T00:00:00.567] [INFO] system - recording: 182 /app/recordedTemp/鋼の錬金術師 #35 [202109150000-カートゥーン]B.ts [2021-09-15T00:00:00.568] [INFO] system - add recorded 182 /app/recordedTemp/鋼の錬金術師 #35 [202109150000-カートゥーン]B.ts [2021-09-15T00:00:00.576] [INFO] system - recording added reserveId: 182, recordedId: 61 [2021-09-15T00:00:00.576] [INFO] system - create video file: 鋼の錬金術師 #35 [202109150000-カートゥーン]B.ts [2021-09-15T00:00:00.582] [INFO] system - set stream.finished: reserveId: 182 recordedId: 61 [2021-09-15T00:00:00.583] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-15T00:00:00.599] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-15T00:00:01.352] [INFO] system - start recEnd reserveId: 181 recordedId: 58 [2021-09-15T00:00:01.354] [INFO] system - remove recording flag: 58 [2021-09-15T00:00:01.369] [INFO] system - start recEnd reserveId: 252 recordedId: 55 [2021-09-15T00:00:01.369] [INFO] system - remove recording flag: 55 [2021-09-15T00:00:01.374] [INFO] system - start recEnd reserveId: 107 recordedId: 57 [2021-09-15T00:00:01.374] [INFO] system - remove recording flag: 57 [2021-09-15T00:00:01.389] [INFO] system - start recEnd reserveId: 253 recordedId: 59 [2021-09-15T00:00:01.389] [INFO] system - remove recording flag: 59 [2021-09-15T00:00:01.436] [INFO] system - move file: /app/recordedTemp/ヒカルの碁[字] #9,10 [202109142300-キッズステーション]B.ts -> /app/recorded/アニメ/ヒカルの碁[字] #9,10 [202109142300-キッズステーション]B.ts [2021-09-15T00:00:01.468] [INFO] system - move file: /app/recordedTemp/【2時間特番祭り】古代の宇宙人S1 #2 任務[二] [202109142200-ヒストリーチャンネル]B.ts -> /app/recorded/学習/【2時間特番祭り】古代の宇宙人S1 #2 任務[二] [202109142200-ヒストリーチャンネル]B.ts [2021-09-15T00:00:01.468] [INFO] system - move file: /app/recordedTemp/[二]スタートレックディスカバリー2#12 [202109142300-スーパー!ドラマTV]B.ts -> /app/recorded/アメドラ/[二]スタートレックディスカバリー2#12 [202109142300-スーパー!ドラマTV]B.ts [2021-09-15T00:00:01.469] [INFO] system - move file: /app/recordedTemp/アダムの怪しい実験：WWIの戦闘機(二) [202109142300-ディスカバリー]B.ts -> /app/recorded/学習/アダムの怪しい実験：WWIの戦闘機(二) [202109142300-ディスカバリー]B.ts [2021-09-15T00:00:29.601] [INFO] system - all reservation update start [2021-09-15T00:00:29.619] [INFO] system - update reservation: 304 [2021-09-15T00:00:29.634] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-15T00:00:29.645] [INFO] system - successful update reservation: 304 [2021-09-15T00:00:29.658] [INFO] system - update reservation: 305 [2021-09-15T00:00:29.679] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-15T00:00:29.686] [INFO] system - successful update reservation: 305 [2021-09-15T00:00:29.696] [INFO] system - update reservation: 307 [2021-09-15T00:00:29.712] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-15T00:00:29.721] [INFO] system - successful update reservation: 307 [2021-09-15T00:00:29.732] [INFO] system - update rule reservation: 1 [2021-09-15T00:00:29.889] [INFO] system - { insert: 0, update: 4, delete: 0 } [2021-09-15T00:00:29.900] [INFO] system - successful update rule reservation: 1 [2021-09-15T00:00:29.911] [INFO] system - update rule reservation: 2 [2021-09-15T00:00:30.484] [INFO] system - { insert: 0, update: 29, delete: 1 } [2021-09-15T00:00:30.545] [INFO] system - successful update rule reservation: 2 [2021-09-15T00:00:30.546] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-15T00:00:30.548] [INFO] system - recording cancel reserveId: 107, recordedId: 57, isPlanToDelete: false [2021-09-15T00:03:23.659] [INFO] system - update rule reservation: 3 [2021-09-15T00:03:23.700] [INFO] system - delete old file: /app/recordedTemp/アダムの怪しい実験：WWIの戦闘機(二) [202109142300-ディスカバリー]B.ts [2021-09-15T00:03:23.700] [INFO] system - update file size: 59 [2021-09-15T00:03:23.706] [INFO] system - add recorded history: 59 [2021-09-15T00:03:23.748] [INFO] system - emit finish recording reserveId: 253, recordedId: 59, isNeedDeleteReservation: true [2021-09-15T00:03:23.749] [INFO] system - add thumbnail queue: 59 [2021-09-15T00:03:23.749] [INFO] system - recording finish reserveId: 253, recordedId: 59, videoFileFulPath: /app/recorded/学習/アダムの怪しい実験：WWIの戦闘機(二) [202109142300-ディスカバリー]B.ts [2021-09-15T00:03:23.781] [INFO] system - { insert: 0, update: 5, delete: 0 } [2021-09-15T00:03:23.862] [INFO] system - successful update rule reservation: 3 [2021-09-15T00:03:23.862] [INFO] system - update rule reservation: 9 [2021-09-15T00:03:24.044] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-15T00:03:24.045] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-15T00:06:21.461] [ERROR] system - get execution error: 1 [2021-09-15T00:06:21.462] [ERROR] system - Error: GetExecutionTimeoutError at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7) [2021-09-15T00:06:21.530] [INFO] system - { insert: 0, update: 14, delete: 2 } [2021-09-15T00:06:21.531] [INFO] system - delete old file: /app/recordedTemp/ヒカルの碁[字] #9,10 [202109142300-キッズステーション]B.ts [2021-09-15T00:06:21.535] [INFO] system - delete old file: /app/recordedTemp/[二]スタートレックディスカバリー2#12 [202109142300-スーパー!ドラマTV]B.ts [2021-09-15T00:06:21.537] [INFO] system - update file size: 57 [2021-09-15T00:06:21.554] [INFO] system - add recorded history: 57 [2021-09-15T00:06:21.559] [INFO] system - emit finish recording reserveId: 107, recordedId: 57, isNeedDeleteReservation: true [2021-09-15T00:06:21.560] [INFO] system - add thumbnail queue: 57 [2021-09-15T00:06:21.560] [INFO] system - recording finish reserveId: 107, recordedId: 57, videoFileFulPath: /app/recorded/アメドラ/[二]スタートレックディスカバリー2#12 [202109142300-スーパー!ドラマTV]B.ts [2021-09-15T00:06:21.580] [INFO] system - successful update rule reservation: 9 [2021-09-15T00:06:21.581] [INFO] system - update reocrded: 60 [2021-09-15T00:06:21.583] [INFO] system - recording cancel reserveId: 252, recordedId: 55, isPlanToDelete: false [2021-09-15T00:06:21.610] [INFO] system - delete old file: /app/recordedTemp/【2時間特番祭り】古代の宇宙人S1 #2 任務[二] [202109142200-ヒストリーチャンネル]B.ts [2021-09-15T00:06:21.698] [INFO] system - update file size: 58 [2021-09-15T00:06:21.711] [INFO] system - add recorded history: 58 [2021-09-15T00:06:21.727] [INFO] system - emit finish recording reserveId: 181, recordedId: 58, isNeedDeleteReservation: true [2021-09-15T00:06:21.727] [INFO] system - add thumbnail queue: 58 [2021-09-15T00:06:21.727] [INFO] system - recording finish reserveId: 181, recordedId: 58, videoFileFulPath: /app/recorded/アニメ/ヒカルの碁[字] #9,10 [202109142300-キッズステーション]B.ts [2021-09-15T00:06:21.864] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-15T00:06:21.865] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-15T00:06:21.881] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-15T00:06:21.882] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-15T00:06:21.896] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-15T00:06:21.896] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-15T00:06:21.941] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-15T00:06:21.941] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-15T00:06:21.974] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-15T00:06:22.047] [INFO] system - create thumbnail: 59, /app/thumbnail/59.jpg [2021-09-15T00:06:22.411] [INFO] system - update file size: 55 [2021-09-15T00:06:22.437] [INFO] system - add recorded history: 55 [2021-09-15T00:06:22.459] [INFO] system - emit finish recording reserveId: 252, recordedId: 55, isNeedDeleteReservation: true [2021-09-15T00:06:22.460] [INFO] system - add thumbnail queue: 55 [2021-09-15T00:06:22.460] [INFO] system - recording finish reserveId: 252, recordedId: 55, videoFileFulPath: /app/recorded/学習/【2時間特番祭り】古代の宇宙人S1 #2 任務[二] [202109142200-ヒストリーチャンネル]B.ts [2021-09-15T00:06:22.460] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-15T00:06:22.479] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-15T00:06:22.667] [INFO] system - create thumbnail: 57, /app/thumbnail/57.jpg [2021-09-15T00:06:23.206] [INFO] system - create thumbnail: 58, /app/thumbnail/58.jpg [2021-09-15T00:06:23.654] [INFO] system - create thumbnail: 55, /app/thumbnail/55.jpg [2021-09-15T00:07:21.488] [ERROR] system - get execution error: 1 [2021-09-15T00:07:21.493] [ERROR] system - Error: GetExecutionTimeoutError at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7) [2021-09-15T00:07:21.561] [ERROR] system - get execution error: 1 [2021-09-15T00:07:21.728] [ERROR] system - get execution error: 1 [2021-09-15T00:07:22.459] [ERROR] system - get execution error: 1 [2021-09-15T00:08:21.515] [ERROR] system - get execution error: 1 [2021-09-15T00:08:21.521] [ERROR] system - Error: GetExecutionTimeoutError at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7) [2021-09-15T00:09:21.538] [ERROR] system - get execution error: 1 [2021-09-15T00:09:21.543] [ERROR] system - Error: GetExecutionTimeoutError at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7) [2021-09-15T00:10:21.564] [ERROR] system - get execution error: 1 [2021-09-15T00:10:21.567] [ERROR] system - Error: GetExecutionTimeoutError at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7) [2021-09-15T00:10:35.479] [INFO] system - all reservation update start [2021-09-15T00:11:21.584] [ERROR] system - get execution error: 1 [2021-09-15T00:11:21.587] [ERROR] system - Error: GetExecutionTimeoutError at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24)

l3tnun commented 2 years ago

recording finish が遅いことで何かが起きているというよりは、get execution error が出ている事から察するに、その時間帯の DB の読み書きが異常に遅いことが原因で recording finish が遅くなっているのではないでしょうか?

EPG 更新と重なって DB の負荷が高くなっているのかもしれません。 23:30~00:30 ぐらいの logs/EPGUpdater/system.log のログはどうなっているでしょうか? 定期的に更新できていれば問題ないですが(デフォルト10分)、そうでない場合はなにか原因がわかるかもしれません。

hikuma3 commented 2 years ago

●9/14 23:30-

[2021-09-14T23:20:24.172] [INFO] system - delete old programs [2021-09-14T23:30:19.598] [INFO] system - start save service [2021-09-14T23:30:19.601] [INFO] system - { insertValues: 0, updateValues: 31 } [2021-09-14T23:30:19.604] [INFO] system - update db [2021-09-14T23:30:19.717] [INFO] system - update db done [2021-09-14T23:30:19.717] [INFO] system - start save program [2021-09-14T23:30:19.738] [INFO] system - { deleteValues: 0, insertValues: 0, updateValues: 2792 } [2021-09-14T23:30:19.738] [INFO] system - update db [2021-09-14T23:30:23.315] [INFO] system - update db done [2021-09-14T23:30:23.317] [INFO] system - delete old programs [2021-09-14T23:40:19.535] [INFO] system - delete old programs [2021-09-14T23:50:19.576] [INFO] system - start save service [2021-09-14T23:50:19.579] [INFO] system - { insertValues: 0, updateValues: 46 } [2021-09-14T23:50:19.581] [INFO] system - update db [2021-09-14T23:50:19.703] [INFO] system - update db done [2021-09-14T23:50:19.704] [INFO] system - start save program [2021-09-14T23:50:19.750] [INFO] system - { deleteValues: 0, insertValues: 0, updateValues: 9884 } [2021-09-14T23:50:19.750] [INFO] system - update db [2021-09-14T23:50:35.541] [INFO] system - update db done [2021-09-14T23:50:35.544] [INFO] system - delete old programs

●9/15

[2021-09-15T00:00:19.583] [INFO] system - start save service [2021-09-15T00:00:19.585] [INFO] system - { insertValues: 0, updateValues: 50 } [2021-09-15T00:00:19.588] [INFO] system - update db [2021-09-15T00:00:19.725] [INFO] system - update db done [2021-09-15T00:00:19.725] [INFO] system - start save program [2021-09-15T00:00:19.757] [INFO] system - { deleteValues: 0, insertValues: 0, updateValues: 5504 } [2021-09-15T00:00:19.757] [INFO] system - update db [2021-09-15T00:00:29.593] [INFO] system - update db done [2021-09-15T00:00:29.594] [INFO] system - delete old programs [2021-09-15T00:10:19.585] [INFO] system - start save service [2021-09-15T00:10:19.587] [INFO] system - { insertValues: 0, updateValues: 19 } [2021-09-15T00:10:19.590] [INFO] system - update db [2021-09-15T00:10:19.655] [INFO] system - update db done [2021-09-15T00:10:19.655] [INFO] system - start save program [2021-09-15T00:10:19.696] [INFO] system - { deleteValues: 0, insertValues: 0, updateValues: 9086 } [2021-09-15T00:10:19.697] [INFO] system - update db [2021-09-15T00:10:35.458] [INFO] system - update db done [2021-09-15T00:10:35.462] [INFO] system - delete old programs [2021-09-15T00:20:19.538] [INFO] system - delete old programs [2021-09-15T00:30:19.588] [INFO] system - start save service [2021-09-15T00:30:19.591] [INFO] system - { insertValues: 0, updateValues: 99 } [2021-09-15T00:30:19.594] [INFO] system - update db [2021-09-15T00:30:19.831] [INFO] system - update db done [2021-09-15T00:30:19.832] [INFO] system - start save program [2021-09-15T00:30:19.923] [INFO] system - { deleteValues: 0, insertValues: 0, updateValues: 15981 } [2021-09-15T00:30:19.923] [INFO] system - update db [2021-09-15T00:30:47.014] [INFO] system - update db done [2021-09-15T00:30:47.017] [INFO] system - delete old programs [2021-09-15T00:40:19.600] [INFO] system - start save service [2021-09-15T00:40:19.602] [INFO] system - { insertValues: 0, updateValues: 16 } [2021-09-15T00:40:19.604] [INFO] system - update db [2021-09-15T00:40:19.655] [INFO] system - update db done [2021-09-15T00:40:19.656] [INFO] system - start save program [2021-09-15T00:40:19.717] [INFO] system - { deleteValues: 0, insertValues: 0, updateValues: 12821 }

l3tnun commented 2 years ago

特に EPGUpdater は問題ないみたいですね。 Mirakurun への接続と DB の更新共に正常にできてますね。

正直お手上げです

hikuma3 commented 2 years ago

なんだか、get execution errorは出なくなりました。このエラーをご連絡した後は、1から2日に１回くらい出ていたんですが、 6日くらい前に再起動してから、全然でないです。

再起動しかしていないのですが...

hikuma3 commented 2 years ago

現状を少し整理します。

現在使っているのは2.6.11
少なくとも9/13以降、「録画中」に残る現象はおこっていない
少なくとも9/13以降、Premature closeは起きていない。
最後にget execution errorが起こったのは、9/16 11:26 。再起動後、同エラーは起きていない。（このタイミングでは再起動しただけで、設定やルールの変更はしていない）
droplogはoffのままになっている。
（新）ただし、0:00-1:00付近でエラーになる課題は残っている様子。

というところです。あまり変更をしていないので、なぜこの様に変化したのかはわかりませんが、「集中放送などが終了」「帯の番組が終わった」などの原因で録画量が減ったり、平行録画数が減った可能性はあります。

hikuma3 commented 2 years ago

上記6について、現象を報告し、ログを添付します。

358の録画は、0:00-1:00 までの録画ですが、epgstationで00:28ごろ [ERROR] system - Error: aborted が発生しています。この問題が、新たな問題なのか？それとも「epgstationのプログラム変更」や「録画状況の変化」によるものなのかはわかりませんが、このスレッドの問題解決の中で、今までは出ていなかった問題と思われるため、ご報告して起きます。

epgstaionのログでは、他にもいくつか見慣れない気がする問題がある様に見えるのですが、 358は何故かmirakurun側で、エラーではなく、普通に終了している気がします。（ログの見方を、間違っているのかもしれない）

●epgstation

epgstation@2.6.11 start node dist/index.js [2021-09-21T23:59:45.011] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-21T23:59:45.031] [INFO] system - preprec: 375 [2021-09-21T23:59:45.033] [INFO] system - preprec: 358 [2021-09-21T23:59:45.064] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-21T23:59:45.065] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-21T23:59:45.082] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-21T23:59:45.082] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-21T23:59:45.095] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-21T23:59:45.310] [INFO] system - start recEnd reserveId: 329 recordedId: 335 [2021-09-21T23:59:45.312] [INFO] system - remove recording flag: 335 [2021-09-21T23:59:45.367] [INFO] system - move file: /app/recordedTemp/FACTORY ARCHIVES「東京スカパラダイスオーケストラ」 [202109212330-フジテレビNEXT]B.ts -> /app/recorded/音楽Classic/FACTORY ARCHIVES「東京スカパラダイスオーケストラ」 [202109212330-フジテレビNEXT]B.ts [2021-09-22T00:00:00.497] [INFO] system - recording: 357 /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:00:00.501] [INFO] system - add recorded 357 /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:00:00.534] [INFO] system - recording added reserveId: 357, recordedId: 337 [2021-09-22T00:00:00.535] [INFO] system - create video file: 鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:00:00.549] [INFO] system - recording: 375 /app/recordedTemp/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:00:00.549] [INFO] system - add recorded 375 /app/recordedTemp/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:00:00.556] [INFO] system - set stream.finished: reserveId: 357 recordedId: 337 [2021-09-22T00:00:00.558] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:00:00.562] [INFO] system - recording added reserveId: 375, recordedId: 338 [2021-09-22T00:00:00.563] [INFO] system - create video file: 古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:00:00.581] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:00:00.583] [INFO] system - set stream.finished: reserveId: 375 recordedId: 338 [2021-09-22T00:00:00.584] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:00:00.602] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:00:01.350] [INFO] system - start recEnd reserveId: 327 recordedId: 334 [2021-09-22T00:00:01.351] [INFO] system - remove recording flag: 334 [2021-09-22T00:00:01.374] [INFO] system - start recEnd reserveId: 312 recordedId: 333 [2021-09-22T00:00:01.374] [INFO] system - remove recording flag: 333 [2021-09-22T00:00:01.381] [INFO] system - start recEnd reserveId: 334 recordedId: 329 [2021-09-22T00:00:01.381] [INFO] system - remove recording flag: 329 [2021-09-22T00:00:02.085] [INFO] system - move file: /app/recordedTemp/ヒカルの碁[字] #19,20 [202109212300-キッズステーション]B.ts -> /app/recorded/アニメ/ヒカルの碁[字] #19,20 [202109212300-キッズステーション]B.ts [2021-09-22T00:00:02.111] [INFO] system - move file: /app/recordedTemp/[二]スタートレックディスカバリー2#13 [202109212300-スーパー!ドラマTV]B.ts -> /app/recorded/アメドラ/[二]スタートレックディスカバリー2#13 [202109212300-スーパー!ドラマTV]B.ts [2021-09-22T00:00:02.129] [INFO] system - move file: /app/recordedTemp/【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109212200-ヒストリーチャンネル]B.ts -> /app/recorded/学習/【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109212200-ヒストリーチャンネル]B.ts [2021-09-22T00:00:58.860] [INFO] system - recording: 358 /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:00:58.861] [INFO] system - add recorded 358 /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:00:58.873] [INFO] system - recording added reserveId: 358, recordedId: 339 [2021-09-22T00:00:58.873] [INFO] system - create video file: [字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:00:58.882] [INFO] system - delete old file: /app/recordedTemp/FACTORY ARCHIVES「東京スカパラダイスオーケストラ」 [202109212330-フジテレビNEXT]B.ts [2021-09-22T00:00:58.900] [INFO] system - set stream.finished: reserveId: 358 recordedId: 339 [2021-09-22T00:00:58.901] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:06:28.146] [INFO] system - update file size: 335 [2021-09-22T00:06:28.161] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:06:28.167] [INFO] system - add recorded history: 335 [2021-09-22T00:06:28.181] [INFO] system - emit finish recording reserveId: 329, recordedId: 335, isNeedDeleteReservation: true [2021-09-22T00:06:28.184] [INFO] system - add thumbnail queue: 335 [2021-09-22T00:06:28.184] [INFO] system - recording finish reserveId: 329, recordedId: 335, videoFileFulPath: /app/recorded/音楽Classic/FACTORY ARCHIVES「東京スカパラダイスオーケストラ」 [202109212330-フジテレビNEXT]B.ts [2021-09-22T00:06:28.184] [INFO] system - update rule reservation: 8 [2021-09-22T00:06:28.185] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:06:28.189] [INFO] system - delete old file: /app/recordedTemp/【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109212200-ヒストリーチャンネル]B.ts [2021-09-22T00:06:28.190] [INFO] system - delete old file: /app/recordedTemp/ヒカルの碁[字] #19,20 [202109212300-キッズステーション]B.ts [2021-09-22T00:06:28.190] [INFO] system - delete old file: /app/recordedTemp/[二]スタートレックディスカバリー2#13 [202109212300-スーパー!ドラマTV]B.ts [2021-09-22T00:06:28.306] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:06:28.386] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:06:28.391] [INFO] system - update file size: 333 [2021-09-22T00:06:28.407] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:06:28.416] [INFO] system - add recorded history: 333 [2021-09-22T00:06:28.438] [INFO] system - update file size: 334 [2021-09-22T00:06:28.448] [INFO] system - add recorded history: 334 [2021-09-22T00:06:28.449] [INFO] system - emit finish recording reserveId: 312, recordedId: 333, isNeedDeleteReservation: true [2021-09-22T00:06:28.450] [INFO] system - add thumbnail queue: 333 [2021-09-22T00:06:28.450] [INFO] system - recording finish reserveId: 312, recordedId: 333, videoFileFulPath: /app/recorded/アメドラ/[二]スタートレックディスカバリー2#13 [202109212300-スーパー!ドラマTV]B.ts [2021-09-22T00:06:28.450] [INFO] system - update rule reservation: 2 [2021-09-22T00:06:28.450] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:06:28.479] [INFO] system - emit finish recording reserveId: 327, recordedId: 334, isNeedDeleteReservation: true [2021-09-22T00:06:28.480] [INFO] system - add thumbnail queue: 334 [2021-09-22T00:06:28.480] [INFO] system - recording finish reserveId: 327, recordedId: 334, videoFileFulPath: /app/recorded/アニメ/ヒカルの碁[字] #19,20 [202109212300-キッズステーション]B.ts [2021-09-22T00:06:28.492] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:06:28.492] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:06:28.537] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:06:28.678] [INFO] system - create thumbnail: 335, /app/thumbnail/335.jpg [2021-09-22T00:06:29.040] [INFO] system - create thumbnail: 333, /app/thumbnail/333.jpg [2021-09-22T00:06:29.175] [INFO] system - update file size: 329 [2021-09-22T00:06:29.184] [INFO] system - add recorded history: 329 [2021-09-22T00:06:29.195] [INFO] system - emit finish recording reserveId: 334, recordedId: 329, isNeedDeleteReservation: true [2021-09-22T00:06:29.196] [INFO] system - add thumbnail queue: 329 [2021-09-22T00:06:29.196] [INFO] system - recording finish reserveId: 334, recordedId: 329, videoFileFulPath: /app/recorded/学習/【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109212200-ヒストリーチャンネル]B.ts [2021-09-22T00:06:29.196] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:06:29.215] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:06:29.330] [INFO] system - { insert: 0, update: 0, delete: 1 } [2021-09-22T00:06:29.333] [INFO] system - create thumbnail: 334, /app/thumbnail/334.jpg [2021-09-22T00:06:29.346] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:06:29.347] [INFO] system - update rule reservation: 4 [2021-09-22T00:06:29.348] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:06:29.378] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:06:29.681] [INFO] system - { insert: 0, update: 0, delete: 1 } [2021-09-22T00:06:29.692] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:06:29.693] [INFO] system - update rule reservation: 9 [2021-09-22T00:06:29.693] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:06:29.734] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:06:29.945] [INFO] system - { insert: 0, update: 0, delete: 1 } [2021-09-22T00:06:29.959] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:06:29.959] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:06:29.973] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:06:30.205] [INFO] system - create thumbnail: 329, /app/thumbnail/329.jpg [2021-09-22T00:07:45.355] [INFO] system - all reservation update start [2021-09-22T00:07:45.374] [INFO] system - update rule reservation: 1 [2021-09-22T00:07:45.537] [INFO] system - { insert: 0, update: 7, delete: 0 } [2021-09-22T00:07:45.561] [INFO] system - successful update rule reservation: 1 [2021-09-22T00:07:45.575] [INFO] system - update rule reservation: 2 [2021-09-22T00:07:46.111] [INFO] system - { insert: 1, update: 22, delete: 0 } [2021-09-22T00:07:46.174] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:07:46.179] [INFO] system - set timer: 607, 641518821 [2021-09-22T00:07:46.190] [INFO] system - update rule reservation: 3 [2021-09-22T00:07:46.295] [INFO] system - { insert: 4, update: 24, delete: 0 } [2021-09-22T00:07:46.346] [INFO] system - successful update rule reservation: 3 [2021-09-22T00:07:46.347] [INFO] system - set timer: 608, 606118653 [2021-09-22T00:07:46.348] [INFO] system - set timer: 609, 620518652 [2021-09-22T00:07:46.349] [INFO] system - set timer: 610, 627718651 [2021-09-22T00:07:46.349] [INFO] system - set timer: 611, 660118651 [2021-09-22T00:07:46.360] [INFO] system - update rule reservation: 4 [2021-09-22T00:07:46.571] [INFO] system - { insert: 11, update: 83, delete: 0 } [2021-09-22T00:07:46.811] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:07:46.812] [INFO] system - set timer: 612, 604318188 [2021-09-22T00:07:46.812] [INFO] system - set timer: 613, 606118188 [2021-09-22T00:07:46.813] [INFO] system - set timer: 614, 606118187 [2021-09-22T00:07:46.814] [INFO] system - set timer: 615, 606118186 [2021-09-22T00:07:46.814] [INFO] system - set timer: 616, 607918186 [2021-09-22T00:07:46.815] [INFO] system - set timer: 617, 631318185 [2021-09-22T00:07:46.815] [INFO] system - set timer: 618, 649318185 [2021-09-22T00:07:46.816] [INFO] system - set timer: 619, 654718184 [2021-09-22T00:07:46.817] [INFO] system - set timer: 620, 674518183 [2021-09-22T00:07:46.817] [INFO] system - set timer: 621, 676318183 [2021-09-22T00:07:46.818] [INFO] system - set timer: 622, 687118182 [2021-09-22T00:07:46.819] [INFO] system - update reocrded: 337 [2021-09-22T00:07:46.821] [INFO] system - update reocrded: 339 [2021-09-22T00:07:46.825] [INFO] system - update rule reservation: 5 [2021-09-22T00:07:46.913] [INFO] system - { insert: 0, update: 2, delete: 0 } [2021-09-22T00:07:46.922] [INFO] system - successful update rule reservation: 5 [2021-09-22T00:07:46.934] [INFO] system - update rule reservation: 6 [2021-09-22T00:07:47.063] [INFO] system - { insert: 1, update: 4, delete: 0 } [2021-09-22T00:07:47.079] [INFO] system - successful update rule reservation: 6 [2021-09-22T00:07:47.080] [INFO] system - set timer: 623, 654117920 [2021-09-22T00:07:47.091] [INFO] system - update rule reservation: 7 [2021-09-22T00:07:47.216] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:07:47.221] [INFO] system - successful update rule reservation: 7 [2021-09-22T00:07:47.231] [INFO] system - update rule reservation: 8 [2021-09-22T00:07:47.317] [INFO] system - { insert: 1, update: 6, delete: 0 } [2021-09-22T00:07:47.332] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:07:47.333] [INFO] system - set timer: 624, 672717667 [2021-09-22T00:07:47.343] [INFO] system - update rule reservation: 9 [2021-09-22T00:07:47.495] [INFO] system - { insert: 3, update: 34, delete: 0 } [2021-09-22T00:07:47.548] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:07:47.548] [INFO] system - set timer: 625, 604317452 [2021-09-22T00:07:47.549] [INFO] system - set timer: 626, 640317451 [2021-09-22T00:07:47.549] [INFO] system - set timer: 627, 647517451 [2021-09-22T00:07:47.550] [INFO] system - update reocrded: 338 [2021-09-22T00:07:47.560] [INFO] system - update rule reservation: 10 [2021-09-22T00:07:47.693] [INFO] system - { insert: 0, update: 2, delete: 0 } [2021-09-22T00:07:47.702] [INFO] system - successful update rule reservation: 10 [2021-09-22T00:07:47.713] [INFO] system - update rule reservation: 11 [2021-09-22T00:07:47.881] [INFO] system - { insert: 0, update: 2, delete: 0 } [2021-09-22T00:07:47.888] [INFO] system - successful update rule reservation: 11 [2021-09-22T00:07:47.899] [INFO] system - update rule reservation: 12 [2021-09-22T00:07:48.021] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:07:48.024] [INFO] system - successful update rule reservation: 12 [2021-09-22T00:07:48.034] [INFO] system - all reservation update finish [2021-09-22T00:17:24.394] [INFO] system - all reservation update start [2021-09-22T00:17:24.426] [INFO] system - update rule reservation: 1 [2021-09-22T00:17:24.611] [INFO] system - { insert: 6, update: 44, delete: 0 } [2021-09-22T00:17:24.774] [INFO] system - successful update rule reservation: 1 [2021-09-22T00:17:24.782] [INFO] system - set timer: 628, 632540218 [2021-09-22T00:17:24.782] [INFO] system - set timer: 629, 632540218 [2021-09-22T00:17:24.783] [INFO] system - set timer: 630, 634340217 [2021-09-22T00:17:24.784] [INFO] system - set timer: 631, 666740216 [2021-09-22T00:17:24.784] [INFO] system - set timer: 632, 672140216 [2021-09-22T00:17:24.785] [INFO] system - set timer: 633, 673940215 [2021-09-22T00:17:24.794] [INFO] system - update rule reservation: 2 [2021-09-22T00:17:25.366] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:25.368] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:17:25.379] [INFO] system - update rule reservation: 3 [2021-09-22T00:17:25.487] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:25.492] [INFO] system - successful update rule reservation: 3 [2021-09-22T00:17:25.502] [INFO] system - update rule reservation: 4 [2021-09-22T00:17:25.702] [INFO] system - { insert: 0, update: 3, delete: 0 } [2021-09-22T00:17:25.720] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:17:25.732] [INFO] system - update rule reservation: 5 [2021-09-22T00:17:25.825] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:25.827] [INFO] system - successful update rule reservation: 5 [2021-09-22T00:17:25.837] [INFO] system - update rule reservation: 6 [2021-09-22T00:17:25.964] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:25.967] [INFO] system - successful update rule reservation: 6 [2021-09-22T00:17:25.977] [INFO] system - update rule reservation: 7 [2021-09-22T00:17:26.107] [INFO] system - { insert: 0, update: 3, delete: 0 } [2021-09-22T00:17:26.117] [INFO] system - successful update rule reservation: 7 [2021-09-22T00:17:26.129] [INFO] system - update rule reservation: 8 [2021-09-22T00:17:26.215] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:26.216] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:17:26.227] [INFO] system - update rule reservation: 9 [2021-09-22T00:17:26.390] [INFO] system - { insert: 0, update: 2, delete: 0 } [2021-09-22T00:17:26.407] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:17:26.417] [INFO] system - update rule reservation: 10 [2021-09-22T00:17:26.568] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:26.570] [INFO] system - successful update rule reservation: 10 [2021-09-22T00:17:26.580] [INFO] system - update rule reservation: 11 [2021-09-22T00:17:26.755] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:26.758] [INFO] system - successful update rule reservation: 11 [2021-09-22T00:17:26.768] [INFO] system - update rule reservation: 12 [2021-09-22T00:17:26.882] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:17:26.884] [INFO] system - successful update rule reservation: 12 [2021-09-22T00:17:26.894] [INFO] system - all reservation update finish [2021-09-22T00:27:18.842] [INFO] system - all reservation update start [2021-09-22T00:27:18.854] [INFO] system - update rule reservation: 1 [2021-09-22T00:27:19.004] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:19.009] [INFO] system - successful update rule reservation: 1 [2021-09-22T00:27:19.021] [INFO] system - update rule reservation: 2 [2021-09-22T00:27:19.527] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:19.528] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:27:19.539] [INFO] system - update rule reservation: 3 [2021-09-22T00:27:19.644] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:19.646] [INFO] system - successful update rule reservation: 3 [2021-09-22T00:27:19.656] [INFO] system - update rule reservation: 4 [2021-09-22T00:27:19.840] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:27:19.848] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:27:19.860] [INFO] system - update rule reservation: 5 [2021-09-22T00:27:19.942] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:19.945] [INFO] system - successful update rule reservation: 5 [2021-09-22T00:27:19.956] [INFO] system - update rule reservation: 6 [2021-09-22T00:27:20.078] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:20.080] [INFO] system - successful update rule reservation: 6 [2021-09-22T00:27:20.091] [INFO] system - update rule reservation: 7 [2021-09-22T00:27:20.214] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:27:20.222] [INFO] system - successful update rule reservation: 7 [2021-09-22T00:27:20.233] [INFO] system - update rule reservation: 8 [2021-09-22T00:27:20.316] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:20.319] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:27:20.329] [INFO] system - update rule reservation: 9 [2021-09-22T00:27:20.480] [INFO] system - { insert: 0, update: 3, delete: 0 } [2021-09-22T00:27:20.491] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:27:20.502] [INFO] system - update rule reservation: 10 [2021-09-22T00:27:20.637] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:20.639] [INFO] system - successful update rule reservation: 10 [2021-09-22T00:27:20.651] [INFO] system - update rule reservation: 11 [2021-09-22T00:27:20.815] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:20.817] [INFO] system - successful update rule reservation: 11 [2021-09-22T00:27:20.827] [INFO] system - update rule reservation: 12 [2021-09-22T00:27:20.939] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:27:20.941] [INFO] system - successful update rule reservation: 12 [2021-09-22T00:27:20.952] [INFO] system - all reservation update finish [2021-09-22T00:28:20.676] [ERROR] system - stream.finished error: reserveId: 375 recordedId: 338 [2021-09-22T00:28:20.678] [ERROR] system - recording end error reserveId: 375 recordedId: 338 [2021-09-22T00:28:20.679] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:28:20.680] [INFO] system - start recEnd reserveId: 375 recordedId: 338 [2021-09-22T00:28:20.680] [INFO] system - remove recording flag: 338 [2021-09-22T00:28:20.689] [ERROR] system - RecordingStreamCreator stream error: 357 [2021-09-22T00:28:20.689] [ERROR] system - stream.finished error: reserveId: 357 recordedId: 337 [2021-09-22T00:28:20.689] [ERROR] system - recording end error reserveId: 357 recordedId: 337 [2021-09-22T00:28:20.689] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:28:20.690] [INFO] system - start recEnd reserveId: 357 recordedId: 337 [2021-09-22T00:28:20.690] [INFO] system - remove recording flag: 337 [2021-09-22T00:28:20.692] [ERROR] system - RecordingStreamCreator stream error: 381 [2021-09-22T00:28:20.693] [ERROR] system - stream.finished error: reserveId: 381 recordedId: 336 [2021-09-22T00:28:20.693] [ERROR] system - recording end error reserveId: 381 recordedId: 336 [2021-09-22T00:28:20.693] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:28:20.693] [INFO] system - start recEnd reserveId: 381 recordedId: 336 [2021-09-22T00:28:20.693] [INFO] system - remove recording flag: 336 [2021-09-22T00:28:20.728] [INFO] system - move file: /app/recordedTemp/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts -> /app/recorded/アニメ/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:28:20.737] [INFO] system - move file: /app/recordedTemp/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts -> /app/recorded/学習/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:28:20.738] [INFO] system - move file: /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts -> /app/recorded/アニメ/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:28:20.763] [ERROR] system - RecordingStreamCreator stream error: 358 [2021-09-22T00:28:20.764] [ERROR] system - stream.finished error: reserveId: 358 recordedId: 339 [2021-09-22T00:28:20.764] [ERROR] system - recording end error reserveId: 358 recordedId: 339 [2021-09-22T00:28:20.764] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:28:20.765] [INFO] system - start recEnd reserveId: 358 recordedId: 339 [2021-09-22T00:28:20.765] [INFO] system - remove recording flag: 339 [2021-09-22T00:28:20.802] [INFO] system - move file: /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts -> /app/recorded/アニメ/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:28:34.401] [INFO] system - delete old file: /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:28:34.515] [INFO] system - update file size: 337 [2021-09-22T00:28:34.522] [INFO] system - emit finish recording reserveId: 357, recordedId: 337, isNeedDeleteReservation: false [2021-09-22T00:28:34.523] [INFO] system - add thumbnail queue: 337 [2021-09-22T00:28:34.524] [INFO] system - recording finish reserveId: 357, recordedId: 337, videoFileFulPath: /app/recorded/アニメ/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:28:34.525] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:29:26.850] [INFO] system - set timer: 357, 0 [2021-09-22T00:29:26.850] [INFO] system - readd recording: 357 [2021-09-22T00:29:26.854] [INFO] system - preprec: 357 [2021-09-22T00:29:26.874] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:29:26.875] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:29:26.886] [INFO] system - delete old file: /app/recordedTemp/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:29:26.886] [INFO] system - delete old file: /app/recordedTemp/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:29:26.903] [INFO] system - delete old file: /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:29:26.916] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:29:26.917] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:26.980] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.180] [INFO] system - update file size: 338 [2021-09-22T00:29:27.193] [INFO] system - emit finish recording reserveId: 375, recordedId: 338, isNeedDeleteReservation: false [2021-09-22T00:29:27.195] [INFO] system - add thumbnail queue: 338 [2021-09-22T00:29:27.201] [INFO] system - recording finish reserveId: 375, recordedId: 338, videoFileFulPath: /app/recorded/学習/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:29:27.203] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:29:27.237] [INFO] system - set timer: 375, 0 [2021-09-22T00:29:27.238] [INFO] system - readd recording: 375 [2021-09-22T00:29:27.240] [INFO] system - preprec: 375 [2021-09-22T00:29:27.247] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:29:27.255] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:29:27.289] [INFO] system - update file size: 339 [2021-09-22T00:29:27.320] [INFO] system - emit finish recording reserveId: 358, recordedId: 339, isNeedDeleteReservation: false [2021-09-22T00:29:27.320] [INFO] system - add thumbnail queue: 339 [2021-09-22T00:29:27.320] [INFO] system - recording finish reserveId: 358, recordedId: 339, videoFileFulPath: /app/recorded/アニメ/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:29:27.326] [INFO] system - create thumbnail: 337, /app/thumbnail/337.jpg [2021-09-22T00:29:27.332] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:29:27.333] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.361] [INFO] system - set timer: 358, 0 [2021-09-22T00:29:27.361] [INFO] system - readd recording: 358 [2021-09-22T00:29:27.363] [INFO] system - preprec: 358 [2021-09-22T00:29:27.388] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.389] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:29:27.432] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:29:27.433] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:29:27.471] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:29:27.472] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.486] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.523] [INFO] system - update file size: 336 [2021-09-22T00:29:27.532] [INFO] system - emit finish recording reserveId: 381, recordedId: 336, isNeedDeleteReservation: false [2021-09-22T00:29:27.533] [INFO] system - add thumbnail queue: 336 [2021-09-22T00:29:27.533] [INFO] system - recording finish reserveId: 381, recordedId: 336, videoFileFulPath: /app/recorded/アニメ/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:29:27.533] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:29:27.572] [INFO] system - set timer: 381, 0 [2021-09-22T00:29:27.573] [INFO] system - readd recording: 381 [2021-09-22T00:29:27.575] [INFO] system - preprec: 381 [2021-09-22T00:29:27.579] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:29:27.580] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:29:27.605] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:29:27.606] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.631] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:27.664] [INFO] system - create thumbnail: 338, /app/thumbnail/338.jpg [2021-09-22T00:29:27.881] [INFO] system - create thumbnail: 339, /app/thumbnail/339.jpg [2021-09-22T00:29:28.065] [INFO] system - create thumbnail: 336, /app/thumbnail/336.jpg [2021-09-22T00:29:45.003] [INFO] system - preprec: 359 [2021-09-22T00:29:45.004] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.007] [INFO] system - preprec: 360 [2021-09-22T00:29:45.009] [INFO] system - preprec: 361 [2021-09-22T00:29:45.011] [INFO] system - preprec: 362 [2021-09-22T00:29:45.026] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.026] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.039] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.039] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.051] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.052] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.063] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:29:45.371] [INFO] system - recording: 375 /app/recordedTemp/古代の宇宙人S11 #139 巨人の島国[二] [202109220000-ヒストリーチャンネル]B.ts [2021-09-22T00:29:50.376] [ERROR] system - recording failed: 375 [2021-09-22T00:29:50.381] [INFO] system - cancel reservation: 375 [2021-09-22T00:29:50.381] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:29:50.383] [ERROR] system - preprec failed: 375 [2021-09-22T00:29:50.383] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T00:29:50.440] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:29:50.445] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:29:50.451] [INFO] system - successful cancel reservation: 375 [2021-09-22T00:29:55.431] [INFO] system - preprec: 375 [2021-09-22T00:29:57.697] [ERROR] system - preprec failed: 362 [2021-09-22T00:29:57.697] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:00.014] [INFO] system - recording: 357 /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:30:02.722] [INFO] system - preprec: 362 [2021-09-22T00:30:05.017] [ERROR] system - recording failed: 357 [2021-09-22T00:30:05.019] [INFO] system - cancel reservation: 357 [2021-09-22T00:30:05.019] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:05.021] [ERROR] system - preprec failed: 357 [2021-09-22T00:30:05.021] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T00:30:05.042] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:05.046] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:30:05.053] [INFO] system - successful cancel reservation: 357 [2021-09-22T00:30:07.715] [ERROR] system - preprec failed: 375 [2021-09-22T00:30:07.715] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:10.025] [INFO] system - preprec: 357 [2021-09-22T00:30:10.145] [INFO] system - recording: 357 /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:30:12.717] [INFO] system - preprec: 375 [2021-09-22T00:30:15.000] [ERROR] system - preprec failed: 362 [2021-09-22T00:30:15.001] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:15.145] [ERROR] system - recording failed: 357 [2021-09-22T00:30:15.148] [INFO] system - cancel reservation: 357 [2021-09-22T00:30:15.148] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:15.150] [ERROR] system - preprec failed: 357 [2021-09-22T00:30:15.150] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T00:30:15.170] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:15.174] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:30:15.176] [INFO] system - successful cancel reservation: 357 [2021-09-22T00:30:20.006] [INFO] system - preprec: 362 [2021-09-22T00:30:20.151] [INFO] system - preprec: 357 [2021-09-22T00:30:20.276] [INFO] system - recording: 357 /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:30:25.031] [ERROR] system - preprec failed: 375 [2021-09-22T00:30:25.031] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:25.278] [ERROR] system - recording failed: 357 [2021-09-22T00:30:25.281] [INFO] system - cancel reservation: 357 [2021-09-22T00:30:25.281] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:25.283] [ERROR] system - preprec failed: 357 [2021-09-22T00:30:25.283] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T00:30:25.303] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:25.305] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:30:25.306] [INFO] system - successful cancel reservation: 357 [2021-09-22T00:30:30.036] [INFO] system - preprec: 375 [2021-09-22T00:30:30.286] [INFO] system - preprec: 357 [2021-09-22T00:30:30.405] [INFO] system - recording: 357 /app/recordedTemp/鋼の錬金術師 #43 [202109220000-カートゥーン]B.ts [2021-09-22T00:30:32.405] [ERROR] system - preprec failed: 362 [2021-09-22T00:30:32.405] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:35.408] [ERROR] system - recording failed: 357 [2021-09-22T00:30:35.411] [INFO] system - cancel reservation: 357 [2021-09-22T00:30:35.411] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:35.413] [ERROR] system - preprec failed: 357 [2021-09-22T00:30:35.413] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T00:30:35.431] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:35.432] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:35.435] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:30:35.445] [INFO] system - successful cancel reservation: 357 [2021-09-22T00:30:35.446] [INFO] system - cancel reservation: 357 [2021-09-22T00:30:35.448] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:35.451] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:30:35.453] [INFO] system - successful cancel reservation: 357 [2021-09-22T00:30:37.407] [INFO] system - preprec: 362 [2021-09-22T00:30:42.416] [ERROR] system - preprec failed: 375 [2021-09-22T00:30:42.417] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:42.418] [INFO] system - cancel reservation: 375 [2021-09-22T00:30:42.419] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:42.438] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:42.443] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:30:42.444] [INFO] system - successful cancel reservation: 375 [2021-09-22T00:30:49.689] [ERROR] system - preprec failed: 362 [2021-09-22T00:30:49.689] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:30:49.691] [INFO] system - cancel reservation: 362 [2021-09-22T00:30:49.691] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:49.717] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:30:49.720] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T00:30:49.727] [INFO] system - successful cancel reservation: 362 [2021-09-22T00:37:17.764] [INFO] system - all reservation update start [2021-09-22T00:37:17.769] [INFO] system - update rule reservation: 1 [2021-09-22T00:37:17.910] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:17.911] [INFO] system - successful update rule reservation: 1 [2021-09-22T00:37:17.922] [INFO] system - update rule reservation: 2 [2021-09-22T00:37:18.435] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:37:18.441] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:37:18.452] [INFO] system - update rule reservation: 3 [2021-09-22T00:37:18.549] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:18.551] [INFO] system - successful update rule reservation: 3 [2021-09-22T00:37:18.562] [INFO] system - update rule reservation: 4 [2021-09-22T00:37:18.746] [INFO] system - { insert: 0, update: 8, delete: 1 } [2021-09-22T00:37:18.770] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:37:18.770] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:37:18.781] [INFO] system - update rule reservation: 5 [2021-09-22T00:37:18.783] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:37:18.885] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:18.887] [INFO] system - successful update rule reservation: 5 [2021-09-22T00:37:18.898] [INFO] system - update rule reservation: 6 [2021-09-22T00:37:19.023] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:19.025] [INFO] system - successful update rule reservation: 6 [2021-09-22T00:37:19.036] [INFO] system - update rule reservation: 7 [2021-09-22T00:37:19.158] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:19.160] [INFO] system - successful update rule reservation: 7 [2021-09-22T00:37:19.171] [INFO] system - update rule reservation: 8 [2021-09-22T00:37:19.253] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:37:19.259] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:37:19.270] [INFO] system - update rule reservation: 9 [2021-09-22T00:37:19.415] [INFO] system - { insert: 0, update: 5, delete: 0 } [2021-09-22T00:37:19.426] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:37:19.437] [INFO] system - update rule reservation: 10 [2021-09-22T00:37:19.563] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:19.566] [INFO] system - successful update rule reservation: 10 [2021-09-22T00:37:19.577] [INFO] system - update rule reservation: 11 [2021-09-22T00:37:19.738] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:19.740] [INFO] system - successful update rule reservation: 11 [2021-09-22T00:37:19.751] [INFO] system - update rule reservation: 12 [2021-09-22T00:37:19.858] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:37:19.861] [INFO] system - successful update rule reservation: 12 [2021-09-22T00:37:19.872] [INFO] system - all reservation update finish [2021-09-22T00:37:50.811] [INFO] system - recording: 360 /app/recordedTemp/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T00:37:50.812] [INFO] system - add recorded 360 /app/recordedTemp/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T00:37:50.823] [INFO] system - recording added reserveId: 360, recordedId: 340 [2021-09-22T00:37:50.823] [INFO] system - create video file: ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T00:37:50.831] [INFO] system - set stream.finished: reserveId: 360 recordedId: 340 [2021-09-22T00:37:50.831] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:37:50.849] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:37:51.360] [INFO] system - recording: 358 /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:37:51.361] [INFO] system - add recorded 358 /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:37:51.368] [INFO] system - recording added reserveId: 358, recordedId: 341 [2021-09-22T00:37:51.368] [INFO] system - create video file: [字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:37:51.373] [INFO] system - set stream.finished: reserveId: 358 recordedId: 341 [2021-09-22T00:37:51.373] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:37:51.388] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:37:51.477] [INFO] system - recording: 359 /app/recordedTemp/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T00:37:51.477] [INFO] system - add recorded 359 /app/recordedTemp/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T00:37:51.483] [INFO] system - recording added reserveId: 359, recordedId: 342 [2021-09-22T00:37:51.483] [INFO] system - create video file: 鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T00:37:51.492] [INFO] system - set stream.finished: reserveId: 359 recordedId: 342 [2021-09-22T00:37:51.493] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:37:51.509] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:37:51.571] [INFO] system - recording: 361 /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:37:51.572] [INFO] system - add recorded 361 /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:37:51.580] [INFO] system - recording added reserveId: 361, recordedId: 343 [2021-09-22T00:37:51.580] [INFO] system - create video file: 超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:37:51.585] [INFO] system - set stream.finished: reserveId: 361 recordedId: 343 [2021-09-22T00:37:51.586] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:37:51.601] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:37:51.886] [INFO] system - recording: 381 /app/recordedTemp/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:37:51.887] [INFO] system - add recorded 381 /app/recordedTemp/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:37:51.896] [INFO] system - recording added reserveId: 381, recordedId: 344 [2021-09-22T00:37:51.896] [INFO] system - create video file: パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:37:51.906] [INFO] system - set stream.finished: reserveId: 381 recordedId: 344 [2021-09-22T00:37:51.907] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:37:51.922] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:47:45.587] [INFO] system - all reservation update start [2021-09-22T00:47:45.606] [INFO] system - update rule reservation: 1 [2021-09-22T00:47:45.767] [INFO] system - { insert: 0, update: 8, delete: 0 } [2021-09-22T00:47:45.792] [INFO] system - successful update rule reservation: 1 [2021-09-22T00:47:45.806] [INFO] system - update rule reservation: 2 [2021-09-22T00:47:46.326] [INFO] system - { insert: 0, update: 23, delete: 0 } [2021-09-22T00:47:46.372] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:47:46.383] [INFO] system - update rule reservation: 3 [2021-09-22T00:47:46.486] [INFO] system - { insert: 0, update: 23, delete: 0 } [2021-09-22T00:47:46.536] [INFO] system - successful update rule reservation: 3 [2021-09-22T00:47:46.548] [INFO] system - update rule reservation: 4 [2021-09-22T00:47:46.722] [INFO] system - { insert: 0, update: 93, delete: 0 } [2021-09-22T00:47:46.854] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:47:46.856] [INFO] system - update reocrded: 341 [2021-09-22T00:47:46.857] [INFO] system - update reocrded: 342 [2021-09-22T00:47:46.858] [INFO] system - update reocrded: 340 [2021-09-22T00:47:46.859] [INFO] system - update reocrded: 343 [2021-09-22T00:47:46.867] [INFO] system - update rule reservation: 5 [2021-09-22T00:47:46.945] [INFO] system - { insert: 0, update: 2, delete: 0 } [2021-09-22T00:47:46.953] [INFO] system - successful update rule reservation: 5 [2021-09-22T00:47:46.964] [INFO] system - update rule reservation: 6 [2021-09-22T00:47:47.092] [INFO] system - { insert: 0, update: 6, delete: 0 } [2021-09-22T00:47:47.106] [INFO] system - successful update rule reservation: 6 [2021-09-22T00:47:47.116] [INFO] system - update rule reservation: 7 [2021-09-22T00:47:47.239] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:47:47.246] [INFO] system - successful update rule reservation: 7 [2021-09-22T00:47:47.257] [INFO] system - update rule reservation: 8 [2021-09-22T00:47:47.337] [INFO] system - { insert: 0, update: 7, delete: 0 } [2021-09-22T00:47:47.351] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:47:47.362] [INFO] system - update rule reservation: 9 [2021-09-22T00:47:47.513] [INFO] system - { insert: 0, update: 29, delete: 0 } [2021-09-22T00:47:47.563] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:47:47.575] [INFO] system - update rule reservation: 10 [2021-09-22T00:47:47.707] [INFO] system - { insert: 0, update: 2, delete: 0 } [2021-09-22T00:47:47.716] [INFO] system - successful update rule reservation: 10 [2021-09-22T00:47:47.727] [INFO] system - update rule reservation: 11 [2021-09-22T00:47:47.892] [INFO] system - { insert: 0, update: 5, delete: 0 } [2021-09-22T00:47:47.910] [INFO] system - successful update rule reservation: 11 [2021-09-22T00:47:47.921] [INFO] system - update rule reservation: 12 [2021-09-22T00:47:48.039] [INFO] system - { insert: 0, update: 1, delete: 0 } [2021-09-22T00:47:48.045] [INFO] system - successful update rule reservation: 12 [2021-09-22T00:47:48.056] [INFO] system - all reservation update finish [2021-09-22T00:55:00.017] [INFO] system - start recEnd reserveId: 381 recordedId: 344 [2021-09-22T00:55:00.019] [INFO] system - remove recording flag: 344 [2021-09-22T00:55:00.050] [INFO] system - move file: /app/recordedTemp/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts -> /app/recorded/アニメ/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B(1).ts [2021-09-22T00:55:03.612] [INFO] system - delete old file: /app/recordedTemp/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B.ts [2021-09-22T00:55:03.670] [INFO] system - update file size: 344 [2021-09-22T00:55:03.677] [INFO] system - add recorded history: 344 [2021-09-22T00:55:03.689] [INFO] system - emit finish recording reserveId: 381, recordedId: 344, isNeedDeleteReservation: true [2021-09-22T00:55:03.690] [INFO] system - add thumbnail queue: 344 [2021-09-22T00:55:03.690] [INFO] system - recording finish reserveId: 381, recordedId: 344, videoFileFulPath: /app/recorded/アニメ/パパジャニWEST ワンピース&キングダム…夢の“マンガ飯再現”検定[字] [202109212356-TBS1]B(1).ts [2021-09-22T00:55:03.691] [INFO] system - update rule reservation: 4 [2021-09-22T00:55:03.691] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:55:03.722] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:55:03.942] [INFO] system - { insert: 0, update: 0, delete: 1 } [2021-09-22T00:55:03.951] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:55:03.952] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:55:03.963] [INFO] system - create thumbnail: 344, /app/thumbnail/344.jpg [2021-09-22T00:55:03.966] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T00:57:08.656] [ERROR] system - RecordingStreamCreator stream error: 360 [2021-09-22T00:57:08.656] [ERROR] system - stream.finished error: reserveId: 360 recordedId: 340 [2021-09-22T00:57:08.657] [ERROR] system - recording end error reserveId: 360 recordedId: 340 [2021-09-22T00:57:08.658] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:57:08.659] [INFO] system - start recEnd reserveId: 360 recordedId: 340 [2021-09-22T00:57:08.660] [INFO] system - remove recording flag: 340 [2021-09-22T00:57:08.667] [ERROR] system - RecordingStreamCreator stream error: 361 [2021-09-22T00:57:08.667] [ERROR] system - stream.finished error: reserveId: 361 recordedId: 343 [2021-09-22T00:57:08.668] [ERROR] system - recording end error reserveId: 361 recordedId: 343 [2021-09-22T00:57:08.668] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:57:08.668] [INFO] system - start recEnd reserveId: 361 recordedId: 343 [2021-09-22T00:57:08.668] [INFO] system - remove recording flag: 343 [2021-09-22T00:57:08.670] [ERROR] system - RecordingStreamCreator stream error: 359 [2021-09-22T00:57:08.671] [ERROR] system - stream.finished error: reserveId: 359 recordedId: 342 [2021-09-22T00:57:08.671] [ERROR] system - recording end error reserveId: 359 recordedId: 342 [2021-09-22T00:57:08.671] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:57:08.671] [INFO] system - start recEnd reserveId: 359 recordedId: 342 [2021-09-22T00:57:08.671] [INFO] system - remove recording flag: 342 [2021-09-22T00:57:08.688] [INFO] system - move file: /app/recordedTemp/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts -> /app/recorded/アニメ/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T00:57:08.690] [INFO] system - move file: /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts -> /app/recorded/アニメ/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:57:08.691] [INFO] system - move file: /app/recordedTemp/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts -> /app/recorded/アニメ/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T00:57:08.750] [ERROR] system - RecordingStreamCreator stream error: 358 [2021-09-22T00:57:08.751] [ERROR] system - stream.finished error: reserveId: 358 recordedId: 341 [2021-09-22T00:57:08.751] [ERROR] system - recording end error reserveId: 358 recordedId: 341 [2021-09-22T00:57:08.751] [ERROR] system - Error: aborted at connResetException (node:internal/errors:691:14) at Socket.socketCloseListener (node:_http_client:407:19) at Socket.emit (node:events:406:35) at TCP. (node:net:672:12) { code: 'ECONNRESET' } [2021-09-22T00:57:08.751] [INFO] system - start recEnd reserveId: 358 recordedId: 341 [2021-09-22T00:57:08.751] [INFO] system - remove recording flag: 341 [2021-09-22T00:57:08.774] [INFO] system - move file: /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts -> /app/recorded/アニメ/[字]キングダム #30,31 [202109220000-BSアニマックス]B(1).ts [2021-09-22T00:57:12.697] [INFO] system - delete old file: /app/recordedTemp/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T00:57:12.720] [INFO] system - update file size: 342 [2021-09-22T00:57:12.730] [INFO] system - emit finish recording reserveId: 359, recordedId: 342, isNeedDeleteReservation: false [2021-09-22T00:57:12.730] [INFO] system - add thumbnail queue: 342 [2021-09-22T00:57:12.730] [INFO] system - recording finish reserveId: 359, recordedId: 342, videoFileFulPath: /app/recorded/アニメ/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T00:57:12.731] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:57:12.754] [INFO] system - set timer: 359, 0 [2021-09-22T00:57:12.754] [INFO] system - readd recording: 359 [2021-09-22T00:57:12.754] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:57:12.755] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:57:12.756] [INFO] system - preprec: 359 [2021-09-22T00:57:12.777] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:57:12.778] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:12.792] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:14.759] [INFO] system - create thumbnail: 342, /app/thumbnail/342.jpg [2021-09-22T00:57:15.847] [INFO] system - delete old file: /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:57:15.885] [INFO] system - update file size: 343 [2021-09-22T00:57:15.892] [INFO] system - emit finish recording reserveId: 361, recordedId: 343, isNeedDeleteReservation: false [2021-09-22T00:57:15.894] [INFO] system - add thumbnail queue: 343 [2021-09-22T00:57:15.894] [INFO] system - recording finish reserveId: 361, recordedId: 343, videoFileFulPath: /app/recorded/アニメ/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:57:15.895] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:57:15.919] [INFO] system - set timer: 361, 0 [2021-09-22T00:57:15.919] [INFO] system - readd recording: 361 [2021-09-22T00:57:15.928] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:57:15.928] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:57:15.930] [INFO] system - preprec: 361 [2021-09-22T00:57:15.945] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:57:15.946] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:15.957] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:16.890] [INFO] system - delete old file: /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:57:16.929] [INFO] system - update file size: 341 [2021-09-22T00:57:16.935] [INFO] system - emit finish recording reserveId: 358, recordedId: 341, isNeedDeleteReservation: false [2021-09-22T00:57:16.936] [INFO] system - add thumbnail queue: 341 [2021-09-22T00:57:16.936] [INFO] system - recording finish reserveId: 358, recordedId: 341, videoFileFulPath: /app/recorded/アニメ/[字]キングダム #30,31 [202109220000-BSアニマックス]B(1).ts [2021-09-22T00:57:16.936] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:57:16.957] [INFO] system - set timer: 358, 0 [2021-09-22T00:57:16.957] [INFO] system - readd recording: 358 [2021-09-22T00:57:16.958] [INFO] system - preprec: 358 [2021-09-22T00:57:16.959] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:57:16.959] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:57:16.973] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:57:16.974] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:16.986] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:17.286] [INFO] system - create thumbnail: 343, /app/thumbnail/343.jpg [2021-09-22T00:57:17.873] [INFO] system - all reservation update start [2021-09-22T00:57:17.882] [INFO] system - update rule reservation: 1 [2021-09-22T00:57:18.024] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:18.031] [INFO] system - successful update rule reservation: 1 [2021-09-22T00:57:18.042] [INFO] system - update rule reservation: 2 [2021-09-22T00:57:18.518] [INFO] system - recording: 361 /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:57:18.523] [INFO] system - add recorded 361 /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:57:18.531] [INFO] system - recording added reserveId: 361, recordedId: 345 [2021-09-22T00:57:18.531] [INFO] system - create video file: 超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T00:57:18.536] [INFO] system - set stream.finished: reserveId: 361 recordedId: 345 [2021-09-22T00:57:18.537] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:57:18.550] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:57:18.665] [INFO] system - recording: 358 /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:57:18.666] [INFO] system - add recorded 358 /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:57:18.677] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:18.680] [INFO] system - successful update rule reservation: 2 [2021-09-22T00:57:18.683] [INFO] system - recording added reserveId: 358, recordedId: 346 [2021-09-22T00:57:18.683] [INFO] system - create video file: [字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T00:57:18.688] [INFO] system - set stream.finished: reserveId: 358 recordedId: 346 [2021-09-22T00:57:18.688] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T00:57:18.700] [INFO] system - update rule reservation: 3 [2021-09-22T00:57:18.704] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T00:57:18.811] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:18.819] [INFO] system - successful update rule reservation: 3 [2021-09-22T00:57:18.829] [INFO] system - update rule reservation: 4 [2021-09-22T00:57:18.857] [INFO] system - create thumbnail: 341, /app/thumbnail/341.jpg [2021-09-22T00:57:19.049] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:19.051] [INFO] system - successful update rule reservation: 4 [2021-09-22T00:57:19.062] [INFO] system - update rule reservation: 5 [2021-09-22T00:57:19.153] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:19.156] [INFO] system - successful update rule reservation: 5 [2021-09-22T00:57:19.166] [INFO] system - update rule reservation: 6 [2021-09-22T00:57:19.294] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:19.297] [INFO] system - successful update rule reservation: 6 [2021-09-22T00:57:19.307] [INFO] system - update rule reservation: 7 [2021-09-22T00:57:19.442] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:19.444] [INFO] system - successful update rule reservation: 7 [2021-09-22T00:57:19.455] [INFO] system - update rule reservation: 8 [2021-09-22T00:57:19.542] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:19.546] [INFO] system - successful update rule reservation: 8 [2021-09-22T00:57:19.549] [INFO] system - delete old file: /app/recordedTemp/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T00:57:19.557] [INFO] system - update rule reservation: 9 [2021-09-22T00:57:19.623] [INFO] system - update file size: 340 [2021-09-22T00:57:19.630] [INFO] system - emit finish recording reserveId: 360, recordedId: 340, isNeedDeleteReservation: false [2021-09-22T00:57:19.631] [INFO] system - add thumbnail queue: 340 [2021-09-22T00:57:19.631] [INFO] system - recording finish reserveId: 360, recordedId: 340, videoFileFulPath: /app/recorded/アニメ/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T00:57:19.631] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T00:57:19.678] [INFO] system - set timer: 360, 0 [2021-09-22T00:57:19.678] [INFO] system - readd recording: 360 [2021-09-22T00:57:19.679] [INFO] system - preprec: 360 [2021-09-22T00:57:19.682] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T00:57:19.683] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFailed [2021-09-22T00:57:19.744] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFailed process is fin [2021-09-22T00:57:19.744] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:19.773] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:57:19.801] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:19.807] [INFO] system - successful update rule reservation: 9 [2021-09-22T00:57:19.818] [INFO] system - update rule reservation: 10 [2021-09-22T00:57:19.916] [INFO] system - create thumbnail: 340, /app/thumbnail/340.jpg [2021-09-22T00:57:20.008] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:20.010] [INFO] system - successful update rule reservation: 10 [2021-09-22T00:57:20.020] [INFO] system - update rule reservation: 11 [2021-09-22T00:57:20.215] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:20.217] [INFO] system - successful update rule reservation: 11 [2021-09-22T00:57:20.227] [INFO] system - update rule reservation: 12 [2021-09-22T00:57:20.348] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T00:57:20.350] [INFO] system - successful update rule reservation: 12 [2021-09-22T00:57:20.361] [INFO] system - all reservation update finish [2021-09-22T00:59:45.005] [INFO] system - preprec: 363 [2021-09-22T00:59:45.020] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:59:45.033] [INFO] system - preprec: 376 [2021-09-22T00:59:45.061] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:59:45.061] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:59:45.076] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPreStart [2021-09-22T00:59:57.373] [ERROR] system - preprec failed: 363 [2021-09-22T00:59:57.374] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T00:59:57.382] [ERROR] system - preprec failed: 376 [2021-09-22T00:59:57.382] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable). at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:494:23) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T01:00:00.032] [INFO] system - recording: 359 /app/recordedTemp/鋼の錬金術師 #44 [202109220030-カートゥーン]B.ts [2021-09-22T01:00:00.035] [INFO] system - recording: 360 /app/recordedTemp/ゲッターロボアーク第12話「折り重なる刻」 [202109220030-BS11イレブン]B.ts [2021-09-22T01:00:01.404] [INFO] system - start recEnd reserveId: 361 recordedId: 345 [2021-09-22T01:00:01.407] [INFO] system - remove recording flag: 345 [2021-09-22T01:00:01.442] [INFO] system - move file: /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts -> /app/recorded/アニメ/超電磁マシーンボルテスV #21 [202109220030-AT-X]B(1).ts [2021-09-22T01:00:02.381] [INFO] system - preprec: 363 [2021-09-22T01:00:02.385] [INFO] system - preprec: 376 [2021-09-22T01:00:03.498] [INFO] system - recording: 376 /app/recordedTemp/【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109220100-ヒストリーチャンネル]B.ts [2021-09-22T01:00:03.499] [INFO] system - add recorded 376 /app/recordedTemp/【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109220100-ヒストリーチャンネル]B.ts [2021-09-22T01:00:03.511] [INFO] system - recording added reserveId: 376, recordedId: 347 [2021-09-22T01:00:03.512] [INFO] system - create video file: 【2時間特番祭り】古代の宇宙人S11 #138 宇宙人のエジプト訪問[二] [202109220100-ヒストリーチャンネル]B.ts [2021-09-22T01:00:03.520] [INFO] system - start recEnd reserveId: 358 recordedId: 346 [2021-09-22T01:00:03.520] [INFO] system - remove recording flag: 346 [2021-09-22T01:00:03.524] [INFO] system - set stream.finished: reserveId: 376 recordedId: 347 [2021-09-22T01:00:03.525] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingStart [2021-09-22T01:00:03.544] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingStart process is fin [2021-09-22T01:00:04.146] [INFO] system - move file: /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts -> /app/recorded/アニメ/[字]キングダム #30,31 [202109220000-BSアニマックス]B(2).ts [2021-09-22T01:00:04.302] [INFO] system - delete old file: /app/recordedTemp/超電磁マシーンボルテスV #21 [202109220030-AT-X]B.ts [2021-09-22T01:00:04.330] [INFO] system - update file size: 345 [2021-09-22T01:00:04.337] [INFO] system - add recorded history: 345 [2021-09-22T01:00:04.343] [INFO] system - emit finish recording reserveId: 361, recordedId: 345, isNeedDeleteReservation: true [2021-09-22T01:00:04.345] [INFO] system - add thumbnail queue: 345 [2021-09-22T01:00:04.345] [INFO] system - recording finish reserveId: 361, recordedId: 345, videoFileFulPath: /app/recorded/アニメ/超電磁マシーンボルテスV #21 [202109220030-AT-X]B(1).ts [2021-09-22T01:00:04.346] [INFO] system - update rule reservation: 4 [2021-09-22T01:00:04.347] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T01:00:08.756] [ERROR] system - recording failed: 359 [2021-09-22T01:00:08.758] [ERROR] system - recording failed: 360 [2021-09-22T01:00:08.770] [ERROR] system - preprec failed: 359 [2021-09-22T01:00:08.771] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T01:00:08.773] [ERROR] system - preprec failed: 360 [2021-09-22T01:00:08.773] [ERROR] system - Error: recordingStartError at RecorderModel. (/app/dist/model/operator/recording/model/operator/recording/RecorderModel.ts:350:24) at Generator.next () at fulfilled (/app/dist/model/operator/recording/RecorderModel.js:36:58) [2021-09-22T01:00:08.775] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T01:00:08.775] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T01:00:08.792] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T01:00:08.792] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T01:00:08.802] [INFO] system - delete old file: /app/recordedTemp/[字]キングダム #30,31 [202109220000-BSアニマックス]B.ts [2021-09-22T01:00:08.807] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh recordingPrepRecFailed [2021-09-22T01:00:08.840] [INFO] system - update file size: 346 [2021-09-22T01:00:08.856] [INFO] system - add recorded history: 346 [2021-09-22T01:00:08.862] [INFO] system - emit finish recording reserveId: 358, recordedId: 346, isNeedDeleteReservation: true [2021-09-22T01:00:08.862] [INFO] system - add thumbnail queue: 346 [2021-09-22T01:00:08.862] [INFO] system - recording finish reserveId: 358, recordedId: 346, videoFileFulPath: /app/recorded/アニメ/[字]キングダム #30,31 [202109220000-BSアニマックス]B(2).ts [2021-09-22T01:00:08.863] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh recordingFinish [2021-09-22T01:00:08.880] [INFO] system - /bin/bash /opt/bin/recordlog.sh recordingFinish process is fin [2021-09-22T01:00:08.970] [INFO] system - { insert: 0, update: 0, delete: 5 } [2021-09-22T01:00:08.981] [INFO] system - successful update rule reservation: 4 [2021-09-22T01:00:08.982] [INFO] system - cancel reservation: 359 [2021-09-22T01:00:08.982] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:08.995] [ERROR] system - reservation is not found: 359 [2021-09-22T01:00:08.998] [INFO] system - cancel reservation: 360 [2021-09-22T01:00:09.009] [FATAL] system - unhandledRejection [2021-09-22T01:00:09.009] [FATAL] system - Error: ReservationIsNotFound at ReservationManageModel. (/app/dist/model/operator/reservation/model/operator/reservation/ReservationManageModel.ts:1040:19) at Generator.next () at fulfilled (/app/dist/model/operator/reservation/ReservationManageModel.js:17:58) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T01:00:09.056] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.056] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.058] [ERROR] system - reservation is not found: 360 [2021-09-22T01:00:09.058] [INFO] system - update rule reservation: 4 [2021-09-22T01:00:09.061] [FATAL] system - unhandledRejection [2021-09-22T01:00:09.061] [FATAL] system - Error: ReservationIsNotFound at ReservationManageModel. (/app/dist/model/operator/reservation/model/operator/reservation/ReservationManageModel.ts:1040:19) at Generator.next () at fulfilled (/app/dist/model/operator/reservation/ReservationManageModel.js:17:58) at runMicrotasks () at processTicksAndRejections (node:internal/process/task_queues:96:5) [2021-09-22T01:00:09.077] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.077] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.111] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.112] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.126] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.126] [INFO] system - execute cmd: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.139] [INFO] system - finish: /bin/bash /opt/bin/recordlog.sh reservedeleted [2021-09-22T01:00:09.246] [INFO] system - create thumbnail: 345, /app/thumbnail/345.jpg [2021-09-22T01:00:09.315] [INFO] system - { insert: 0, update: 0, delete: 0 } [2021-09-22T01:00:09.322] [INFO] system - successful update rule reservation: 4 [2021-09-22T01:00:09.836] [INFO] system - create thumbnail: 346, /app/thumbnail/346.jpg

●mirakurun

2021-09-21T23:59:45.469+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26099) 2021-09-21T23:59:45.469+09:00 info: TunerDevice#4 streaming to user 172.18.0.2:57242 (priority=2) 2021-09-21T23:59:45.469+09:00 info: TSDecoder#212 has created (command=arib-b25-stream-test) 2021-09-21T23:59:45.527+09:00 info: TSDecoder#212 process has spawned by command arib-b25-stream-test (pid=26100) 2021-09-22T00:00:00.339+09:00 info: TSFilter#_onEIT: closing because eventId=64497 has ended... 2021-09-22T00:00:00.348+09:00 info: TSFilter#_onEIT: now ready for eventId=50983 2021-09-22T00:00:00.351+09:00 info: TSFilter#_onEIT: closing because eventId=44513 has ended... 2021-09-22T00:00:00.372+09:00 info: TSFilter#_onEIT: closing because eventId=56053 has ended... 2021-09-22T00:00:00.374+09:00 info: TSFilter#_onEIT: now ready for eventId=56054 2021-09-22T00:00:01.345+09:00 info: TSFilter#_close: closed (serviceId=330, eventId=64497) 2021-09-22T00:00:01.345+09:00 info: TunerDevice#1 end streaming to user 172.18.0.2:57222 (priority=2) 2021-09-22T00:00:01.346+09:00 info: TSDecoder#207 has closed (command=arib-b25-stream-test) 2021-09-22T00:00:01.351+09:00 info: 172.18.0.2 - GET /api/programs/70033064497/stream?decode=1 HTTP/1.1 200 - - 15323.914 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:00:01.363+09:00 info: TSDecoder#207 process has closed with exit code=0 by signal SIGKILL (pid=25926) 2021-09-22T00:00:01.363+09:00 info: TSFilter#_close: closed (serviceId=310, eventId=44513) 2021-09-22T00:00:01.364+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57220 (priority=2) 2021-09-22T00:00:01.364+09:00 info: TSDecoder#206 has closed (command=arib-b25-stream-test) 2021-09-22T00:00:01.365+09:00 info: 172.18.0.2 - GET /api/programs/70031044513/stream?decode=1 HTTP/1.1 200 - - 15331.009 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:00:01.370+09:00 info: TSDecoder#206 process has closed with exit code=0 by signal SIGKILL (pid=25923) 2021-09-22T00:00:01.372+09:00 info: TSFilter#_close: closed (serviceId=342, eventId=56053) 2021-09-22T00:00:01.372+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57192 (priority=2) 2021-09-22T00:00:01.373+09:00 info: TSDecoder#201 has closed (command=arib-b25-stream-test) 2021-09-22T00:00:01.373+09:00 info: 172.18.0.2 - GET /api/programs/70034256053/stream?decode=1 HTTP/1.1 200 - - 15588.898 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:00:01.378+09:00 info: TSDecoder#201 process has closed with exit code=0 by signal SIGKILL (pid=25742) 2021-09-22T00:00:02.785+09:00 info: TSFilter#_onEIT: now ready for eventId=53486 2021-09-22T00:00:04.346+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:00:04.363+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=25925) 2021-09-22T00:00:04.464+09:00 info: TunerDevice#1 released 2021-09-22T00:01:06.080+09:00 info: ChannelItem#'BS:BS23_1' serviceId=255 check has started 2021-09-22T00:01:06.087+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:01:06.087+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:01:06.150+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS23_1 - - (pid=26105) 2021-09-22T00:01:06.151+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:01:26.156+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:01:26.158+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:01:26.162+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:01:26.269+09:00 info: ChannelItem#'BS:BS3_2' serviceId=256 check has started 2021-09-22T00:01:26.273+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:01:26.273+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:01:26.286+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26105) 2021-09-22T00:01:26.386+09:00 info: TunerDevice#1 released 2021-09-22T00:01:26.449+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS3_2 - - (pid=26109) 2021-09-22T00:01:26.449+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:01:46.453+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:01:46.455+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:01:46.457+09:00 warn: ChannelItem#'BS:BS3_2' serviceId=256 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:01:49.470+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26109) 2021-09-22T00:01:49.571+09:00 info: TunerDevice#1 released 2021-09-22T00:03:14.289+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:03:52.279+09:00 info: Service.saveLogoData(): saving... (networkId=32739 logoId=141) 2021-09-22T00:03:52.285+09:00 info: Service.saveLogoData(): saved. (networkId=32739 logoId=141) 2021-09-22T00:04:26.170+09:00 info: ChannelItem#'BS:BS23_1' serviceId=255 check has started 2021-09-22T00:04:26.174+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:04:26.174+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:04:26.263+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS23_1 - - (pid=26113) 2021-09-22T00:04:26.264+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:04:46.269+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:04:46.271+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:04:46.274+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:04:46.463+09:00 info: ChannelItem#'BS:BS3_2' serviceId=256 check has started 2021-09-22T00:04:46.467+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:04:46.467+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:04:46.480+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26113) 2021-09-22T00:04:46.580+09:00 info: TunerDevice#1 released 2021-09-22T00:04:46.674+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS3_2 - - (pid=26117) 2021-09-22T00:04:46.674+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:05:06.678+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:05:06.680+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:05:06.685+09:00 warn: ChannelItem#'BS:BS3_2' serviceId=256 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:05:09.694+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26117) 2021-09-22T00:05:09.796+09:00 info: TunerDevice#1 released 2021-09-22T00:07:17.051+09:00 info: 172.18.0.2 - GET /api/services? HTTP/1.1 200 - - 32.023 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:07:46.282+09:00 info: ChannelItem#'BS:BS23_1' serviceId=255 check has started 2021-09-22T00:07:46.288+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:07:46.289+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:07:46.414+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS23_1 - - (pid=26121) 2021-09-22T00:07:46.414+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:08:06.418+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:08:06.420+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:08:06.422+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:08:06.691+09:00 info: ChannelItem#'BS:BS3_2' serviceId=256 check has started 2021-09-22T00:08:06.696+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:08:06.696+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:08:06.712+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26121) 2021-09-22T00:08:06.813+09:00 info: TunerDevice#1 released 2021-09-22T00:08:06.932+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS3_2 - - (pid=26125) 2021-09-22T00:08:06.932+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:08:26.933+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:08:26.934+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:08:26.936+09:00 warn: ChannelItem#'BS:BS3_2' serviceId=256 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:08:29.948+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26125) 2021-09-22T00:08:30.049+09:00 info: TunerDevice#1 released 2021-09-22T00:09:40.134+09:00 info: Service.saveLogoData(): saving... (networkId=32739 logoId=140) 2021-09-22T00:09:40.144+09:00 info: Service.saveLogoData(): saved. (networkId=32739 logoId=140) 2021-09-22T00:11:06.433+09:00 info: ChannelItem#'BS:BS23_1' serviceId=255 check has started 2021-09-22T00:11:06.440+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:11:06.440+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:11:06.557+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS23_1 - - (pid=26129) 2021-09-22T00:11:06.557+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:11:18.643+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:11:26.562+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:11:26.563+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:11:26.566+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:11:26.942+09:00 info: ChannelItem#'BS:BS3_2' serviceId=256 check has started 2021-09-22T00:11:26.947+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:11:26.947+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:11:26.960+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26129) 2021-09-22T00:11:27.060+09:00 info: TunerDevice#1 released 2021-09-22T00:11:27.181+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 BS3_2 - - (pid=26133) 2021-09-22T00:11:27.181+09:00 info: TunerDevice#1 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:11:47.185+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:11:47.186+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:11:47.188+09:00 warn: ChannelItem#'BS:BS3_2' serviceId=256 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:11:50.203+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26133) 2021-09-22T00:11:50.303+09:00 info: TunerDevice#1 released 2021-09-22T00:12:45.999+09:00 info: Network#4 EPG gathering is already in progress on another stream 2021-09-22T00:12:46.003+09:00 info: Network#6 EPG gathering has started 2021-09-22T00:12:46.005+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:12:46.005+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:12:46.120+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS8 - - (pid=26137) 2021-09-22T00:12:46.120+09:00 info: TunerDevice#1 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:13:52.401+09:00 info: Service.saveLogoData(): saving... (networkId=32739 logoId=141) 2021-09-22T00:13:52.407+09:00 info: Service.saveLogoData(): saved. (networkId=32739 logoId=141) 2021-09-22T00:15:45.813+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:15:45.814+09:00 info: TunerDevice#1 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:15:45.815+09:00 info: Network#6 EPG gathering has finished 2021-09-22T00:15:45.818+09:00 info: Network#7 EPG gathering is already in progress on another stream 2021-09-22T00:15:45.820+09:00 info: Network#32391 EPG gathering has started 2021-09-22T00:15:45.822+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:15:45.822+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:15:45.932+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 16 - - (pid=26141) 2021-09-22T00:15:45.932+09:00 info: TunerDevice#3 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:15:46.782+09:00 info: TSFilter#_standbyLogoData: waiting for logo data for 30 minutes... (networkId=32391, logoId=16) 2021-09-22T00:15:48.813+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:15:48.831+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26137) 2021-09-22T00:15:48.934+09:00 info: TunerDevice#1 released 2021-09-22T00:16:46.595+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:16:46.596+09:00 info: TunerDevice#3 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:16:46.599+09:00 info: Network#32391 EPG gathering has finished 2021-09-22T00:16:46.601+09:00 info: Network#32736 EPG gathering has started 2021-09-22T00:16:46.603+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:16:46.603+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:16:46.716+09:00 info: TunerDevice#6 process has spawned by command recpt1 --device /dev/px4video6 27 - - (pid=26145) 2021-09-22T00:16:46.717+09:00 info: TunerDevice#6 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:16:49.596+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:16:49.612+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal null (pid=26141) 2021-09-22T00:16:49.715+09:00 info: TunerDevice#3 released 2021-09-22T00:17:17.033+09:00 info: 172.18.0.2 - GET /api/services? HTTP/1.1 200 - - 16.900 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:17:47.502+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:17:47.503+09:00 info: TunerDevice#6 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:17:47.504+09:00 info: Network#32736 EPG gathering has finished 2021-09-22T00:17:47.506+09:00 info: Network#32737 EPG gathering has started 2021-09-22T00:17:47.508+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:17:47.508+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:17:47.619+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 26 - - (pid=26149) 2021-09-22T00:17:47.620+09:00 info: TunerDevice#3 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:17:50.502+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:17:50.515+09:00 info: TunerDevice#6 process has closed with exit code=0 by signal null (pid=26145) 2021-09-22T00:17:50.615+09:00 info: TunerDevice#6 released 2021-09-22T00:18:30.470+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:25:45.911+09:00 info: TSFilter#_standbyLogoData: stopped waiting for logo data (networkId=32739, logoId=140) 2021-09-22T00:27:17.039+09:00 info: 172.18.0.2 - GET /api/services? HTTP/1.1 200 - - 13.805 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:27:47.624+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:27:47.625+09:00 info: TunerDevice#3 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:27:47.626+09:00 info: Network#32737 EPG gathering has finished 2021-09-22T00:27:47.629+09:00 info: Network#32738 EPG gathering has started 2021-09-22T00:27:47.632+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:27:47.632+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:27:47.750+09:00 info: TunerDevice#6 process has spawned by command recpt1 --device /dev/px4video6 25 - - (pid=26153) 2021-09-22T00:27:47.750+09:00 info: TunerDevice#6 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:27:50.632+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal null (pid=26149) 2021-09-22T00:27:50.734+09:00 info: TunerDevice#3 released 2021-09-22T00:28:20.675+09:00 info: 172.18.0.2 - GET /api/programs/327390104841967/stream?decode=1 HTTP/1.1 200 - - 18007.516 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:28:20.676+09:00 info: TSDecoder#209 has closed (command=arib-b25-stream-test) 2021-09-22T00:28:20.678+09:00 info: TSFilter#_close: closed (serviceId=1048, eventId=41967) 2021-09-22T00:28:20.678+09:00 info: TunerDevice#2 end streaming to user 172.18.0.2:57234 (priority=2) 2021-09-22T00:28:20.680+09:00 info: 172.18.0.2 - GET /api/programs/70034256054/stream?decode=1 HTTP/1.1 200 - - 15482.350 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:28:20.680+09:00 info: TSDecoder#211 has closed (command=arib-b25-stream-test) 2021-09-22T00:28:20.681+09:00 info: TSFilter#_close: closed (serviceId=342, eventId=56054) 2021-09-22T00:28:20.682+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57240 (priority=1) 2021-09-22T00:28:20.684+09:00 info: 172.18.0.2 - GET /api/programs/70033150983/stream?decode=1 HTTP/1.1 200 - - 15403.119 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:28:20.684+09:00 info: TSDecoder#210 has closed (command=arib-b25-stream-test) 2021-09-22T00:28:20.684+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50983) 2021-09-22T00:28:20.684+09:00 info: TunerDevice#5 end streaming to user 172.18.0.2:57238 (priority=2) 2021-09-22T00:28:20.685+09:00 info: TSDecoder#211 process has closed with exit code=0 by signal SIGKILL (pid=26094) 2021-09-22T00:28:20.685+09:00 info: TSDecoder#209 process has closed with exit code=0 by signal SIGKILL (pid=26062) 2021-09-22T00:28:20.686+09:00 info: TSDecoder#210 process has closed with exit code=0 by signal SIGKILL (pid=26092) 2021-09-22T00:28:20.763+09:00 info: 172.18.0.2 - GET /api/programs/40023653486/stream?decode=1 HTTP/1.1 200 - - 17845.148 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:28:20.764+09:00 info: TSDecoder#212 has closed (command=arib-b25-stream-test) 2021-09-22T00:28:20.766+09:00 info: TSFilter#_close: closed (serviceId=236, eventId=53486) 2021-09-22T00:28:20.766+09:00 info: TunerDevice#4 end streaming to user 172.18.0.2:57242 (priority=2) 2021-09-22T00:28:20.768+09:00 info: TSDecoder#212 process has closed with exit code=0 by signal SIGKILL (pid=26100) 2021-09-22T00:28:23.684+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal null (pid=26061) 2021-09-22T00:28:23.688+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal null (pid=25739) 2021-09-22T00:28:23.696+09:00 info: TunerDevice#5 process has closed with exit code=0 by signal null (pid=26091) 2021-09-22T00:28:23.768+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:28:23.782+09:00 info: TunerDevice#4 process has closed with exit code=0 by signal null (pid=26099) 2021-09-22T00:28:23.785+09:00 info: TunerDevice#2 released 2021-09-22T00:28:23.789+09:00 info: TunerDevice#0 released 2021-09-22T00:28:23.796+09:00 info: TunerDevice#5 released 2021-09-22T00:28:23.882+09:00 info: TunerDevice#4 released 2021-09-22T00:29:26.887+09:00 info: TSFilter: created (serviceId=331, eventId=50983) 2021-09-22T00:29:26.888+09:00 info: TSFilter: waiting for serviceId=331, eventId=50983 2021-09-22T00:29:27.029+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 CS6 - - (pid=26157) 2021-09-22T00:29:27.030+09:00 info: TunerDevice#0 streaming to user 172.18.0.2:57258 (priority=2) 2021-09-22T00:29:27.030+09:00 info: TSDecoder#213 has created (command=arib-b25-stream-test) 2021-09-22T00:29:27.216+09:00 info: TSDecoder#213 process has spawned by command arib-b25-stream-test (pid=26158) 2021-09-22T00:29:27.249+09:00 info: TSFilter: created (serviceId=342, eventId=56054) 2021-09-22T00:29:27.249+09:00 info: TSFilter: waiting for serviceId=342, eventId=56054 2021-09-22T00:29:27.417+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS14 - - (pid=26160) 2021-09-22T00:29:27.417+09:00 info: TunerDevice#1 streaming to user 172.18.0.2:57260 (priority=1) 2021-09-22T00:29:27.417+09:00 info: TSDecoder#214 has created (command=arib-b25-stream-test) 2021-09-22T00:29:27.601+09:00 info: TSDecoder#214 process has spawned by command arib-b25-stream-test (pid=26161) 2021-09-22T00:29:27.619+09:00 info: TSFilter: created (serviceId=236, eventId=53486) 2021-09-22T00:29:27.619+09:00 info: TSFilter: waiting for serviceId=236, eventId=53486 2021-09-22T00:29:27.742+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26166) 2021-09-22T00:29:27.743+09:00 info: TunerDevice#4 streaming to user 172.18.0.2:57262 (priority=2) 2021-09-22T00:29:27.744+09:00 info: TSDecoder#215 has created (command=arib-b25-stream-test) 2021-09-22T00:29:27.874+09:00 info: TSDecoder#215 process has spawned by command arib-b25-stream-test (pid=26170) 2021-09-22T00:29:27.877+09:00 info: TSFilter: created (serviceId=1048, eventId=41967) 2021-09-22T00:29:27.878+09:00 info: TSFilter: waiting for serviceId=1048, eventId=41967 2021-09-22T00:29:28.009+09:00 info: TunerDevice#2 process has spawned by command recpt1 --device /dev/px4video2 22 - - (pid=26172) 2021-09-22T00:29:28.009+09:00 info: TunerDevice#2 streaming to user 172.18.0.2:57264 (priority=2) 2021-09-22T00:29:28.010+09:00 info: TSDecoder#216 has created (command=arib-b25-stream-test) 2021-09-22T00:29:28.128+09:00 info: TSDecoder#216 process has spawned by command arib-b25-stream-test (pid=26176) 2021-09-22T00:29:38.659+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:29:45.019+09:00 info: TSFilter: created (serviceId=331, eventId=50984) 2021-09-22T00:29:45.019+09:00 info: TSFilter: waiting for serviceId=331, eventId=50984 2021-09-22T00:29:45.019+09:00 info: TunerDevice#0 streaming to user 172.18.0.2:57266 (priority=2) 2021-09-22T00:29:45.020+09:00 info: TSDecoder#217 has created (command=arib-b25-stream-test) 2021-09-22T00:29:45.129+09:00 info: TSDecoder#217 process has spawned by command arib-b25-stream-test (pid=26181) 2021-09-22T00:29:45.131+09:00 info: TSFilter: created (serviceId=211, eventId=34954) 2021-09-22T00:29:45.131+09:00 info: TSFilter: waiting for serviceId=211, eventId=34954 2021-09-22T00:29:45.235+09:00 info: TunerDevice#5 process has spawned by command recpt1 --device /dev/px4video5 BS9_0 - - (pid=26183) 2021-09-22T00:29:45.236+09:00 info: TunerDevice#5 streaming to user 172.18.0.2:57268 (priority=2) 2021-09-22T00:29:45.236+09:00 info: TSDecoder#218 has created (command=arib-b25-stream-test) 2021-09-22T00:29:45.344+09:00 info: TSDecoder#218 process has spawned by command arib-b25-stream-test (pid=26184) 2021-09-22T00:29:45.346+09:00 info: TSFilter: created (serviceId=333, eventId=60522) 2021-09-22T00:29:45.346+09:00 info: TSFilter: waiting for serviceId=333, eventId=60522 2021-09-22T00:29:45.359+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26160) 2021-09-22T00:29:45.360+09:00 info: TSFilter#_close: closed (serviceId=342, eventId=56054) 2021-09-22T00:29:45.362+09:00 info: TunerDevice#1 end streaming to user 172.18.0.2:57260 (priority=1) 2021-09-22T00:29:45.362+09:00 info: TSDecoder#214 has closed (command=arib-b25-stream-test) 2021-09-22T00:29:45.363+09:00 info: 172.18.0.2 - GET /api/programs/70034256054/stream?decode=1 HTTP/1.1 200 - - 18113.444 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:29:45.364+09:00 info: TSDecoder#214 process has closed with exit code=0 by signal SIGKILL (pid=26161) 2021-09-22T00:29:45.460+09:00 info: TunerDevice#1 released 2021-09-22T00:29:45.568+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS16 - - (pid=26189) 2021-09-22T00:29:45.569+09:00 info: TunerDevice#1 streaming to user 172.18.0.2:57270 (priority=2) 2021-09-22T00:29:45.569+09:00 info: TSDecoder#219 has created (command=arib-b25-stream-test) 2021-09-22T00:29:45.672+09:00 info: TSDecoder#219 process has spawned by command arib-b25-stream-test (pid=26190) 2021-09-22T00:29:57.697+09:00 info: 172.18.0.2 - GET /api/programs/40014112150/stream?decode=1 HTTP/1.1 503 - - 12347.417 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:00.001+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=50983... 2021-09-22T00:30:00.002+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50983) 2021-09-22T00:30:00.003+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57258 (priority=2) 2021-09-22T00:30:00.003+09:00 info: TSDecoder#213 has closed (command=arib-b25-stream-test) 2021-09-22T00:30:00.005+09:00 info: 172.18.0.2 - GET /api/programs/70033150983/stream?decode=1 HTTP/1.1 200 - - 33120.571 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:00.007+09:00 info: TSDecoder#213 process has closed with exit code=0 by signal SIGKILL (pid=26158) 2021-09-22T00:30:07.714+09:00 info: 172.18.0.2 - GET /api/programs/70034256054/stream?decode=1 HTTP/1.1 503 - - 12276.996 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:10.031+09:00 info: TSFilter: created (serviceId=331, eventId=50983) 2021-09-22T00:30:10.031+09:00 info: TSFilter: waiting for serviceId=331, eventId=50983 2021-09-22T00:30:10.032+09:00 info: TunerDevice#0 streaming to user 172.18.0.2:57278 (priority=2) 2021-09-22T00:30:10.033+09:00 info: TSDecoder#220 has created (command=arib-b25-stream-test) 2021-09-22T00:30:10.138+09:00 info: TSDecoder#220 process has spawned by command arib-b25-stream-test (pid=26195) 2021-09-22T00:30:10.138+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=50983... 2021-09-22T00:30:10.138+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50983) 2021-09-22T00:30:10.138+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57278 (priority=2) 2021-09-22T00:30:10.139+09:00 info: TSDecoder#220 has closed (command=arib-b25-stream-test) 2021-09-22T00:30:10.142+09:00 info: 172.18.0.2 - GET /api/programs/70033150983/stream?decode=1 HTTP/1.1 200 - - 109.939 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:10.143+09:00 info: TSDecoder#220 process has closed with exit code=0 by signal SIGKILL (pid=26195) 2021-09-22T00:30:15.000+09:00 info: 172.18.0.2 - GET /api/programs/40014112150/stream?decode=1 HTTP/1.1 503 - - 12273.204 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:20.158+09:00 info: TSFilter: created (serviceId=331, eventId=50983) 2021-09-22T00:30:20.158+09:00 info: TSFilter: waiting for serviceId=331, eventId=50983 2021-09-22T00:30:20.158+09:00 info: TunerDevice#0 streaming to user 172.18.0.2:57284 (priority=2) 2021-09-22T00:30:20.159+09:00 info: TSDecoder#221 has created (command=arib-b25-stream-test) 2021-09-22T00:30:20.270+09:00 info: TSDecoder#221 process has spawned by command arib-b25-stream-test (pid=26197) 2021-09-22T00:30:20.271+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=50983... 2021-09-22T00:30:20.271+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50983) 2021-09-22T00:30:20.271+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57284 (priority=2) 2021-09-22T00:30:20.272+09:00 info: TSDecoder#221 has closed (command=arib-b25-stream-test) 2021-09-22T00:30:20.272+09:00 info: 172.18.0.2 - GET /api/programs/70033150983/stream?decode=1 HTTP/1.1 200 - - 116.212 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:20.273+09:00 info: TSDecoder#221 process has closed with exit code=0 by signal SIGKILL (pid=26197) 2021-09-22T00:30:25.031+09:00 info: 172.18.0.2 - GET /api/programs/70034256054/stream?decode=1 HTTP/1.1 503 - - 12308.024 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:30.292+09:00 info: TSFilter: created (serviceId=331, eventId=50983) 2021-09-22T00:30:30.292+09:00 info: TSFilter: waiting for serviceId=331, eventId=50983 2021-09-22T00:30:30.292+09:00 info: TunerDevice#0 streaming to user 172.18.0.2:57288 (priority=2) 2021-09-22T00:30:30.293+09:00 info: TSDecoder#222 has created (command=arib-b25-stream-test) 2021-09-22T00:30:30.397+09:00 info: TSDecoder#222 process has spawned by command arib-b25-stream-test (pid=26199) 2021-09-22T00:30:30.398+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=50983... 2021-09-22T00:30:30.398+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50983) 2021-09-22T00:30:30.398+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57288 (priority=2) 2021-09-22T00:30:30.398+09:00 info: TSDecoder#222 has closed (command=arib-b25-stream-test) 2021-09-22T00:30:30.401+09:00 info: 172.18.0.2 - GET /api/programs/70033150983/stream?decode=1 HTTP/1.1 200 - - 110.115 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:30.401+09:00 info: TSDecoder#222 process has closed with exit code=0 by signal SIGKILL (pid=26199) 2021-09-22T00:30:32.404+09:00 info: 172.18.0.2 - GET /api/programs/40014112150/stream?decode=1 HTTP/1.1 503 - - 12393.263 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:42.416+09:00 info: 172.18.0.2 - GET /api/programs/70034256054/stream?decode=1 HTTP/1.1 503 - - 12374.391 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:30:49.689+09:00 info: 172.18.0.2 - GET /api/programs/40014112150/stream?decode=1 HTTP/1.1 503 - - 12276.318 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:37:17.018+09:00 info: 172.18.0.2 - GET /api/services? HTTP/1.1 200 - - 17.199 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:37:47.751+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:37:47.752+09:00 info: TunerDevice#6 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:37:47.753+09:00 info: Network#32738 EPG gathering has finished 2021-09-22T00:37:47.753+09:00 info: Network#32739 EPG gathering has skipped by epgGatheringInterval 2021-09-22T00:37:47.756+09:00 info: Network#32740 EPG gathering has started 2021-09-22T00:37:47.756+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:37:47.756+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:37:47.870+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 21 - - (pid=26201) 2021-09-22T00:37:47.870+09:00 info: TunerDevice#3 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:37:48.594+09:00 info: TunerDevice#3 process has closed with exit code=1 by signal null (pid=26201) 2021-09-22T00:37:48.624+09:00 info: TunerDevice#1 process has closed with exit code=1 by signal null (pid=26189) 2021-09-22T00:37:48.625+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal null (pid=26172) 2021-09-22T00:37:48.626+09:00 info: TunerDevice#4 process has closed with exit code=1 by signal null (pid=26166) 2021-09-22T00:37:48.626+09:00 info: TunerDevice#0 process has closed with exit code=1 by signal null (pid=26157) 2021-09-22T00:37:48.628+09:00 info: TunerDevice#5 process has closed with exit code=1 by signal null (pid=26183) 2021-09-22T00:37:48.628+09:00 info: TunerDevice#6 process has closed with exit code=0 by signal null (pid=26153) 2021-09-22T00:37:48.695+09:00 info: TunerDevice#3 released 2021-09-22T00:37:48.696+09:00 warn: TunerDevice#3 respawning because request has not closed 2021-09-22T00:37:48.809+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 21 - - (pid=26205) 2021-09-22T00:37:48.810+09:00 info: TunerDevice#1 released 2021-09-22T00:37:48.810+09:00 warn: TunerDevice#1 respawning because request has not closed 2021-09-22T00:37:48.914+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS16 - - (pid=26206) 2021-09-22T00:37:48.915+09:00 info: TunerDevice#2 released 2021-09-22T00:37:48.915+09:00 warn: TunerDevice#2 respawning because request has not closed 2021-09-22T00:37:49.020+09:00 info: TunerDevice#2 process has spawned by command recpt1 --device /dev/px4video2 22 - - (pid=26207) 2021-09-22T00:37:49.020+09:00 info: TunerDevice#4 released 2021-09-22T00:37:49.020+09:00 warn: TunerDevice#4 respawning because request has not closed 2021-09-22T00:37:49.133+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26208) 2021-09-22T00:37:49.134+09:00 info: TunerDevice#0 released 2021-09-22T00:37:49.134+09:00 warn: TunerDevice#0 respawning because request has not closed 2021-09-22T00:37:49.239+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 CS6 - - (pid=26209) 2021-09-22T00:37:49.239+09:00 info: TunerDevice#5 released 2021-09-22T00:37:49.239+09:00 warn: TunerDevice#5 respawning because request has not closed 2021-09-22T00:37:49.344+09:00 info: TunerDevice#5 process has spawned by command recpt1 --device /dev/px4video5 BS9_0 - - (pid=26210) 2021-09-22T00:37:49.344+09:00 info: TunerDevice#6 released 2021-09-22T00:37:49.346+09:00 info: TunerDevice#0 process has closed with exit code=1 by signal null (pid=26209) 2021-09-22T00:37:49.347+09:00 info: TunerDevice#4 process has closed with exit code=1 by signal null (pid=26208) 2021-09-22T00:37:49.347+09:00 info: TunerDevice#2 process has closed with exit code=1 by signal null (pid=26207) 2021-09-22T00:37:49.348+09:00 info: TunerDevice#1 process has closed with exit code=1 by signal null (pid=26206) 2021-09-22T00:37:49.348+09:00 info: TunerDevice#3 process has closed with exit code=1 by signal null (pid=26205) 2021-09-22T00:37:49.349+09:00 info: TunerDevice#5 process has closed with exit code=1 by signal null (pid=26210) 2021-09-22T00:37:49.448+09:00 info: TunerDevice#0 released 2021-09-22T00:37:49.449+09:00 warn: TunerDevice#0 respawning because request has not closed 2021-09-22T00:37:49.558+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 CS6 - - (pid=26211) 2021-09-22T00:37:49.559+09:00 info: TunerDevice#4 released 2021-09-22T00:37:49.559+09:00 warn: TunerDevice#4 respawning because request has not closed 2021-09-22T00:37:49.667+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26212) 2021-09-22T00:37:49.668+09:00 info: TunerDevice#2 released 2021-09-22T00:37:49.668+09:00 warn: TunerDevice#2 respawning because request has not closed 2021-09-22T00:37:49.770+09:00 info: TunerDevice#2 process has spawned by command recpt1 --device /dev/px4video2 22 - - (pid=26213) 2021-09-22T00:37:49.771+09:00 info: TunerDevice#1 released 2021-09-22T00:37:49.771+09:00 warn: TunerDevice#1 respawning because request has not closed 2021-09-22T00:37:49.876+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS16 - - (pid=26214) 2021-09-22T00:37:49.876+09:00 info: TunerDevice#3 released 2021-09-22T00:37:49.877+09:00 warn: TunerDevice#3 respawning because request has not closed 2021-09-22T00:37:49.995+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 21 - - (pid=26215) 2021-09-22T00:37:49.995+09:00 info: TunerDevice#5 released 2021-09-22T00:37:49.996+09:00 warn: TunerDevice#5 respawning because request has not closed 2021-09-22T00:37:50.107+09:00 info: TunerDevice#5 process has spawned by command recpt1 --device /dev/px4video5 BS9_0 - - (pid=26216) 2021-09-22T00:37:50.108+09:00 info: TunerDevice#4 process has closed with exit code=1 by signal null (pid=26212) 2021-09-22T00:37:50.108+09:00 info: TunerDevice#0 process has closed with exit code=1 by signal null (pid=26211) 2021-09-22T00:37:50.209+09:00 info: TunerDevice#4 released 2021-09-22T00:37:50.209+09:00 warn: TunerDevice#4 respawning because request has not closed 2021-09-22T00:37:50.319+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26217) 2021-09-22T00:37:50.320+09:00 info: TunerDevice#0 released 2021-09-22T00:37:50.320+09:00 warn: TunerDevice#0 respawning because request has not closed 2021-09-22T00:37:50.427+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 CS6 - - (pid=26221) 2021-09-22T00:37:50.583+09:00 info: TSFilter#_onEIT: now ready for eventId=34954 2021-09-22T00:37:51.266+09:00 info: TSFilter#_onEIT: now ready for eventId=53486 2021-09-22T00:37:51.371+09:00 info: TSFilter#_onEIT: now ready for eventId=50984 2021-09-22T00:37:51.383+09:00 info: TSFilter#_onEIT: now ready for eventId=60522 2021-09-22T00:37:51.763+09:00 info: TSFilter#_onEIT: now ready for eventId=41967 2021-09-22T00:38:48.770+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:44:58.116+09:00 info: TunerDevice#0 process has closed with exit code=1 by signal null (pid=26221) 2021-09-22T00:44:58.119+09:00 info: TunerDevice#5 process has closed with exit code=1 by signal null (pid=26216) 2021-09-22T00:44:58.120+09:00 info: TunerDevice#4 process has closed with exit code=1 by signal null (pid=26217) 2021-09-22T00:44:58.120+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal null (pid=26215) 2021-09-22T00:44:58.121+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal null (pid=26213) 2021-09-22T00:44:58.122+09:00 info: TunerDevice#1 process has closed with exit code=1 by signal null (pid=26214) 2021-09-22T00:44:58.219+09:00 info: TunerDevice#0 released 2021-09-22T00:44:58.220+09:00 warn: TunerDevice#0 respawning because request has not closed 2021-09-22T00:44:58.335+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 CS6 - - (pid=26237) 2021-09-22T00:44:58.336+09:00 info: TunerDevice#5 released 2021-09-22T00:44:58.336+09:00 warn: TunerDevice#5 respawning because request has not closed 2021-09-22T00:44:58.440+09:00 info: TunerDevice#5 process has spawned by command recpt1 --device /dev/px4video5 BS9_0 - - (pid=26238) 2021-09-22T00:44:58.441+09:00 info: TunerDevice#4 released 2021-09-22T00:44:58.441+09:00 warn: TunerDevice#4 respawning because request has not closed 2021-09-22T00:44:58.549+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26239) 2021-09-22T00:44:58.550+09:00 info: TunerDevice#3 released 2021-09-22T00:44:58.550+09:00 warn: TunerDevice#3 respawning because request has not closed 2021-09-22T00:44:58.656+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 21 - - (pid=26240) 2021-09-22T00:44:58.656+09:00 info: TunerDevice#2 released 2021-09-22T00:44:58.657+09:00 warn: TunerDevice#2 respawning because request has not closed 2021-09-22T00:44:58.765+09:00 info: TunerDevice#2 process has spawned by command recpt1 --device /dev/px4video2 22 - - (pid=26241) 2021-09-22T00:44:58.765+09:00 info: TunerDevice#1 released 2021-09-22T00:44:58.765+09:00 warn: TunerDevice#1 respawning because request has not closed 2021-09-22T00:44:58.883+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS16 - - (pid=26242) 2021-09-22T00:44:58.885+09:00 info: TunerDevice#2 process has closed with exit code=1 by signal null (pid=26241) 2021-09-22T00:44:58.885+09:00 info: TunerDevice#3 process has closed with exit code=1 by signal null (pid=26240) 2021-09-22T00:44:58.886+09:00 info: TunerDevice#4 process has closed with exit code=1 by signal null (pid=26239) 2021-09-22T00:44:58.886+09:00 info: TunerDevice#5 process has closed with exit code=1 by signal null (pid=26238) 2021-09-22T00:44:58.887+09:00 info: TunerDevice#0 process has closed with exit code=1 by signal null (pid=26237) 2021-09-22T00:44:58.887+09:00 info: TunerDevice#1 process has closed with exit code=1 by signal null (pid=26242) 2021-09-22T00:44:58.986+09:00 info: TunerDevice#2 released 2021-09-22T00:44:58.987+09:00 warn: TunerDevice#2 respawning because request has not closed 2021-09-22T00:44:59.096+09:00 info: TunerDevice#2 process has spawned by command recpt1 --device /dev/px4video2 22 - - (pid=26243) 2021-09-22T00:44:59.097+09:00 info: TunerDevice#3 released 2021-09-22T00:44:59.097+09:00 warn: TunerDevice#3 respawning because request has not closed 2021-09-22T00:44:59.200+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 21 - - (pid=26244) 2021-09-22T00:44:59.201+09:00 info: TunerDevice#4 released 2021-09-22T00:44:59.201+09:00 warn: TunerDevice#4 respawning because request has not closed 2021-09-22T00:44:59.303+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26245) 2021-09-22T00:44:59.304+09:00 info: TunerDevice#5 released 2021-09-22T00:44:59.304+09:00 warn: TunerDevice#5 respawning because request has not closed 2021-09-22T00:44:59.426+09:00 info: TunerDevice#5 process has spawned by command recpt1 --device /dev/px4video5 BS9_0 - - (pid=26246) 2021-09-22T00:44:59.427+09:00 info: TunerDevice#0 released 2021-09-22T00:44:59.427+09:00 warn: TunerDevice#0 respawning because request has not closed 2021-09-22T00:44:59.537+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 CS6 - - (pid=26247) 2021-09-22T00:44:59.537+09:00 info: TunerDevice#1 released 2021-09-22T00:44:59.538+09:00 warn: TunerDevice#1 respawning because request has not closed 2021-09-22T00:44:59.648+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS16 - - (pid=26248) 2021-09-22T00:44:59.649+09:00 info: TunerDevice#4 process has closed with exit code=1 by signal null (pid=26245) 2021-09-22T00:44:59.749+09:00 info: TunerDevice#4 released 2021-09-22T00:44:59.750+09:00 warn: TunerDevice#4 respawning because request has not closed 2021-09-22T00:44:59.867+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 BS13_2 - - (pid=26252) 2021-09-22T00:45:26.682+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:45:26.683+09:00 info: TunerDevice#3 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:45:26.684+09:00 info: Network#32740 EPG gathering has finished 2021-09-22T00:45:26.686+09:00 info: Network#32741 EPG gathering has started 2021-09-22T00:45:26.688+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:45:26.688+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:45:26.796+09:00 info: TunerDevice#7 process has spawned by command recpt1 --device /dev/px4video7 24 - - (pid=26268) 2021-09-22T00:45:26.796+09:00 info: TunerDevice#7 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:45:29.684+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:45:29.693+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal null (pid=26244) 2021-09-22T00:45:29.794+09:00 info: TunerDevice#3 released 2021-09-22T00:46:27.264+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:46:27.265+09:00 info: TunerDevice#7 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:46:27.268+09:00 info: Network#32741 EPG gathering has finished 2021-09-22T00:46:27.271+09:00 info: Network#32742 EPG gathering has started 2021-09-22T00:46:27.273+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:46:27.273+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:46:27.381+09:00 info: TunerDevice#3 process has spawned by command recpt1 --device /dev/px4video3 23 - - (pid=26272) 2021-09-22T00:46:27.382+09:00 info: TunerDevice#3 streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:46:28.337+09:00 info: TSFilter#_standbyLogoData: waiting for logo data for 30 minutes... (networkId=32742, logoId=1) 2021-09-22T00:46:30.265+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:46:30.276+09:00 info: TunerDevice#7 process has closed with exit code=0 by signal null (pid=26268) 2021-09-22T00:46:30.377+09:00 info: TunerDevice#7 released 2021-09-22T00:47:17.044+09:00 info: 172.18.0.2 - GET /api/services? HTTP/1.1 200 - - 15.811 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:47:18.508+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:55:00.001+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=41967... 2021-09-22T00:55:00.007+09:00 info: TSFilter#_close: closed (serviceId=1048, eventId=41967) 2021-09-22T00:55:00.008+09:00 info: TunerDevice#2 end streaming to user 172.18.0.2:57264 (priority=2) 2021-09-22T00:55:00.009+09:00 info: TSDecoder#216 has closed (command=arib-b25-stream-test) 2021-09-22T00:55:00.013+09:00 info: 172.18.0.2 - GET /api/programs/327390104841967/stream?decode=1 HTTP/1.1 200 - - 504262.684 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:55:00.015+09:00 info: TSDecoder#216 process has closed with exit code=0 by signal SIGKILL (pid=26176) 2021-09-22T00:55:03.009+09:00 info: save db /app-data/services.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:55:03.017+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal null (pid=26243) 2021-09-22T00:55:03.119+09:00 info: TunerDevice#2 released 2021-09-22T00:56:27.383+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:56:27.384+09:00 info: TunerDevice#3 end streaming to user Mirakurun:getEPG() (priority=-1) 2021-09-22T00:56:27.385+09:00 info: Network#32742 EPG gathering has finished 2021-09-22T00:56:27.403+09:00 info: Program GC has finished and removed 230 programs 2021-09-22T00:56:27.403+09:00 info: ChannelItem#'BS:BS23_1' serviceId=255 check has started 2021-09-22T00:56:30.391+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal null (pid=26272) 2021-09-22T00:56:30.492+09:00 info: TunerDevice#3 released 2021-09-22T00:56:37.404+09:00 info: save db /app-data/programs.json w/ integirty (c5nesldxPAbxWsvIsiNY5rjspiL0vY8gY/gv6vzVo0o=) 2021-09-22T00:56:39.876+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:56:39.886+09:00 info: ChannelItem#'BS:BS3_2' serviceId=256 check has started 2021-09-22T00:56:52.157+09:00 warn: ChannelItem#'BS:BS3_2' serviceId=256 check has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:56:52.159+09:00 info: ChannelItem#'BS:BS21_2' serviceId=245 check has started 2021-09-22T00:57:04.436+09:00 warn: ChannelItem#'BS:BS21_2' serviceId=245 check has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:57:04.437+09:00 info: ChannelItem#'BS:BS21_1' serviceId=244 check has started 2021-09-22T00:57:08.652+09:00 info: 172.18.0.2 - GET /api/programs/40021134954/stream?decode=1 HTTP/1.1 200 - - 485786.671 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:57:08.652+09:00 info: TSDecoder#218 has closed (command=arib-b25-stream-test) 2021-09-22T00:57:08.653+09:00 info: TSFilter#_close: closed (serviceId=211, eventId=34954) 2021-09-22T00:57:08.654+09:00 info: TunerDevice#5 end streaming to user 172.18.0.2:57268 (priority=2) 2021-09-22T00:57:08.655+09:00 info: TSDecoder#218 process has closed with exit code=0 by signal SIGKILL (pid=26184) 2021-09-22T00:57:08.662+09:00 info: 172.18.0.2 - GET /api/programs/70033150984/stream?decode=1 HTTP/1.1 200 - - 486455.256 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:57:08.662+09:00 info: TSDecoder#217 has closed (command=arib-b25-stream-test) 2021-09-22T00:57:08.663+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50984) 2021-09-22T00:57:08.663+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57266 (priority=2) 2021-09-22T00:57:08.665+09:00 info: 172.18.0.2 - GET /api/programs/70033360522/stream?decode=1 HTTP/1.1 200 - - 486543.259 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:57:08.665+09:00 info: TSDecoder#219 has closed (command=arib-b25-stream-test) 2021-09-22T00:57:08.665+09:00 info: TSFilter#_close: closed (serviceId=333, eventId=60522) 2021-09-22T00:57:08.665+09:00 info: TunerDevice#1 end streaming to user 172.18.0.2:57270 (priority=2) 2021-09-22T00:57:08.666+09:00 info: TSDecoder#217 process has closed with exit code=0 by signal SIGKILL (pid=26181) 2021-09-22T00:57:08.666+09:00 info: TSDecoder#219 process has closed with exit code=0 by signal SIGKILL (pid=26190) 2021-09-22T00:57:08.697+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T00:57:08.697+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T00:57:08.709+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal null (pid=26247) 2021-09-22T00:57:08.749+09:00 info: 172.18.0.2 - GET /api/programs/40023653486/stream?decode=1 HTTP/1.1 200 - - 503742.570 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:57:08.750+09:00 info: TSDecoder#215 has closed (command=arib-b25-stream-test) 2021-09-22T00:57:08.752+09:00 info: TSFilter#_close: closed (serviceId=236, eventId=53486) 2021-09-22T00:57:08.752+09:00 info: TunerDevice#4 end streaming to user 172.18.0.2:57262 (priority=2) 2021-09-22T00:57:08.754+09:00 info: TSDecoder#215 process has closed with exit code=0 by signal SIGKILL (pid=26170) 2021-09-22T00:57:08.809+09:00 info: TunerDevice#0 released 2021-09-22T00:57:08.967+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 BS21_1 - - (pid=26276) 2021-09-22T00:57:08.967+09:00 info: TunerDevice#0 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:57:11.667+09:00 info: TunerDevice#5 process has closed with exit code=0 by signal null (pid=26246) 2021-09-22T00:57:11.677+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26248) 2021-09-22T00:57:11.758+09:00 info: TunerDevice#4 process has closed with exit code=0 by signal null (pid=26252) 2021-09-22T00:57:11.767+09:00 info: TunerDevice#5 released 2021-09-22T00:57:11.777+09:00 info: TunerDevice#1 released 2021-09-22T00:57:11.859+09:00 info: TunerDevice#4 released 2021-09-22T00:57:12.933+09:00 info: TSFilter: created (serviceId=331, eventId=50984) 2021-09-22T00:57:12.933+09:00 info: TSFilter: waiting for serviceId=331, eventId=50984 2021-09-22T00:57:13.038+09:00 info: TunerDevice#1 process has spawned by command recpt1 --device /dev/px4video1 CS6 - - (pid=26280) 2021-09-22T00:57:13.038+09:00 info: TunerDevice#1 streaming to user 172.18.0.2:57298 (priority=2) 2021-09-22T00:57:13.039+09:00 info: TSDecoder#223 has created (command=arib-b25-stream-test) 2021-09-22T00:57:13.146+09:00 info: TSDecoder#223 process has spawned by command arib-b25-stream-test (pid=26281) 2021-09-22T00:57:15.937+09:00 info: TSFilter: created (serviceId=333, eventId=60522) 2021-09-22T00:57:15.937+09:00 info: TSFilter: waiting for serviceId=333, eventId=60522 2021-09-22T00:57:16.050+09:00 info: TunerDevice#4 process has spawned by command recpt1 --device /dev/px4video4 CS16 - - (pid=26286) 2021-09-22T00:57:16.050+09:00 info: TunerDevice#4 streaming to user 172.18.0.2:57300 (priority=2) 2021-09-22T00:57:16.051+09:00 info: TSDecoder#224 has created (command=arib-b25-stream-test) 2021-09-22T00:57:16.155+09:00 info: TSDecoder#224 process has spawned by command arib-b25-stream-test (pid=26287) 2021-09-22T00:57:16.963+09:00 info: TSFilter: created (serviceId=236, eventId=53486) 2021-09-22T00:57:16.963+09:00 info: TSFilter: waiting for serviceId=236, eventId=53486 2021-09-22T00:57:17.075+09:00 info: TunerDevice#5 process has spawned by command recpt1 --device /dev/px4video5 BS13_2 - - (pid=26292) 2021-09-22T00:57:17.075+09:00 info: TunerDevice#5 streaming to user 172.18.0.2:57302 (priority=2) 2021-09-22T00:57:17.075+09:00 info: TSDecoder#225 has created (command=arib-b25-stream-test) 2021-09-22T00:57:17.189+09:00 info: TSDecoder#225 process has spawned by command arib-b25-stream-test (pid=26293) 2021-09-22T00:57:17.257+09:00 info: 172.18.0.2 - GET /api/services? HTTP/1.1 200 - - 52.856 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:57:18.376+09:00 info: TSFilter#_onEIT: now ready for eventId=60522 2021-09-22T00:57:18.544+09:00 info: TSFilter#_onEIT: now ready for eventId=53486 2021-09-22T00:57:19.686+09:00 info: TSFilter: created (serviceId=211, eventId=34954) 2021-09-22T00:57:19.686+09:00 info: TSFilter: waiting for serviceId=211, eventId=34954 2021-09-22T00:57:19.710+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal null (pid=26276) 2021-09-22T00:57:19.811+09:00 info: TunerDevice#0 released 2021-09-22T00:57:19.901+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 BS9_0 - - (pid=26298) 2021-09-22T00:57:19.901+09:00 info: TunerDevice#0 streaming to user 172.18.0.2:57306 (priority=2) 2021-09-22T00:57:19.902+09:00 info: TSDecoder#226 has created (command=arib-b25-stream-test) 2021-09-22T00:57:19.997+09:00 info: TSDecoder#226 process has spawned by command arib-b25-stream-test (pid=26299) 2021-09-22T00:57:28.971+09:00 info: TSFilter#_close: closed (serviceId=null, eventId=null) 2021-09-22T00:57:28.973+09:00 info: TunerDevice#0 end streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T00:57:28.976+09:00 warn: ChannelItem#'BS:BS21_1' serviceId=244 check has failed [Error: stream has closed before get network at TSFilter. (/app/src/Mirakurun/Tuner.ts:223:28) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at TSFilter._close (/app/src/Mirakurun/TSFilter.ts:1074:14) at Object.onceWrapper (node:events:513:28) at TSFilter.emit (node:events:406:35) at Timeout._onTimeout (/app/src/Mirakurun/Tuner.ts:200:37) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:57:28.981+09:00 info: ChannelItem#'BS:BS19_0' serviceId=234 check has started 2021-09-22T00:57:41.260+09:00 warn: ChannelItem#'BS:BS19_0' serviceId=234 check has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:57:41.271+09:00 info: ChannelItem#'BS:BS23_0' serviceId=251 check has started 2021-09-22T00:57:53.538+09:00 warn: ChannelItem#'BS:BS23_0' serviceId=251 check has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:58:46.457+09:00 info: ChannelItem#'BS:BS23_1' service scan has started 2021-09-22T00:58:58.735+09:00 warn: ChannelItem#'BS:BS23_1' service scan has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:59:06.651+09:00 info: ChannelItem#'BS:BS3_2' service scan has started 2021-09-22T00:59:18.933+09:00 warn: ChannelItem#'BS:BS3_2' service scan has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:59:39.888+09:00 info: ChannelItem#'BS:BS23_1' serviceId=255 check has started 2021-09-22T00:59:45.080+09:00 info: 172.18.0.2 - GET /api/programs/70033150984? HTTP/1.1 200 597 - 29.872 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:59:45.087+09:00 info: 172.18.0.2 - GET /api/programs/70033150984? HTTP/1.1 200 597 - 2.631 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:59:52.159+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: no available tuners at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32) at listOnTimeout (node:internal/timers:557:17) at processTimers (node:internal/timers:500:7)] 2021-09-22T00:59:52.169+09:00 info: ChannelItem#'BS:BS3_2' serviceId=256 check has started 2021-09-22T00:59:57.379+09:00 info: 172.18.0.2 - GET /api/programs/40014112151/stream?decode=1 HTTP/1.1 503 - - 12279.265 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T00:59:57.381+09:00 info: 172.18.0.2 - GET /api/programs/70034256055/stream?decode=1 HTTP/1.1 503 - - 12286.281 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T01:00:00.001+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=50984... 2021-09-22T01:00:00.004+09:00 info: TSFilter#_close: closed (serviceId=331, eventId=50984) 2021-09-22T01:00:00.005+09:00 info: TunerDevice#1 end streaming to user 172.18.0.2:57298 (priority=2) 2021-09-22T01:00:00.006+09:00 info: TSDecoder#223 has closed (command=arib-b25-stream-test) 2021-09-22T01:00:00.009+09:00 info: 172.18.0.2 - GET /api/programs/70033150984/stream?decode=1 HTTP/1.1 200 - - 167081.245 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T01:00:00.010+09:00 warn: TSFilter#_observeProvideEvent: closing because EIT p/f timed out for eventId=34954... 2021-09-22T01:00:00.011+09:00 info: TSFilter#_close: closed (serviceId=211, eventId=34954) 2021-09-22T01:00:00.011+09:00 info: TunerDevice#0 end streaming to user 172.18.0.2:57306 (priority=2) 2021-09-22T01:00:00.012+09:00 info: TSDecoder#226 has closed (command=arib-b25-stream-test) 2021-09-22T01:00:00.014+09:00 info: 172.18.0.2 - GET /api/programs/40021134954/stream?decode=1 HTTP/1.1 200 - - 160328.258 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T01:00:00.020+09:00 info: TSDecoder#226 process has closed with exit code=0 by signal SIGKILL (pid=26299) 2021-09-22T01:00:00.021+09:00 info: TSDecoder#223 process has closed with exit code=0 by signal SIGKILL (pid=26281) 2021-09-22T01:00:00.183+09:00 info: TSFilter: created (serviceId=0, eventId=0) 2021-09-22T01:00:00.183+09:00 info: TSFilter: waiting for serviceId=0, eventId=0 2021-09-22T01:00:00.196+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal null (pid=26298) 2021-09-22T01:00:00.297+09:00 info: TunerDevice#0 released 2021-09-22T01:00:00.392+09:00 info: TunerDevice#0 process has spawned by command recpt1 --device /dev/px4video0 BS3_2 - - (pid=26304) 2021-09-22T01:00:00.392+09:00 info: TunerDevice#0 streaming to user Mirakurun:getServices() (priority=-1) 2021-09-22T01:00:00.398+09:00 info: TSFilter#_onEIT: closing because eventId=60522 has ended... 2021-09-22T01:00:01.399+09:00 info: TSFilter#_close: closed (serviceId=333, eventId=60522) 2021-09-22T01:00:01.400+09:00 info: TunerDevice#4 end streaming to user 172.18.0.2:57300 (priority=2) 2021-09-22T01:00:01.400+09:00 info: TSDecoder#224 has closed (command=arib-b25-stream-test) 2021-09-22T01:00:01.402+09:00 info: 172.18.0.2 - GET /api/programs/70033360522/stream?decode=1 HTTP/1.1 200 - - 2575.899 ms epgstation/2.6.11 MirakurunClient/3.9.0-beta.1 Node/v16.8.0 (linux) 2021-09-22T01:00:01.405+09:00 info: TSDecoder#224 process has closed with exit code=0 by signal SIGKILL (pid=26287) 2021-09-22T01:00:02.404+09:00 info: TSFilter: created (serviceId=141, eventId=12151) 2021-09-22T01:00:02.404+09:00 info: TSFilter: waiting for serviceId=141, eventId=12151 2021-09-22T01:00:02.405+09:00 info: TSFilter: created (serviceId=342, eventId=56055) 2021-09-22T01:00:02.406+09:00 info: TSFilter: waiting for serviceId=342, eventId=56055 2021-09-22T01:00:02.416+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal null (pid=26280)

l3tnun commented 2 years ago

返信が遅くなってしまってすいません。

ログを見る限り epgstation と mirakurun がうまく通信できていなさそうな感じがします。

Error: aborted ですが mirakurun から正常に通信が閉じられていないのかなあと思います。

https://github.com/nodejs/node/blob/v16.x/lib/_http_client.js#L405-L407

あと epgstation ログにも以下のようにでていますが、Mirakurun のチューナの状態がおかしいようです。

[2021-09-22T00:29:57.697] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).

Mirakurun のログだと以下の部分ですかね

2021-09-22T00:56:39.876+09:00 warn: ChannelItem#'BS:BS23_1' serviceId=255 check has failed [Error: no available tuners
at Timeout.find [as _onTimeout] (/app/src/Mirakurun/Tuner.ts:390:32)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)]

おそらく発生場所は↓ですが、使用できるチューナがあるはずなのに実際にはチューナが開放されていないとこうなりそうですので、Mirakurun 側の不具合調査も行ったほうが良いかと思います。

https://github.com/Chinachu/Mirakurun/blob/3.9.0-beta.1/src/Mirakurun/Tuner.ts#L390

hikuma3 commented 2 years ago

お世話になります。前回ご連絡からの期間で、ずっとget execution error: の再現確認をしていました。 epgstationのepgstation@2.6.11からepgstation@2.6.20に更新しています。

私が経験的にエラーになりやすいと思っていたのは、長時間番組の録画後周辺でした。必ずではありませんが、4時間、５時間などの長時間番組録画後に、続く次の録画くらいのタイミングでget execution error: が始まることが多いように思えたからです。

私の環境では、droplogと一時録画をローカルのSSDへ。録画後の保管場所をNASに指定してあります。録画後のエンコードはしていません。EPGS <->NAS間は1Gbpsの有線LANで接続していますが、さすがに25-40GBのtsファイルだと転送に時間がかかります。 get execution error: の発生原因はロックが長いことという事でしたので、もしファイル転送の時間がロックに影響しているのであれば、「ファイル転送が遅くなれば、現象が再現しやすいのではないか？」と思い、実験してみました。

EPGS<->NAS間のHUBを1Gbpsから100Mbpsに変更して、2時間程度の番組を複数連続して録画したところ、以前に比べてget execution error: が非常に発生しやすくなりました。この実験で変更したのはHUBだけです。

ということで、録画終了後のtsファイルの移動(またはコピー)が遅い場合にget execution error: になるのではないかと思うのですが、いかがでしょうか？課題解決に向けて何か、お気づきの点はありませんか？

l3tnun / EPGStation

録画の強制終了について #510

環境

Issue