search

l3tnun / EPGStation

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

【質問】録画エラー時の通知について #105

Closed cuckoozero closed 6 years ago

cuckoozero commented 6 years ago

いつもお世話になっております。

EPGStation ver.0.9.0で運用していたところ、特定の予約ルールで録画が失敗するケースがありました。 EPGStation-master\logs\Operator\system.logを確認したところ

[2018-06-16T07:29:45.740] [INFO] system - preprec: 40010332550 hogehuga
[2018-06-16T07:29:58.336] [ERROR] system - preprec failed: 40010332550 hogehuga
[2018-06-16T07:30:03.338] [INFO] system - preprec: 40010332550 hogehuga
[2018-06-16T07:30:15.647] [ERROR] system - preprec failed: 40010332550 hogehuga
[2018-06-16T07:30:20.648] [INFO] system - preprec: 40010332550 hogehuga
[2018-06-16T07:30:32.951] [ERROR] system - preprec failed: 40010332550 hogehuga
[2018-06-16T07:30:37.952] [INFO] system - add skip: 40010332550

というエラーが確認できました。 現在はver.0.9.5にアップデートして経過観察中です。

質問はどのような場合にこのエラーが発生するのだろうかということと、録画が失敗した場合にユーザーへ通知する方法がないでしょうかということです。

お時間のある時にでも教えて頂けると助かります。

l3tnun commented 6 years ago

preprec では EPGStation が Mirakurun へ指定した programId のストリームを要求しています。 そのため preprec でエラーが発生したという事は Mirakurun からのストリームの取得に失敗したということですね。 Mirakurun の実装 を見ると 50*250 = 12500ミリ秒 リトライを続けるので、上記のログの preprec -> preprec failed までの時間と一致します。 おそらく何らかの原因でチューナの空きが無かったのだと思いますが、Mirakurun 側のログを見ないとわからないですね。

ユーザへのエラー通知ですが現状特に用意していません。 通知方法があれば便利だと思いますので preprec failed 時に設定した外部コマンドを実行できるように機能追加したいと思います。

l3tnun commented 6 years ago

config.json に recordedPrepRecFailedCommand と recordedFailedCommand を追加しました。 これで録画準備失敗時と録画中のエラー発生時に外部コマンドが実行できるようになりました。 詳細は doc/config.md を参照してください。

cuckoozero commented 6 years ago

早速エラー発生時コマンドを利用して通知メールを送信するようにさせて頂きました。

いつもながら素早い対応ありがとうございました。

cuckoozero commented 6 years ago

本日も同じ予約ルールでエラーが発生しました。 その際の録画予約状況を考えるにチューナーは空いていたと思うのですが…

今回はEPGStation-master\logs\Operator\system.logに

[2018-06-18T07:29:45.036] [INFO] system - preprec: 40010334354 hogehuga
[2018-06-18T07:29:57.351] [ERROR] system - preprec failed: 40010334354 hogehuga
[2018-06-18T07:29:57.351] [ERROR] system - IncomingMessage {

以下６００行以上のエラーメッセージが記録されていました。 さすがにすべて貼るのは憚られるので、確認するべきポイントなどを教えていただけませんでしょうか？

l3tnun commented 6 years ago

600 行とは長いですね。 見てみないと何とも言えないのですべて貼ってください。 あと、同時刻の Mirakurun のログも見たいです。 それと使用環境 (os, node, Mirakurun, EPGStation のバージョン等) も書いていただけると助かります。

cuckoozero commented 6 years ago

ありがとうございます。

仕様環境は以下の通りです。 Windows10 home x64 node.js v8.10.0 Mirakurun 2.7.0 EPGStation 0.9.6

EPGStation-master\logs\Operator\system.log

[2018-06-18T07:29:45.036] [INFO] system - preprec: 40010334354 hogehuga
[2018-06-18T07:29:57.351] [ERROR] system - preprec failed: 40010334354 hogehuga
[2018-06-18T07:29:57.351] [ERROR] system - IncomingMessage {
  _readableState: 
   ReadableState {
     objectMode: false,
     highWaterMark: 16384,
     buffer: BufferList { head: null, tail: null, length: 0 },
     length: 0,
     pipes: null,
     pipesCount: 0,
     flowing: null,
     ended: false,
     endEmitted: false,
     reading: false,
     sync: true,
     needReadable: false,
     emittedReadable: false,
     readableListening: false,
     resumeScheduled: false,
     destroyed: false,
     defaultEncoding: 'utf8',
     awaitDrain: 0,
     readingMore: true,
     decoder: null,
     encoding: null },
  readable: true,
  domain: null,
  _events: { end: [Function: responseOnEnd] },
  _eventsCount: 1,
  _maxListeners: undefined,
  socket: 
   Socket {
     connecting: false,
     _hadError: false,
     _handle: 
      Pipe {
        writeQueueSize: 0,
        owner: [Circular],
        onread: [Function: onread],
        reading: true },
     _parent: null,
     _host: null,
     _readableState: 
      ReadableState {
        objectMode: false,
        highWaterMark: 16384,
        buffer: [Object],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: true,
        ended: false,
        endEmitted: false,
        reading: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        resumeScheduled: false,
        destroyed: false,
        defaultEncoding: 'utf8',
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Array],
        finish: [Function: onSocketFinish],
        _socketEnd: [Function: onSocketEnd],
        free: [Function: onFree],
        close: [Array],
        agentRemove: [Function: onRemove],
        drain: [Function: ondrain],
        error: [Function: socketErrorListener],
        data: [Function: socketOnData] },
     _eventsCount: 9,
     _maxListeners: undefined,
     _writableState: 
      WritableState {
        objectMode: false,
        highWaterMark: 16384,
        finalCalled: false,
        needDrain: false,
        ending: false,
        ended: false,
        finished: false,
        destroyed: false,
        decodeStrings: false,
        defaultEncoding: 'utf8',
        length: 0,
        writing: false,
        corked: 0,
        sync: false,
        bufferProcessing: false,
        onwrite: [Function: bound onwrite],
        writecb: null,
        writelen: 0,
        bufferedRequest: null,
        lastBufferedRequest: null,
        pendingcb: 0,
        prefinished: false,
        errorEmitted: false,
        bufferedRequestCount: 0,
        corkedRequestsFree: [Object] },
     writable: true,
     allowHalfOpen: false,
     _bytesDispatched: 192,
     _sockname: null,
     _pendingData: null,
     _pendingEncoding: '',
     server: null,
     _server: null,
     _writev: null,
     parser: 
      HTTPParser {
        '0': [Function: parserOnHeaders],
        '1': [Function: parserOnHeadersComplete],
        '2': [Function: parserOnBody],
        '3': [Function: parserOnMessageComplete],
        '4': null,
        _headers: [],
        _url: '',
        _consumed: false,
        socket: [Circular],
        incoming: [Circular],
        outgoing: [Object],
        maxHeaderPairs: 2000,
        onIncoming: [Function: parserOnIncomingClient] },
     _httpMessage: 
      ClientRequest {
        domain: null,
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        output: [],
        outputEncodings: [],
        outputCallbacks: [],
        outputSize: 0,
        writable: true,
        _last: true,
        upgrading: false,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: false,
        sendDate: false,
        _removedConnection: false,
        _removedContLen: false,
        _removedTE: false,
        _contentLength: 0,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _headerSent: true,
        socket: [Circular],
        connection: [Circular],
        _header: 'GET /api/programs/40010334354/stream?decode=1 HTTP/1.1\r\nUser-Agent: EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)\r\nX-Mirakurun-Priority: 2\r\nHost: localhost\r\nConnection: close\r\n\r\n',
        _onPendingData: [Function: noopPendingOutput],
        agent: [Object],
        socketPath: '\\\\.\\pipe\\mirakurun',
        timeout: undefined,
        method: 'GET',
        path: '/api/programs/40010334354/stream?decode=1',
        _ended: false,
        res: [Circular],
        aborted: undefined,
        timeoutCb: null,
        upgradeOrConnect: false,
        parser: [Object],
        maxHeadersCount: null,
        [Symbol(outHeadersKey)]: [Object] },
     read: [Function],
     _consuming: true,
     [Symbol(asyncId)]: 5586431,
     [Symbol(bytesRead)]: 0 },
  connection: 
   Socket {
     connecting: false,
     _hadError: false,
     _handle: 
      Pipe {
        writeQueueSize: 0,
        owner: [Circular],
        onread: [Function: onread],
        reading: true },
     _parent: null,
     _host: null,
     _readableState: 
      ReadableState {
        objectMode: false,
        highWaterMark: 16384,
        buffer: [Object],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: true,
        ended: false,
        endEmitted: false,
        reading: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        resumeScheduled: false,
        destroyed: false,
        defaultEncoding: 'utf8',
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Array],
        finish: [Function: onSocketFinish],
        _socketEnd: [Function: onSocketEnd],
        free: [Function: onFree],
        close: [Array],
        agentRemove: [Function: onRemove],
        drain: [Function: ondrain],
        error: [Function: socketErrorListener],
        data: [Function: socketOnData] },
     _eventsCount: 9,
     _maxListeners: undefined,
     _writableState: 
      WritableState {
        objectMode: false,
        highWaterMark: 16384,
        finalCalled: false,
        needDrain: false,
        ending: false,
        ended: false,
        finished: false,
        destroyed: false,
        decodeStrings: false,
        defaultEncoding: 'utf8',
        length: 0,
        writing: false,
        corked: 0,
        sync: false,
        bufferProcessing: false,
        onwrite: [Function: bound onwrite],
        writecb: null,
        writelen: 0,
        bufferedRequest: null,
        lastBufferedRequest: null,
        pendingcb: 0,
        prefinished: false,
        errorEmitted: false,
        bufferedRequestCount: 0,
        corkedRequestsFree: [Object] },
     writable: true,
     allowHalfOpen: false,
     _bytesDispatched: 192,
     _sockname: null,
     _pendingData: null,
     _pendingEncoding: '',
     server: null,
     _server: null,
     _writev: null,
     parser: 
      HTTPParser {
        '0': [Function: parserOnHeaders],
        '1': [Function: parserOnHeadersComplete],
        '2': [Function: parserOnBody],
        '3': [Function: parserOnMessageComplete],
        '4': null,
        _headers: [],
        _url: '',
        _consumed: false,
        socket: [Circular],
        incoming: [Circular],
        outgoing: [Object],
        maxHeaderPairs: 2000,
        onIncoming: [Function: parserOnIncomingClient] },
     _httpMessage: 
      ClientRequest {
        domain: null,
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        output: [],
        outputEncodings: [],
        outputCallbacks: [],
        outputSize: 0,
        writable: true,
        _last: true,
        upgrading: false,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: false,
        sendDate: false,
        _removedConnection: false,
        _removedContLen: false,
        _removedTE: false,
        _contentLength: 0,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _headerSent: true,
        socket: [Circular],
        connection: [Circular],
        _header: 'GET /api/programs/40010334354/stream?decode=1 HTTP/1.1\r\nUser-Agent: EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)\r\nX-Mirakurun-Priority: 2\r\nHost: localhost\r\nConnection: close\r\n\r\n',
        _onPendingData: [Function: noopPendingOutput],
        agent: [Object],
        socketPath: '\\\\.\\pipe\\mirakurun',
        timeout: undefined,
        method: 'GET',
        path: '/api/programs/40010334354/stream?decode=1',
        _ended: false,
        res: [Circular],
        aborted: undefined,
        timeoutCb: null,
        upgradeOrConnect: false,
        parser: [Object],
        maxHeadersCount: null,
        [Symbol(outHeadersKey)]: [Object] },
     read: [Function],
     _consuming: true,
     [Symbol(asyncId)]: 5586431,
     [Symbol(bytesRead)]: 0 },
  httpVersionMajor: 1,
  httpVersionMinor: 1,
  httpVersion: '1.1',
  complete: false,
  headers: 
   { server: 'Mirakurun/2.7.0',
     'content-type': 'application/json',
     date: 'Sun, 17 Jun 2018 22:29:57 GMT',
     connection: 'close',
     'transfer-encoding': 'chunked' },
  rawHeaders: 
   [ 'Server',
     'Mirakurun/2.7.0',
     'Content-Type',
     'application/json',
     'Date',
     'Sun, 17 Jun 2018 22:29:57 GMT',
     'Connection',
     'close',
     'Transfer-Encoding',
     'chunked' ],
  trailers: {},
  rawTrailers: [],
  upgrade: false,
  url: '',
  method: null,
  statusCode: 503,
  statusMessage: 'Tuner Resource Unavailable',
  client: 
   Socket {
     connecting: false,
     _hadError: false,
     _handle: 
      Pipe {
        writeQueueSize: 0,
        owner: [Circular],
        onread: [Function: onread],
        reading: true },
     _parent: null,
     _host: null,
     _readableState: 
      ReadableState {
        objectMode: false,
        highWaterMark: 16384,
        buffer: [Object],
        length: 0,
        pipes: null,
        pipesCount: 0,
        flowing: true,
        ended: false,
        endEmitted: false,
        reading: true,
        sync: false,
        needReadable: true,
        emittedReadable: false,
        readableListening: false,
        resumeScheduled: false,
        destroyed: false,
        defaultEncoding: 'utf8',
        awaitDrain: 0,
        readingMore: false,
        decoder: null,
        encoding: null },
     readable: true,
     domain: null,
     _events: 
      { end: [Array],
        finish: [Function: onSocketFinish],
        _socketEnd: [Function: onSocketEnd],
        free: [Function: onFree],
        close: [Array],
        agentRemove: [Function: onRemove],
        drain: [Function: ondrain],
        error: [Function: socketErrorListener],
        data: [Function: socketOnData] },
     _eventsCount: 9,
     _maxListeners: undefined,
     _writableState: 
      WritableState {
        objectMode: false,
        highWaterMark: 16384,
        finalCalled: false,
        needDrain: false,
        ending: false,
        ended: false,
        finished: false,
        destroyed: false,
        decodeStrings: false,
        defaultEncoding: 'utf8',
        length: 0,
        writing: false,
        corked: 0,
        sync: false,
        bufferProcessing: false,
        onwrite: [Function: bound onwrite],
        writecb: null,
        writelen: 0,
        bufferedRequest: null,
        lastBufferedRequest: null,
        pendingcb: 0,
        prefinished: false,
        errorEmitted: false,
        bufferedRequestCount: 0,
        corkedRequestsFree: [Object] },
     writable: true,
     allowHalfOpen: false,
     _bytesDispatched: 192,
     _sockname: null,
     _pendingData: null,
     _pendingEncoding: '',
     server: null,
     _server: null,
     _writev: null,
     parser: 
      HTTPParser {
        '0': [Function: parserOnHeaders],
        '1': [Function: parserOnHeadersComplete],
        '2': [Function: parserOnBody],
        '3': [Function: parserOnMessageComplete],
        '4': null,
        _headers: [],
        _url: '',
        _consumed: false,
        socket: [Circular],
        incoming: [Circular],
        outgoing: [Object],
        maxHeaderPairs: 2000,
        onIncoming: [Function: parserOnIncomingClient] },
     _httpMessage: 
      ClientRequest {
        domain: null,
        _events: [Object],
        _eventsCount: 2,
        _maxListeners: undefined,
        output: [],
        outputEncodings: [],
        outputCallbacks: [],
        outputSize: 0,
        writable: true,
        _last: true,
        upgrading: false,
        chunkedEncoding: false,
        shouldKeepAlive: false,
        useChunkedEncodingByDefault: false,
        sendDate: false,
        _removedConnection: false,
        _removedContLen: false,
        _removedTE: false,
        _contentLength: 0,
        _hasBody: true,
        _trailer: '',
        finished: true,
        _headerSent: true,
        socket: [Circular],
        connection: [Circular],
        _header: 'GET /api/programs/40010334354/stream?decode=1 HTTP/1.1\r\nUser-Agent: EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)\r\nX-Mirakurun-Priority: 2\r\nHost: localhost\r\nConnection: close\r\n\r\n',
        _onPendingData: [Function: noopPendingOutput],
        agent: [Object],
        socketPath: '\\\\.\\pipe\\mirakurun',
        timeout: undefined,
        method: 'GET',
        path: '/api/programs/40010334354/stream?decode=1',
        _ended: false,
        res: [Circular],
        aborted: undefined,
        timeoutCb: null,
        upgradeOrConnect: false,
        parser: [Object],
        maxHeadersCount: null,
        [Symbol(outHeadersKey)]: [Object] },
     read: [Function],
     _consuming: true,
     [Symbol(asyncId)]: 5586431,
     [Symbol(bytesRead)]: 0 },
  _consuming: false,
  _dumped: false,
  req: 
   ClientRequest {
     domain: null,
     _events: { error: [Function], prefinish: [Function: requestOnPrefinish] },
     _eventsCount: 2,
     _maxListeners: undefined,
     output: [],
     outputEncodings: [],
     outputCallbacks: [],
     outputSize: 0,
     writable: true,
     _last: true,
     upgrading: false,
     chunkedEncoding: false,
     shouldKeepAlive: false,
     useChunkedEncodingByDefault: false,
     sendDate: false,
     _removedConnection: false,
     _removedContLen: false,
     _removedTE: false,
     _contentLength: 0,
     _hasBody: true,
     _trailer: '',
     finished: true,
     _headerSent: true,
     socket: 
      Socket {
        connecting: false,
        _hadError: false,
        _handle: [Object],
        _parent: null,
        _host: null,
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _eventsCount: 9,
        _maxListeners: undefined,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        _bytesDispatched: 192,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        _writev: null,
        parser: [Object],
        _httpMessage: [Circular],
        read: [Function],
        _consuming: true,
        [Symbol(asyncId)]: 5586431,
        [Symbol(bytesRead)]: 0 },
     connection: 
      Socket {
        connecting: false,
        _hadError: false,
        _handle: [Object],
        _parent: null,
        _host: null,
        _readableState: [Object],
        readable: true,
        domain: null,
        _events: [Object],
        _eventsCount: 9,
        _maxListeners: undefined,
        _writableState: [Object],
        writable: true,
        allowHalfOpen: false,
        _bytesDispatched: 192,
        _sockname: null,
        _pendingData: null,
        _pendingEncoding: '',
        server: null,
        _server: null,
        _writev: null,
        parser: [Object],
        _httpMessage: [Circular],
        read: [Function],
        _consuming: true,
        [Symbol(asyncId)]: 5586431,
        [Symbol(bytesRead)]: 0 },
     _header: 'GET /api/programs/40010334354/stream?decode=1 HTTP/1.1\r\nUser-Agent: EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)\r\nX-Mirakurun-Priority: 2\r\nHost: localhost\r\nConnection: close\r\n\r\n',
     _onPendingData: [Function: noopPendingOutput],
     agent: 
      Agent {
        domain: null,
        _events: [Object],
        _eventsCount: 1,
        _maxListeners: undefined,
        defaultPort: 80,
        protocol: 'http:',
        options: [Object],
        requests: {},
        sockets: [Object],
        freeSockets: {},
        keepAliveMsecs: 1000,
        keepAlive: false,
        maxSockets: Infinity,
        maxFreeSockets: 256 },
     socketPath: '\\\\.\\pipe\\mirakurun',
     timeout: undefined,
     method: 'GET',
     path: '/api/programs/40010334354/stream?decode=1',
     _ended: false,
     res: [Circular],
     aborted: undefined,
     timeoutCb: null,
     upgradeOrConnect: false,
     parser: 
      HTTPParser {
        '0': [Function: parserOnHeaders],
        '1': [Function: parserOnHeadersComplete],
        '2': [Function: parserOnBody],
        '3': [Function: parserOnMessageComplete],
        '4': null,
        _headers: [],
        _url: '',
        _consumed: false,
        socket: [Object],
        incoming: [Circular],
        outgoing: [Circular],
        maxHeaderPairs: 2000,
        onIncoming: [Function: parserOnIncomingClient] },
     maxHeadersCount: null,
     [Symbol(outHeadersKey)]: 
      { 'user-agent': [Array],
        'x-mirakurun-priority': [Array],
        host: [Array] } } }
cuckoozero commented 6 years ago

C:\Users\hoge\AppData\Local\Mirakurun\stderrの同時刻付近

2018-06-18T03:21:22.153+09:00 warn: ChannelItem#'BS:007' service scan has failed [Error: stream has closed before get network]
2018-06-18T03:21:42.319+09:00 warn: ChannelItem#'BS:008' service scan has failed [Error: stream has closed before get network]
2018-06-18T03:22:02.484+09:00 warn: ChannelItem#'BS:009' service scan has failed [Error: stream has closed before get network]
2018-06-18T04:30:28.019+09:00 warn: ChannelItem#'BS:007' service scan has failed [Error: stream has closed before get network]
2018-06-18T04:30:48.032+09:00 warn: ChannelItem#'BS:008' service scan has failed [Error: stream has closed before get network]
2018-06-18T04:31:08.043+09:00 warn: ChannelItem#'BS:009' service scan has failed [Error: stream has closed before get network]
2018-06-18T05:30:48.057+09:00 warn: ChannelItem#'BS:007' service scan has failed [Error: stream has closed before get network]
2018-06-18T05:31:08.071+09:00 warn: ChannelItem#'BS:008' service scan has failed [Error: stream has closed before get network]
2018-06-18T05:31:28.102+09:00 warn: ChannelItem#'BS:009' service scan has failed [Error: stream has closed before get network]
2018-06-18T06:31:08.077+09:00 warn: ChannelItem#'BS:007' service scan has failed [Error: stream has closed before get network]
2018-06-18T06:31:28.108+09:00 warn: ChannelItem#'BS:008' service scan has failed [Error: stream has closed before get network]
2018-06-18T06:31:48.140+09:00 warn: ChannelItem#'BS:009' service scan has failed [Error: stream has closed before get network]
2018-06-18T07:14:58.663+09:00 warn: Network#4 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:21:12.687+09:00 warn: Network#6 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:21:25.016+09:00 warn: Network#7 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:31:20.388+09:00 warn: ChannelItem#'BS:007' service scan has failed [Error: no available tuners]
2018-06-18T07:31:40.409+09:00 warn: ChannelItem#'BS:008' service scan has failed [Error: no available tuners]
2018-06-18T07:32:00.434+09:00 warn: ChannelItem#'BS:009' service scan has failed [Error: no available tuners]
2018-06-18T07:36:37.313+09:00 warn: Network#4 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:42:50.055+09:00 warn: Network#6 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:43:02.362+09:00 warn: Network#7 EPG gathering has failed [Error: no available tuners]
2018-06-18T08:15:04.763+09:00 error: { Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:364:12)
    at resolve (C:\Users\hoge\AppData\Roaming\npm\node_modules\mirakurun\lib\Mirakurun\TunerDevice.js:301:41)
    at new Promise (<anonymous>)
    at TunerDevice.<anonymous> (C:\Users\hoge\AppData\Roaming\npm\node_modules\mirakurun\lib\Mirakurun\TunerDevice.js:296:19)
    at Generator.next (<anonymous>)
    at C:\Users\hoge\AppData\Roaming\npm\node_modules\mirakurun\lib\Mirakurun\TunerDevice.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\Users\hoge\AppData\Roaming\npm\node_modules\mirakurun\lib\Mirakurun\TunerDevice.js:3:12)
    at TunerDevice._kill (C:\Users\hoge\AppData\Roaming\npm\node_modules\mirakurun\lib\Mirakurun\TunerDevice.js:288:16)
    at Timeout.setTimeout [as _onTimeout] (C:\Users\hoge\AppData\Roaming\npm\node_modules\mirakurun\lib\Mirakurun\TunerDevice.js:172:26) code: 'EPIPE' }

です。 お手数をおかけします。よろしくお願いします。

cuckoozero commented 6 years ago

こちらも貼ります C:\Users\hoge\AppData\Local\Mirakurun\stdoutの同時刻付近

2018-06-18T07:27:34.919+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `null` (pid=4216)
2018-06-18T07:27:35.035+09:00 info: TunerDevice#0 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 1 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S0.dll --output - --channel 011` (pid=1784)
2018-06-18T07:27:35.036+09:00 info: TunerDevice#0 streaming to user `192.168.12.60:58493` (priority=2)
2018-06-18T07:27:35.058+09:00 info: TunerDevice#0 > * BonRecTest *
- - GET /api/programs/40010334354/stream?decode=1 HTTP/1.1 503 - - 12304.964 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
- - GET /api/programs/40010334354/stream?decode=1 HTTP/1.1 503 - - 12313.681 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
- - GET /api/programs/40010334354/stream?decode=1 HTTP/1.1 503 - - 12309.693 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
2018-06-18T07:31:08.079+09:00 info: ChannelItem#'BS:007' service scan has started
2018-06-18T07:31:20.884+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-18T07:31:20.885+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:58447` (priority=2)
192.168.12.60 - GET /api/channels/BS/014/stream?decode=0 HTTP/1.0 200 - - 17.182 ms -
2018-06-18T07:31:20.897+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-18T07:31:20.925+09:00 info: TunerDevice#1 > Abort!
2018-06-18T07:31:20.951+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal `null` (pid=9292)
2018-06-18T07:31:21.059+09:00 info: TunerDevice#1 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 1 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S1.dll --output - --channel 007` (pid=9864)
2018-06-18T07:31:21.059+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:58697` (priority=2)
2018-06-18T07:31:21.079+09:00 info: TunerDevice#1 > * BonRecTest *
2018-06-18T07:31:28.109+09:00 info: ChannelItem#'BS:008' service scan has started
2018-06-18T07:31:48.142+09:00 info: ChannelItem#'BS:009' service scan has started
192.168.12.60 - GET /api/channels/CS/011/stream?decode=0 HTTP/1.0 200 - - 496.433 ms -
2018-06-18T07:31:58.028+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-18T07:31:58.028+09:00 info: TunerDevice#0 end streaming to user `192.168.12.60:58493` (priority=2)
2018-06-18T07:31:58.036+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-18T07:31:58.099+09:00 info: TunerDevice#0 > Abort!
2018-06-18T07:31:58.130+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `null` (pid=1784)
2018-06-18T07:31:58.239+09:00 info: TunerDevice#0 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 1 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S0.dll --output - --channel 002` (pid=1300)
2018-06-18T07:31:58.239+09:00 info: TunerDevice#0 streaming to user `192.168.12.60:58723` (priority=2)
2018-06-18T07:31:58.252+09:00 info: TunerDevice#0 > * BonRecTest *
192.168.12.60 - GET /api/channels/CS/002/stream?decode=0 HTTP/1.0 200 - - 482.207 ms -
2018-06-18T07:33:54.176+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-18T07:33:54.176+09:00 info: TunerDevice#0 end streaming to user `192.168.12.60:58723` (priority=2)
2018-06-18T07:33:54.186+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-18T07:33:54.279+09:00 info: TunerDevice#0 > Abort!
2018-06-18T07:33:54.309+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `null` (pid=1300)
2018-06-18T07:33:54.418+09:00 info: TunerDevice#0 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 1 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S0.dll --output - --channel 009` (pid=7616)
l3tnun commented 6 years ago

EPGStation 側のログを見ると

  statusCode: 503,
  statusMessage: 'Tuner Resource Unavailable',

Mirakurun から 503 エラーが返って来ている事がわかります。 Mirakurun 側でのエラー発生箇所はここ になっていて、使用可能なチューナーがうまく取得できていないようですね。

Mirakurun の stdout ログでも確認できます。

2018-06-18T07:27:35.036+09:00 info: TunerDevice#0 streaming to user `192.168.12.60:58493` (priority=2)
2018-06-18T07:27:35.058+09:00 info: TunerDevice#0 > * BonRecTest *
- - GET /api/programs/40010334354/stream?decode=1 HTTP/1.1 503 - - 12304.964 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
- - GET /api/programs/40010334354/stream?decode=1 HTTP/1.1 503 - - 12313.681 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
- - GET /api/programs/40010334354/stream?decode=1 HTTP/1.1 503 - - 12309.693 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)

Mirakurun の stderr ログを見ると

2018-06-18T07:14:58.663+09:00 warn: Network#4 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:21:12.687+09:00 warn: Network#6 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:21:25.016+09:00 warn: Network#7 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:31:20.388+09:00 warn: ChannelItem#'BS:007' service scan has failed [Error: no available tuners]
2018-06-18T07:31:40.409+09:00 warn: ChannelItem#'BS:008' service scan has failed [Error: no available tuners]
2018-06-18T07:32:00.434+09:00 warn: ChannelItem#'BS:009' service scan has failed [Error: no available tuners]
2018-06-18T07:36:37.313+09:00 warn: Network#4 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:42:50.055+09:00 warn: Network#6 EPG gathering has failed [Error: no available tuners]
2018-06-18T07:43:02.362+09:00 warn: Network#7 EPG gathering has failed [Error: no available tuners]

no available tuners が多数出ていてこれはおかしいですね。 Mirakurun に詳しいわけではないのではっきりとは断定できませんが EPGStation 側の問題ではなく、Mirakurun のチューナー設定に問題があるように思います。

Mirakurun のチューナー設定はどのようになっていますか？

cuckoozero commented 6 years ago

確かにno available tunersがたくさんありますね。 今回Mirakurunのログを確認してはじめて気が付きました。 以前は確かに視聴できていたチャンネルもできなくなっているものがありました。 恐らく5月末に実施されたBSトランスポンダ移動によってエラーが発生してるのだと思います。

MirakurunとBonRecTestのチャンネル設定を更新しました。 明日の朝７時３０分の予約録画でエラーが解消したかどうか確認して報告します。

l3tnun commented 6 years ago

ログを見ると BonRecTest.exe で B25 デコードをしているようですが、これは推奨されていません。 arib-b25-stream-test 等を利用して B25 デコードをした方が良いです。

cuckoozero commented 6 years ago

ログを見ると BonRecTest.exe で B25 デコードをしているようですが、これは推奨されていません。

知らなかったです。 しかしarib-b25-stream-testはWindowsには対応していないようで、また公式でもWindows用のtuners.ymlでは"decoder: ~"と使用しない設定であることからBonRecTest.exe側でデコードするものと思っていました。（Windows向けの設定情報が乏しいのも悩みです）

l3tnun commented 6 years ago

Windows 対応してないんですか。それは知らなかったです。 B25周りはアレですし、WIndows は実験的サポートしかしていないので自分でやれってことなんでしょうね。

BonRecTest.exe 側でデコードする時、サービスごとではなくチャンネルごとにまとめてデーコードされるため CS などの 1 つのチャンネルに複数のサービスが存在する場合に、デコード処理が追いつかなくなるので良くないんですよね。 あと、EPG取得だけ実行している場合無駄にデコードされるとかもあります。

cuckoozero commented 6 years ago

BonRecTest.exe 側でデコードする時、サービスごとではなくチャンネルごとにまとめてデーコードされるため CS などの 1 つのチャンネルに複数のサービスが存在する場合に、デコード処理が追いつかなくなるので良くないんですよね。

なるほど～ 昨日録画したファイルの、裏でもうひと番組の録画が走った時間のところだけ画像が乱れたり止まったりするのはもしかしたらそれが原因なのかもしれませんね。 だとしたら困ったなぁ。

l3tnun commented 6 years ago

arib-b25-stream-test のソースをダウンロードして中を見てみると makefile.win があり、ビルドができれば b25.exe が生成されるようなので試してみてはどうでしょうか？

decoder: hogehoge\b25.exe

で動くのではないかなぁと思います。

cuckoozero commented 6 years ago

やさしさに甘えて質問します。 arib-b25-stream-test のソースをダウンロードしてきたので、ビルドにチャレンジしようと思うのですがうまくいきません。 makeをインストールし、srcフォルダでmakeをすると以下のエラーで止まります。

gcc -fPIC -MM arib_std_b25.c b_cas_card.c multi2.c ts_section_parser.c td.c > Makefile.dep
gcc -O2 -g -fPIC -Wall `pkg-config libpcsclite --cflags` -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64   -c -o arib_std_b25.o arib_std_b25.c
gcc: error: `pkg-config: No such file or directory
gcc: error: libpcsclite: No such file or directory
gcc: error: unrecognized command line option '--cflags`'
make: *** [arib_std_b25.o] エラー 1

いろいろやり方を探すんですけどもすみません、わかりませんでした。 教えてください。<( )>

l3tnun commented 6 years ago

環境が無いのでこちらではわかりません（そもそもできるかも知らないので）

https://github.com/epgdatacapbon/libaribb25 最近開発が進んでいるのでこっちのほうがいいかもしれないですね。

l3tnun commented 6 years ago

https://github.com/epgdatacapbon/libaribb25 vs2017 をインストールしてビルドしてみましたが b25.exe 生成されますね。 Windows に Mirakurun 環境を入れていないのでわかりませんが動くのではないのでしょうか？

cuckoozero commented 6 years ago

b25.exeビルドできました！ しかしdecoder: hogehoge\b25.exeを設定してMirakurunを再起動しましたがデコードされませんね。 C:\Users\hoge\AppData\Local\Mirakurun\stderrにb25.exeのエラーメッセージが表示されてました。

b25 - ARIB STD-B25 test program version 0.2.7
usage: b25 [options] src.m2t dst.m2t [more pair ..]
options:
  -r round (integer, default=4)
  -s strip
     0: keep null(padding) stream (default)
     1: strip null stream
  -m EMM
     0: ignore EMM (default)
     1: send EMM to B-CAS card
  -p power_on_control_info
     0: do nothing additionaly
     1: show B-CAS EMM receiving request (default)
  -v verbose
     0: silent
     1: show processing status (default)

残念ながらMirakurunのほうでまだ対応されてないんでしょうかね。

l3tnun commented 6 years ago

epgdatacapbon/libaribb25 と arib-b25-stream-test の b25 の仕様は違うのが原因ですね。 pipeで渡して処理するようになっていないですね。申し訳ない

arib-b25-stream-test のビルドの件ですが、ソースコードを一箇所修正し makefile.win を使用してビルドすれば b25.exe が生成できるのでチャレンジしてみてください。

どの部分を修正するだとかは issue の本題から逸れるのと b25 周りはアレですので詳しくは書きません。

cuckoozero commented 6 years ago

うっ、プログラムの素養がなくて全く分からないんですが、頑張ってみます。

今朝の録画の報告です。 結果的には今朝も失敗してしまいました。

EPGStation-master\logs\Operator\system.logには前回のような長いエラーは記録されていませんでした。

[2018-06-19T07:29:45.351] [INFO] system - preprec: 40010334761 hogehuga
[2018-06-19T07:29:49.454] [INFO] system - recording: 40010334761 hogehuga
[2018-06-19T07:29:50.074] [INFO] system - recording stream: c:\TV\EPGStation\recorded\hogehuga-2018年06月19日07時30分00秒.ts
[2018-06-19T07:29:56.245] [ERROR] system - recording failed: 40010334761 hogehuga
[2018-06-19T07:29:56.839] [ERROR] system - preprec failed: 40010334761 hogehuga
[2018-06-19T07:29:58.385] [ERROR] system - Error: recordingStartError
    at Timeout.setTimeout [as _onTimeout] (C:\TV\EPGStation\dist\server\Model\Operator\Recording\RecordingManageModel.js:273:28)
    at ontimeout (timers.js:482:11)
    at tryOnTimeout (timers.js:317:5)
    at Timer.listOnTimeout (timers.js:277:5)

一方、C:\Users\hoge\AppData\Local\Mirakurun\stdoutとstderrにはログが記録されておらず、 Mirakurun UIのLogsウインドウに表示されたログでは

192.168.12.60 - GET /api/channels/CS/004/stream?decode=1 HTTP/1.0 200 - - 331.981 ms -
2018-06-19T07:29:23.578+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-19T07:29:23.578+09:00 info: TunerDevice#0 end streaming to user `192.168.12.60:49347` (priority=2)
2018-06-19T07:29:24.034+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-19T07:29:24.041+09:00 info: TunerDevice#1 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 1 --driver C:\TV\BonRecTest\BonDriver_PT3-S1.dll --output - --channel 011` (pid=11052)
2018-06-19T07:29:24.042+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:49348` (priority=2)
2018-06-19T07:29:24.202+09:00 info: TunerDevice#1 > * BonRecTest *
192.168.12.60 - GET /api/channels/CS/011/stream?decode=1 HTTP/1.0 200 - - 589.045 ms -
2018-06-19T07:29:24.623+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-19T07:29:24.623+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:49348` (priority=2)
2018-06-19T07:29:30.137+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `SIGTERM` (pid=7108)
2018-06-19T07:29:31.450+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal `SIGTERM` (pid=11052)
2018-06-19T07:29:46.347+09:00 info: TSFilter has created (serviceId=103, eventId=34761)
2018-06-19T07:29:46.435+09:00 info: TunerDevice#0 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 0 --driver C:\TV\BonRecTest\BonDriver_PT3-S0.dll --output - --channel 004` (pid=5060)
2018-06-19T07:29:46.436+09:00 info: TunerDevice#0 streaming to user `unix:1529360986345` (priority=2)
2018-06-19T07:29:47.164+09:00 info: TunerDevice#0 > * BonRecTest *
2018-06-19T07:29:47.166+09:00 info: TunerDevice#0 >
2018-06-19T07:29:47.288+09:00 info: TunerDevice#0 > Error: Could not open tuner
- - GET /api/programs/40010334761/stream?decode=1 HTTP/1.1 200 - - 1578.401 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
2018-06-19T07:29:47.924+09:00 info: TSFilter has closed (serviceId=103, eventId=34761)
2018-06-19T07:29:47.925+09:00 info: TunerDevice#0 end streaming to user `unix:1529360986345` (priority=2)
2018-06-19T07:29:47.961+09:00 info: TunerDevice#0 process has closed with exit code=4294967295 by signal `null` (pid=5060)
2018-06-19T07:30:07.317+09:00 info: TSFilter has created (serviceId=103, eventId=34761)
2018-06-19T07:30:07.324+09:00 info: TunerDevice#0 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 0 --driver C:\TV\BonRecTest\BonDriver_PT3-S0.dll --output - --channel 004` (pid=11204)
2018-06-19T07:30:07.325+09:00 info: TunerDevice#0 streaming to user `unix:1529361007316` (priority=2)
2018-06-19T07:30:08.086+09:00 info: TunerDevice#0 > * BonRecTest *
2018-06-19T07:30:08.089+09:00 info: TunerDevice#0 >

と、ここまで書いたところでEPGStationからのライブ試聴もできなくなっていることに気が付きました。 Mirakurunを再起動したところ正常に見えるようになった。更新されていなかったstdoutとstderrも昨夜の分から含めてログが記録されたところから、今朝はMirakurunが正常に動作していなかったようです。 また明日報告します。

cuckoozero commented 6 years ago

おはようございます。

残念ながら今朝も録画失敗してしまいました。 EPGStation-master\logs\Operator\system.logには以下のエラーが記録されており、録画開始直前にMirakurunが停止していたようです。

[2018-06-20T07:03:25.108] [INFO] system - updateAll done
[2018-06-20T07:12:59.209] [INFO] system - clean recording
[2018-06-20T07:13:00.252] [INFO] system - start Updater pid: 10000
[2018-06-20T07:23:00.260] [ERROR] system - Error: MirakurunManageModelIsRunning
    at MirakurunManageModel.update (C:\TV\EPGStation\dist\server\Model\Operator\EPGUpdate\MirakurunManageModel.js:38:19)
    at Operator.updateDB (C:\TV\EPGStation\dist\server\Operator\Operator.js:51:34)
    at Operator.<anonymous> (C:\TV\EPGStation\dist\server\Operator\Operator.js:70:22)
    at Generator.next (<anonymous>)
    at C:\TV\EPGStation\dist\server\Operator\Operator.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\TV\EPGStation\dist\server\Operator\Operator.js:3:12)
    at Timeout.setInterval [as _onTimeout] (C:\TV\EPGStation\dist\server\Operator\Operator.js:69:31)
    at ontimeout (timers.js:482:11)
    at tryOnTimeout (timers.js:317:5)
[2018-06-20T07:29:46.404] [INFO] system - preprec: 40010300174 hogehuga
[2018-06-20T07:33:00.280] [ERROR] system - Error: MirakurunManageModelIsRunning
    at MirakurunManageModel.update (C:\TV\EPGStation\dist\server\Model\Operator\EPGUpdate\MirakurunManageModel.js:38:19)
    at Operator.updateDB (C:\TV\EPGStation\dist\server\Operator\Operator.js:51:34)
    at Operator.<anonymous> (C:\TV\EPGStation\dist\server\Operator\Operator.js:70:22)
    at Generator.next (<anonymous>)
    at C:\TV\EPGStation\dist\server\Operator\Operator.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\TV\EPGStation\dist\server\Operator\Operator.js:3:12)
    at Timeout.setInterval [as _onTimeout] (C:\TV\EPGStation\dist\server\Operator\Operator.js:69:31)
    at ontimeout (timers.js:482:11)
    at tryOnTimeout (timers.js:317:5)

今度こそうまくいくと思っていたのに、なにか呪われているような気がしてきました。

b25.exeのビルドはできました！！ が、しかし、decoder: hogehoge\b25.exeを設定してチューナー（TVTest）を立ち上げるとカードリーダーを読みには行くんですが（LEDが点滅する）、そこでMirakurunが固まってしまいます。 こちらもなかなか難しいようです。

l3tnun commented 6 years ago

録画設定をしているのはNHK BSプレミアムの朝ドラでしょうか？ 多分問題ないとは思いますがこちらでも試してみますね。

b25.exe 件はそうなると arib-b25-stream-test を修正するか epgdatacapbon/libaribb25 を改造して使えるようにするしか無いですね。

cuckoozero commented 6 years ago

録画設定をしているのはNHK BSプレミアムの朝ドラでしょうか？

おっしゃる通りです。 日に何度が放送があって７時３０分に取り逃しても他でカバーできてはいるんですが、何故かこの朝の放送だけが失敗続きなんです。

b25.exe 件はそうなると arib-b25-stream-test を修正するか epgdatacapbon/libaribb25 を改造して使えるようにするしか無いですね。

うーむ、MirakurunのWindows環境はexperimentalとのことでkanreisaさんを頼るわけにもいかなそうですしそうなりますかね。 しかしb25.exeを使うとMirakurunが固まる件は、b25.exe実行時に帰ってきたエラーをMirakurunが解釈できずに待ち続けているような動作にも見えますので、これはあちらに一報いれたほうがいいような気もします。

ちなみに固まったMirakurunを再起動したのちにstderrに書き込まれるエラーメッセージは以下になります。

no EMM receiving request
Error: write EOF
    at _errnoException (util.js:1022:11)
    at WriteWrap.afterWrite [as oncomplete] (net.js:880:14)

MirakurunのIssueに書き込むべきかどうか、ご意見を聞かせてください。

l3tnun commented 6 years ago

Mirakurun の decoder 設定は指定されたコマンドにパイプで ts を流し込んでいるだけなので固まるのは b25.exe から正常にデコード結果を受け取れないからだと思います。 Mirakurun とデコード周りはわざわざ分離しているので Mirakurun の issue として扱う話題ではないです。

cuckoozero commented 6 years ago

了解です。 ご意見ありがとうございます。

cuckoozero commented 6 years ago

おはようございます。 残念ながら今朝も昨日と同じ状態です。 Mirakurunのログでは7:13までは動作していました。 C:\Users\hoge\AppData\Local\Mirakurun\stdout

2018-06-21T07:13:13.337+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:13:13.337+09:00 info: TunerDevice#0 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2018-06-21T07:13:13.337+09:00 info: Network#7 EPG gathering has finished
2018-06-21T07:13:13.376+09:00 info: EPG GC has finished and removed 127 events
2018-06-21T07:13:13.400+09:00 info: Program GC has finished and removed 106 programs
2018-06-21T07:13:16.369+09:00 info: TunerDevice#0 > Abort!
2018-06-21T07:13:16.370+09:00 info: TunerDevice#0 > 
2018-06-21T07:13:16.408+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `null` (pid=9668)
2018-06-21T07:13:21.467+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:13:21.468+09:00 info: TunerDevice#3 end streaming to user `192.168.12.60:61022` (priority=2)
192.168.12.60 - GET /api/channels/GR/29/stream?decode=0 HTTP/1.0 200 - - 709.551 ms -

2018-06-21T07:13:21.468+09:00 info: TunerDevice#3 end streaming to user192.168.12.60:61022(priority=2)は並行稼働しているTVRockのEPG取得だと思います。

EPGStation-master\logs\Operator\system.logも昨日と同様です。

[2018-06-21T07:08:10.496] [INFO] system - updateAll done
[2018-06-21T07:17:44.067] [INFO] system - start Updater pid: 6024
[2018-06-21T07:27:44.071] [ERROR] system - Error: MirakurunManageModelIsRunning
    at MirakurunManageModel.update (C:\TV\EPGStation\dist\server\Model\Operator\EPGUpdate\MirakurunManageModel.js:38:19)
    at Operator.updateDB (C:\TV\EPGStation\dist\server\Operator\Operator.js:51:34)
    at Operator.<anonymous> (C:\TV\EPGStation\dist\server\Operator\Operator.js:70:22)
    at Generator.next (<anonymous>)
    at C:\TV\EPGStation\dist\server\Operator\Operator.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\TV\EPGStation\dist\server\Operator\Operator.js:3:12)
    at Timeout.setInterval [as _onTimeout] (C:\TV\EPGStation\dist\server\Operator\Operator.js:69:31)
    at ontimeout (timers.js:482:11)
    at tryOnTimeout (timers.js:317:5)
[2018-06-21T07:29:45.156] [INFO] system - preprec: 40010300718 連続テレビ小説 半分、青い。(70)「結婚したい!」[解][字][デ]
[2018-06-21T07:37:44.093] [ERROR] system - Error: MirakurunManageModelIsRunning
    at MirakurunManageModel.update (C:\TV\EPGStation\dist\server\Model\Operator\EPGUpdate\MirakurunManageModel.js:38:19)
    at Operator.updateDB (C:\TV\EPGStation\dist\server\Operator\Operator.js:51:34)
    at Operator.<anonymous> (C:\TV\EPGStation\dist\server\Operator\Operator.js:70:22)
    at Generator.next (<anonymous>)
    at C:\TV\EPGStation\dist\server\Operator\Operator.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (C:\TV\EPGStation\dist\server\Operator\Operator.js:3:12)
    at Timeout.setInterval [as _onTimeout] (C:\TV\EPGStation\dist\server\Operator\Operator.js:69:31)
    at ontimeout (timers.js:482:11)
    at tryOnTimeout (timers.js:317:5)

そちらはいかがでしたでしょうか？

cuckoozero commented 6 years ago

b25.exeを使うとMirakurunが固まる件は、ソースの修正を見直してb25.exeをビルドしなおしたところ解消しました。 Mirakurunがフリーズしなくなっただけで、デコードはできずstderrに残るエラーも変わらないですけども。

l3tnun commented 6 years ago

Mirakurun のログを 07:08 から 07:37 頃まで貼ってもらえますか？ 07:14 に開始した EPGStation の Updater が動いたままなのが気になります。

過去のログと合わせて考えると EPGStation と TVRock がpriority = 2 で動いているのであると思いますが、コンフリクトする事が考えられるのでどちらかの priority を下げるか上げるかして調整してください。

こちらの録画は特に問題なく成功しました。

cuckoozero commented 6 years ago

当該ログを張ります。

2018-06-21T07:06:42.779+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=7352)
- - GET /api/services HTTP/1.1 200 - - 5.806 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
- - GET /api/programs HTTP/1.1 200 - - 326.889 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
- - GET /api/tuners HTTP/1.1 200 - - 0.877 ms EPGStation/0.9.6 MirakurunClient/2.7.0 Node/v8.10.0 (win32)
2018-06-21T07:08:34.069+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:08:44.493+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:08:44.493+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:60750` (priority=2)
192.168.12.60 - GET /api/channels/BS/018/stream?decode=0 HTTP/1.0 200 - - 589.857 ms -
2018-06-21T07:08:44.504+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:08:44.511+09:00 info: TunerDevice#1 > Abort!
2018-06-21T07:08:44.512+09:00 info: TunerDevice#1 > 
2018-06-21T07:08:44.613+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal `null` (pid=8704)
2018-06-21T07:08:44.720+09:00 info: TunerDevice#1 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 0 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S1.dll --output - --channel 015` (pid=3972)
2018-06-21T07:08:44.721+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:60899` (priority=2)
2018-06-21T07:08:44.739+09:00 info: TunerDevice#1 > * BonRecTest *
2018-06-21T07:08:45.696+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:08:45.696+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:60899` (priority=2)
192.168.12.60 - GET /api/channels/BS/015/stream?decode=0 HTTP/1.0 200 - - 586.186 ms -
2018-06-21T07:08:45.705+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:08:45.706+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:60900` (priority=2)
2018-06-21T07:08:46.920+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:08:46.920+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:60900` (priority=2)
192.168.12.60 - GET /api/channels/BS/015/stream?decode=0 HTTP/1.0 200 - - 5.607 ms -
2018-06-21T07:08:46.928+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:08:46.929+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:60902` (priority=2)
2018-06-21T07:08:48.102+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:08:48.102+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:60902` (priority=2)
192.168.12.60 - GET /api/channels/BS/015/stream?decode=0 HTTP/1.0 200 - - 15.947 ms -
2018-06-21T07:08:48.110+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:08:48.110+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:60912` (priority=2)
2018-06-21T07:08:49.303+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:08:49.304+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:60912` (priority=2)
192.168.12.60 - GET /api/channels/BS/015/stream?decode=0 HTTP/1.0 200 - - 21.723 ms -
2018-06-21T07:08:49.312+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:08:49.312+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:60922` (priority=2)
2018-06-21T07:08:50.303+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
192.168.12.60 - GET /api/channels/GR/36/stream?decode=0 HTTP/1.0 200 - - 737.372 ms -
2018-06-21T07:08:51.879+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:08:51.880+09:00 info: TunerDevice#3 end streaming to user `192.168.12.60:60799` (priority=2)
2018-06-21T07:08:51.889+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:08:51.895+09:00 info: TunerDevice#2 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-T0.dll --output - --channel 34` (pid=10752)
2018-06-21T07:08:51.896+09:00 info: TunerDevice#2 streaming to user `192.168.12.60:60924` (priority=2)
2018-06-21T07:08:51.925+09:00 info: TunerDevice#2 > * BonRecTest *
2018-06-21T07:08:54.912+09:00 info: TunerDevice#3 > Abort!
2018-06-21T07:08:54.932+09:00 info: TunerDevice#3 process has closed with exit code=0 by signal `null` (pid=4884)
2018-06-21T07:08:58.185+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:06.157+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:11.028+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:15.811+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:26.351+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:37.596+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:42.910+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:46.184+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:53.710+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:09:58.057+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:02.398+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:06.210+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:12.319+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:13.318+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:10:13.318+09:00 info: TunerDevice#0 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2018-06-21T07:10:13.318+09:00 info: Network#6 EPG gathering has finished
2018-06-21T07:10:13.319+09:00 info: Network#7 EPG gathering has started
2018-06-21T07:10:13.319+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:10:13.371+09:00 info: TunerDevice#0 > Abort!
2018-06-21T07:10:13.392+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `null` (pid=5272)
2018-06-21T07:10:13.500+09:00 info: TunerDevice#0 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 1 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S0.dll --output - --channel 001` (pid=9668)
2018-06-21T07:10:13.500+09:00 info: TunerDevice#0 streaming to user `Mirakurun:getEPG()` (priority=-1)
2018-06-21T07:10:13.530+09:00 info: TunerDevice#0 > * BonRecTest *
2018-06-21T07:10:21.605+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:32.589+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:38.732+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:42.291+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:46.852+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:53.761+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:10:59.960+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:01.996+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:11:01.996+09:00 info: TunerDevice#2 end streaming to user `192.168.12.60:60924` (priority=2)
192.168.12.60 - GET /api/channels/GR/34/stream?decode=0 HTTP/1.0 200 - - 722.371 ms -
2018-06-21T07:11:02.014+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:11:02.021+09:00 info: TunerDevice#3 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-T1.dll --output - --channel 29` (pid=8336)
2018-06-21T07:11:02.021+09:00 info: TunerDevice#3 streaming to user `192.168.12.60:61022` (priority=2)
2018-06-21T07:11:02.087+09:00 info: TunerDevice#3 > * BonRecTest *
2018-06-21T07:11:05.086+09:00 info: TunerDevice#2 > Abort!
2018-06-21T07:11:05.102+09:00 info: TunerDevice#2 process has closed with exit code=0 by signal `null` (pid=10752)
2018-06-21T07:11:06.068+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:17.053+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:21.925+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:35.207+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:41.322+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:45.266+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:11:56.702+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:11:56.702+09:00 info: TunerDevice#1 end streaming to user `192.168.12.60:60922` (priority=2)
192.168.12.60 - GET /api/channels/BS/015/stream?decode=0 HTTP/1.0 200 - - 27.118 ms -
2018-06-21T07:11:56.714+09:00 info: TSFilter has created (serviceId=null, eventId=null)
2018-06-21T07:11:56.818+09:00 info: TunerDevice#1 > Abort!
2018-06-21T07:11:56.818+09:00 info: TunerDevice#1 > 
2018-06-21T07:11:56.940+09:00 info: TunerDevice#1 process has closed with exit code=0 by signal `null` (pid=3972)
2018-06-21T07:11:57.049+09:00 info: TunerDevice#1 process has spawned by command `C:\TV\BonRecTest\BonRecTest.exe --space 0 --decoder C:\TV\BonRecTest\B25Decoder.dll --driver C:\TV\BonRecTest\BonDriver_PT3-S1.dll --output - --channel 001` (pid=9048)
2018-06-21T07:11:57.050+09:00 info: TunerDevice#1 streaming to user `192.168.12.60:61069` (priority=2)
2018-06-21T07:11:57.072+09:00 info: TunerDevice#1 > * BonRecTest *
2018-06-21T07:12:26.871+09:00 info: save db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T07:13:13.337+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:13:13.337+09:00 info: TunerDevice#0 end streaming to user `Mirakurun:getEPG()` (priority=-1)
2018-06-21T07:13:13.337+09:00 info: Network#7 EPG gathering has finished
2018-06-21T07:13:13.376+09:00 info: EPG GC has finished and removed 127 events
2018-06-21T07:13:13.400+09:00 info: Program GC has finished and removed 106 programs
2018-06-21T07:13:16.369+09:00 info: TunerDevice#0 > Abort!
2018-06-21T07:13:16.370+09:00 info: TunerDevice#0 > 
2018-06-21T07:13:16.408+09:00 info: TunerDevice#0 process has closed with exit code=0 by signal `null` (pid=9668)
2018-06-21T07:13:21.467+09:00 info: TSFilter has closed (serviceId=null, eventId=null)
2018-06-21T07:13:21.468+09:00 info: TunerDevice#3 end streaming to user `192.168.12.60:61022` (priority=2)
192.168.12.60 - GET /api/channels/GR/29/stream?decode=0 HTTP/1.0 200 - - 709.551 ms -
configDir: C:\Users\cucko\.Mirakurun
dataDir: C:\Users\cucko\AppData\Local\Mirakurun
2018-06-21T08:38:34.929+09:00 info: load config `C:\Users\cucko\.Mirakurun\server.yml`
2018-06-21T08:38:34.935+09:00 info: load config `C:\Users\cucko\.Mirakurun\channels.yml`
2018-06-21T08:38:34.957+09:00 info: load config `C:\Users\cucko\.Mirakurun\tuners.yml`
2018-06-21T08:38:34.974+09:00 info: 4 of 4 tuners loaded
2018-06-21T08:38:34.981+09:00 info: load db `C:\Users\cucko\AppData\Local\Mirakurun\services.json`
2018-06-21T08:38:35.002+09:00 info: load db `C:\Users\cucko\AppData\Local\Mirakurun\programs.json`
2018-06-21T08:39:55.125+09:00 info: listening on http+unix://\\.\pipe\mirakurun

Mirakurunが固まったと思われる7:13以降は再起動した8:38までログがありませんでした。

過去のログと合わせて考えると EPGStation と TVRock がpriority = 2 で動いているのであると思いますが、コンフリクトする事が考えられるのでどちらかの priority を下げるか上げるかして調整してください。

これについてはおとといの夜にEPGStationのpriorityを3に変更したので、昨日の朝の録画からはそうなっているのではないかと思います。

すいません、よろしくお願いします。

l3tnun commented 6 years ago

綺麗さっぱり 08:38 までログがないんですね。 あまり把握はしていないのですが Mirakurun の logLevel を上げてみると何が起きているか分かるかもしれないですね。

Configuration.md によれば logLevel 3 が debug とのことなので 2, 3 あたりまで上げると原因究明に役に立つかもしれないです。

cuckoozero commented 6 years ago

logLevel: 3に変更しました。 それからTVRockはひとまず停止しました。 明日は”素”のログが取れるかと思います。

今度こそ！

cuckoozero commented 6 years ago

ついに録画できました！ さて何が良かったのか？ TVRock→TVTest→BonDriver_mirakurun→Mirakurun でMirakurunが停止してしまうことがあるんですかね？ このままTVRockは停止して経過を見ようと思います。

l3tnun commented 6 years ago

録画できて何よりです。 EPGStationが原因という訳では無さそうなのでこの issue は閉じますね。