録画完了後エンコードされないものがある #382

tomo0611 · 2021-01-16T02:53:51Z

環境

Version of EPGStation: v2.0.2
Version of Mirakurun: v3.5.0
Version of Node: v14.15.1
Version of NPM: v6.14.11
OS: Ubuntu Server 20.04 (5.4.0-58-generic)
Architecture: x64
ストレージ: 480GB (100GB以上の空きスペース)

Issue

録画完了後、エンコードされないものがあり、放送終了から時間が経っても録画キューに残り続ける。

BS11イレブンでのみ発生する模様です。

エンコードコマンド

エンコードに利用しているコマンドは以下の通りでターミナルから実行したら普段よりエラーは多いもののちゃんとm2tsに変換できます。

tomochan@tomontu-server:~/Videos$ ffmpeg -i '[新] XXX #1「YYY」.ts' -c:a ac3 -ab 256k -ignore_unknown -c:v copy -copyts -start_at_zero -muxdelay 0 -max_delay 0 '[新] XXX #1「YYY」.m2ts'
ffmpeg version 4.2.4-1ubuntu0.1 Copyright (c) 2000-2020 the FFmpeg developers
[mpeg2video] Invalid frame dimensions 0x0.
    Last message repeated 9 times
[mpegts] start time for stream 3 is not set in estimate_timings_from_pts
[mpegts] PES packet size mismatch
Input #0, mpegts, from '[新] XXX #1「YYY」.ts':
  Duration: 00:30:04.73, start: ZZZ, bitrate: 18183 kb/s
  Program 211
    Metadata:
      service_name    : BS11イレブン
      service_provider: 日本BS放送
    Stream #0:0[0x140]: Video: mpeg2video, yuv420p(tv, bt709, top first), 1920x1080 [SAR 1:1 DAR 16:9], 29.97 fps
    Stream #0:1[0x141]: Audio: aac (LC), 48000 Hz, stereo, fltp, 241 kb/s
    Stream #0:2[0x145]: Subtitle: arib_caption (Profile A)
    Stream #0:3[0x138]: Data: bin_data
Stream mapping:
  Stream #0:0 -> #0:0 (copy)
  Stream #0:1 -> #0:1 (aac (native) -> ac3 (native))

[aac] SBR was found before the first channel element.
[aac] Sample rate index in program config element does not match the sample rate index configured by the container.
[aac] Inconsistent channel configuration.
[aac] get_buffer() failed
Error while decoding stream #0:1: Invalid argument
Output #0, mpegts, to '[新] XXX #1「YYY」.m2ts':
  Metadata:
    encoder         : Lavf58.29.100
    Stream #0:0: Video: mpeg2video, yuv420p(tv, bt709, top first), 1920x1080 [SAR 1:1 DAR 16:9], 29.97 fps
    Stream #0:1: Audio: ac3, 48000 Hz, stereo, fltp, 256 kb/s
    Metadata:
      encoder         : Lavc58.54.100 ac3
[mpegts] PES packet size mismatch
[aac] Input buffer exhausted before END element found
Error while decoding stream #0:1: Invalid data found when processing input

frame=54070 fps=681 q=-1.0 Lsize= 4226567kB time=00:30:04.59 bitrate=19186.6kbits/s speed=75.7x
video:3772223kB audio:56383kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 10.394431%

五等分の花嫁∬ 第2話「七つのさよなら第一章」の後に D4DJ First Mix(第11話) がエンコードされるはずですが、
五等分の花嫁∬ 第2話「七つのさよなら第一章」は無視されてD4DJ First Mix(第11話)のエンコードが始まっています。

ログ(Service)

[2021-01-15T23:30:02.298] [INFO] system - add new encode: 59
[2021-01-15T23:30:02.330] [INFO] system - encode start. mode: MPEG2-TS name: アニメ D4DJ First Mix #11 file: /home/tomochan/Videos/アニメ D4DJ First Mix #11.ts -> /home/tomochan/Videos/アニメ D4DJ First Mix #11.m2ts
[2021-01-15T23:30:02.359] [INFO] system - create new encode process: 1610721002359
[2021-01-15T23:30:02.990] [INFO] system - add new encode: 60
[2021-01-15T23:30:03.125] [INFO] system - encode start. mode: MPEG2-TS name: 蜘蛛ですが、なにか？ 第2話「マイホーム、炎上？」.ts file: /home/tomochan/Videos/蜘蛛ですが、なにか？ 第2話「マイホーム、炎上？」.ts -> /home/tomochan/Videos/蜘蛛ですが、なにか？ 第2話「マイホーム、炎上？」.m2ts
[2021-01-15T23:30:03.159] [INFO] system - create new encode process: 1610721003159
[2021-01-15T23:32:34.057] [INFO] system - exit code: 0, signal: null
[2021-01-15T23:32:34.058] [INFO] system - Successfully encod: 60 /home/tomochan/Videos/蜘蛛ですが、なにか？ 第2話「マイホーム、炎上？」.m2ts
[2021-01-15T23:32:34.058] [INFO] system - rmOrg: true, hasSam: false
[2021-01-16T00:00:02.937] [INFO] system - add new encode: 61
[2021-01-16T00:00:03.004] [INFO] system - encode start. mode: MPEG2-TS name: D4DJ First Mix(第11話) file: /home/tomochan/Videos/D4DJ First Mix(第11話).ts -> /home/tomochan/Videos/D4DJ First Mix(第11話).m2ts
[2021-01-16T00:00:03.032] [INFO] system - create new encode process: 1610722803032
[2021-01-16T00:01:12.932] [INFO] system - exit code: 0, signal: null
[2021-01-16T00:01:12.932] [INFO] system - Successfully encod: 61 /home/tomochan/Videos/D4DJ First Mix(第11話).m2ts
[2021-01-16T00:01:12.933] [INFO] system - rmOrg: true, hasSam: false
[2021-01-16T00:30:03.136] [INFO] system - add new encode: 62
[2021-01-16T00:30:03.168] [INFO] system - encode start. mode: MPEG2-TS name: 蜘蛛ですが、なにか？(第2話) file: /home/tomochan/Videos/蜘蛛ですが、なにか？(第2話).ts -> /home/tomochan/Videos/蜘蛛ですが、なにか？(第2話).m2ts
[2021-01-16T00:30:03.194] [INFO] system - create new encode process: 1610724603194
[2021-01-16T00:30:03.811] [INFO] system - add new encode: 63
[2021-01-16T00:30:03.882] [INFO] system - encode start. mode: MPEG2-TS name: バック・アロウ #2「夢はまったく迷惑なのか」 file: /home/tomochan/Videos/バック・アロウ #2「夢はまったく迷惑なのか」.ts -> /home/tomochan/Videos/バック・アロウ #2「夢はまったく迷惑なのか」.m2ts
[2021-01-16T00:30:03.920] [INFO] system - create new encode process: 1610724603919

ログ(Operator)

[2021-01-15T23:57:42.698] [INFO] system - successful update rule reservation: 21
[2021-01-15T23:57:42.708] [INFO] system - all reservation update finish
[2021-01-15T23:59:45.003] [INFO] system - preprec: 1836
[2021-01-15T23:59:45.029] [INFO] system - preprec: 1844
[2021-01-16T00:00:01.895] [INFO] system - recording: 1844 /home/tomochan/Videos/蜘蛛ですが、なにか？(第2話).ts
[2021-01-16T00:00:01.900] [INFO] system - add recorded: 1844 /home/tomochan/Videos/蜘蛛ですが、なにか？(第2話).ts
[2021-01-16T00:00:01.941] [INFO] system - create video file: 蜘蛛ですが、なにか？(第2話).ts
[2021-01-16T00:00:01.966] [INFO] system - execute cmd: /bin/bash /home/tomochan/XXX.sh (録画開始通知)
[2021-01-16T00:00:02.446] [INFO] system - /bin/bash /home/tomochan/XXX.sh process is fin
[2021-01-16T00:00:02.825] [DEBUG] system - delete stream: 1824
[2021-01-16T00:00:02.897] [FATAL] system - movingFromTmp error: 4485
[2021-01-16T00:00:02.897] [FATAL] system - Error: RecordedTmpIsUndefined
    at RecordingUtilModel.<anonymous> (/home/tomochan/EPGStationV2/dist/model/operator/recording/model/operator/recording/RecordingUtilModel.ts:203:19)
    at Generator.next (<anonymous>)
    at fulfilled (/home/tomochan/EPGStationV2/dist/model/operator/recording/RecordingUtilModel.js:36:58)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
[2021-01-16T00:00:02.905] [INFO] system - update file size: 4485
[2021-01-16T00:00:02.934] [DEBUG] system - delete recording index: 1824
[2021-01-16T00:00:02.935] [INFO] system - add thumbnail queue: 4485
[2021-01-16T00:00:02.936] [INFO] system - recording finish: 1824 /home/tomochan/Videos/D4DJ First Mix(第11話).ts
[2021-01-16T00:00:02.936] [INFO] system - update rule reservation: 1
[2021-01-16T00:00:02.938] [INFO] system - execute cmd: /bin/bash /home/tomochan/XXX.sh (録画終了通知)
[2021-01-16T00:00:03.357] [INFO] system - recording: 1836 /home/tomochan/Videos/バック・アロウ #2「夢はまったく迷惑なのか」.ts
[2021-01-16T00:00:03.358] [INFO] system - add recorded: 1836 /home/tomochan/Videos/バック・アロウ #2「夢はまったく迷惑なのか」.ts
[2021-01-16T00:00:03.438] [INFO] system - create video file: バック・アロウ #2「夢はまったく迷惑なのか」.ts
[2021-01-16T00:00:03.441] [INFO] system - successful update rule reservation: 1
[2021-01-16T00:00:03.442] [DEBUG] system - delete recording: 1833
[2021-01-16T00:00:03.442] [INFO] system - stop recording: 1833
[2021-01-16T00:00:03.451] [DEBUG] system - delete stream: 1833
[2021-01-16T00:00:03.882] [INFO] system - create thumbnail: 4485, /home/tomochan/EPGStationV2/thumbnail/2134.jpg
[2021-01-16T00:00:24.272] [INFO] system - /bin/bash /home/tomochan/XXX.sh process is fin (録画終了通知)
[2021-01-16T00:00:24.274] [INFO] system - execute cmd: /bin/bash /home/tomochan/XXX.sh (録画開始通知)
[2021-01-16T00:00:24.482] [INFO] system - /bin/bash /home/tomochan/XXX.sh process is fin (録画開始通知)
[2021-01-16T00:01:12.937] [INFO] system - add video file: 2134 D4DJ First Mix(第11話).m2ts
[2021-01-16T00:01:13.032] [INFO] system - delete video file: 4485
[2021-01-16T00:01:13.074] [INFO] system - delete: /home/tomochan/Videos/D4DJ First Mix(第11話).ts
[2021-01-16T00:07:44.105] [INFO] system - all reservation update start
[2021-01-16T00:07:44.183] [INFO] system - update rule reservation: 1

Configは以下のようになっていて、recordedTmpは設定していません。

recordedFormat: '%HALF_WIDTH_TITLE%'
recordedFileExtension: .ts
recorded:
    - name: recorded
      path: '/home/tomochan/Videos/'

録画後のプロセス

録画終了後、サムネ付きで外部にメッセージを送信するスクリプトを動かした後、 enc2.js でエンコードを行っています。
enc2.js は enc3.js のパラメータを少し変えただけのものです。

The text was updated successfully, but these errors were encountered:

l3tnun · 2021-01-16T06:37:27Z

録画終了処理が一部うまくできていないようですね。
recordedTmp の設定が無いのに移動させようとしていることが気になります。
#377 と関連しているかもしていません。

原因が不明ですがソース追ってみます。

l3tnun · 2021-01-16T07:40:47Z

Error: RecordedTmpIsUndefined この問題については修正しましたが、今回の問題には影響がないことがわかりました。

l3tnun · 2021-01-16T07:48:08Z

まず、エンコードが始まらない理由ですが、これは録画の状態が録画中から録画済みへ移行しないためです。

そのため、今回スクショで頂いた録画の中で録画中から録画済みへ移動しなかった録画のログを提供していただきたいです。(一枚目のスクショの録画中に残っている番組であればどれでも大丈夫です。)
理由としては録画終了処理がそもそも実行されているか確認したいためです。

お手数おかけしますが、よろしくお願い致します。

tomo0611 · 2021-01-16T11:22:15Z

録画のログとは上に貼ってあるoperatorとserviceのsystem以外のログですか?

録画終了処理がされてないと思われます。
外部コマンドも叩かれていないので。

tomo0611 · 2021-01-16T12:42:43Z

家に帰ってからもう一度確認しますが、ログは貼ってあるやつで全てだっただと思います。

1824がD4DJ First Mix(第11話) で
1833が五等分の花嫁∬ 第2話「七つのさよなら第一章」だった気が(これも帰って確認します)

外部からデータベースのアイテムを読み書きするスクリプトが走ってるのでそれの影響もないか確認します

l3tnun · 2021-01-16T13:25:42Z

情報ありがとうございます。
終了処理が走っているか否か判別したかっただけですので、ログの件は大丈夫です。

外部からデータベースのアイテムを読み書きするスクリプトが走ってるのでそれの影響もないか確認します

使用している DB は何でしょうか？
SQLite3 の場合書き込みに失敗して処理が上手くいかないかもしれません。

今回うまく動作していない部分が↓の recEnd 関数なのですが、

EPGStation/src/model/operator/recording/RecorderModel.ts

Line 472 in c5c291c

private async recEnd(recFile: fs.WriteStream): Promise<void> {

この関数内のどこが上手く行っていないのか、もしくは recEnd が呼び出されていないのか不明なのでログを追加します。
ログを追加したら master に反映させますので、それで様子を見ていただきたいです。

l3tnun · 2021-01-16T14:09:32Z

recEnd のログ拡充を master に反映させました。

tomo0611 · 2021-01-16T15:10:09Z

データベースはmariadbを使っています。
masterブランチからpullしてしばらく様子みます、ありがとうございます。

一応、データベースの様子も貼っておきます

MariaDB [epgstation]> select * from video_file order by id desc limit 4;
+------+---------------------+-------------------------------------------------------------------------------------------------------------------------------+---------+----------+-------------+------------+
| id   | parentDirectoryName | filePath                                                                                                                      | type    | name     | size        | recordedId |
+------+---------------------+---------------------------------------------------------------------------------------------------------------------------------------+---------+----------+-------------+------------+
| 4541 | recorded            | 22／7検算中 #2「声優メンバーのプロフィールを改めて確認しまSHOW!」.m2ts                                                                | encoded | MPEG2-TS |  4539825408 |       2150 |
| 4540 | recorded            | はたらく細胞!! 第2話「獲得免疫／パイエル板」.ts                                                                                      | ts      | TS       |           0 |       2151 |
| 4521 | recorded            | ./encoded/アニメ D4DJ First Mix #11.mp4                                                                                               | encoded | Re:Drive |   602472707 |       2132 |
| 4486 | recorded            | 五等分の花嫁∬ 第2話「七つのさよなら 第一章」.ts                                                                                       | ts      | TS       |           0 |       2135 |
+------+---------------------+---------------------------------------------------------------------------------------------------------------------------------------+---------+----------+-------------+------------+
4 rows in set (0.001 sec)

TSが録画した生データで、正常に動作すればMPEG2-TSに変換されます。で別のところでmp4にしてあげてそれをRe:Driveとしてvideo_fileに外部のphpスクリプトで追加してあげてます。

MariaDB [epgstation]> select * from recorded where startAt=1610721000000 order by id desc limit 1;

id	reserveId	ruleId	programId	channelId	isProtected	startAt	endAt	duration	name	halfWidthName	description	halfWidthDescription	extended	halfWidthExtended	genre1	subGenre1	genre2	subGenre2	genre3	subGenre3	videoType	videoResolution	videoStreamContent	videoComponentType	audioSamplingRate	audioComponentType	isRecording	dropLogFileId
2135	1833	1	40021124803	400211	0	1610721000000	1610722800000	1800000	五等分の花嫁∬　第２話「七つのさよなら第一章」	五等分の花嫁∬ 第2話「七つのさよなら第一章」	(概要)	(概要)	(番組内容)	7	0	NULL	NULL	NULL	NULL	mpeg2	1080i	1	NULL	48000	3	0	NULL

tomo0611 · 2021-01-17T00:25:53Z

適用後、早速発生してくれた(?)のでログ貼ります。

ログを見た感じ、stop recording: 1850 (ホリミヤ page. 2「顔は、ひとつだけじゃない。」)とあるので録画の停止自体は行われているみたいです。(終了処理は行われていないが)

とりあえず、録画停止通知スクリプトで20sほどsleepをしている部分があったのでそれを削除してまたやってみます。

system.log (Operator)

// 録画開始準備
[2021-01-17T00:29:45.005] [INFO] system - preprec: 1849 (アニメ STEINS;GATE 第16話)
[2021-01-17T00:29:45.030] [INFO] system - preprec: 1850 (ホリミヤ page. 2「顔は、ひとつだけじゃない。」)

// 録画開始
[2021-01-17T00:30:01.257] [INFO] system - recording: 1849 /home/tomochan/Videos/アニメ STEINS;GATE 第16話.ts
[2021-01-17T00:30:01.263] [INFO] system - add recorded: 1849 /home/tomochan/Videos/アニメ STEINS;GATE 第16話.ts
[2021-01-17T00:30:01.300] [INFO] system - create video file: アニメ STEINS;GATE 第16話.ts
[2021-01-17T00:30:01.325] [INFO] system - execute cmd: 録画開始通知(アニメ STEINS;GATE 第16話)
[2021-01-17T00:30:01.665] [INFO] system - 録画開始通知(アニメ STEINS;GATE 第16話) process is fin
[2021-01-17T00:30:02.447] [INFO] system - recording: 1850 /home/tomochan/Videos/ホリミヤ page．2「顔は、ひとつだけじゃない。」.ts
[2021-01-17T00:30:02.449] [INFO] system - add recorded: 1850 /home/tomochan/Videos/ホリミヤ page．2「顔は、ひとつだけじゃない。」.ts
[2021-01-17T00:30:02.477] [INFO] system - create video file: ホリミヤ page. 2「顔は、ひとつだけじゃない。」.ts
[2021-01-17T00:30:02.497] [INFO] system - execute cmd: 録画開始通知(ホリミヤ page. 2「顔は、ひとつだけじゃない。」)
[2021-01-17T00:30:02.702] [INFO] system - 録画開始通知(ホリミヤ page. 2「顔は、ひとつだけじゃない。」) process is fin

(番組内容更新などは除いてます)

// 次の録画開始準備
[2021-01-17T00:59:45.003] [INFO] system - preprec: 1851 (Levius レビウス #2.ts)

// 録画完了処理
[2021-01-17T01:00:02.161] [INFO] system - finish stream: 2156 (アニメ STEINS;GATE 第16話)
[2021-01-17T01:00:02.163] [INFO] system - stop recording: 2156 (アニメ STEINS;GATE 第16話)
[2021-01-17T01:00:02.166] [INFO] system - remove recording flag: 2156 (アニメ STEINS;GATE 第16話)
[2021-01-17T01:00:02.232] [INFO] system - update file size: 4549
[2021-01-17T01:00:02.264] [INFO] system - add recorded history: 2156 (アニメ STEINS;GATE 第16話)
[2021-01-17T01:00:02.282] [INFO] system - add thumbnail queue: 4549
[2021-01-17T01:00:02.283] [INFO] system - recording finish: 1849 /home/tomochan/Videos/アニメ STEINS;GATE 第16話.ts
[2021-01-17T01:00:02.284] [INFO] system - update rule reservation: 1
[2021-01-17T01:00:02.286] [INFO] system - execute cmd: 録画完了通知 (アニメ STEINS;GATE 第16話) 20秒sleep含む
[2021-01-17T01:00:02.717] [INFO] system - { insert: 0, update: 0, delete: 2 }
[2021-01-17T01:00:02.719] [INFO] system - recording: 1851 /home/tomochan/Videos/Levius レビウス #2.ts
[2021-01-17T01:00:02.723] [INFO] system - add recorded: 1851 /home/tomochan/Videos/Levius レビウス #2.ts
[2021-01-17T01:00:02.767] [INFO] system - successful update rule reservation: 1
[2021-01-17T01:00:02.768] [INFO] system - stop recording: 1850 (ホリミヤ page. 2「顔は、ひとつだけじゃない。」)
[2021-01-17T01:00:02.795] [INFO] system - create video file: Levius レビウス #2.ts
[2021-01-17T01:00:03.116] [INFO] system - create thumbnail: 4549, /home/tomochan/EPGStationV2/thumbnail/2156.jpg (アニメ STEINS;GATE 第16話)
[2021-01-17T01:00:23.686] [INFO] system - 次の番組(Levius レビウス #2)の録画開始通知 process is fin
[2021-01-17T01:00:23.688] [INFO] system - execute cmd: 次の番組(Levius レビウス #2)の録画開始通知
[2021-01-17T01:00:23.957] [INFO] system - /bin/bash /home/tomochan/EPGStationV2/config/postLine4.sh process is fin
[2021-01-17T01:01:03.648] [INFO] system - add video file: 2156 アニメ STEINS;GATE 第16話.m2ts (m2tsにエンコード)
[2021-01-17T01:01:03.664] [INFO] system - delete video file: 4549 (tsを削除)
[2021-01-17T01:01:03.703] [INFO] system - delete: /home/tomochan/Videos/アニメ STEINS;GATE 第16話.ts (tsを削除)

[2021-01-17T01:06:33.865] [INFO] system - all reservation update start

system.log (Service)

[2021-01-17T00:27:33.508] [INFO] system - Successfully encod: 2 (前の番組)
[2021-01-17T00:27:33.508] [INFO] system - rmOrg: true, hasSam: false
[2021-01-17T01:00:02.292] [INFO] system - add new encode: 3
[2021-01-17T01:00:02.336] [INFO] system - encode start. mode: MPEG2-TS name: アニメ STEINS;GATE 第16話 file: /home/tomochan/Videos/アニメ STEINS;GATE 第16話.ts -> /home/tomochan/Videos/アニメ STEINS;GATE 第16話.m2ts
[2021-01-17T01:00:02.363] [INFO] system - create new encode process: 1610812802362
[2021-01-17T01:01:03.641] [INFO] system - exit code: 0, signal: null
[2021-01-17T01:01:03.641] [INFO] system - Successfully encod: 3 /home/tomochan/Videos/アニメ STEINS;GATE 第16話.m2ts
[2021-01-17T01:01:03.642] [INFO] system - rmOrg: true, hasSam: false
[2021-01-17T01:30:03.721] [INFO] system - add new encode: 4 (次の番組)

tomo0611 · 2021-01-17T00:44:34Z

ソースを見る感じ、mirakurunへのstreamが閉じてない気もするのでmirakurunのhttpログも貼っておきます

STDOUT

tomochan@tomontu-server:/usr/local/etc/mirakurun$ tail -n 5000 /usr/local/var/log/mirakurun.stdout.log | grep epgstation
2021-01-17T00:29:08.827+09:00 info: - - GET /api/programs/40014119033/stream?decode=1 HTTP/1.1 200 - - 2346.212 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-17T00:29:12.897+09:00 info: - - GET /api/programs/40021124846/stream?decode=1 HTTP/1.1 200 - - 1005.419 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-17T01:00:02.165+09:00 info: - - GET /api/programs/40014118091/stream?decode=1 HTTP/1.1 200 - - 16167.990 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-17T01:00:02.774+09:00 info: - - GET /api/programs/40021124847/stream?decode=1 HTTP/1.1 200 - - 17359.469 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-17T01:30:03.460+09:00 info: - - GET /api/programs/40021124848/stream?decode=1 HTTP/1.1 200 - - 17393.391 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)

tomo0611 · 2021-01-17T01:24:40Z

ログ比較

[2021-01-17T00:29:45.005] [INFO] system - preprec: 1849 (アニメ STEINS;GATE 第16話)
[2021-01-17T00:30:01.257] [INFO] system - recording: 1849
[2021-01-17T00:30:01.263] [INFO] system - add recorded: 1849
[2021-01-17T00:30:01.300] [INFO] system - create video file: アニメ STEINS;GATE 第16話.ts
[2021-01-17T00:30:01.325] [INFO] system - execute cmd: 録画開始通知
[2021-01-17T00:30:01.665] [INFO] system - 録画開始通知 process is fin
[2021-01-17T01:00:02.161] [INFO] system - finish stream: 2156
[2021-01-17T01:00:02.163] [INFO] system - stop recording: 2156
[2021-01-17T01:00:02.166] [INFO] system - remove recording flag: 2156
[2021-01-17T01:00:02.232] [INFO] system - update file size: 4549
[2021-01-17T01:00:02.264] [INFO] system - add recorded history: 2156
[2021-01-17T01:00:02.282] [INFO] system - add thumbnail queue: 4549
[2021-01-17T01:00:02.283] [INFO] system - recording finish: 1849 /home/tomochan/Videos/アニメ STEINS;GATE 第16話.ts
[2021-01-17T01:00:02.286] [INFO] system - execute cmd: 録画完了通知 20秒sleep含む

[2021-01-17T00:29:45.030] [INFO] system - preprec: 1850 (ホリミヤ page. 2「顔は、ひとつだけじゃない。」)
[2021-01-17T00:30:02.447] [INFO] system - recording: 1850
[2021-01-17T00:30:02.449] [INFO] system - add recorded: 1850
[2021-01-17T00:30:02.477] [INFO] system - create video file: ホリミヤ page. 2「顔は、ひとつだけじゃない。」.ts
[2021-01-17T00:30:02.497] [INFO] system - execute cmd: 録画開始通知
[2021-01-17T00:30:02.702] [INFO] system - 録画開始通知 process is fin
[2021-01-17T01:00:02.768] [INFO] system - stop recording: 1850 (ホリミヤ page. 2「顔は、ひとつだけじゃない。」)

疑問点

finish streamのログがなく先にrecEndが呼び出されている
failed to recording: recorded id is nullもremove recording flag: ${this.recordedId}も出てない
正常なほうはstop recordingの後のrecordedIdがpreprecの時とは異なり2156なのに対して、失敗したほうはpreprecから変わらず1850 (調べるとデータベースのテーブルrecordedに2157として登録されていた)

l3tnun · 2021-01-17T03:46:09Z

情報提供ありがとうございます。

追記したログのメッセージミスりました。
stop recording が２つ存在してますね。(紛らわしいので修正します)
多分今回呼ばれたのが↓の cancel 関数内ものだと思われます。

EPGStation/src/model/operator/recording/RecorderModel.ts

Line 643 in 9871059

this.log.system.info(`stop recording: ${this.reserve.id}`);

故に finish stream ログが残らず、recordedId の 2157 ではなく、reserveId 1850 が表示されたようです。

おそらく、epgの定期更新によってルール更新処理が走り (下記ログ1行目)
録画中の予約が削除され、 (下記ログ3行目)
cancel コマンドが呼び出された。
その結果、なんらかの理由により recEnd 関数が呼び出されない？ようですね

[2021-01-17T01:00:02.284] [INFO] system - update rule reservation: 1
[2021-01-17T01:00:02.286] [INFO] system - execute cmd: 録画完了通知 (アニメ STEINS;GATE 第16話) 20秒sleep含む
[2021-01-17T01:00:02.717] [INFO] system - { insert: 0, update: 0, delete: 2 }

stop recording のログが出ていているので、本来であれば ↓ の部分によってmirakurunのストリームを切断し、ストリーム切断検出後 recEnd 関数が呼ばれるはずなのですが動いていないようですね。

EPGStation/src/model/operator/recording/RecorderModel.ts

Lines 645 to 648 in 9871059

    
           if (this.stream !== null) { 
        
               this.stream.destroy(); 
        
               this.stream.push(null); // eof 通知 
        
           }

原因追ってみます。

tomo0611 · 2021-01-17T04:16:59Z

一応mirakurunのログを貼っておきます

2021-01-17T00:29:45.118+09:00 info: TunerDevice#1 process has spawned by command `recpt1 --b25 --device /dev/px4video1 BS13_0 - -` (pid=1517168)
2021-01-17T00:29:45.119+09:00 info: TunerDevice#1 streaming to user `unix:1610810985055` (priority=2)
2021-01-17T00:29:45.125+09:00 info: TSFilter has created (serviceId=211, eventId=24847)
2021-01-17T00:29:45.126+09:00 info: TSFilter is waiting for serviceId=211, eventId=24847
2021-01-17T00:29:45.126+09:00 info: TunerDevice#0 streaming to user `unix:1610810985124` (priority=2)
2021-01-17T00:30:01.173+09:00 info: TSFilter is now ready for eventId=18091
2021-01-17T00:30:02.399+09:00 info: TSFilter is now ready for eventId=24847
2021-01-17T00:40:00.862+09:00 info: Network#4 EPG gathering has started
2021-01-17T00:40:00.898+09:00 info: EPG GC has queued
2021-01-17T00:40:13.208+09:00 info: Network#32721 EPG gathering has started
2021-01-17T00:40:13.218+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:40:13.220+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:40:13.285+09:00 info: TunerDevice#2 process has spawned by command `recpt1 --b25 --device /dev/px4video2 13 - -` (pid=1663710)
2021-01-17T00:40:13.290+09:00 info: TunerDevice#2 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:41:14.495+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:41:14.501+09:00 info: TunerDevice#2 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:41:14.508+09:00 info: Network#32721 EPG gathering has finished
2021-01-17T00:41:14.510+09:00 info: Network#32722 EPG gathering has started
2021-01-17T00:41:14.516+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:41:14.518+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:41:14.589+09:00 info: TunerDevice#3 process has spawned by command `recpt1 --b25 --device /dev/px4video3 16 - -` (pid=1696877)
2021-01-17T00:41:14.591+09:00 info: TunerDevice#3 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:41:17.522+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=1663710)
2021-01-17T00:41:17.625+09:00 info: TunerDevice#2 released
2021-01-17T00:42:15.391+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:42:15.394+09:00 info: TunerDevice#3 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:42:15.397+09:00 info: Network#32722 EPG gathering has finished
2021-01-17T00:42:15.398+09:00 info: Network#32723 EPG gathering has started
2021-01-17T00:42:15.404+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:42:15.405+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:42:15.474+09:00 info: TunerDevice#2 process has spawned by command `recpt1 --b25 --device /dev/px4video2 15 - -` (pid=1697502)
2021-01-17T00:42:15.476+09:00 info: TunerDevice#2 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:42:18.417+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=1696877)
2021-01-17T00:42:18.525+09:00 info: TunerDevice#3 released
2021-01-17T00:42:33.282+09:00 info: save db `/usr/local/var/db/mirakurun/programs.json` w/ integirty (Eq6rBJthGe3Djy6GIEsOjVDeMO2V/Zk1xw1h+WdDBWI=)
2021-01-17T00:43:16.261+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:43:16.266+09:00 info: TunerDevice#2 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:43:16.269+09:00 info: Network#32723 EPG gathering has finished
2021-01-17T00:43:16.270+09:00 info: Network#32724 EPG gathering has started
2021-01-17T00:43:16.274+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:43:16.275+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:43:16.332+09:00 info: TunerDevice#3 process has spawned by command `recpt1 --b25 --device /dev/px4video3 17 - -` (pid=1697986)
2021-01-17T00:43:16.333+09:00 info: TunerDevice#3 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:43:19.287+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=1697502)
2021-01-17T00:43:19.390+09:00 info: TunerDevice#2 released
2021-01-17T00:44:16.611+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:44:16.614+09:00 info: TunerDevice#3 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:44:16.616+09:00 info: Network#32724 EPG gathering has finished
2021-01-17T00:44:16.617+09:00 info: Network#32725 EPG gathering has started
2021-01-17T00:44:16.621+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:44:16.622+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:44:16.680+09:00 info: TunerDevice#2 process has spawned by command `recpt1 --b25 --device /dev/px4video2 14 - -` (pid=1698010)
2021-01-17T00:44:16.682+09:00 info: TunerDevice#2 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:44:19.644+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=1697986)
2021-01-17T00:44:19.749+09:00 info: TunerDevice#3 released
2021-01-17T00:44:26.613+09:00 info: save db `/usr/local/var/db/mirakurun/programs.json` w/ integirty (Eq6rBJthGe3Djy6GIEsOjVDeMO2V/Zk1xw1h+WdDBWI=)
2021-01-17T00:45:17.626+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:45:17.632+09:00 info: TunerDevice#2 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:45:17.637+09:00 info: Network#32725 EPG gathering has finished
2021-01-17T00:45:17.637+09:00 info: Network#32118 EPG gathering has started
2021-01-17T00:45:17.642+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:45:17.642+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:45:17.704+09:00 info: TunerDevice#3 process has spawned by command `recpt1 --b25 --device /dev/px4video3 18 - -` (pid=1698015)
2021-01-17T00:45:17.705+09:00 info: TunerDevice#3 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:45:20.649+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=1698010)
2021-01-17T00:45:20.751+09:00 info: TunerDevice#2 released
2021-01-17T00:46:18.120+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:46:18.124+09:00 info: TunerDevice#3 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:46:18.127+09:00 info: Network#32118 EPG gathering has finished
2021-01-17T00:46:18.128+09:00 info: Network#32127 EPG gathering has started
2021-01-17T00:46:18.132+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:46:18.132+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:46:18.195+09:00 info: TunerDevice#2 process has spawned by command `recpt1 --b25 --device /dev/px4video2 21 - -` (pid=1698021)
2021-01-17T00:46:18.197+09:00 info: TunerDevice#2 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:46:21.147+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=1698015)
2021-01-17T00:46:21.251+09:00 info: TunerDevice#3 released
2021-01-17T00:47:13.716+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:47:13.719+09:00 info: TunerDevice#2 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:47:13.721+09:00 info: Network#32127 EPG gathering has finished
2021-01-17T00:47:13.722+09:00 info: Network#32096 EPG gathering has started
2021-01-17T00:47:13.727+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:47:13.727+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:47:13.786+09:00 info: TunerDevice#3 process has spawned by command `recpt1 --b25 --device /dev/px4video3 25 - -` (pid=1698028)
2021-01-17T00:47:13.788+09:00 info: TunerDevice#3 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:47:16.738+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=1698021)
2021-01-17T00:47:16.841+09:00 info: TunerDevice#2 released
2021-01-17T00:47:26.715+09:00 info: save db `/usr/local/var/db/mirakurun/programs.json` w/ integirty (Eq6rBJthGe3Djy6GIEsOjVDeMO2V/Zk1xw1h+WdDBWI=)
2021-01-17T00:48:15.612+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:48:15.616+09:00 info: TunerDevice#3 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:48:15.619+09:00 info: Network#32096 EPG gathering has finished
2021-01-17T00:48:15.620+09:00 info: Network#32102 EPG gathering has started
2021-01-17T00:48:15.625+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:48:15.625+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:48:15.685+09:00 info: TunerDevice#2 process has spawned by command `recpt1 --b25 --device /dev/px4video2 23 - -` (pid=1698036)
2021-01-17T00:48:15.686+09:00 info: TunerDevice#2 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:48:18.629+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=1698028)
2021-01-17T00:48:18.732+09:00 info: TunerDevice#3 released
2021-01-17T00:49:16.570+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:49:16.573+09:00 info: TunerDevice#2 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:49:16.575+09:00 info: Network#32102 EPG gathering has finished
2021-01-17T00:49:16.576+09:00 info: Network#32086 EPG gathering has started
2021-01-17T00:49:16.582+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2021-01-17T00:49:16.582+09:00 info: TSFilter is waiting for serviceId=null, eventId=null
2021-01-17T00:49:16.640+09:00 info: TunerDevice#3 process has spawned by command `recpt1 --b25 --device /dev/px4video3 26 - -` (pid=1698042)
2021-01-17T00:49:16.641+09:00 info: TunerDevice#3 streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:49:19.593+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=1698036)
2021-01-17T00:49:19.696+09:00 info: TunerDevice#2 released
2021-01-17T00:49:32.730+09:00 info: save db `/usr/local/var/db/mirakurun/programs.json` w/ integirty (Eq6rBJthGe3Djy6GIEsOjVDeMO2V/Zk1xw1h+WdDBWI=)
2021-01-17T00:50:17.448+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2021-01-17T00:50:17.452+09:00 info: TunerDevice#3 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2021-01-17T00:50:17.455+09:00 info: Network#32086 EPG gathering has finished
2021-01-17T00:50:17.494+09:00 info: EPG GC has finished and removed 40 events
2021-01-17T00:50:17.524+09:00 info: Program GC has finished and removed 40 programs
2021-01-17T00:50:20.472+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=1698042)
2021-01-17T00:50:20.576+09:00 info: TunerDevice#3 released
2021-01-17T00:50:35.736+09:00 info: save db `/usr/local/var/db/mirakurun/programs.json` w/ integirty (Eq6rBJthGe3Djy6GIEsOjVDeMO2V/Zk1xw1h+WdDBWI=)
2021-01-17T00:59:45.061+09:00 info: TSFilter has created (serviceId=211, eventId=24848)
2021-01-17T00:59:45.063+09:00 info: TSFilter is waiting for serviceId=211, eventId=24848
2021-01-17T00:59:45.064+09:00 info: TunerDevice#0 streaming to user `unix:1610812785057` (priority=2)
2021-01-17T01:00:01.145+09:00 info: TSFilter is closing because eventId=18091 has ended...
2021-01-17T01:00:02.153+09:00 info: TSFilter has closed (serviceId=141, eventId=18091)
2021-01-17T01:00:02.154+09:00 info: TunerDevice#1 end streaming to user `unix:1610810985055` (priority=2)
2021-01-17T01:00:02.165+09:00 info: - - GET /api/programs/40014118091/stream?decode=1 HTTP/1.1 200 - - 16167.990 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-17T01:00:02.400+09:00 info: TSFilter is closing because eventId=24847 has ended...
2021-01-17T01:00:02.403+09:00 info: TSFilter is now ready for eventId=24848
2021-01-17T01:00:02.774+09:00 info: - - GET /api/programs/40021124847/stream?decode=1 HTTP/1.1 200 - - 17359.469 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-17T01:00:02.777+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-17T01:00:02.778+09:00 info: TunerDevice#0 end streaming to user `unix:1610810985124` (priority=2)
2021-01-17T01:00:05.174+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal `null` (pid=1517168)
2021-01-17T01:00:05.277+09:00 info: TunerDevice#1 released

tomo0611 · 2021-01-17T04:35:33Z

これ、アニメ STEINS;GATE 第16話を閉じるときはTSFilter has closed (serviceId=141, eventId=18091)なのに
ホリミヤ page. 2を開くときはTSFilter has created (serviceId=211, eventId=24847) で
閉じるときはTSFilter has closed (serviceId=211, eventId=null) でフィルター終了時にeventIdが消えているのが原因な気がしました
もしかして、mirakurun側の問題ですか?

l3tnun · 2021-01-17T04:57:18Z

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

おそらく mirakurun 側は正しく処理ができていると思います。

https://github.com/Chinachu/Mirakurun/blob/bbd2282319287d4efb9ae2f5e627ca3526a5c218/src/Mirakurun/TSFilter.ts#L777-L781

↑が該当部分コードだと思いますが、

        this.emit("close");
        this.emit("end");

とあるのでストリームの切断自体は正しくできていると思います。
eventId が無いのは epg の更新処理によって消えたのだと思います。

mirakurun のソースを見る限り↓ログが出ていればストリームの停止はできているようですね。
https://github.com/Chinachu/Mirakurun/blob/cce9bb5e270d16da465bbbdd4eabf4b0b8c9befe/src/Mirakurun/TunerDevice.ts#L198-L221

> 2021-01-17T01:00:02.778+09:00 info: TunerDevice#0 end streaming to user `unix:1610810985124` (priority=2)

epgstation 側でもほぼ同時刻に stream 切断処理を行っているので、epgstation 側のストリーム停止判定に何か悪影響を与えているのかもしれません。

[2021-01-17T01:00:02.768] [INFO] system - stop recording: 1850 (ホリミヤ page. 2「顔は、ひとつだけじゃない。」)

もし、ほぼ同時刻に mirakurun と epgstation からストリームを切断していることが原因であれば、epgstation の cancel 処理を工夫すれば回避できそうです。(根本解決ではないですが)

それ用にブランチを切るのでそれで様子を見てもらえますか？

l3tnun · 2021-01-17T07:00:32Z

fix-382 ブランチとして切りました。
録画終了間際であれば RecorderModel の cancel 関数でのストリーム切断を行わないようにしています。

tomo0611 · 2021-01-17T14:55:17Z

ありがとうございます
今すぐ適用して様子を見てみます

tomo0611 · 2021-01-19T02:29:07Z

適用しましたがまだ発生しているみたいです。

スクショ

放送

00:30~01:00に
BS11イレブンで裏世界ピクニック第3話「巨頭の村」(1881)が放送されていて同時に
サンテレビで裏世界ピクニック(第3話) (1882)が放送されていた。

抜粋するとこんな感じでdestroy streamまでは呼ばれたもののfinsh streamが呼ばれていませんでした。

system.log (Operator)

[2021-01-19T00:30:02.016] [INFO] system - recording: 1882 /home/tomochan/Videos/裏世界ピクニック(第3話).ts
[2021-01-19T00:30:02.024] [INFO] system - add drop log file: /home/tomochan/EPGStationV2/drop/裏世界ピクニック(第3話).ts.log
[2021-01-19T00:30:02.063] [INFO] system - add recorded: 1882 /home/tomochan/Videos/裏世界ピクニック(第3話).ts
[2021-01-19T00:30:02.099] [INFO] system - create video file: 裏世界ピクニック(第3話).ts
[2021-01-19T00:30:02.944] [INFO] system - recording: 1881 /home/tomochan/Videos/裏世界ピクニック 第3話「巨頭の村」.ts
[2021-01-19T00:30:02.976] [INFO] system - { insert: 0, update: 0, delete: 2 }
[2021-01-19T00:30:03.036] [INFO] system - add drop log file: /home/tomochan/EPGStationV2/drop/裏世界ピクニック 第3話「巨頭の村」.ts.log
[2021-01-19T00:30:03.100] [INFO] system - add recorded: 1881 /home/tomochan/Videos/裏世界ピクニック 第3話「巨頭の村」.ts
[2021-01-19T00:30:03.171] [INFO] system - create video file: 裏世界ピクニック 第3話「巨頭の村」.ts
[2021-01-19T01:00:02.902] [INFO] system - stop recording: reserveId: 1881, recordedId: 2203
[2021-01-19T01:00:02.903] [INFO] system - destory stream: reserveId: 1881, recordedId: 2203
[2021-01-19T01:00:02.919] [INFO] system - stop recording: reserveId: 1882, recordedId: 2202
[2021-01-19T01:00:02.925] [INFO] system - destory stream: reserveId: 1882, recordedId: 2202
[2021-01-19T01:00:02.946] [INFO] system - finish stream: 2202
[2021-01-19T01:00:02.950] [INFO] system - start recEnd: 2202
[2021-01-19T01:00:02.951] [INFO] system - remove recording flag: 2202
[2021-01-19T01:00:03.036] [INFO] system - { recordedId: 2202, error: 0, drop: 0, scrambling: 0 }
[2021-01-19T01:00:03.075] [INFO] system - add thumbnail queue: 4650
[2021-01-19T01:00:03.076] [INFO] system - recording finish: 1882 /home/tomochan/Videos/裏世界ピクニック(第3話).ts
[2021-01-19T01:01:44.690] [INFO] system - add video file: 2202 裏世界ピクニック(第3話).m2ts
[2021-01-19T01:01:44.717] [INFO] system - delete video file: 4650
[2021-01-19T01:01:44.783] [INFO] system - delete: /home/tomochan/Videos/裏世界ピクニック(第3話).ts

全部含めたログは長くなるので gist に貼っておきました。

Mirakurun

2021-01-19T01:00:01.132+09:00 info: TSFilter is closing because eventId=18217 has ended...
2021-01-19T01:00:01.140+09:00 info: TSFilter is now ready for eventId=18218
2021-01-19T01:00:01.818+09:00 info: TSFilter is closing because eventId=10643 has ended...
2021-01-19T01:00:02.140+09:00 info: TSFilter has closed (serviceId=141, eventId=18217)
2021-01-19T01:00:02.143+09:00 info: TunerDevice#1 end streaming to user `unix:1610983785067` (priority=2)
2021-01-19T01:00:02.154+09:00 info: - - GET /api/programs/40014118217/stream?decode=1 HTTP/1.1 200 - - 16144.613 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-19T01:00:02.418+09:00 info: TSFilter is closing because eventId=24946 has ended...
2021-01-19T01:00:02.419+09:00 info: TSFilter is now ready for eventId=24947
2021-01-19T01:00:02.819+09:00 info: TSFilter has closed (serviceId=43056, eventId=10643)
2021-01-19T01:00:02.819+09:00 info: TunerDevice#3 end streaming to user `unix:1610983785079` (priority=2)
2021-01-19T01:00:02.911+09:00 info: - - GET /api/programs/40021124946/stream?decode=1 HTTP/1.1 200 - - 17410.065 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-19T01:00:02.916+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-19T01:00:02.920+09:00 info: TunerDevice#0 end streaming to user `unix:1610983785141` (priority=2)
2021-01-19T01:00:02.931+09:00 info: - - GET /api/programs/320864305610643/stream?decode=1 HTTP/1.1 200 - - 16919.118 ms epgstation/2.0.4 MirakurunClient/3.3.1 Node/v14.15.1 (linux)
2021-01-19T01:00:05.860+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=3614767)
2021-01-19T01:00:05.962+09:00 info: TunerDevice#3 released

tomochan@tomontu-server:~$ tail -n 55000 /usr/local/var/log/mirakurun.stdout.log | grep "TSFilter has closed (serviceId=211"
2021-01-11T23:30:03.359+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-11T23:30:23.133+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-11T23:49:34.280+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-12T00:00:03.781+09:00 info: TSFilter has closed (serviceId=211, eventId=24586) // 失敗
2021-01-12T00:30:03.279+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-12T01:00:03.045+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-12T01:10:03.495+09:00 info: TSFilter has closed (serviceId=211, eventId=24589)
2021-01-13T00:00:05.745+09:00 info: TSFilter has closed (serviceId=211, eventId=24626)
2021-01-13T00:30:03.513+09:00 info: TSFilter has closed (serviceId=211, eventId=24627)
2021-01-13T01:00:03.490+09:00 info: TSFilter has closed (serviceId=211, eventId=24628)
2021-01-13T01:30:02.975+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-14T00:15:03.531+09:00 info: TSFilter has closed (serviceId=211, eventId=24664)
2021-01-14T00:30:03.507+09:00 info: TSFilter has closed (serviceId=211, eventId=24665)
2021-01-14T00:59:45.146+09:00 info: TSFilter has closed (serviceId=211, eventId=24666)
2021-01-14T01:30:03.071+09:00 info: TSFilter has closed (serviceId=211, eventId=null) // 失敗
2021-01-14T02:00:03.473+09:00 info: TSFilter has closed (serviceId=211, eventId=24668)
2021-01-14T23:00:03.481+09:00 info: TSFilter has closed (serviceId=211, eventId=24762)
2021-01-14T23:30:03.410+09:00 info: TSFilter has closed (serviceId=211, eventId=24763)
2021-01-15T00:00:03.332+09:00 info: TSFilter has closed (serviceId=211, eventId=24764) // 失敗
2021-01-15T00:30:02.847+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-15T01:00:03.393+09:00 info: TSFilter has closed (serviceId=211, eventId=24766) // 失敗
2021-01-15T01:30:03.378+09:00 info: TSFilter has closed (serviceId=211, eventId=24767)
2021-01-15T22:30:03.428+09:00 info: TSFilter has closed (serviceId=211, eventId=24800)
2021-01-15T23:00:03.368+09:00 info: TSFilter has closed (serviceId=211, eventId=null) // 失敗
2021-01-15T23:30:02.742+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-16T00:00:03.456+09:00 info: TSFilter has closed (serviceId=211, eventId=null) // 失敗
2021-01-16T00:30:03.439+09:00 info: TSFilter has closed (serviceId=211, eventId=24804)
2021-01-16T01:00:03.416+09:00 info: TSFilter has closed (serviceId=211, eventId=24805)
2021-01-16T01:30:03.418+09:00 info: TSFilter has closed (serviceId=211, eventId=24806)
2021-01-16T02:00:03.377+09:00 info: TSFilter has closed (serviceId=211, eventId=24807)
2021-01-16T22:30:03.411+09:00 info: TSFilter has closed (serviceId=211, eventId=24842)
2021-01-16T23:30:03.545+09:00 info: TSFilter has closed (serviceId=211, eventId=24844)
2021-01-17T00:00:05.820+09:00 info: TSFilter has closed (serviceId=211, eventId=24845)
2021-01-17T00:26:04.851+09:00 info: TSFilter has closed (serviceId=211, eventId=24846)
2021-01-17T00:29:12.902+09:00 info: TSFilter has closed (serviceId=211, eventId=24846)
2021-01-17T01:00:02.777+09:00 info: TSFilter has closed (serviceId=211, eventId=null) // 失敗
2021-01-17T01:30:03.442+09:00 info: TSFilter has closed (serviceId=211, eventId=24848)
2021-01-17T02:00:03.412+09:00 info: TSFilter has closed (serviceId=211, eventId=24849)
2021-01-17T22:00:03.390+09:00 info: TSFilter has closed (serviceId=211, eventId=24889)
2021-01-17T23:00:03.399+09:00 info: TSFilter has closed (serviceId=211, eventId=24891)
2021-01-17T23:58:05.071+09:00 info: TSFilter has closed (serviceId=211, eventId=24893)
2021-01-17T23:59:37.421+09:00 info: TSFilter has closed (serviceId=211, eventId=24893)
2021-01-18T00:30:03.018+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-18T01:00:03.370+09:00 info: TSFilter has closed (serviceId=211, eventId=24895)
2021-01-18T23:30:03.048+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-19T00:00:03.498+09:00 info: TSFilter has closed (serviceId=211, eventId=24944) // 失敗
2021-01-19T00:30:03.068+09:00 info: TSFilter has closed (serviceId=211, eventId=null)
2021-01-19T01:00:02.916+09:00 info: TSFilter has closed (serviceId=211, eventId=null) // 失敗
2021-01-19T01:10:03.413+09:00 info: TSFilter has closed (serviceId=211, eventId=24947)
2021-01-19T03:00:03.394+09:00 info: TSFilter has closed (serviceId=211, eventId=24951)

l3tnun · 2021-01-19T09:27:11Z

適応と経過観察及びログの提供ありがとうございます。
なかなか原因が掴めませんね...

ログ精査します。

tomo0611 · 2021-01-19T14:53:59Z

とりあえず、僕側でRecorderModelの分岐や関数のところにログを加えまくったので録画に失敗した時にどの経路でキャンセルが起きているのかを伝えさせていただきます

tomo0611 · 2021-01-20T05:32:09Z

やはり番組表更新が原因みたいでした
Mirakurunが接続中かつ番組終了から10秒くらいなら録画をキャンセルしない的な処理をすれば良さげな気がします

[2021-01-20T01:30:02.136] [INFO] system - doRecord(L373) 録画終了処理 stream ended 1921
[2021-01-20T01:30:02.142] [INFO] system - finish stream: 2214
[2021-01-20T01:30:02.143] [INFO] system - recEnd(L494) 録画終了処理開始 1921
[2021-01-20T01:30:02.143] [INFO] system - start recEnd: 2214
[2021-01-20T01:30:02.144] [INFO] system - Destroy Stream(L215) 1921
[2021-01-20T01:30:02.144] [INFO] system - Destroy Stream(L223) Stream Unpipe 1921
[2021-01-20T01:30:02.145] [INFO] system - Destroy Stream(L226) Stream Destroy 1921
[2021-01-20T01:30:02.146] [INFO] system - Destroy Stream(L231) Stream become null 1921
[2021-01-20T01:30:02.146] [INFO] system - remove recording flag: 2214
[2021-01-20T01:30:02.252] [INFO] system - update file size: 4689
[2021-01-20T01:30:02.258] [INFO] system - { recordedId: 2214, error: 0, drop: 0, scrambling: 0 }
[2021-01-20T01:30:02.297] [INFO] system - add recorded history: 2214
[2021-01-20T01:30:02.322] [INFO] system - add thumbnail queue: 4689
[2021-01-20T01:30:02.324] [INFO] system - recording finish: 1921 /home/tomochan/Videos/アニメ ジョジョの奇妙な冒険 スターダストクルセイダース 第16話.ts
[2021-01-20T01:30:02.325] [INFO] system - update rule reservation: 1
[2021-01-20T01:30:02.327] [INFO] system - execute cmd: /bin/bash /home/tomochan/EPGStationV2/config/postLine2.sh
[2021-01-20T01:30:02.672] [INFO] system - { insert: 0, update: 0, delete: 2 }
[2021-01-20T01:30:02.700] [INFO] system - successful update rule reservation: 1
[2021-01-20T01:30:02.702] [INFO] system - cancel(L641) 予約キャンセル開始 1920
[2021-01-20T01:30:02.703] [INFO] system - stop recording: reserveId: 1920, recordedId: 2215
[2021-01-20T01:30:02.703] [INFO] system - destory stream: reserveId: 1920, recordedId: 2215
[2021-01-20T01:30:02.703] [INFO] system - cancel(L708) 録画通常キャンセル 1920
[2021-01-20T01:30:02.713] [INFO] system - cancel(L710) streamをdestroyしました 1920
[2021-01-20T01:30:02.713] [INFO] system - cancel(L712) eof通知完了 1920
[2021-01-20T01:30:03.011] [INFO] system - create thumbnail: 4689, /home/tomochan/EPGStationV2/thumbnail/2214.jpg
[2021-01-20T01:30:12.771] [INFO] system - /bin/bash /home/tomochan/EPGStationV2/config/postLine2.sh process is fin
[2021-01-20T01:31:24.103] [INFO] system - add video file: 2214 アニメ ジョジョの奇妙な冒険 スターダストクルセイダース 第16話.m2ts
[2021-01-20T01:31:24.161] [INFO] system - delete video file: 4689
[2021-01-20T01:31:24.192] [INFO] system - delete: /home/tomochan/Videos/アニメ ジョジョの奇妙な冒険 スターダストクルセイダース 第16話.ts

tomo0611 · 2021-01-20T05:34:16Z

mirakuruneventendtimeoutが1000じゃ足りないんですかね。。
とりあえず5000にしてやってみます

l3tnun · 2021-01-20T13:20:31Z

解析ありがとうございます。

[2021-01-20T01:31:24.192] [INFO] system - delete: /home/tomochan/Videos/アニメ ジョジョの奇妙な冒険 スターダストクルセイダース 第16話.ts

最後の行恐ろしく不穏なのですが、これは .ts を .m2ts にリネームする過程で削除しているだけですか？（config/postLine2.shでやってる？）
この解析結果だと recEnd 関数が呼ばれサムネイル作成等々も完了していそうですが、録画中に残っていますか？

tomo0611 · 2021-01-20T13:27:12Z

enc2.js でtsファイルからm2tsファイルにエンコードしてます(不要なepgや時間情報を落とす為に)
postLine2はlineに録画完了通知をします
postLine4はlineに録画開始通知をします

あと書き足りなかったのですが、録画完了できずに録画中になってるのは1920の小野下野のどこでもクエスト2 #2です。ジョジョは問題なくエンコードできてます

l3tnun · 2021-01-21T12:33:15Z

説明ありがとうございます。

ジョジョは問題なくエンコードできてます

そうですよね。安心しました。

今のところご推察どおり、ルールの更新による録画キャンセル時の挙動が起因しているようですね。

mirakuruneventendtimeoutが1000じゃ足りないんですかね。。
とりあえず5000にしてやってみます

これって何か効果得られましたか？

これでもだめなら、録画終了処理とキャンセル処理が何か上手く噛み合ってないところを根本的に見直す必要があると思うので、修正にかなり時間が掛かりそうです。
（本腰を入れてソースの見直しに入るので作業自体は土日ですね。）

tomo0611 · 2021-01-21T13:17:22Z

僕の不手際でYamlの文法ミスがあり昨日の夜はちゃんと5000が適用されていなかったので今晩が初めて5000msでの録画になります。

また明日報告します

tomo0611 · 2021-01-21T15:29:37Z

設定を変えましたがダメみたいですね…

[2021-01-21T23:30:02.469] [INFO] system - Recording(L172) 1941
[2021-01-21T23:30:02.478] [INFO] system - recording: 1941 /home/tomochan/Videos/ゆるキャン△ SEASON 2 第3話「たなぼたキャンプと改めて思ったこと」.ts
[2021-01-21T23:30:02.483] [INFO] system - add drop log file: /home/tomochan/EPGStationV2/drop/ゆるキャン△ SEASON 2 第3話「たなぼたキャンプと改めて思ったこと」.ts.log
[2021-01-21T23:30:02.500] [INFO] system - add recorded: 1941 /home/tomochan/Videos/ゆるキャン△ SEASON 2 第3話「たなぼたキャンプと改めて思ったこと」.ts
[2021-01-21T23:30:02.500] [INFO] system - doRecord(L336) Starting createRecorded 1941
[2021-01-21T23:30:02.501] [INFO] system - doRecord(L338) Ended createRecorded 1941
[2021-01-21T23:30:02.518] [INFO] system - doRecord(L340) Ended insertOnce 1941
[2021-01-21T23:30:02.518] [INFO] system - create video file: ゆるキャン△ SEASON 2 第3話「たなぼたキャンプと改めて思ったこと」.ts
[2021-01-21T23:30:02.532] [INFO] system - doRecord(L369) 録画終了処理 1941
[2021-01-21T23:30:02.532] [INFO] system - doRecord(L371) 録画終了処理 stream was not null 1941
[2021-01-21T23:30:02.532] [INFO] system - doRecord(L395) 録画開始通知 1941
[2021-01-22T00:00:02.933] [INFO] system - recording finish: 1940 /home/tomochan/Videos/アニメ ソードアート・オンライン オルタナティブ ガンゲイル・オンライン #03.ts
[2021-01-22T00:00:02.933] [INFO] system - update rule reservation: 1
[2021-01-22T00:00:02.935] [INFO] system - execute cmd: /bin/bash /home/tomochan/EPGStationV2/config/postLine2.sh
[2021-01-22T00:00:03.439] [INFO] system - { insert: 0, update: 0, delete: 2 }
[2021-01-22T00:00:03.528] [INFO] system - successful update rule reservation: 1
[2021-01-22T00:00:03.534] [INFO] system - cancel(L641) 予約キャンセル開始 1941
[2021-01-22T00:00:03.535] [INFO] system - stop recording: reserveId: 1941, recordedId: 2238
[2021-01-22T00:00:03.535] [INFO] system - destory stream: reserveId: 1941, recordedId: 2238
[2021-01-22T00:00:03.535] [INFO] system - cancel(L708) 録画通常キャンセル 1941
[2021-01-22T00:00:03.535] [INFO] system - cancel(L710) streamをdestroyしました 1941
[2021-01-22T00:00:03.536] [INFO] system - cancel(L712) eof通知完了 1941

l3tnun · 2021-02-13T07:02:51Z

cancel 関数にてストリーム停止後に一定時間内に recEnd 関数が呼ばれなかったら強制的に呼び出す対策をしてみました。
ブランチは add-cancel-timer になります。
動作確認お願いできますでしょうか？

tomo0611 · 2021-05-05T05:00:31Z

結局、しばらく様子見してたんですが、02/15(月) 23:30 ~ 00:00を最後に一度も起きなくなったので恐らくチューナー側の調子が悪いのかなと思われました (冬頃はdevice開けなくなったりなどチューナー安定してなかったので

折角対応していただいたのに申し訳ございませんが、こちら側の問題だと思われますのでissue閉じさせていただきます。

l3tnun · 2021-05-05T05:03:06Z

なるほど、了解です。
ちなみに、参考までに使っていたチューナを教えてもらえますか?

tomo0611 · 2021-05-05T05:41:13Z

PX-W3U4です。
冬頃は安定せずにヒーターで温めてからサーバーごと再起動かけることが何度かありました
最近は安定していますが。。

l3tnun added the bug label Jan 16, 2021

l3tnun added a commit that referenced this issue Jan 16, 2021

recordedTmp 非使用時に recordedTmp 移動処理をしないように修正 #382

531bcd5

l3tnun added a commit that referenced this issue Jan 16, 2021

録画終了時のログ追加 #382

9871059

l3tnun added a commit that referenced this issue Jan 17, 2021

fix log message #382

3428d27

l3tnun added a commit that referenced this issue Jan 17, 2021

RecorderModel の cancel 関数実行時に、録画終了間際であれば mirakurun のストリーム切断を待つように修正 #382

6a279f2

l3tnun closed this as completed Jan 21, 2021

l3tnun reopened this Jan 21, 2021

l3tnun added a commit that referenced this issue Feb 13, 2021

ルール更新による録画停止時に recEnd 関数が呼ばれない問題の暫定対処 #382

50232ee

tomo0611 closed this as completed May 5, 2021

l3tnun mentioned this issue May 6, 2021

録画に失敗して、録画中から番組が消えなくなってしまう #465

Closed

l3tnun mentioned this issue Jul 20, 2021

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

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

録画完了後エンコードされないものがある #382

録画完了後エンコードされないものがある #382

tomo0611 commented Jan 16, 2021 •

edited

l3tnun commented Jan 16, 2021

l3tnun commented Jan 16, 2021

l3tnun commented Jan 16, 2021

tomo0611 commented Jan 16, 2021

tomo0611 commented Jan 16, 2021

l3tnun commented Jan 16, 2021

l3tnun commented Jan 16, 2021

tomo0611 commented Jan 16, 2021

tomo0611 commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

l3tnun commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

l3tnun commented Jan 17, 2021

l3tnun commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

tomo0611 commented Jan 19, 2021

l3tnun commented Jan 19, 2021

tomo0611 commented Jan 19, 2021

tomo0611 commented Jan 20, 2021

tomo0611 commented Jan 20, 2021

l3tnun commented Jan 20, 2021

tomo0611 commented Jan 20, 2021

l3tnun commented Jan 21, 2021 •

edited

tomo0611 commented Jan 21, 2021

tomo0611 commented Jan 21, 2021

l3tnun commented Feb 13, 2021

tomo0611 commented May 5, 2021

l3tnun commented May 5, 2021

tomo0611 commented May 5, 2021

録画完了後エンコードされないものがある #382

録画完了後エンコードされないものがある #382

Comments

tomo0611 commented Jan 16, 2021 • edited

環境

Issue

エンコードコマンド

ログ(Service)

ログ(Operator)

録画後のプロセス

l3tnun commented Jan 16, 2021

l3tnun commented Jan 16, 2021

l3tnun commented Jan 16, 2021

tomo0611 commented Jan 16, 2021

tomo0611 commented Jan 16, 2021

l3tnun commented Jan 16, 2021

l3tnun commented Jan 16, 2021

tomo0611 commented Jan 16, 2021

tomo0611 commented Jan 17, 2021

system.log (Operator)

system.log (Service)

tomo0611 commented Jan 17, 2021

STDOUT

tomo0611 commented Jan 17, 2021

ログ比較

疑問点

l3tnun commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

l3tnun commented Jan 17, 2021

l3tnun commented Jan 17, 2021

tomo0611 commented Jan 17, 2021

tomo0611 commented Jan 19, 2021

スクショ

放送

system.log (Operator)

Mirakurun

l3tnun commented Jan 19, 2021

tomo0611 commented Jan 19, 2021

tomo0611 commented Jan 20, 2021

tomo0611 commented Jan 20, 2021

l3tnun commented Jan 20, 2021

tomo0611 commented Jan 20, 2021

l3tnun commented Jan 21, 2021 • edited

tomo0611 commented Jan 21, 2021

tomo0611 commented Jan 21, 2021

l3tnun commented Feb 13, 2021

tomo0611 commented May 5, 2021

l3tnun commented May 5, 2021

tomo0611 commented May 5, 2021

tomo0611 commented Jan 16, 2021 •

edited

l3tnun commented Jan 21, 2021 •

edited