Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

長時間の連続録画時に録画が止まってしまう #533

Open
MicotoTisaki opened this issue Aug 30, 2021 · 22 comments
Open

長時間の連続録画時に録画が止まってしまう #533

MicotoTisaki opened this issue Aug 30, 2021 · 22 comments

Comments

@MicotoTisaki
Copy link

環境

  • Version of EPGStation: 2.6.3
  • Version of Mirakurun: 3.7.1
  • Version of Node: 14.15.4
  • Version of NPM: 6.14.14
  • OS:ubuntu20.04
  • Architecture: x64

Issue

...
複数チャンネルの同時録画を行っている状態で2日ほど放置で稼働させている際に予約は入っているのですが録画が開始されず、録画中のタブにもタスクが表示されない状態になってしまいます。サーバーの再起動をかけると再開されます。

構成はepgstationに対してmirakurunを40772と40773にて2つ起動しており、remoteMirakurunの設定にて40772に集め、CAS処理を分散させている状態です。

以下にlogを添付します。

・Service/system.log

[2021-08-30T09:27:43.815] [ERROR] system - Error: IPCTimeout
at Timeout._onTimeout (/app/dist/model/ipc/model/ipc/IPCClient.ts:126:28)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)
[2021-08-30T10:02:29.129] [ERROR] system - Error: IPCTimeout
at Timeout._onTimeout (/app/dist/model/ipc/model/ipc/IPCClient.ts:126:28)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)

よろしくお願いします。
@l3tnun
Copy link
Owner

l3tnun commented Aug 30, 2021

まず、ServiceでIPCTimeoutエラーが出ていますが、プロセスが多重起動していないでしょうか?

あと、録画や予約部分はOperatorに集約されていますので、Operator/system.log を貼ってください。

@MicotoTisaki
Copy link
Author

Operator/system.logを確認したのですが再起動の際にエラーログが消えてしまったらしいです。再発した際にログの抽出をします。申し訳ございません。

また、プロセス自体は以下の様にpsで確認したのですが、多重起動はしていないっぽいです。

mirakurun@Mirakurun:/git/docker-mirakurun-epgstation/epgstation/logs/Operator$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
3dc8bb405afc ffmpeg-nvenc "/usr/local/bin/ffmp…" 6 minutes ago Up 6 minutes fervent_bassi
26576c33459d ffmpeg-nvenc "/usr/local/bin/ffmp…" 6 minutes ago Up 6 minutes gracious_kepler
24e04e900c67 docker-mirakurun-epgstation_epgstation "npm start" 44 hours ago Up About an hour 0.0.0.0:8888-8889->8888-8889/tcp, :::8888-8889->8888-8889/tcp epgstation-v2
04b6f086bbbb chinachu/mirakurun "docker-entrypoint.s…" 44 hours ago Up About an hour 0.0.0.0:9230->9229/tcp, :::9230->9229/tcp, 0.0.0.0:40773->40772/tcp, :::40773->40772/tcp mirakurun2-3.5.0
befdb0aaad58 chinachu/mirakurun "docker-entrypoint.s…" 44 hours ago Up About an hour 0.0.0.0:9229->9229/tcp, :::9229->9229/tcp, 0.0.0.0:40772->40772/tcp, :::40772->40772/tcp mirakurun-3.5.0
48de3218ad88 mariadb:10.4 "docker-entrypoint.s…" 44 hours ago Up About an hour 3306/tcp mysql-epgstation-v2
mirakurun@Mirakurun:~/git/docker-mirakurun-epgstation/epgstation/logs/Operator$ docker-compose ps
Name Command State Ports
docker-mirakurun-epgstation_ffmpeg-nvenc_1 /usr/local/bin/ffmpeg --help Exit 0
epgstation-v2 npm start Up 0.0.0.0:8888->8888/tcp,:::8888->8888/tcp, 0.0.0.0:8889->8889/tcp,:::8889->8889/tcp
mirakurun-3.5.0 docker-entrypoint.sh ./doc ... Up 0.0.0.0:40772->40772/tcp,:::40772->40772/tcp, 0.0.0.0:9229->9229/tcp,:::9229->9229/tcp
mirakurun2-3.5.0 docker-entrypoint.sh ./doc ... Up 0.0.0.0:40773->40772/tcp,:::40773->40772/tcp, 0.0.0.0:9230->9229/tcp,:::9230->9229/tcp
mysql-epgstation-v2 docker-entrypoint.sh mysql ... Up 3306/tcp

ただ、IPCTimeOutエラーも定期的に出てくるので、再発した際にプロセスの確認をします。ログを取れておらず申し訳ございません。

@l3tnun
Copy link
Owner

l3tnun commented Aug 30, 2021

dockerを使用しているようですが、なんのimageを使用しているのでしょうか?
あと、docker ps ではプロセスの多重起動は分かりません。コンテナの外か中で ps コマンド等で調べてください。

@MicotoTisaki
Copy link
Author

docker-compose.ymlのepgstationは以下の様になっており、DockerfileはFROM l3tnun/epgstation:master-debianとなっています。

epgstation:
    container_name: epgstation-v2
    build: epgstation
    volumes:
        - /etc/localtime:/etc/localtime:ro
        - ./epgstation/config:/app/config
        - ./epgstation/data:/app/data
        - ./epgstation/thumbnail:/app/thumbnail
        - ./epgstation/logs:/app/logs
        - /mnt/hddRaid:/app/recorded
        - /var/run/docker.sock:/var/run/docker.sock
        - /usr/bin/docker:/usr/bin/docker
    environment:
        TZ: "Asia/Tokyo"
    devices:
        - /dev/dri:/dev/dri
    depends_on:
        - mirakurun
        - mysql
    ports:
        - "8888:8888"
        - "8889:8889"
    #user: "1000:1000"
    restart: always
    privileged: true

また、epgstationのdocker内のプロセスを確認するためにdocker topコマンドを叩いた結果が以下のような感じになりました。このプロセスで大丈夫でしょうか。

mirakurun@Mirakurun:~/git/docker-mirakurun-epgstation/epgstation$ docker top 24e04e900c67
UID PID PPID C STIME TTY TIME CMD
root 49858 49837 0 16:19 ? 00:00:00 npm start
root 49927 49858 0 16:19 ? 00:00:00 sh -c node dist/index.js
root 49928 49927 53 16:19 ? 03:28:01 node dist/index.js
root 49988 49928 0 16:19 ? 00:02:48 /usr/local/bin/node /app/dist/model/service/ServiceExecutor.js
root 50544 49928 0 16:19 ? 00:02:17 /usr/local/bin/node /app/dist/model/epgUpdater/EPGUpdateExecutor.js
root 66762 49988 0 21:54 ? 00:00:00 /bin/bash /app/config/enc_vaapi.sh main
root 66806 66762 47 21:54 ? 00:24:50 /usr/local/bin/ffmpeg -dual_mono_mode main -vaapi_device /dev/dri/renderD128 -hwaccel vaapi -i /app/recorded/2021年08月30日20時00分00秒-月?プレミア８　冤罪犯[字][解].m2ts -vf format=nv12|vaapi,hwupload,deinterlace_vaapi,scale_vaapi=w=1280:h=720 -c:v h264_vaapi -c:a ac3 -qp 20 -ac 2 /app/recorded/2021年08月30日20時00分00秒-月?プレミ
ア８　冤罪犯[字][解]-vaapi.mp4
root 70964 49988 0 22:28 ? 00:00:00 /bin/bash /app/config/enc_vaapi.sh main
root 70971 70964 54 22:28 ? 00:09:38 /usr/local/bin/ffmpeg -dual_mono_mode main -vaapi_device /dev/dri/renderD128 -hwaccel vaapi -i /app/recorded/2021年08月30日20時05分00秒-東京２０２０パラリンピック◇車いすラグビー・決勝「アメリカ×イギリス」.m2ts -vf format=nv12|vaapi,hwupload,deinterlace_vaapi,scale_vaapi=w=1280:h=720 -c:v h264_vaapi -c:a ac3 -qp 20 -ac 2 /app/recorded/2021年08月30日20時05分00秒-東京２０２０パラリンピック◇車いすラグビー・決勝「アメリカ×イギリス」-vaapi.mp4
root 72168 49988 0 22:36 ? 00:00:00 /bin/bash /app/config/enc_nvenc.sh
root 72171 72168 0 22:36 ? 00:00:00 docker run --rm --gpus all -u0:44 -v /mnt/hddRaid:/app/recorded ffmpeg-nvenc -c:v mpeg2_cuvid -deint adaptive -drop_second_field 1 -i /app/recorded/2021年08月30日21時00分00秒-[映]スパルタカス［復元完全版］（１９６０）.m2ts -c:v h264_nvenc -vb 3M -rc vbr_hq -c:a aac -b:a 192k -r:a 48000 -ac 2 /app/recorded/2021年08月30日21時00分00秒-[映]スパルタカス［復元完全版］（１９６０）-nvenc.mp4
root 72841 49988 0 22:38 ? 00:00:00 /bin/bash /app/config/enc_nvenc.sh
root 72845 72841 0 22:38 ? 00:00:00 docker run --rm --gpus all -u0:44 -v /mnt/hddRaid:/app/recorded ffmpeg-nvenc -c:v mpeg2_cuvid -deint adaptive -drop_second_field 1 -i /app/recorded/2021年08月30日21時15分00秒-ブエルタ・ア・エスパーニャ2021 第15ステージ Cycle＊.m2ts -c:v h264_nvenc -vb 3M -rc vbr_hq -c:a aac -b:a 192k -r:a 48000 -ac 2 /app/recorded/2021年08月30日21時15分00秒-ブエルタ・ア・エスパーニャ2021 第15ステージ Cycle＊-nvenc.mp4
root 74537 49988 0 22:45 ? 00:00:00 /bin/bash /app/config/enc_nvenc.sh
root 74540 74537 0 22:45 ? 00:00:00 docker run --rm --gpus all -u0:44 -v /mnt/hddRaid:/app/recorded ffmpeg-nvenc -c:v mpeg2_cuvid -deint adaptive -drop_second_field 1 -i /app/recorded/2021年08月30日22時00分00秒-フロム・ジ・アース／人類、月に立つ　＃１１二.m2ts -c:v h264_nvenc -vb 3M -rc vbr_hq -c:a aac -b:a 192k -r:a 48000 -ac 2 /app/recorded/2021年08月30日22時00分00秒-フロム・ジ・アース／人類、月に立つ　＃１１二-nvenc.mp4
root 74938 49988 0 22:46 ? 00:00:00 /bin/bash /app/config/enc_vaapi.sh main
root 74945 74938 53 22:46 ? 00:00:07 /usr/local/bin/ffmpeg -dual_mono_mode main -vaapi_device /dev/dri/renderD128 -hwaccel vaapi -i /app/recorded/2021年08月30日22時00分00秒-しゃべくり００７【東京五輪バスケットボール女子日本代表＆超熱血コーチの素顔】字.m2ts -vf format=nv12|vaapi,hwupload,deinterlace_vaapi,scale_vaapi=w=1280:h=720 -c:v h264_vaapi -c:a ac3 -qp 20 -ac 2 /app/recorded/2021年08月30日22時00分00秒-しゃべくり００７【東京五輪バスケットボール女子日本代表＆超熱血コーチの素顔】字-vaapi.mp4

@MicotoTisaki
Copy link
Author

また、先程予約をしておいた番組が録画スタートしていなかったため、その際のOperator/system.logを添付させていただきます。

Operator/system.log

[2021-08-30T22:28:57.235] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:29:15.398] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.405] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.406] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.423] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.425] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.428] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.432] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.436] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.439] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.443] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.489] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.566] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.583] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.588] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.592] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.607] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.616] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.620] [ERROR] system - get execution error: 2
[2021-08-30T22:29:15.662] [ERROR] system - get execution error: 2
[2021-08-30T22:29:18.071] [INFO] system - add video file: 8239 2021年08月30日20時00分00秒-[生][デ]ＢＳフジＬＩＶＥプライムニュース-nvenc.mp4
[2021-08-30T22:29:18.156] [INFO] system - delete video file: 13586
[2021-08-30T22:29:18.175] [INFO] system - delete: /app/recorded/2021年08月30日20時00分00秒-[生][デ]ＢＳフジＬＩＶＥプライムニュース.m2ts
[2021-08-30T22:29:22.042] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:29:44.478] [INFO] system - add video file: 8274 2021年08月30日21時54分00秒-東京ＧＯＯＤ！　北斎が愛した墨田区　すみだ北斎美術館[字]-vaapi.mp4
[2021-08-30T22:29:44.555] [INFO] system - delete video file: 13658
[2021-08-30T22:29:44.602] [INFO] system - delete: /app/recorded/2021年08月30日21時54分00秒-東京ＧＯＯＤ！　北斎が愛した墨田区　すみだ北斎美術館[字].m2ts
[2021-08-30T22:29:44.786] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:29:45.002] [INFO] system - preprec: 87758
[2021-08-30T22:29:45.019] [INFO] system - preprec: 84489
[2021-08-30T22:29:45.020] [INFO] system - preprec: 82150
[2021-08-30T22:30:00.549] [INFO] system - recording: 84489 /app/recorded/2021年08月30日22時30分00秒-[プロ野球]亀山つとむ・江草仁貴のトラツボ！ #4.m2ts
[2021-08-30T22:30:00.562] [INFO] system - add drop log file: /app/drop/2021年08月30日22時30分00秒-[プロ野球]亀山つとむ・江草仁貴のトラツボ！ #4.m2ts.log
[2021-08-30T22:30:00.592] [INFO] system - add recorded 84489 /app/recorded/2021年08月30日22時30分00秒-[プロ野球]亀山つとむ・江草仁貴のトラツボ！ #4.m2ts
[2021-08-30T22:30:00.613] [INFO] system - recording added reserveId: 84489, recordedId: 8337
[2021-08-30T22:30:00.614] [INFO] system - create video file: 2021年08月30日22時30分00秒-[プロ野球]亀山つとむ・江草仁貴のトラツボ！ #4.m2ts
[2021-08-30T22:30:00.629] [INFO] system - set stream.finished: reserveId: 84489 recordedId: 8337
[2021-08-30T22:30:01.042] [INFO] system - recording: 82150 /app/recorded/2021年08月30日22時30分00秒-月が導く異世界道中　＃８「亜空ランキング」[再].m2ts
[2021-08-30T22:30:01.150] [INFO] system - add drop log file: /app/drop/2021年08月30日22時30分00秒-月が導く異世界道中　＃８「亜空ランキング」[再].m2ts.log
[2021-08-30T22:30:01.176] [INFO] system - add recorded 82150 /app/recorded/2021年08月30日22時30分00秒-月が導く異世界道中　＃８「亜空ランキング」[再].m2ts
[2021-08-30T22:30:01.205] [INFO] system - recording added reserveId: 82150, recordedId: 8338
[2021-08-30T22:30:01.206] [INFO] system - create video file: 2021年08月30日22時30分00秒-月が導く異世界道中　＃８「亜空ランキング」[再].m2ts
[2021-08-30T22:30:01.223] [INFO] system - set stream.finished: reserveId: 82150 recordedId: 8338
[2021-08-30T22:30:01.416] [INFO] system - recording: 87758 /app/recorded/2021年08月30日22時30分00秒-[字]サウナを愛でたい　「東京都足立区北千住 タカラ湯」.m2ts
[2021-08-30T22:30:01.421] [INFO] system - add drop log file: /app/drop/2021年08月30日22時30分00秒-[字]サウナを愛でたい　「東京都足立区北千住 タカラ湯」.m2ts.log
[2021-08-30T22:30:01.441] [INFO] system - add recorded 87758 /app/recorded/2021年08月30日22時30分00秒-[字]サウナを愛でたい　「東京都足立区北千住 タカラ湯」.m2ts
[2021-08-30T22:30:01.490] [INFO] system - recording added reserveId: 87758, recordedId: 8339
[2021-08-30T22:30:01.491] [INFO] system - create video file: 2021年08月30日22時30分00秒-[字]サウナを愛でたい　「東京都足立区北千住 タカラ湯」.m2ts
[2021-08-30T22:30:01.523] [INFO] system - set stream.finished: reserveId: 87758 recordedId: 8339
[2021-08-30T22:30:11.803] [INFO] system - all reservation update start
[2021-08-30T22:31:11.817] [ERROR] system - get execution error: 1
[2021-08-30T22:31:11.820] [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-08-30T22:31:18.468] [INFO] system - add video file: 8275 2021年08月30日21時54分00秒-ＶＩＲＴＵＡＬ　ＢＵＺＺ　ＴＡＬＫ！　★過去最高の圧とテンション！織田信姫！[再]-vaapi.mp4
[2021-08-30T22:31:18.584] [INFO] system - delete video file: 13659
[2021-08-30T22:31:18.620] [INFO] system - delete: /app/recorded/2021年08月30日21時54分00秒-ＶＩＲＴＵＡＬ　ＢＵＺＺ　ＴＡＬＫ！　★過去最高の圧とテンション！織田信姫！[再].m2ts
[2021-08-30T22:31:18.814] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:32:11.847] [ERROR] system - get execution error: 1
[2021-08-30T22:32:11.849] [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-08-30T22:32:59.710] [INFO] system - add video file: 8277 2021年08月30日21時54分00秒-四季彩キッチン[字]-vaapi.mp4
[2021-08-30T22:32:59.863] [INFO] system - delete video file: 13661
[2021-08-30T22:33:00.019] [INFO] system - delete: /app/recorded/2021年08月30日21時54分00秒-四季彩キッチン[字].m2ts
[2021-08-30T22:33:00.203] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:33:11.899] [ERROR] system - get execution error: 1
[2021-08-30T22:33:11.901] [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-08-30T22:34:11.916] [ERROR] system - get execution error: 1
[2021-08-30T22:34:11.919] [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-08-30T22:34:11.937] [INFO] system - all reservation update finish
[2021-08-30T22:34:48.341] [INFO] system - add video file: 8270 2021年08月30日21時30分00秒-結束！侍ジャパン #75-nvenc.mp4
[2021-08-30T22:34:48.495] [INFO] system - delete video file: 13649
[2021-08-30T22:34:48.531] [INFO] system - delete: /app/recorded/2021年08月30日21時30分00秒-結束！侍ジャパン #75.m2ts
[2021-08-30T22:34:49.224] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:36:29.740] [INFO] system - add video file: 8268 2021年08月30日21時30分00秒-野性爆弾くっきー！のロックン・ロール★サーカス　＃２-nvenc.mp4
[2021-08-30T22:36:29.777] [INFO] system - delete video file: 13647
[2021-08-30T22:36:29.790] [INFO] system - delete: /app/recorded/2021年08月30日21時30分00秒-野性爆弾くっきー！のロックン・ロール★サーカス　＃２.m2ts
[2021-08-30T22:36:30.547] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:36:41.284] [INFO] system - add video file: 8262 2021年08月30日21時00分00秒-ナイト・ドクター【衝突する５人！異なる価値観が交錯する！？】　＃０９[字][解][デ]-vaapi.mp4
[2021-08-30T22:36:41.295] [INFO] system - delete video file: 13636
[2021-08-30T22:36:41.316] [INFO] system - delete: /app/recorded/2021年08月30日21時00分00秒-ナイト・ドクター【衝突する５人！異なる価値観が交錯する！？】　＃０９[字][解][デ].m2ts
[2021-08-30T22:36:42.456] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:36:46.355] [INFO] system - add video file: 8286 2021年08月30日22時00分00秒-[字]にっぽん！歴史鑑定「信長を追いつめた男！朝倉義景」-nvenc.mp4
[2021-08-30T22:36:46.377] [INFO] system - delete video file: 13670
[2021-08-30T22:36:46.408] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-[字]にっぽん！歴史鑑定「信長を追いつめた男！朝倉義景」.m2ts
[2021-08-30T22:36:46.783] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:36:46.851] [INFO] system - add video file: 8273 2021年08月30日21時54分00秒-Ｔｈｅ　Ｇｉｆｔ[字]-vaapi.mp4
[2021-08-30T22:36:46.961] [INFO] system - delete video file: 13657
[2021-08-30T22:36:46.980] [INFO] system - delete: /app/recorded/2021年08月30日21時54分00秒-Ｔｈｅ　Ｇｉｆｔ[字].m2ts
[2021-08-30T22:36:47.094] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:37:03.391] [INFO] system - add video file: 8285 2021年08月30日22時00分00秒-フロム・ジ・アース／人類、月に立つ　＃１１[二]-nvenc.mp4
[2021-08-30T22:37:03.435] [INFO] system - delete video file: 13669
[2021-08-30T22:37:03.454] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-フロム・ジ・アース／人類、月に立つ　＃１１[二].m2ts
[2021-08-30T22:37:03.592] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:37:06.456] [INFO] system - add video file: 8269 2021年08月30日21時30分00秒-東京２０２０パラリンピック◇陸上　女子１５００ｍ　Ｔ５４・予選ほか（中継）[字]-vaapi.mp4
[2021-08-30T22:37:06.622] [INFO] system - delete video file: 13648
[2021-08-30T22:37:06.806] [INFO] system - delete: /app/recorded/2021年08月30日21時30分00秒-東京２０２０パラリンピック◇陸上　女子１５００ｍ　Ｔ５４・予選ほか（中継）[字].m2ts
[2021-08-30T22:37:07.663] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:37:20.785] [INFO] system - add video file: 8281 2021年08月30日22時00分00秒-[字][デ]クイズ！脳ベルＳＨＯＷ　第1267回-nvenc.mp4
[2021-08-30T22:37:20.832] [INFO] system - delete video file: 13665
[2021-08-30T22:37:20.853] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-[字][デ]クイズ！脳ベルＳＨＯＷ　第1267回.m2ts
[2021-08-30T22:37:20.956] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:37:54.416] [INFO] system - add video file: 8287 2021年08月30日22時00分00秒-所ＪＡＰＡＮ【幸せ全開！三代目ＪＳＢ山下がメルカリ出品＆小林幸子(秘)４億円豪邸】[字]-vaapi.mp4
[2021-08-30T22:37:54.537] [INFO] system - delete video file: 13671
[2021-08-30T22:37:54.562] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-所ＪＡＰＡＮ【幸せ全開！三代目ＪＳＢ山下がメルカリ出品＆小林幸子(秘)４億円豪邸】[字].m2ts
[2021-08-30T22:37:54.617] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:38:27.940] [INFO] system - add video file: 8288 2021年08月30日22時00分00秒-ＷＢＳ[字]-vaapi.mp4
[2021-08-30T22:38:28.009] [INFO] system - delete video file: 13672
[2021-08-30T22:38:28.031] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-ＷＢＳ[字].m2ts
[2021-08-30T22:38:28.071] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:39:00.203] [INFO] system - add video file: 8283 2021年08月30日22時00分00秒-しゃべくり００７【東京五輪バスケットボール女子日本代表＆超熱血コーチの素顔】[字]-vaapi.mp4
[2021-08-30T22:39:00.245] [INFO] system - delete video file: 13667
[2021-08-30T22:39:00.298] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-しゃべくり００７【東京五輪バスケットボール女子日本代表＆超熱血コーチの素顔】[字].m2ts
[2021-08-30T22:39:00.378] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:39:09.054] [INFO] system - add video file: 8276 2021年08月30日21時54分00秒-報道ステーション[字]-vaapi.mp4
[2021-08-30T22:39:09.066] [INFO] system - delete video file: 13660
[2021-08-30T22:39:09.080] [INFO] system - delete: /app/recorded/2021年08月30日21時54分00秒-報道ステーション[字].m2ts
[2021-08-30T22:39:09.258] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:39:54.181] [INFO] system - add video file: 8280 2021年08月30日22時00分00秒-教えてもらう前と後【歌うま女性芸人ＢＥＳＴ１０★圧巻！友近の本気ｖｓゆめっち】[字]-vaapi.mp4
[2021-08-30T22:39:54.336] [INFO] system - delete video file: 13664
[2021-08-30T22:39:54.539] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-教えてもらう前と後【歌うま女性芸人ＢＥＳＴ１０★圧巻！友近の本気ｖｓゆめっち】[字].m2ts
[2021-08-30T22:39:54.624] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:40:05.342] [INFO] system - all reservation update start
[2021-08-30T22:40:42.190] [INFO] system - add video file: 8284 2021年08月30日22時00分00秒-ＳＨＯＷ　ＢＹ　ＲＯＣＫ！！ましゅまいれっしゅ！！　＃９「カバンには鉄板です」[再]-vaapi.mp4
[2021-08-30T22:40:42.314] [INFO] system - delete video file: 13668
[2021-08-30T22:40:42.354] [INFO] system - delete: /app/recorded/2021年08月30日22時00分00秒-ＳＨＯＷ　ＢＹ　ＲＯＣＫ！！ましゅまいれっしゅ！！　＃９「カバンには鉄板です」[再].m2ts
[2021-08-30T22:40:42.433] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:41:05.381] [ERROR] system - get execution error: 1
[2021-08-30T22:41:05.383] [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-08-30T22:42:05.400] [ERROR] system - get execution error: 1
[2021-08-30T22:42:05.405] [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-08-30T22:42:40.133] [INFO] system - add video file: 8310 2021年08月30日21時30分00秒-東京２０２０パラリンピック◇陸上　女子１５００ｍ　Ｔ５４・予選ほか（中継）字-vaapi.mp4
[2021-08-30T22:42:40.172] [INFO] system - delete video file: 13696
[2021-08-30T22:42:40.191] [INFO] system - delete: /app/recorded/2021年08月30日21時30分00秒-東京２０２０パラリンピック◇陸上　女子１５００ｍ　Ｔ５４・予選ほか（中継）字.m2ts
[2021-08-30T22:42:40.598] [INFO] system - encodingFinishCommand: undefined
[2021-08-30T22:43:05.431] [ERROR] system - get execution error: 1
[2021-08-30T22:43:05.434] [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-08-30T22:44:05.486] [ERROR] system - get execution error: 1
[2021-08-30T22:44:05.487] [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-08-30T22:44:05.504] [INFO] system - all reservation update finish
[2021-08-30T22:44:32.173] [INFO] system - add video file: 8259 2021年08月30日21時00分00秒-[字]吉田類の酒場放浪記▼今日はおうちキャンプ　リベンジ-nvenc.mp4
[2021-08-30T22:44:32.209] [INFO] system - delete video file: 13633

長くなってしまい申し訳ありません。30分始めあたりと40分辺りでエラーが出ています。また、同時に放送開始した番組で問題なく録画が始まっている番組もありました。よろしくお願いします。

@l3tnun
Copy link
Owner

l3tnun commented Aug 31, 2021

多重起動の件は問題なさそうです。Operator が応答できていないことが IPCTimeout の原因のようです。

次に、Operator の方ですが、正直何がどうなったらこのような事になるのか分かりません。
予約管理の lock が何らかの理由で取れないことが原因のようですが、その要因が分からないです。

以下の点を確認させてください

  1. 起動直後から get execution error やその他のエラーが発生していないか。発生している場合はそのログがほしいです。
  2. どのような予約(ルール)を設定しているのか見せていただきたいです。
  3. epgstation のweb ui 以外から予約やルールの設定をしていないか。

@l3tnun
Copy link
Owner

l3tnun commented Aug 31, 2021

あと使用しているデータベースの種類も教えて下さい。

@MicotoTisaki
Copy link
Author

一部get execution error を発見したのでその前後を添付します。

[2021-08-31T04:30:05.950] [INFO] system - emit finish recording reserveId: 89886, recordedId: 8471, isNeedDeleteReservation: true
[2021-08-31T04:30:05.950] [DEBUG] system - delete recording index: 89886
[2021-08-31T04:30:05.950] [INFO] system - add thumbnail queue: 14026
[2021-08-31T04:30:05.951] [INFO] system - recording finish reserveId: 89886, recordedId: 8471, videoFileFulPath: /app/recorded/2021年08月31日04時00分00秒-空からクルージング特別編「イタリア・シチリア島の古代遺跡」.m2ts
[2021-08-31T04:30:06.345] [DEBUG] system - ffmpeg version 4.1 Copyright (c) 2000-2018 the FFmpeg developers
built with gcc 8 (Debian 8.3.0-6)
configuration: --prefix=/usr/local --disable-shared --pkg-config-flags=--static --enable-gpl --enable-libass --enable-libfreetype --enable-libmp3lame --enable-libopus --enable-libtheora --enable-libvorbis --enable-libvpx --enable-libx264 --enable-libx265 --enable-version3 --enable-nonfree --disable-debug --disable-doc --enable-vaapi
libavutil 56. 22.100 / 56. 22.100
libavcodec 58. 35.100 / 58. 35.100
libavformat 58. 20.100 / 58. 20.100
libavdevice 58. 5.100 / 58. 5.100
libavfilter 7. 40.101 / 7. 40.101
libswscale 5. 3.100 / 5. 3.100
libswresample 3. 3.100 / 3. 3.100
libpostproc 55. 3.100 / 55. 3.100
[mpeg2video @ 0x55651933ca40] Invalid frame dimensions 0x0.
Last message repeated 5 times
[mpegts @ 0x556519316fc0] start time for stream 2 is not set in estimate_timings_from_pts
[mpegts @ 0x556519316fc0] start time for stream 3 is not set in estimate_timings_from_pts
[mpegts @ 0x556519316fc0] Could not find codec parameters for stream 4 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x556519316fc0] Could not find codec parameters for stream 5 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x556519316fc0] Could not find codec parameters for stream 6 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x556519316fc0] Could not find codec parameters for stream 7 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x556519316fc0] Could not find codec parameters for stream 8 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x556519316fc0] Could not find codec parameters for stream 9 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
Input #0, mpegts, from '/app/recorded/2021年08月31日04時00分00秒-空からクルージング特別編「イタリア・シチリア島の古代遺跡」.m2ts':
Duration: 00:20:09.19, start: 1870.150544, bitrate: 19344 kb/s
Program 101
Metadata:
service_name : ?~����ӱ
service_provider: ?~���
Stream #0:0[0x100]: Video: mpeg2video (Main) ([2][0][0][0] / 0x0002), yuv420p(tv, bt709, top first), 1440x1080 [SAR 4:3 DAR 16:9], 29.97 fps, 29.97 tbr, 90k tbn, 59.94 tbc
Stream #0:1[0x110]: Audio: aac (LC) ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp, 310 kb/s
Stream #0:2[0x130]: Data: bin_data ([6][0][0][0] / 0x0006)
Stream #0:3[0x138]: Data: bin_data ([6][0][0][0] / 0x0006)
Stream #0:4[0x140]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:5[0x160]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:6[0x161]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:7[0x162]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:8[0x170]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:9[0x171]: Unknown: none ([13][0][0][0] / 0x000D)
Program 102
Metadata:
service_name : ?~����ӱ
service_provider: ?~���
Program 700
Metadata:
service_name : ?~���?|�!<�?~�
service_provider: ?~���
Program 701
Metadata:
service_name : ?~���?|�!<�?~�
service_provider: ?~���
Program 707
Metadata:
service_name : ?~���?|�����
service_provider: ?~���
Program 929
Metadata:
service_name : ?~���?|����!<�
service_provider: ?~���
Stream mapping:
Stream #0:0 -> #0:0 (mpeg2video (native) -> mjpeg (native))
Press [q] to stop, [?] for help

[2021-08-31T04:30:06.458] [DEBUG] system - [swscaler @ 0x556519550140] deprecated pixel format used, make sure you did set range correctly
Output #0, image2, to '/app/thumbnail/8471.jpg':
Metadata:
encoder : Lavf58.20.100
Stream #0:0: Video: mjpeg, yuvj420p(pc), 480x270 [SAR 1:1 DAR 16:9], q=2-31, 200 kb/s, 29.97 fps, 29.97 tbn, 29.97 tbc
Metadata:
encoder : Lavc58.35.100 mjpeg
Side data:
cpb: bitrate max/min/avg: 0/0/200000 buffer size: 0 vbv_delay: -1

[2021-08-31T04:30:06.504] [DEBUG] system - frame= 1 fps=0.0 q=3.7 Lsize=N/A time=00:00:00.03 bitrate=N/A dup=1 drop=1 speed=0.233x
video:18kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown

[2021-08-31T04:30:06.519] [INFO] system - create thumbnail: 14026, /app/thumbnail/8471.jpg
[2021-08-31T04:30:33.136] [INFO] system - add video file: 8484 2021年08月31日04時29分00秒-日テレみどころ-vaapi.mp4
[2021-08-31T04:30:33.217] [INFO] system - delete video file: 14060
[2021-08-31T04:30:33.270] [INFO] system - delete: /app/recorded/2021年08月31日04時29分00秒-日テレみどころ.m2ts
[2021-08-31T04:30:33.365] [INFO] system - encodingFinishCommand: undefined
[2021-08-31T04:30:52.592] [ERROR] system - get execution error: 1
[2021-08-31T04:30:52.600] [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-08-31T04:31:01.421] [ERROR] system - get execution error: 1
[2021-08-31T04:31:01.427] [ERROR] system - get execution error: 1
[2021-08-31T04:31:03.553] [ERROR] system - get execution error: 1
[2021-08-31T04:31:04.424] [ERROR] system - get execution error: 1
[2021-08-31T04:31:05.994] [ERROR] system - get execution error: 1
[2021-08-31T04:31:52.701] [ERROR] system - get execution error: 1
[2021-08-31T04:31:52.703] [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-08-31T04:32:51.434] [INFO] system - add video file: 8477 2021年08月31日02時30分00秒-【モタスポマンデー】世界ツーリングカー・カッ
プ（WTCR）2021 第4戦 決勝(2)-nvenc.mp4
[2021-08-31T04:32:51.763] [INFO] system - delete video file: 14036
[2021-08-31T04:32:51.853] [INFO] system - delete: /app/recorded/2021年08月31日02時30分00秒-【モタスポマンデー】世界ツーリングカー・カップ（WTCR）2021 第4戦 決勝.m2ts
[2021-08-31T04:32:52.268] [INFO] system - encodingFinishCommand: undefined
[2021-08-31T04:32:52.722] [ERROR] system - get execution error: 1
[2021-08-31T04:32:52.723] [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-08-31T04:33:52.743] [ERROR] system - get execution error: 1
[2021-08-31T04:33:52.744] [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-08-31T04:33:52.760] [INFO] system - all reservation update finish
[2021-08-31T04:34:45.001] [INFO] system - preprec: 82216
[2021-08-31T04:35:02.099] [INFO] system - recording: 82216 /app/recorded/2021年08月31日04時35分00秒-みんなのうた「そんなぼくがすき」「
バケバケＮｉｇｈｔ！」.m2ts
[2021-08-31T04:35:02.152] [INFO] system - add drop log file: /app/drop/2021年08月31日04時35分00秒-みんなのうた「そんなぼくがすき」「バ
ケバケＮｉｇｈｔ！」.m2ts.log
[2021-08-31T04:35:02.212] [INFO] system - add recorded 82216 /app/recorded/2021年08月31日04時35分00秒-みんなのうた「そんなぼくがすき」
「バケバケＮｉｇｈｔ！」.m2ts
[2021-08-31T04:35:02.245] [INFO] system - recording added reserveId: 82216, recordedId: 8490
[2021-08-31T04:35:02.246] [INFO] system - create video file: 2021年08月31日04時35分00秒-みんなのうた「そんなぼくがすき」「バケバケＮｉ
ｇｈｔ！」.m2ts
[2021-08-31T04:35:02.267] [INFO] system - set stream.finished: reserveId: 82216 recordedId: 8490
[2021-08-31T04:35:02.876] [DEBUG] system - delete stream: 82212
[2021-08-31T04:35:02.877] [INFO] system - start recEnd reserveId: 82212 recordedId: 8481
[2021-08-31T04:35:02.878] [INFO] system - stop drop check: /app/drop/2021年08月31日04時24分00秒-瀬戸内　ふるさとの絶景.m2ts.log
[2021-08-31T04:35:02.880] [INFO] system - remove recording flag: 8481
[2021-08-31T04:35:02.921] [INFO] system - update file size: 14050
[2021-08-31T04:35:02.922] [INFO] system - { recordedId: 8481, error: 0, drop: 0, scrambling: 0 }
[2021-08-31T04:35:02.973] [INFO] system - add recorded history: 8481
[2021-08-31T04:35:02.989] [INFO] system - emit finish recording reserveId: 82212, recordedId: 8481, isNeedDeleteReservation: true
[2021-08-31T04:35:02.990] [DEBUG] system - delete recording index: 82212
[2021-08-31T04:35:02.991] [INFO] system - add thumbnail queue: 14050
[2021-08-31T04:35:02.992] [INFO] system - recording finish reserveId: 82212, recordedId: 8481, videoFileFulPath: /app/recorded/2021年08月31日04時24分00秒-瀬戸内　ふるさとの絶景.m2ts
[2021-08-31T04:35:03.131] [DEBUG] system - ffmpeg version 4.1 Copyright (c) 2000-2018 the FFmpeg developers
built with gcc 8 (Debian 8.3.0-6)
configuration: --prefix=/usr/local --disable-shared --pkg-config-flags=--static --enable-gpl --enable-libass --enable-libfreetype --enable-libmp3lame --enable-libopus --enable-libtheora --enable-libvorbis --enable-libvpx --enable-libx264 --enable-libx265 --enable-version3 --enable-nonfree --disable-debug --disable-doc --enable-vaapi
libavutil 56. 22.100 / 56. 22.100
libavcodec 58. 35.100 / 58. 35.100
libavformat 58. 20.100 / 58. 20.100
libavdevice 58. 5.100 / 58. 5.100
libavfilter 7. 40.101 / 7. 40.101
libswscale 5. 3.100 / 5. 3.100
libswresample 3. 3.100 / 3. 3.100
libpostproc 55. 3.100 / 55. 3.100

[2021-08-31T04:35:03.175] [DEBUG] system - [mpeg2video @ 0x5618059e9180] Invalid frame dimensions 0x0.

[2021-08-31T04:35:03.258] [DEBUG] system - Last message repeated 4 times
[mpegts @ 0x5618059e3fc0] start time for stream 2 is not set in estimate_timings_from_pts
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 3 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 4 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 5 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 6 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 7 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 8 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
[mpegts @ 0x5618059e3fc0] Could not find codec parameters for stream 9 (Unknown: none ([13][0][0][0] / 0x000D)): unknown codec
Consider increasing the value for the 'analyzeduration' and 'probesize' options
Input #0, mpegts, from '/app/recorded/2021年08月31日04時24分00秒-瀬戸内　ふるさとの絶景.m2ts':
Duration: 00:11:05.94, start: 54777.639022, bitrate: 15501 kb/s
Program 1024
Metadata:
service_name : ?NHK?Am9g?1�?El5~
service_provider:
Stream #0:0[0x100]: Video: mpeg2video (Main) ([2][0][0][0] / 0x0002), yuv420p(tv, bt709, top first), 1440x1080 [SAR 4:3 DAR 16:9], 29.97 fps, 29.97 tbr, 90k tbn, 59.94 tbc
Stream #0:1[0x110]: Audio: aac (LC) ([15][0][0][0] / 0x000F), 48000 Hz, stereo, fltp, 255 kb/s
Stream #0:2[0x138]: Data: bin_data ([6][0][0][0] / 0x0006)
Stream #0:3[0x140]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:4[0x160]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:5[0x161]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:6[0x162]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:7[0x170]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:8[0x171]: Unknown: none ([13][0][0][0] / 0x000D)
Stream #0:9[0x172]: Unknown: none ([13][0][0][0] / 0x000D)
Program 1025
Metadata:
service_name : ?NHK?Am9g?2�?El5~
service_provider:
Program 1408
Metadata:
service_name : ?NHK?7HBS?G�?El5~
service_provider:
Stream mapping:
Stream #0:0 -> #0:0 (mpeg2video (native) -> mjpeg (native))
Press [q] to stop, [?] for help

[2021-08-31T04:35:03.287] [DEBUG] system - [swscaler @ 0x561805db42c0] deprecated pixel format used, make sure you did set range correctly
Output #0, image2, to '/app/thumbnail/8481.jpg':
Metadata:
encoder : Lavf58.20.100
Stream #0:0: Video: mjpeg, yuvj420p(pc), 480x270 [SAR 1:1 DAR 16:9], q=2-31, 200 kb/s, 29.97 fps, 29.97 tbn, 29.97 tbc
Metadata:
encoder : Lavc58.35.100 mjpeg
Side data:
cpb: bitrate max/min/avg: 0/0/200000 buffer size: 0 vbv_delay: -1

[2021-08-31T04:35:03.305] [DEBUG] system - frame= 1 fps=0.0 q=3.1 Lsize=N/A time=00:00:00.03 bitrate=N/A dup=1 drop=1 speed=0.965x
video:12kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown

[2021-08-31T04:35:03.328] [INFO] system - create thumbnail: 14050, /app/thumbnail/8481.jpg
[2021-08-31T04:35:34.991] [INFO] system - add video file: 8468 2021年08月31日03時59分00秒-日テレポシュレ-vaapi.mp4
[2021-08-31T04:35:35.032] [INFO] system - delete video file: 14022
[2021-08-31T04:35:35.057] [INFO] system - delete: /app/recorded/2021年08月31日03時59分00秒-日テレポシュレ.m2ts
[2021-08-31T04:35:35.555] [INFO] system - encodingFinishCommand: undefined
[2021-08-31T04:36:02.993] [ERROR] system - get execution error: 1
[2021-08-31T04:38:23.269] [INFO] system - add video file: 8471 2021年08月31日04時00分00秒-空からクルージング特別編「イタリア・シチリア
島の古代遺跡」-vaapi.mp4
[2021-08-31T04:38:23.302] [INFO] system - delete video file: 14026
[2021-08-31T04:38:23.318] [INFO] system - delete: /app/recorded/2021年08月31日04時00分00秒-空からクルージング特別編「イタリア・シチリア島の古代遺跡」.m2ts
[2021-08-31T04:38:23.747] [INFO] system - encodingFinishCommand: undefined
[2021-08-31T04:38:30.134] [INFO] system - add video file: 8447 2021年08月31日03時30分00秒-中国ドラマ　新・白蛇伝～千年一度の恋～ 第１２話「怨念の雪」（字幕）(1)-nvenc.mp4
[2021-08-31T04:38:30.144] [INFO] system - delete video file: 13982
[2021-08-31T04:38:30.153] [INFO] system - delete: /app/recorded/2021年08月31日03時30分00秒-中国ドラマ　新・白蛇伝～千年一度の恋～ 第１
２話「怨念の雪」（字幕）(1).m2ts
[2021-08-31T04:38:31.298] [INFO] system - encodingFinishCommand: undefined
[2021-08-31T04:39:00.969] [INFO] system - add video file: 8481 2021年08月31日04時24分00秒-瀬戸内　ふるさとの絶景-vaapi.mp4
[2021-08-31T04:39:00.984] [INFO] system - delete video file: 14050
[2021-08-31T04:39:00.992] [INFO] system - delete: /app/recorded/2021年08月31日04時24分00秒-瀬戸内　ふるさとの絶景.m2ts
[2021-08-31T04:39:01.038] [INFO] system - encodingFinishCommand: undefined
[2021-08-31T04:39:45.000] [INFO] system - preprec: 82217
[2021-08-31T04:39:57.493] [INFO] system - all reservation update start
[2021-08-31T04:40:01.696] [INFO] system - recording: 82217 /app/recorded/2021年08月31日04時40分00秒-視点・論点「パラリンピック選手の“脳の再編”」[字][再].m2ts
[2021-08-31T04:40:01.706] [INFO] system - add drop log file: /app/drop/2021年08月31日04時40分00秒-視点・論点「パラリンピック選手の“脳の再編”」[字][再].m2ts.log
[2021-08-31T04:40:01.730] [INFO] system - add recorded 82217 /app/recorded/2021年08月31日04時40分00秒-視点・論点「パラリンピック選手の“脳の再編”」[字][再].m2ts
[2021-08-31T04:40:01.742] [INFO] system - recording added reserveId: 82217, recordedId: 8491
[2021-08-31T04:40:01.742] [INFO] system - create video file: 2021年08月31日04時40分00秒-視点・論点「パラリンピック選手の“脳の再編”」[字][再].m2ts
[2021-08-31T04:40:01.749] [INFO] system - set stream.finished: reserveId: 82217 recordedId: 8491
[2021-08-31T04:40:02.600] [DEBUG] system - delete stream: 82216
[2021-08-31T04:40:02.601] [INFO] system - start recEnd reserveId: 82216 recordedId: 8490
[2021-08-31T04:40:02.601] [INFO] system - stop drop check: /app/drop/2021年08月31日04時35分00秒-みんなのうた「そんなぼくがすき」「バケ
バケＮｉｇｈｔ！」.m2ts.log

また、予約は以下のようにとっており、epgstation以外からは予約設定を行っていません。各ルールはチャンネル別にエンコード方法を分けており、nvencとvaapiで分けております。
screencapture-192-168-1-110-8888-2021-08-31-21_25_40
screencapture-192-168-1-110-8888-2021-08-31-21_30_16

また、mariadb10.4を使用しています。
よろしくお願いします。

@MicotoTisaki
Copy link
Author

何度か動作を確認していて、どうやらエンコードが全部終了すると録画を再開する挙動をしているのですが、現在config.ymlの設定で以下の様に書いています。

encodeProcessNum: 8
concurrentEncodeNum: 6
この場合、ProcessNumを超える数のエンコードタスクが発生した場合は予約している録画を開始せずに停止し、上記のようなエラーの形で現れることがあるのでしょうか？

@l3tnun
Copy link
Owner

l3tnun commented Sep 2, 2021

エンコードは Service 側で行われているので、基本的には録画処理を行っている Operator 側には影響はないはずです。
エンコード終了後に DB へ登録する処理を Service からOperator に依頼するので、何らかの理由で Operator が反応できない場合は IPCTimeout が発生し、登録が失敗することはあるかもしれません。

@MicotoTisaki
Copy link
Author

先ほど再起動し get execution errorが起動直後から発生しないかどうか確認しましたが、ルールに追加してある予約の登録がDEBUGで走るだけで特にERRORは吐かれませんでした。また再起動前に get execution errorをOperator/system.logから探しましたが上記に記載したログ以外は見当たりませんでした。
先ほど再起動を行ったので、もう一度様子を見てエラーログが出てくるかどうか確認してみます。

@l3tnun
Copy link
Owner

l3tnun commented Sep 12, 2021

get execution error ですが、予約処理のロックが意図せず外れたことが原因かと思います。
epgstation では予約の更新時には予約処理の競合が起きないようにロックの管理を行っています。
このロックは何らかの理由でロック解除がされなかった時を想定して、ロック取得60秒後にロックが自動で解除されるようになっています。

おそらくですが、ルール1件あたりの予約数が多いことで、この60秒を超過し予約処理が正常に実行できなかったのではないかと思います。

対策として、1つのルールで複数の放送局を指定して全録のようなことをされているように見えますが、
これをやめていただき、放送局ごとにルールを作成してもらうと症状が緩和されるかと思います。
正直このようなルール(ルール一件あたりの予約の多さ)を想定して作られていないです。

@l3tnun l3tnun mentioned this issue Sep 12, 2021
Open
@MicotoTisaki
Copy link
Author

その後、ルールを放送局ごとに分けて予約を行うように設定を変えた所、/Service/system.logの方から以下のようなエラーが再起動後毎回発生するようになってしまいました。

[2021-09-23T02:03:12.171] [INFO] system - config.yml read success
[2021-09-23T02:03:14.147] [INFO] system - SocketIO Server has started.
[2021-09-23T02:03:14.148] [INFO] system - http server listening on 8888
[2021-09-23T02:04:17.324] [ERROR] system - Error: IPCTimeout
at Timeout._onTimeout (/app/dist/model/ipc/model/ipc/IPCClient.ts:126:28)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)
[2021-09-23T02:04:21.988] [ERROR] system - Error: IPCTimeout
at Timeout._onTimeout (/app/dist/model/ipc/model/ipc/IPCClient.ts:126:28)
at listOnTimeout (node:internal/timers:557:17)
at processTimers (node:internal/timers:500:7)

また、予約自体は自動で入るのですが、その後録画中のデータも止まり/Operator/system.logの方では以下のようなログが出力されてます。

[2021-09-23T02:06:28.157] [INFO] system - delete: /app/recorded/2021年09月23日01時30分00秒-FIMスーパースポーツ世界選手権2021 第9戦 カタルーニャ.m2ts
[2021-09-23T02:06:28.407] [INFO] system - encodingFinishCommand: undefined
[2021-09-23T02:20:34.672] [INFO] system - update rule: 59
[2021-09-23T02:20:34.679] [INFO] system - rule updated successfully: 59
[2021-09-23T02:20:47.146] [INFO] system - update rule: 60
[2021-09-23T02:20:47.149] [INFO] system - rule updated successfully: 60
[2021-09-23T02:20:57.784] [INFO] system - update rule: 61
[2021-09-23T02:20:57.796] [INFO] system - rule updated successfully: 61
[2021-09-23T02:21:08.988] [INFO] system - update rule: 62
[2021-09-23T02:21:08.992] [INFO] system - rule updated successfully: 62
[2021-09-23T02:21:34.680] [ERROR] system - get execution error: 1
[2021-09-23T02:21:34.681] [FATAL] system - unhandledRejection
[2021-09-23T02:21:34.682] [FATAL] 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-23T02:21:47.153] [ERROR] system - get execution error: 1
[2021-09-23T02:21:47.154] [FATAL] system - unhandledRejection
[2021-09-23T02:21:47.154] [FATAL] 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-23T02:21:57.800] [ERROR] system - get execution error: 1
[2021-09-23T02:21:57.801] [FATAL] system - unhandledRejection
[2021-09-23T02:21:57.801] [FATAL] 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-23T02:22:08.997] [ERROR] system - get execution error: 1
[2021-09-23T02:22:08.998] [FATAL] system - unhandledRejection
[2021-09-23T02:22:08.998] [FATAL] 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)

@l3tnun
Copy link
Owner

l3tnun commented Oct 24, 2021

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

IPCTimeout が出ている件ですが、ServiceExecutor.js が残り続けて多重起動していなければ、/Operator/system.log で出ている get execution error が原因かと思います。

get execution error が出ている原因ですが、ルール毎の予約件数に関係する話でないとするとよくわからないです。

Operator 側で ExecutionManagementModel を使用しているのは 予約を管理する ReservationManageModel だけなので、
ReservationManageModel が ExecutionManagementModel からロックの取得に失敗しているのは確かなのですが...

ルールの全件更新時にしてもエラーが ↓まで落ちてくるのが謎です。
https://github.com/l3tnun/EPGStation/blob/master/src/index.ts#L34-L37

ReservationManageModel の updateAll() (全件更新時に呼ばれる) で、try catch しているのでそこで止まるはずなのと、
https://github.com/l3tnun/EPGStation/blob/master/src/model/operator/reservation/ReservationManageModel.ts#L979-L1012
get execution error が約 10 秒おきに出てくるのもよく分かりません。

ExecutionManagementModel からロックを取得する際のタイムアウト時間は 60 秒に設定されているので、60秒おきであればまだわかるのですが...
https://github.com/l3tnun/EPGStation/blob/master/src/model/ExecutionManagementModel.ts#L24

すいませんが、現状ではお力になれそうにないです。

@MicotoTisaki
Copy link
Author

色々調べていただきありがとうございます。一応現状再起動によりエラーを一時的に解消できるため、crontabからdocker-compose down && docker-compose up -dという形で対応しようと思います。

またここ数週間監視をしていたところ、ちょうど1週間の連続録画によりエラー発生の後録画が入らなくなるといった形でした。番組表自体は通常通り取得できているのですが、番組表のページにて赤枠も入っていない状態でした。番組表更新のタイミングで予約リストが更新されていない可能性もあるのかなと使っていて感じました。

こちらでもまた使用してみて何か気づいた点がありましたらお知らせさせて頂こうと思います。長い期間ありがとうございました。

@l3tnun
Copy link
Owner

l3tnun commented Nov 7, 2021

こちらこそ、ありがとうございます。
解決に至らず申し訳ない。

またここ数週間監視をしていたところ、ちょうど1週間の連続録画によりエラー発生の後録画が入らなくなるといった形でした。

おそらく、get execution errorが多発して予約情報が更新されないことが原因かと思います。
番組情報の取得と予約更新は別プロセスで動いているので、番組情報だけは正常に更新されています。

@MicotoTisaki
Copy link
Author

お世話になっております。あの後容量残量の許容値を調整したりNodeがOut of Memoryを吐いていたのでメモリ増設で対応したりしていました。どうやらエラーの一部はhdd残量の閾値に対するremoveの挙動と録画データの書き込みが一時的に釣り合っておらずに発生していた部分もあったのかなと思われます。

また、epgstationの方はv2.6.15にアップデートを行い、Mirakurunは3.7.1のまま稼働させています。

ただ、それを解決した後にも同様のエラーログが発生しているタイミングがあったのでもしかしたらと思いコメントさせていただきます。前回仰っていた60秒ごとのエラーも発生していました。今回のエラーログだと末尾の方が2つのエラー出力が交互に60秒ごとに出力されていました。

[2021-11-19T07:30:05.710] [INFO] system - create thumbnail: 71016, /app/thumbnail/54016.jpg
[2021-11-19T07:30:10.160] [INFO] system - preprec: 242057
[2021-11-19T07:30:10.191] [INFO] system - recording: 242057 /app/recorded/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts
[2021-11-19T07:30:10.192] [DEBUG] system - delete stream: 242057
[2021-11-19T07:30:10.192] [INFO] system - add drop log file: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(1).log
[2021-11-19T07:30:15.290] [ERROR] system - recording failed: 242057
[2021-11-19T07:30:15.293] [INFO] system - stop drop check: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(1).log
[2021-11-19T07:30:15.294] [INFO] system - stop drop check: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(1).log
[2021-11-19T07:30:15.294] [DEBUG] system - delete recording index: 242057
[2021-11-19T07:30:15.295] [ERROR] system - preprec failed: 242057
[2021-11-19T07:30:15.295] [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-11-19T07:30:20.300] [INFO] system - preprec: 242057
[2021-11-19T07:30:20.347] [INFO] system - recording: 242057 /app/recorded/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts
[2021-11-19T07:30:20.348] [DEBUG] system - delete stream: 242057
[2021-11-19T07:30:20.349] [INFO] system - add drop log file: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(2).log
[2021-11-19T07:30:25.485] [ERROR] system - recording failed: 242057
[2021-11-19T07:30:25.486] [INFO] system - stop drop check: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(2).log
[2021-11-19T07:30:25.486] [INFO] system - stop drop check: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(2).log
[2021-11-19T07:30:25.486] [DEBUG] system - delete recording index: 242057
[2021-11-19T07:30:25.487] [ERROR] system - preprec failed: 242057
[2021-11-19T07:30:25.487] [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-11-19T07:30:30.488] [INFO] system - preprec: 242057
[2021-11-19T07:30:30.523] [INFO] system - recording: 242057 /app/recorded/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts
[2021-11-19T07:30:30.523] [DEBUG] system - delete stream: 242057
[2021-11-19T07:30:30.524] [INFO] system - add drop log file: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(3).log
[2021-11-19T07:30:31.107] [DEBUG] system - delete stream: 242053
[2021-11-19T07:30:31.107] [ERROR] system - preprec failed: 242053
[2021-11-19T07:30:31.107] [ERROR] system - Error: socket hang up
at connResetException (node:internal/errors:691:14)
at Socket.socketOnEnd (node:_http_client:471:23)
at Socket.emit (node:events:402:35)
at endReadableNT (node:internal/streams/readable:1343:12)
at processTicksAndRejections (node:internal/process/task_queues:83:21) {
code: 'ECONNRESET'
}
[2021-11-19T07:30:31.136] [DEBUG] system - delete stream: 242056
[2021-11-19T07:30:31.137] [ERROR] system - preprec failed: 242056
[2021-11-19T07:30:31.137] [ERROR] system - Error: socket hang up
at connResetException (node:internal/errors:691:14)
at Socket.socketOnEnd (node:_http_client:471:23)
at Socket.emit (node:events:402:35)
at endReadableNT (node:internal/streams/readable:1343:12)
at processTicksAndRejections (node:internal/process/task_queues:83:21) {
code: 'ECONNRESET'
}
[2021-11-19T07:30:35.612] [ERROR] system - recording failed: 242057
[2021-11-19T07:30:35.613] [INFO] system - stop drop check: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(3).log
[2021-11-19T07:30:35.613] [INFO] system - stop drop check: /app/drop/2021年11月19日07時15分00秒-【連続テレビ小説】マー姉ちゃん（４７）[字].m2ts(3).log
[2021-11-19T07:30:35.613] [DEBUG] system - delete recording index: 242057
[2021-11-19T07:30:35.614] [ERROR] system - preprec failed: 242057
[2021-11-19T07:30:35.614] [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-11-19T07:30:35.616] [DEBUG] system - delete recording index: 242057
[2021-11-19T07:30:36.110] [INFO] system - preprec: 242053
[2021-11-19T07:30:36.137] [INFO] system - preprec: 242056
[2021-11-19T07:30:38.179] [ERROR] system - get execution error: 1
[2021-11-19T07:30:38.179] [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-11-19T07:30:43.086] [INFO] system - all reservation update start
[2021-11-19T07:31:01.797] [ERROR] system - get execution error: 1
[2021-11-19T07:31:02.114] [ERROR] system - get execution error: 1
[2021-11-19T07:31:02.522] [ERROR] system - get execution error: 1
[2021-11-19T07:31:02.910] [ERROR] system - get execution error: 1
[2021-11-19T07:31:03.867] [ERROR] system - get execution error: 1
[2021-11-19T07:31:04.102] [ERROR] system - get execution error: 1
[2021-11-19T07:31:05.109] [ERROR] system - get execution error: 2
[2021-11-19T07:31:05.109] [FATAL] system - unhandledRejection
[2021-11-19T07:31:05.109] [FATAL] 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-11-19T07:31:15.294] [ERROR] system - get execution error: 2
[2021-11-19T07:31:15.295] [FATAL] system - unhandledRejection
[2021-11-19T07:31:15.295] [FATAL] 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-11-19T07:31:25.487] [ERROR] system - get execution error: 2
[2021-11-19T07:31:25.488] [FATAL] system - unhandledRejection
[2021-11-19T07:31:25.488] [FATAL] 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-11-19T07:31:35.615] [ERROR] system - get execution error: 2
[2021-11-19T07:31:35.616] [FATAL] system - unhandledRejection
[2021-11-19T07:31:35.616] [FATAL] 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-11-19T07:31:35.623] [ERROR] system - get execution error: 2
[2021-11-19T07:31:35.623] [FATAL] system - unhandledRejection
[2021-11-19T07:31:35.623] [FATAL] 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-11-19T07:31:38.190] [ERROR] system - get execution error: 1
[2021-11-19T07:31:38.191] [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-11-19T07:31:43.093] [ERROR] system - get execution error: 1
[2021-11-19T07:31:43.093] [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-11-19T07:32:38.203] [ERROR] system - get execution error: 1
[2021-11-19T07:32:38.203] [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-11-19T07:32:43.104] [ERROR] system - get execution error: 1
[2021-11-19T07:32:43.105] [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-11-19T07:33:38.215] [ERROR] system - get execution error: 1
[2021-11-19T07:33:38.216] [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-11-19T07:33:43.117] [ERROR] system - get execution error: 1
[2021-11-19T07:33:43.117] [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-11-19T07:34:38.232] [ERROR] system - get execution error: 1
[2021-11-19T07:34:38.233] [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-11-19T07:34:43.134] [ERROR] system - get execution error: 1
[2021-11-19T07:34:43.134] [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-11-19T07:35:38.253] [ERROR] system - get execution error: 1
[2021-11-19T07:35:38.253] [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-11-19T07:35:43.149] [ERROR] system - get execution error: 1
[2021-11-19T07:35:43.150] [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-11-19T07:36:38.265] [ERROR] system - get execution error: 1
[2021-11-19T07:36:38.265] [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-11-19T07:36:43.169] [ERROR] system - get execution error: 1
[2021-11-19T07:36:43.169] [ERROR] system - Error: GetExecutionTimeoutError
at Timeout._onTimeout (/app/dist/model/model/ExecutionManagementModel.ts:48:24)
at listOnTimeout (node:internal/timers:557:17)
[2021-11-19T07:37:38.278] [ERROR] system - get execution error: 1
[2021-11-19T07:37:38.278] [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-11-19T07:37:43.190] [ERROR] system - get execution error: 1
[2021-11-19T07:37:43.191] [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-11-19T07:38:38.291] [ERROR] system - get execution error: 1
[2021-11-19T07:38:38.292] [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-11-19T07:38:43.206] [ERROR] system - get execution error: 1
[2021-11-19T07:38:43.206] [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)

また、このエラーが発生している状態としては、epgstation側では番組表上では指定したルールに基づき予約はテレビ東京以外は赤枠になり予約が入っているがテレビ東京のみ検索に当該しても予約が入らない状態であり、また赤枠で予約の入っている番組でも地デジ放送の番組の録画が開始されないといった状態です。
image
image
image

このエラーログ以前はdocker-composeの再起動による予約枠の更新や一部録画終了に伴うdropcheckなどのログが含まれていました。

もし何か改善点などがあれば教えていただけると幸いです。

解決したい点としては、テレビ東京などの様に予約が入らない局が発生する点・予約が入っているのに録画がスタートしない点とったところです。

@MicotoTisaki
Copy link
Author

連続投稿申し訳ございません。Mirakurun側を3.9.0-beta.21にアップデートしたのですが、その際にちょっと異なったエラーの出方をしたのでその部分を添付させていただきます。

[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.771] [ERROR] system - get execution error: 1
[2021-11-19T08:01:53.772] [INFO] system - successful update rule reservation: 78
[2021-11-19T08:01:53.805] [ERROR] system - get execution error: 1
[2021-11-19T08:02:01.259] [DEBUG] system - delete stream: 242076
[2021-11-19T08:02:01.259] [ERROR] system - preprec failed: 242076
[2021-11-19T08:02:01.259] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:01.260] [DEBUG] system - delete recording index: 242076
[2021-11-19T08:02:01.260] [DEBUG] system - delete stream: 242080
[2021-11-19T08:02:01.260] [ERROR] system - preprec failed: 242080
[2021-11-19T08:02:01.260] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:01.261] [DEBUG] system - delete recording index: 242080
[2021-11-19T08:02:01.261] [DEBUG] system - delete stream: 242078
[2021-11-19T08:02:01.261] [ERROR] system - preprec failed: 242078
[2021-11-19T08:02:01.261] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:01.261] [DEBUG] system - delete recording index: 242078
[2021-11-19T08:02:01.261] [DEBUG] system - delete stream: 242077
[2021-11-19T08:02:01.261] [ERROR] system - preprec failed: 242077
[2021-11-19T08:02:01.261] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:01.261] [DEBUG] system - delete recording index: 242077
[2021-11-19T08:02:01.261] [DEBUG] system - delete stream: 242081
[2021-11-19T08:02:01.261] [ERROR] system - preprec failed: 242081
[2021-11-19T08:02:01.261] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:01.261] [DEBUG] system - delete recording index: 242081
[2021-11-19T08:02:01.262] [DEBUG] system - delete stream: 242074
[2021-11-19T08:02:01.262] [ERROR] system - preprec failed: 242074
[2021-11-19T08:02:01.262] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:01.262] [DEBUG] system - delete recording index: 242074
[2021-11-19T08:02:06.045] [DEBUG] system - delete stream: 242073
[2021-11-19T08:02:06.045] [ERROR] system - preprec failed: 242073
[2021-11-19T08:02:06.045] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:06.045] [DEBUG] system - delete recording index: 242073
[2021-11-19T08:02:06.046] [DEBUG] system - delete stream: 242079
[2021-11-19T08:02:06.046] [ERROR] system - preprec failed: 242079
[2021-11-19T08:02:06.046] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:06.046] [DEBUG] system - delete recording index: 242079
[2021-11-19T08:02:06.046] [DEBUG] system - delete stream: 242082
[2021-11-19T08:02:06.046] [ERROR] system - preprec failed: 242082
[2021-11-19T08:02:06.046] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)
[2021-11-19T08:02:06.046] [DEBUG] system - delete recording index: 242082
[2021-11-19T08:02:26.989] [ERROR] system - get execution error: 1
[2021-11-19T08:02:26.990] [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-11-19T08:03:01.262] [ERROR] system - get execution error: 2
[2021-11-19T08:03:01.264] [FATAL] system - unhandledRejection
[2021-11-19T08:03:01.265] [FATAL] 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-11-19T08:03:01.265] [ERROR] system - get execution error: 2
[2021-11-19T08:03:01.266] [FATAL] system - unhandledRejection
[2021-11-19T08:03:01.266] [FATAL] 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-11-19T08:03:01.266] [ERROR] system - get execution error: 2
[2021-11-19T08:03:01.266] [FATAL] system - unhandledRejection
[2021-11-19T08:03:01.266] [FATAL] 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-11-19T08:03:01.267] [ERROR] system - get execution error: 2
[2021-11-19T08:03:01.267] [FATAL] system - unhandledRejection
[2021-11-19T08:03:01.267] [FATAL] 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-11-19T08:03:01.268] [ERROR] system - get execution error: 2
[2021-11-19T08:03:01.268] [FATAL] system - unhandledRejection
[2021-11-19T08:03:01.268] [FATAL] 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-11-19T08:03:01.268] [ERROR] system - get execution error: 2
[2021-11-19T08:03:01.268] [FATAL] system - unhandledRejection
[2021-11-19T08:03:01.268] [FATAL] 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-11-19T08:03:06.047] [ERROR] system - get execution error: 2
[2021-11-19T08:03:06.048] [FATAL] system - unhandledRejection
[2021-11-19T08:03:06.048] [FATAL] 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-11-19T08:03:06.048] [ERROR] system - get execution error: 2
[2021-11-19T08:03:06.049] [FATAL] system - unhandledRejection
[2021-11-19T08:03:06.049] [FATAL] 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-11-19T08:03:06.049] [ERROR] system - get execution error: 2
[2021-11-19T08:03:06.050] [FATAL] system - unhandledRejection
[2021-11-19T08:03:06.050] [FATAL] 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)

@l3tnun
Copy link
Owner

l3tnun commented Nov 21, 2021 •
edited
Loading

異なったエラーというのは下記のエラーのことだと思いますが、これは MIrakurun 側でチューナの空きがないと言っています。
epgstation がチューナを握ったまま離さないのか、Mirakurun 側の不具合なのかは分かりません、
このエラーが出ている前後の Mirakurun のログを合わせてみると分かるかもしれません。

[2021-11-19T08:02:01.259] [ERROR] system - Error: Bad status respond (503 Tuner Resource Unavailable).
at Client._requestStream (/app/node_modules/mirakurun/src/client.ts:624:23)
at runMicrotasks ()
at processTicksAndRejections (node:internal/process/task_queues:96:5)

解決したい点としては、テレビ東京などの様に予約が入らない局が発生する点・予約が入っているのに録画がスタートしない点とったところです。

get execution error が出ている事によって予約の更新が行われないことが原因だと思われますが、
epgstation は起動時または予約更新(ルール更新、手動予約更新時)に変更が合った予約に対して、タイマーを設定しています。
故に予約追加 -> タイマーのセット と動作するのですが、このタイマーのセットの部分が正常に行われていないように思われます。

予約1件に対して1タイマーが設定されているので、予約の件数がかなり多い状況では、うまく処理しきれていないのかもしれません。
もしかしたら、録画を行う放送局(=ルール数)を減らしたら問題が解消されるかもしれません。

@MicotoTisaki
Copy link
Author

今件お世話になっております。チューナーの空きの方に関するエラーは解決しました。

get execution error の方に対してなのですが、epgstationはmirakurunsのような並列起動による1epgstationに対する予約件数の過多によるエラー解決は可能なのでしょうか。また、その際に録画済みデータの共有などは可能なのでしょうか。
機能としては、2つのepgstationで地デジ用・BS/CS用などで分け、地デジ用のepgstationのアドレスからBS/CS用epgstationで録画した内容を視聴するイメージです。もしその様な事が可能ならこのエラーは回避できるのかなと思っています。

もし実装されていないのなら新規機能としてご提案するとは可能でしょうか。

@MicotoTisaki
Copy link
Author

MicotoTisaki commented Feb 6, 2022 •
edited
Loading

お世話になっております。先日epgstationをv2.6.20にアップデートしたところ、get execution errorの発生しているコードの位置が変わったため添付させていただきます。現状、BS/CSは録画できるのですが、地デジ全般が番組表で赤枠が入っているのに録画がスタートしない状態です。また、NHKEテレ1とテレビ東京1に関しては番組表は取得できているのですが、ルールに追加しても条件に引っかかるが予約が入らないといった状態になっています。

[2022-02-06T09:35:39.388] [ERROR] system - get execution error: 1
[2022-02-06T09:35:39.388] [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)

申し訳ありません。今再度確認したところ、エラー行数は前回と特に変わっていませんでした。

@MicotoTisaki
Copy link
Author

お世話になっております。その後少々環境変更を行い、動作確認やログ収取を行いました。その結果、録画が入らなくなる事に関しては解決しました。しかし、番組終了時に正常に終了しない不具合が発生しております。
一部番組は正常に終了し録画中のタブから消えるのですが、消えない番組も存在し、特に規則性はありませんでした。その際のエラーは以下のような感じでした。

[2022-03-01T09:33:37.960] [ERROR] system - get execution error: 1
[2022-03-01T09:33:37.961] [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)
[2022-03-01T09:33:38.141] [ERROR] system - get execution error: 1
[2022-03-01T09:33:38.141] [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)
[2022-03-01T09:33:38.419] [ERROR] system - get execution error: 1
[2022-03-01T09:33:38.419] [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)
[2022-03-01T09:33:38.883] [ERROR] system - get execution error: 1
[2022-03-01T09:33:38.884] [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)

現在はこのエラーのみが発生している状態です。５日ほど録画を放置していると録画中のタブが114件ほどになってしまう状況です。ただ、Mirakurun側では特にチューナー不足などは発生していない様なので、チューナー自体の開放はしている様です。
原因が分かればよろしくお願いします。

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@l3tnun @MicotoTisaki