Runner for lives: fails resuming live stream after a connection loss

JohnXLivingston commented 1 year ago

Describe the current behavior

Hi,

It seems that runners can fail resuming a live just after a connection loss. You have to wait a few seconds before being able to resume the live.

I'm not sure what are the relevant error logs. I made several tests, and had different logs (but it fails each time).

Here are some logs on the Peertube server:

error[18/09/2023 09:50:31] Error in controller.

{
  "err": "Error: Unexpected end of form\n    at Multipart._final (/var/www/peertube/versions/peertube-v5.2.1/node_modules/busboy/lib/types/multipart.js:588:17)\n    at callFinal (node:internal/streams/writable:696:27)\n    at prefinish (node:internal/streams/writable:725:7)\n    at finishMaybe (node:internal/streams/writable:735:5)\n    at Multipart.Writable.end (node:internal/streams/writable:633:5)\n    at IncomingMessage.onend (node:internal/streams/readable:693:10)\n    at Object.onceWrapper (node:events:627:28)\n    at IncomingMessage.emit (node:events:525:35)\n    at endReadableNT (node:internal/streams/readable:1358:12)\n    at processTicksAndRejections (node:internal/process/task_queues:83:21)"
}

...

error[18/09/2023 09:52:23] Cannot execute job 9 in queue video-live-ending.

{
  "payload": {
    "videoId": 34528,
    "replayDirectory": "/var/www/peertube/storage/streaming-playlists/hls/c09e9d24-00bf-4679-aaf7-1eaac120cecb/replay/2023-09-18T07:47:13.963Z",
    "liveSessionId": 52,
    "streamingPlaylistId": 361053,
    "publishedAt": "2023-09-18T07:46:14.655Z"
  },
  "err": {
    "stack": "TypeError: Cannot read properties of undefined (reading 'withVideoOrPlaylist')\n    at generateVideoMiniature (/var/www/peertube/versions/peertube-v5.2.1/dist/server/lib/thumbnail.js:82:92)\n    at /var/www/peertube/versions/peertube-v5.2.1/dist/server/lib/job-queue/handlers/video-live-ending.js:111:72\n    at Generator.next (<anonymous>)\n    at fulfilled (/var/www/peertube/versions/peertube-v5.2.1/node_modules/tslib/tslib.js:164:62)",
    "message": "Cannot read properties of undefined (reading 'withVideoOrPlaylist')"
  }
}

error[18/09/2023 09:52:55] Cannot execute job 10 in queue video-live-ending.

{
  "payload": {
    "videoId": 34528,
    "replayDirectory": "/var/www/peertube/storage/streaming-playlists/hls/c09e9d24-00bf-4679-aaf7-1eaac120cecb/replay/2023-09-18T07:47:49.370Z",
    "liveSessionId": 53,
    "streamingPlaylistId": 361054,
    "publishedAt": "2023-09-18T07:46:14.655Z"
  },
  "err": {
    "stack": "TypeError: Cannot read properties of undefined (reading 'withVideoOrPlaylist')\n    at generateVideoMiniature (/var/www/peertube/versions/peertube-v5.2.1/dist/server/lib/thumbnail.js:82:92)\n    at /var/www/peertube/versions/peertube-v5.2.1/dist/server/lib/job-queue/handlers/video-live-ending.js:111:72\n    at Generator.next (<anonymous>)\n    at fulfilled (/var/www/peertube/versions/peertube-v5.2.1/node_modules/tslib/tslib.js:164:62)",
    "message": "Cannot read properties of undefined (reading 'withVideoOrPlaylist')"
  }
}

error[18/09/2023 09:53:56] Remote runner prunner-fossninja-org had an error with job 74a77cc4-4dbd-400b-b22d-a3e5a99dd21e (live-rtmp-hls-transcoding)

{
  "errorMessage": "ffprobe exited with code 1\nffprobe version 5.1.3-1 Copyright (c) 2007-2022 the FFmpeg developers\n  built with gcc 12 (Debian 12.2.0-14)\n  configuration: --prefix=/usr --extra-version=1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libglslang --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librist --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libsvtav1 --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --disable-sndio --enable-libjxl --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-libplacebo --enable-librav1e --enable-shared\n  libavutil      57. 28.100 / 57. 28.100\n  libavcodec     59. 37.100 / 59. 37.100\n  libavformat    59. 27.100 / 59. 27.100\n  libavdevice    59.  7.100 / 59.  7.100\n  libavfilter     8. 44.100 /  8. 44.100\n  libswscale      6.  7.100 /  6.  7.100\n  libswresample   4.  7.100 /  4.  7.100\n  libpostproc    56.  6.100 / 56.  6.100\nrtmp://www.yiny.org:1935/live/17d9a9f0-3e07-47d9-b3af-aa356171dc8c: Input/output error\n",
  "totalFailures": 1,
  "tags": [
    "api",
    "runner",
    "prunner-fossninja-org",
    "74a77cc4-4dbd-400b-b22d-a3e5a99dd21e",
    "live-rtmp-hls-transcoding"
  ]
}

error[18/09/2023 09:56:28] Cannot update last runner contact for yiny

{
  "err": {
    "stack": "Error\n    at Query.run (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/dialects/postgres/query.js:50:25)\n    at /var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/sequelize.js:315:28\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at async PostgresQueryInterface.update (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/dialects/abstract/query-interface.js:355:12)\n    at async RunnerModel.save (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:2490:35)\n    at async /var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/sequelize.js:507:18",
    "message": "n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture\nparmi les transactions",
    "name": "SequelizeDatabaseError",
    "parent": {
      "stack": "error: n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture\nparmi les transactions\n    at Parser.parseErrorMessage (/var/www/peertube/versions/peertube-v5.2.1/node_modules/pg-protocol/dist/parser.js:287:98)\n    at Parser.handlePacket (/var/www/peertube/versions/peertube-v5.2.1/node_modules/pg-protocol/dist/parser.js:126:29)\n    at Parser.parse (/var/www/peertube/versions/peertube-v5.2.1/node_modules/pg-protocol/dist/parser.js:39:38)\n    at Socket.<anonymous> (/var/www/peertube/versions/peertube-v5.2.1/node_modules/pg-protocol/dist/index.js:11:42)\n    at Socket.emit (node:events:513:28)\n    at addChunk (node:internal/streams/readable:315:12)\n    at readableAddChunk (node:internal/streams/readable:289:9)\n    at Socket.Readable.push (node:internal/streams/readable:228:10)\n    at TCP.onStreamRead (node:internal/stream_base_commons:190:23)",
      "message": "n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture\nparmi les transactions",
      "length": 323,
      "name": "error",
      "severity": "ERREUR",
      "code": "40001",
      "detail": "Reason code: Canceled on identification as a pivot, during write.",
      "hint": "La transaction pourrait réussir après une nouvelle tentative.",
      "file": "predicate.c",
      "line": "4819",
      "routine": "OnConflict_CheckForSerializationFailure",
      "sql": "UPDATE \"runner\" SET \"lastContact\"=$1,\"updatedAt\"=$2 WHERE \"id\" = $3",
      "parameters": [
        "2023-09-18 07:56:28.785 +00:00",
        "2023-09-18 07:56:28.847 +00:00",
        1
      ]
    },
    "sql": "UPDATE \"runner\" SET \"lastContact\"=$1,\"updatedAt\"=$2 WHERE \"id\" = $3"
  },
  "tags": [
    "runner",
    "yiny"
  ]
}

error[18/09/2023 09:56:28] Error in controller.

{
  "err": "Error\n    at Query.run (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/dialects/postgres/query.js:50:25)\n    at /var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/sequelize.js:315:28\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at async PostgresQueryInterface.select (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/dialects/abstract/query-interface.js:407:12)\n    at async Function.findAll (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:1140:21)\n    at async Function.findOne (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:1240:12)\n    at async self.reload (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:2562:22)",
  "sql": "SELECT \"RunnerJobModel\".\"id\", \"RunnerJobModel\".\"uuid\", \"RunnerJobModel\".\"type\", \"RunnerJobModel\".\"payload\", \"RunnerJobModel\".\"privatePayload\", \"RunnerJobModel\".\"state\", \"RunnerJobModel\".\"failures\", \"RunnerJobModel\".\"error\", \"RunnerJobModel\".\"priority\", \"RunnerJobModel\".\"processingJobToken\", \"RunnerJobModel\".\"progress\", \"RunnerJobModel\".\"startedAt\", \"RunnerJobModel\".\"finishedAt\", \"RunnerJobModel\".\"dependsOnRunnerJobId\", \"RunnerJobModel\".\"runnerId\", \"RunnerJobModel\".\"createdAt\", \"RunnerJobModel\".\"updatedAt\", \"Runner\".\"id\" AS \"Runner.id\", \"Runner\".\"runnerToken\" AS \"Runner.runnerToken\", \"Runner\".\"name\" AS \"Runner.name\", \"Runner\".\"description\" AS \"Runner.description\", \"Runner\".\"lastContact\" AS \"Runner.lastContact\", \"Runner\".\"ip\" AS \"Runner.ip\", \"Runner\".\"runnerRegistrationTokenId\" AS \"Runner.runnerRegistrationTokenId\", \"Runner\".\"createdAt\" AS \"Runner.createdAt\", \"Runner\".\"updatedAt\" AS \"Runner.updatedAt\" FROM \"runnerJob\" AS \"RunnerJobModel\" LEFT OUTER JOIN \"runner\" AS \"Runner\" ON \"RunnerJobModel\".\"runnerId\" = \"Runner\".\"id\" WHERE \"RunnerJobModel\".\"id\" = 57;"
}

error[18/09/2023 09:56:28] Error in controller.

{
  "err": "Error\n    at Query.run (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/dialects/postgres/query.js:50:25)\n    at /var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/sequelize.js:315:28\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at async PostgresQueryInterface.select (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/dialects/abstract/query-interface.js:407:12)\n    at async Function.findAll (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:1140:21)\n    at async Function.findOne (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:1240:12)\n    at async self.reload (/var/www/peertube/versions/peertube-v5.2.1/node_modules/sequelize/lib/model.js:2562:22)",
  "sql": "SELECT \"RunnerJobModel\".\"id\", \"RunnerJobModel\".\"uuid\", \"RunnerJobModel\".\"type\", \"RunnerJobModel\".\"payload\", \"RunnerJobModel\".\"privatePayload\", \"RunnerJobModel\".\"state\", \"RunnerJobModel\".\"failures\", \"RunnerJobModel\".\"error\", \"RunnerJobModel\".\"priority\", \"RunnerJobModel\".\"processingJobToken\", \"RunnerJobModel\".\"progress\", \"RunnerJobModel\".\"startedAt\", \"RunnerJobModel\".\"finishedAt\", \"RunnerJobModel\".\"dependsOnRunnerJobId\", \"RunnerJobModel\".\"runnerId\", \"RunnerJobModel\".\"createdAt\", \"RunnerJobModel\".\"updatedAt\", \"Runner\".\"id\" AS \"Runner.id\", \"Runner\".\"runnerToken\" AS \"Runner.runnerToken\", \"Runner\".\"name\" AS \"Runner.name\", \"Runner\".\"description\" AS \"Runner.description\", \"Runner\".\"lastContact\" AS \"Runner.lastContact\", \"Runner\".\"ip\" AS \"Runner.ip\", \"Runner\".\"runnerRegistrationTokenId\" AS \"Runner.runnerRegistrationTokenId\", \"Runner\".\"createdAt\" AS \"Runner.createdAt\", \"Runner\".\"updatedAt\" AS \"Runner.updatedAt\" FROM \"runnerJob\" AS \"RunnerJobModel\" LEFT OUTER JOIN \"runner\" AS \"Runner\" ON \"RunnerJobModel\".\"runnerId\" = \"Runner\".\"id\" WHERE \"RunnerJobModel\".\"id\" = 57;"
}

Here are some logs on the runners:

sept. 18 07:56:28 yiny prunner[1914701]: [07:56:28.889] ERROR (1914701): Cannot request/accept job on https://www.yiny.org for runner yiny
sept. 18 07:56:28 yiny prunner[1914701]:     err: {
sept. 18 07:56:28 yiny prunner[1914701]:       "type": "Error",
sept. 18 07:56:28 yiny prunner[1914701]:       "message": "Expected status 200, got 500. \nThe server responded: \"n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture\nparmi les transactions\".\nYou may take a closer look at the logs. To see how to do so, check out this page: https://github.com/Chocobozzz/PeerTube/blob/develop/support/doc/development/tests.md#debug-server-logs",
sept. 18 07:56:28 yiny prunner[1914701]:       "stack":
sept. 18 07:56:28 yiny prunner[1914701]:           Error: Expected status 200, got 500.
sept. 18 07:56:28 yiny prunner[1914701]:           The server responded: "n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture
sept. 18 07:56:28 yiny prunner[1914701]:           parmi les transactions".
sept. 18 07:56:28 yiny prunner[1914701]:           You may take a closer look at the logs. To see how to do so, check out this page: https://github.com/Chocobozzz/PeerTube/blob/develop/support/doc/development/tests.md#debug-server-logs
sept. 18 07:56:28 yiny prunner[1914701]:               at buildRequest (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:77227:14)
sept. 18 07:56:28 yiny prunner[1914701]:               at makePostBodyRequest (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:77169:10)
sept. 18 07:56:28 yiny prunner[1914701]:               at RunnerJobsCommand.postBodyRequest (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:77298:12)
sept. 18 07:56:28 yiny prunner[1914701]:               at RunnerJobsCommand.accept (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:77684:28)
sept. 18 07:56:28 yiny prunner[1914701]:               at RunnerServer.tryToExecuteJobAsync (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:88081:45)
sept. 18 07:56:28 yiny prunner[1914701]:               at RunnerServer.checkAvailableJobs (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:88047:20)
sept. 18 07:56:28 yiny prunner[1914701]:               at processTicksAndRejections (node:internal/process/task_queues:96:5)
sept. 18 07:56:28 yiny prunner[1914701]:           ----
sept. 18 07:56:28 yiny prunner[1914701]:               at file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:77230:19
sept. 18 07:56:28 yiny prunner[1914701]:               at file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48825:17
sept. 18 07:56:28 yiny prunner[1914701]:               at Test._assertFunction (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48811:17)
sept. 18 07:56:28 yiny prunner[1914701]:               at Test.assert (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48701:27)
sept. 18 07:56:28 yiny prunner[1914701]:               at localAssert (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48669:18)
sept. 18 07:56:28 yiny prunner[1914701]:               at file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48673:11
sept. 18 07:56:28 yiny prunner[1914701]:               at Test.Request3.callback (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48242:7)
sept. 18 07:56:28 yiny prunner[1914701]:               at file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:48394:22
sept. 18 07:56:28 yiny prunner[1914701]:               at IncomingMessage.<anonymous> (file:///usr/lib/node_modules/@peertube/peertube-runner/dist/peertube-runner.js:47644:11)
sept. 18 07:56:28 yiny prunner[1914701]:               at IncomingMessage.emit (node:events:525:35)
sept. 18 07:56:28 yiny prunner[1914701]:       "res": {
sept. 18 07:56:28 yiny prunner[1914701]:         "req": {
sept. 18 07:56:28 yiny prunner[1914701]:           "method": "POST",
sept. 18 07:56:28 yiny prunner[1914701]:           "url": "https://www.yiny.org/api/v1/runners/jobs/80754f40-5ca8-4b06-b721-418de6254059/accept",
sept. 18 07:56:28 yiny prunner[1914701]:           "data": {
sept. 18 07:56:28 yiny prunner[1914701]:             "runnerToken": "***************"
sept. 18 07:56:28 yiny prunner[1914701]:           },
sept. 18 07:56:28 yiny prunner[1914701]:           "headers": {
sept. 18 07:56:28 yiny prunner[1914701]:             "content-type": "application/json"
sept. 18 07:56:28 yiny prunner[1914701]:           }
sept. 18 07:56:28 yiny prunner[1914701]:         },
sept. 18 07:56:28 yiny prunner[1914701]:         "header": {
sept. 18 07:56:28 yiny prunner[1914701]:           "server": "nginx/1.18.0",
sept. 18 07:56:28 yiny prunner[1914701]:           "date": "Mon, 18 Sep 2023 07:56:28 GMT",
sept. 18 07:56:28 yiny prunner[1914701]:           "content-type": "application/problem+json; charset=utf-8",
sept. 18 07:56:28 yiny prunner[1914701]:           "content-length": "376",
sept. 18 07:56:28 yiny prunner[1914701]:           "connection": "close",
sept. 18 07:56:28 yiny prunner[1914701]:           "x-powered-by": "PeerTube",
sept. 18 07:56:28 yiny prunner[1914701]:           "x-frame-options": "DENY",
sept. 18 07:56:28 yiny prunner[1914701]:           "tk": "N",
sept. 18 07:56:28 yiny prunner[1914701]:           "access-control-allow-origin": "*",
sept. 18 07:56:28 yiny prunner[1914701]:           "access-control-allow-credentials": "true",
sept. 18 07:56:28 yiny prunner[1914701]:           "access-control-expose-headers": "Retry-After",
sept. 18 07:56:28 yiny prunner[1914701]:           "x-ratelimit-limit": "50",
sept. 18 07:56:28 yiny prunner[1914701]:           "x-ratelimit-remaining": "48",
sept. 18 07:56:28 yiny prunner[1914701]:           "x-ratelimit-reset": "1695023790",
sept. 18 07:56:28 yiny prunner[1914701]:           "etag": "W/\"178-pDOhowUBGxqpLBTdWGlvZH2d+Po\""
sept. 18 07:56:28 yiny prunner[1914701]:         },
sept. 18 07:56:28 yiny prunner[1914701]:         "status": 500,
sept. 18 07:56:28 yiny prunner[1914701]:         "text": "{\"type\":\"https://docs.joinpeertube.org/api-rest-reference.html#section/Errors/SequelizeDatabaseError\",\"detail\":\"n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture\\nparmi les transactions\",\"status\":500,\"code\":\"SequelizeDatabaseError\",\"error\":\"n'a pas pu sérialiser un accès à cause des dépendances de lecture/écriture\\nparmi les transactions\"}"
sept. 18 07:56:28 yiny prunner[1914701]:       }
sept. 18 07:56:28 yiny prunner[1914701]:     }

I generate the live using ffmpeg (see the "steps to reproduce" section). Here are the console content when the live fails:

ffmpeg version 5.1.3-1 Copyright (c) 2000-2022 the FFmpeg developers
  built with gcc 12 (Debian 12.2.0-14)
  configuration: --prefix=/usr --extra-version=1 --toolchain=hardened --libdir=/usr/lib/x86_64-linux-gnu --incdir=/usr/include/x86_64-linux-gnu --arch=amd64 --enable-gpl --disable-stripping --enable-gnutls --enable-ladspa --enable-libaom --enable-libass --enable-libbluray --enable-libbs2b --enable-libcaca --enable-libcdio --enable-libcodec2 --enable-libdav1d --enable-libflite --enable-libfontconfig --enable-libfreetype --enable-libfribidi --enable-libglslang --enable-libgme --enable-libgsm --enable-libjack --enable-libmp3lame --enable-libmysofa --enable-libopenjpeg --enable-libopenmpt --enable-libopus --enable-libpulse --enable-librabbitmq --enable-librist --enable-librubberband --enable-libshine --enable-libsnappy --enable-libsoxr --enable-libspeex --enable-libsrt --enable-libssh --enable-libsvtav1 --enable-libtheora --enable-libtwolame --enable-libvidstab --enable-libvorbis --enable-libvpx --enable-libwebp --enable-libx265 --enable-libxml2 --enable-libxvid --enable-libzimg --enable-libzmq --enable-libzvbi --enable-lv2 --enable-omx --enable-openal --enable-opencl --enable-opengl --enable-sdl2 --disable-sndio --enable-libjxl --enable-pocketsphinx --enable-librsvg --enable-libmfx --enable-libdc1394 --enable-libdrm --enable-libiec61883 --enable-chromaprint --enable-frei0r --enable-libx264 --enable-libplacebo --enable-librav1e --enable-shared
  libavutil      57. 28.100 / 57. 28.100
  libavcodec     59. 37.100 / 59. 37.100
  libavformat    59. 27.100 / 59. 27.100
  libavdevice    59.  7.100 / 59.  7.100
  libavfilter     8. 44.100 /  8. 44.100
  libswscale      6.  7.100 /  6.  7.100
  libswresample   4.  7.100 /  4.  7.100
  libpostproc    56.  6.100 / 56.  6.100
[Parsed_drawtext_2 @ 0x5637b8988380] Using "/usr/share/fonts/truetype/noto/NotoSans-Regular.ttf"
Input #0, lavfi, from 'aevalsrc=0 [out1]; testsrc=s=1280x720,drawtext=borderw=5:fontcolor=white:fontsize=30:text='%{localtime}/%{pts\:hms}':x=\(w-text_w\)/2:y=\(h-text_h-line_h\)/2 [out0]':
  Duration: N/A, start: 0.000000, bitrate: 2822 kb/s
  Stream #0:0: Video: rawvideo (RGB[24] / 0x18424752), rgb24, 1280x720 [SAR 1:1 DAR 16:9], 25 tbr, 25 tbn
  Stream #0:1: Audio: pcm_f64le, 44100 Hz, mono, dbl, 2822 kb/s
Stream mapping:
  Stream #0:0 -> #0:0 (rawvideo (native) -> h264 (libx264))
  Stream #0:1 -> #0:1 (pcm_f64le (native) -> aac (native))
Press [q] to stop, [?] for help
[libx264 @ 0x5637b89b02c0] using SAR=1/1
[libx264 @ 0x5637b89b02c0] frame MB size (80x45) > level limit (1620)
[libx264 @ 0x5637b89b02c0] MB rate (90000) > level limit (40500)
[libx264 @ 0x5637b89b02c0] using cpu capabilities: MMX2 SSE2Fast SSSE3 SSE4.2 AVX FMA3 BMI2 AVX2
[libx264 @ 0x5637b89b02c0] profile Constrained Baseline, level 3.0, 4:2:0, 8-bit
[libx264 @ 0x5637b89b02c0] 264 - core 164 r3095 baee400 - H.264/MPEG-4 AVC codec - Copyleft 2003-2022 - http://www.videolan.org/x264.html - options: cabac=0 ref=2 deblock=1:0:0 analyse=0x1:0x111 me=hex subme=7 psy=1 psy_rd=1.00:0.00 mixed_ref=1 me_range=16 chroma_me=1 trellis=1 8x8dct=0 cqm=0 deadzone=21,11 fast_pskip=1 chroma_qp_offset=-2 threads=12 lookahead_threads=2 sliced_threads=0 nr=0 decimate=1 interlaced=0 bluray_compat=0 constrained_intra=0 bframes=0 weightp=0 keyint=250 keyint_min=25 scenecut=40 intra_refresh=0 rc_lookahead=40 rc=crf mbtree=1 crf=23.0 qcomp=0.60 qpmin=0 qpmax=69 qpstep=4 ip_ratio=1.40 aq=1:1.00
Output #0, flv, to 'rtmp://www.yiny.org:1935/live/17d9a9f0-3e07-47d9-b3af-aa356171dc8c':
  Metadata:
    encoder         : Lavf59.27.100
  Stream #0:0: Video: h264 ([7][0][0][0] / 0x0007), yuv420p(tv, progressive), 1280x720 [SAR 1:1 DAR 16:9], q=2-31, 25 fps, 1k tbn
    Metadata:
      encoder         : Lavc59.37.100 libx264
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
  Stream #0:1: Audio: aac (LC) ([10][0][0][0] / 0x000A), 44100 Hz, mono, fltp, 69 kb/s
    Metadata:
      encoder         : Lavc59.37.100 aac
av_interleaved_write_frame(): Connection reset by peer30.25 bitrate= 220.5kbits/s speed=0.997x    
    Last message repeated 55 times
[flv @ 0x5637b89abf80] Failed to update header with correct duration.
[flv @ 0x5637b89abf80] Failed to update header with correct filesize.
Error writing trailer of rtmp://www.yiny.org:1935/live/17d9a9f0-*************: Connection reset by peer
frame=  764 fps= 25 q=-1.0 Lsize=     820kB time=00:00:30.53 bitrate= 219.9kbits/s speed=0.994x    
video:853kB audio:5kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
Error closing file rtmp://www.yiny.org:1935/live/17d9a9f0-****************: Broken pipe
[libx264 @ 0x5637b89b02c0] frame I:4     Avg QP:11.79  size: 21172
[libx264 @ 0x5637b89b02c0] frame P:760   Avg QP:16.04  size:  1037
[libx264 @ 0x5637b89b02c0] mb I  I16..4: 92.5%  0.0%  7.5%
[libx264 @ 0x5637b89b02c0] mb P  I16..4:  2.8%  0.0%  0.1%  P16..4:  6.2%  0.4%  0.1%  0.0%  0.0%    skip:9

Steps to reproduce

Create a permanent live (with automatic replay)
Start streaming (see below for the streaming script)
ctrl+c to stop the stream
wait 1 second, try to launch ffmpeg again
wait a few seconds for the error

If you wait 15 or 20 seconds on step 4, everything works fine.

Here is the ffmpeg commande line:


ffmpeg -re -f lavfi -i "aevalsrc=0 [out1]; testsrc=s=1280x720,drawtext=borderw=5:fontcolor=white:fontsize=30:text='%{localtime}/%{pts\:hms}':x=\(w-text_w\)/2:y=\(h-text_h-line_h\)/2 [out0]" \
  -acodec aac -vcodec h264 -strict -2 -pix_fmt yuv420p -profile:v baseline -level 3.0 -f flv rtmp://www.yiny.org:1935/live/************

Note: I have 3 runners connected to the instance (1 on the instance itself, 2 remotes, same result for boths)

Describe the expected behavior

Should not fail.

Additional information

PeerTube instance:
- URL: https://www.yiny.org
- Version: 5.2.1 (runner 0.0.6)
- NodeJS version: v16.20.2 (v16.20.2 or v18.17.1 for the runners, same result for both)
- Ffmpeg version: 4.3.6-0+deb11u1 ( 4.3.6-0+deb11u1 or 5.1.3-1 for the runners, same result for both)

agates commented 1 year ago

I am noticing similar behavior

Chocobozzz commented 1 year ago

Hi,

Can you paste info logs just around error[18/09/2023 09:52:23] Cannot execute job 9 in queue video-live-ending. so I can also debug this error? I'm looking for this log in particular.

After [07:56:28.889] ERROR (1914701): Cannot request/accept job on https://www.yiny.org for runner yiny error, your runner doesn't retry to request new jobs after a few seconds?

JohnXLivingston commented 1 year ago

Can you paste info logs just around error[18/09/2023 09:52:23] Cannot execute job 9 in queue video-live-ending. so I can also debug this error? I'm looking for this log in particular.

Oops... logs have rotated, last available log is the same day, but 5 hours after. i'll try to get the log file from my backup.

JohnXLivingston commented 1 year ago

Can't find the log @Chocobozzz. Git blame says it was added september the 1st, but last release was august 30. This log does not exist in v5.2.1 :/

After [07:56:28.889] ERROR (1914701): Cannot request/accept job on https://www.yiny.org for runner yiny error, your runner doesn't retry to request new jobs after a few seconds?

I don't remember. There are 3 runners for this server, and i don't notice any other issue. The live can be resumed after a few seconds.

Chocobozzz commented 1 year ago

Git blame says it was added september the 1st, but last release was august 30. This log does not exist in v5.2.1 :/

Oup's sorry about that. We'll see in the next release then :)

The live can be resumed after a few seconds.

When you cut your live, it's a normal behaviour that you have to wait a few seconds before retrying (1 to 3 seconds I guess). But 20 seconds is too much.

JohnXLivingston commented 1 year ago

When you cut your live, it's a normal behaviour that you have to wait a few seconds before retrying (1 to 3 seconds I guess). But 20 seconds is too much.

Oh, i didn't know. I just retried (same conditions). I was able to resume the live after 10 seconds, but it failed after a few seconds. In the runner job list, there were 2 "live-rtmp-hls-transcoding" jobs, both in "Processing" states. Then one was "Completed", the other "Errored" (on 2 different runners).

I don't really undertand what's happening, i don't know enough about how lives are handled by Peertube. If you want, we can meet on a visio so we can test together. Send me a mail if interested.

Chocobozzz commented 8 months ago

Hi @JohnXLivingston

Do you still have the issue with peertube 6.0.3 and latest peertube-runner (0.0.10)?