Recording does not "stop" and is stuck.

[KurtzPT]

Left yesterday when it was recording two streams, today I went to check and the two streams that did finish hours ago are still marked as recording. Saw the following errors:

2022-01-30 01:36:35.768 | hook | Hook called NOTICE: PHP message: PHP Warning: Undefined array key "challenge" in /var/www/twitchautomator/src/Controller/ApiController.php on line 680 2022-01-30 01:36:35.771 | automator | Stream online for robcdee (retry 1) 2022-01-30 01:36:35.855 | automator | VOD exists and is still capturing on robcdee_2022-01-30T01_35_41Z45339704077 (retry 1) 2022/01/30 01:36:35 [error] 21#21: *2686 FastCGI sent in stderr: "PHP message: PHP Warning: Undefined array key "challenge" in /var/www/twitchautomator/src/Controller/ApiController.php on line 680" while reading response header from upstream, client: 172.29.0.1, server: , request: "POST /api/v0/hook HTTP/1.1", upstream: "fastcgi://unix:/run/php-fpm.sock:", host: ""

[KurtzPT]

Also it seems the only way of "stopping" the record (which is not really stopping since the record process is not running), is by removing the files on the /vods directory.

The force stop recording button (can't remember the exact name) gives out an API error and doesn't stop anything.

[MrBrax]

you can check if the recording is actually running if the processes are alive still, but they were probably not in this case, just marked as online in the json

just seems to be a strict fix, not sure why that would suddenly start to happen though, either some php8 stuff or something new with the twitch api

pushed a test commit for it

[KurtzPT]

pulled the changes, I'll report tomorrow the results.

[KurtzPT]

I went to check today and I see that one stream came online not long before I updated the code, but for some reason it didn't start the recording at all. (It marks as recording but no .ts file at all)

Logs from the recording that failed:

2022-01-31 03:22:12.394 | hook | Hook called 2022-01-31 03:22:12.426 | automator | Channel update for robcdee 2022-01-31 03:22:12.428 | automator | Channel robcdee not online, saving channel data to cache: Just Chatting (Tokyo | Chinese new year's eve! | !yt !vpn $7sr) 2022-01-31 03:31:15.208 | hook | Hook called 2022-01-31 03:31:15.211 | automator | Stream online for robcdee (retry 0) 2022-01-31 03:31:15.249 | job | Loading job capture_robcdee_2022-01-31T03_30_35Z_45353361245 failed, no json file 2022-01-31 03:31:15.250 | vodclass | Create VOD JSON: robcdee_2022-01-31T03_30_35Z_45353361245.json 2022-01-31 03:31:15.251 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 with no chapters!! 2022-01-31 03:31:15.252 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 (create json) 2022-01-31 03:31:15.255 | vodclass | JSON has been changed since loading of robcdee_2022-01-31T03_30_35Z_45353361245 2022-01-31 03:31:15.256 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 with no chapters!! 2022-01-31 03:31:15.257 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 (stream download) 2022-01-31 03:31:15.258 | vodclass | Refreshing JSON on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 03:31:15.261 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 03:31:15.292 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 while not finalized! 2022-01-31 03:31:15.293 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 with no chapters!! 2022-01-31 03:31:15.295 | vodclass | Saving JSON of robcdee_2022-01-31T03_30_35Z_45353361245 (is_capturing set) 2022-01-31 03:31:15.298 | automator | Update game for robcdee_2022-01-31T03_30_35Z_45353361245 2022-01-31 03:31:15.306 | automator | Channel data for robcdee fetched from cache. 2022-01-31 03:31:26.053 | hook | Hook called 2022-01-31 03:31:26.057 | automator | Stream online for robcdee (retry 1) 2022-01-31 03:31:26.090 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 03:31:26.096 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 03:31:26.106 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 03:31:26.109 | automator | VOD exists and is still capturing on robcdee_2022-01-31T03_30_35Z_45353361245 (retry 1) 2022-01-31 09:20:21.235 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 09:20:21.241 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 09:20:48.845 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 09:20:48.851 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 10:20:04.390 | hook | Hook called 2022-01-31 10:20:04.420 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:20:04.425 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 10:20:04.431 | automator | Channel update for robcdee 2022-01-31 10:20:04.438 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:20:04.442 | automator | Channel data for robcdee fetched from notification. 2022-01-31 10:20:15.177 | hook | Hook called 2022-01-31 10:20:15.204 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:20:15.210 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 10:20:15.216 | automator | Channel update for robcdee 2022-01-31 10:20:15.221 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:20:15.225 | automator | Channel data for robcdee fetched from notification. 2022-01-31 10:20:35.982 | hook | Hook called 2022-01-31 10:20:36.012 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:20:36.018 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 10:20:36.026 | automator | Channel update for robcdee 2022-01-31 10:20:36.033 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:20:36.037 | automator | Channel data for robcdee fetched from notification. 2022-01-31 10:21:16.743 | hook | Hook called 2022-01-31 10:21:16.772 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:21:16.777 | job | Capturing status for robcdee_2022-01-31T03_30_35Z_45353361245 is null 2022-01-31 10:21:16.784 | automator | Channel update for robcdee 2022-01-31 10:21:16.791 | vodclass | No chapters on robcdee_2022-01-31T03_30_35Z_45353361245! 2022-01-31 10:21:16.796 | automator | Channel data for robcdee fetched from notification.

EDIT: Trying to figure out if the issue comes from the #87 change, I've disabled the option and I'm waiting for someone to start a stream.

[KurtzPT]

Let me know if you want separated errors on their own issues in github, but I found also this error popping up today (on a old record):

2022-01-31 00:00:00.048 | cron | Cronjob mute check start 2022-01-31 00:00:00.066 | vodclass | Check muted VOD for sodapoppin_2022-01-29T17_52_28Z_45334623693 2022-01-31 00:00:00.414 | helper | Querying video info for id 1280205877 2022-01-31 00:00:00.415 | cron | Cronjob mute check: sodapoppin_2022-01-29T17_52_28Z_45334623693 error: sizeof(): Argument #1 ($value) must be of type Countable|array, null given 2022-01-31 00:00:00.416 | cron | Cronjob mute check end

[mr-flibble]

Hello, just to let you know: I also have "stuck" capturing (from 5 days ago) No running jobs. Abort record button give me "Invalid API endpoint" error.

Reboot did not help, so its probably realy stuck in some json.

At least it does not block new capturing, so its cosmetic problem :)

[KurtzPT]

Abort record does not seem to function even when a stream is correctly recording, it gives always the "Invalid API endpoint" message

[MrBrax]

The "abort capture" kills the running job, so even if the endpoint did work, it wouldn't help here because there are no running jobs

[MrBrax]

I went to check today and I see that one stream came online not long before I updated the code, but for some reason it didn't start the recording at all. (It marks as recording but no .ts file at all)

Logs from the recording that failed:

I feel like there must be something in the webserver logs, can you check that? I don't seem to have any errors on my side.

[MrBrax]

I'm still using PHP 7 on my setup, so probably something stemming from that

[KurtzPT]

The "abort capture" kills the running job, so even if the endpoint did work, it wouldn't help here because there are no running jobs

I tried out on a running job and it didn't kill the process, I had to kill myself via shell.

I'll take a look at the webserver logs and report back

[MrBrax]

ok it was just a get/post mixup for the kill job endpoint, might work now?

[MrBrax]

i really should move the api to a crud layout

[KurtzPT]

ok it was just a get/post mixup for the kill job endpoint, might work now?

Can confirm that it now kills the job correctly.

Regarding the webserver logs, it seems nginx is set not to log anything?

access_log /dev/stdout main_timed; error_log /dev/stderr notice;

[MrBrax]

it should output to the docker console i think, not sure if there's any actual file logging

[KurtzPT]

Whelp, I already removed the old docker containers to update with the new commits. I'll wait for someone to start streaming. At least the .log file that TA creates only had those entries I put above.

[MrBrax]

yeah they won't include php errors, i think i could have them piped in there but i think that could cause some infinite loop stuff

[KurtzPT]

Just noticed while trying to test the "abort feature", while it worked I have errors on the docker logs:

NOTICE: PHP message: PHP Fatal error: Uncaught Error: Cannot use object of type App\TwitchChannel as array in /var/www/twitchautomator/src/TwitchAutomator.php:894 Stack trace: 0 /var/www/twitchautomator/src/TwitchAutomator.php(446): App\TwitchAutomator->download() 1 /var/www/twitchautomator/src/Traits/ApiChannel.php(74): App\TwitchAutomator->handle() 2 /var/www/twitchautomator/vendor/slim/slim/Slim/Handlers/Strategies/RequestResponse.php(43): App\Controller\ApiController->channel_force_record() 3 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/Route.php(384): Slim\Handlers\Strategies\RequestResponse->__invoke() 4 /var/www/twitchautomator/vendor/slim/slim/Slim/MiddlewareDispatcher.php(81): Slim\Routing\Route->handle() 5 /var/www/twitchautomator/vendor/slim/slim/Slim/MiddlewareDispatcher.php(81): Slim\MiddlewareDispatcher->handle() 6 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/Route.php(341): Slim\MiddlewareDispatcher->handle() 7 /var/www/twitchautomator/vendor/slim/slim/Slim/Rout...

[MrBrax]

hmm, i wonder if i mixed that up with the global config, seems like it's accessing the channel config

[KurtzPT]

Ok finally someone started to stream and it's recording just fine. I basically just disabled the option that you added on #87 , might be the issue.

Anyway I'll post it here the docker logs, I see some warnings and errors but I'm not sure if it impacts anything:

[MrBrax]

oh weird, that's not good

[KurtzPT]

@MrBrax finally got the error with #87 option on and the record failed:

[MrBrax]

oh boy stricter typing is gonna be fun

i'm gonna redo the api to use json instead, makes no sense to use forms still, so commits will be very broken for a while

[KurtzPT]

Alright, let me know when I can test it out.

[MrBrax]

ok i think it should be fairly stable now outside of unnoticed php strict warnings

[KurtzPT]

Going to update to the following commit https://github.com/MrBrax/TwitchAutomator/commit/00c93723ddf8376fadda8b018bfe8796cd3c92e7 and test

[KurtzPT]

After setting Get extra metadata when updating chapter. I get the following:

014 . - web_1 | 2022-02-01 13:15:13.725 | hook | Hook called with invalid JSON. web_1 | 192.168.32.1 - - [01/Feb/2022:13:15:13 +0000] "GET /api/v0/hook HTTP/1.1" 200 27 "-" "GuzzleHttp/7" "redacted" 0.017 0.017 . - web_1 | 2022-02-01 13:15:13.762 | config | Saved config from settings/save

[MrBrax]

yeah that should be fine, it checks the hook address so it's accessible

[KurtzPT]

Clicking on the "about":

web_1 | NOTICE: PHP message: PHP Warning: Undefined array key "youtube-dl" in /var/www/twitchautomator/src/Controller/ApiController.php on line 411 web_1 | NOTICE: PHP message: PHP Warning: Trying to access array offset on value of type null in /var/www/twitchautomator/src/Controller/ApiController.php on line 411 web_1 | NOTICE: PHP message: PHP Warning: Undefined array key "youtube-dl" in /var/www/twitchautomator/src/Controller/ApiController.php on line 411 web_1 | NOTICE: PHP message: PHP Warning: Trying to access array offset on value of type null in /var/www/twitchautomator/src/Controller/ApiController.php on line 411 web_1 | NOTICE: PHP message: PHP Fatal error: Uncaught TypeError: version_compare(): Argument #2 ($version2) must be of type string, null given in /var/www/twitchautomator/src/Controller/ApiController.php:411 web_1 | Stack trace: web_1 | #0 /var/www/twitchautomator/src/Controller/ApiController.php(411): version_compare() web_1 | #1 /var/www/twitchautomator/vendor/slim/slim/Slim/Handlers/Strategies/RequestResponse.php(43): App\Controller\ApiController->about() web_1 | #2 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/Route.php(384): Slim\Handlers\Strategies\RequestResponse->invoke() web_1 | #3 /var/www/twitchautomator/vendor/slim/slim/Slim/MiddlewareDispatcher.php(81): Slim\Routing\Route->handle() web_1 | #4 /var/www/twitchautomator/vendor/slim/slim/Slim/MiddlewareDispatcher.php(81): Slim\MiddlewareDispatcher->handle() web_1 | #5 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/Route.php(341): Slim\MiddlewareDispatcher->handle() web_1 | #6 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/RouteRunner.php(84): Slim\Routing\Route->run() web_1 | #7 /var/www/twitchau... web_1 | 2022/02/01 13:18:22 [error] 19#19: *69 FastCGI sent in stderr: "PHP message: PHP Warning: Undefined array key "youtube-dl" in /var/www/twitchautomator/src/Controller/ApiController.php on line 411PHP message: PHP Warning: Trying to access array offset on value of type null in /var/www/twitchautomator/src/Controller/ApiController.php on line 411PHP message: PHP Warning: Undefined array key "youtube-dl" in /var/www/twitchautomator/src/Controller/ApiController.php on line 411PHP message: PHP Warning: Trying to access array offset on value of type null in /var/www/twitchautomator/src/Controller/ApiController.php on line 411PHP message: PHP Fatal error: Uncaught TypeError: version_compare(): Argument #2 ($version2) must be of type string, null given in /var/www/twitchautomator/src/Controller/ApiController.php:411 web_1 | Stack trace: web_1 | #0 /var/www/twitchautomator/src/Controller/ApiController.php(411): version_compare() web_1 | #1 /var/www/twitchautomator/vendor/slim/slim/Slim/Handlers/Strategies/RequestResponse.php(43): App\Controller\ApiController->about() web_1 | #2 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/Route.php(384): Slim\Handlers\Strategies\RequestResponse->invoke() web_1 | #3 /var/www/twitchautomator/vendor/slim/slim/Slim/MiddlewareDispatcher.php(81): Slim\Routing\Route->handle() web_1 | #4 /var/www/twitchautomator/vendor/slim/slim/Slim/MiddlewareDispatcher.php(81): Slim\MiddlewareDispatcher->handle() web_1 | #5 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/Route.php(341): Slim\MiddlewareDispatcher->handle() web_1 | #6 /var/www/twitchautomator/vendor/slim/slim/Slim/Routing/RouteRunner.php(84): Slim\Routing\Route->run()

[MrBrax]

alright, i should probably find where to set warning displays on my host

[MrBrax]

seems like my host is using php8 after all, and i have full error reporting on. weird that i don't get those warnings

[KurtzPT]

everything seems to be going fine, even with #87 option turned on I'm recording streams just fine.

[KurtzPT]

I got again another stream that went offline but TA didn't stop the recording (but streamlink stopped recording). So TA still shows it recording and it doesn't download the chat/convert the .TS file at all.

The issue seems that the hook is not being called when the stream went offline for some reason, because I don't see any entries on the logs for it.

[MrBrax]

When the capturing by streamlink stops, it will do the conversion and all that, the hook not being called shouldn't break it. Must be some error in the logs somewhere.

[KurtzPT]

Ok this is very weird, I actually have two streams that TA still shows as recording when there's no streamlink on for those streams.

The first stream is the one I mentioned above, after the hook that started the recording, I don't see any mentions of the stream in the logs, besides these ones (made hours after the stream ended):

2022-02-02 12:07:22.604 | automator | Channel update for moonmoon 2022-02-02 12:07:22.613 | automator | Channel data for moonmoon fetched from notification. 2022-02-02 12:07:22.871 | helper | No streams found for user id 121059319 2022-02-02 12:07:22.873 | automator | No streams in metadata request. 2022-02-02 12:07:22.876 | vodclass | Saving JSON of moonmoon_2022-02-01T23_30_38Z_40497374619 while not finalized! 2022-02-02 12:07:22.878 | vodclass | Saving JSON of moonmoon_2022-02-01T23_30_38Z_40497374619 (game update) 2022-02-02 12:07:22.890 | automator | Game updated on 'moonmoon' to 'League of Legends' (Next stream Thursday @ 3PM PST ish peepoS - !gallery | !vods) using notification. 192.168.32.1 - - [02/Feb/2022:12:07:22 +0000] "POST /api/v0/hook HTTP/1.1" 200 31 "-" "Go-http-client/1.1" "54.184.54.118" 0.419 0.418 .

I believe this is just a title update on the stream.

The second stream is even weird, It started recording and it stopped after 2 hours. Then it started a 2nd recording and this one is still "recording". But according to Twitch the stream was 8 hours and it didn't stop after 2 hours.

These are the logs I'm seeing:

2022-02-02 05:26:04.395 | hook | Hook called 2022-02-02 05:26:04.398 | automator | Stream offline for robcdee 2022-02-02 05:26:04.399 | automator | Stream end 192.168.32.1 - - [02/Feb/2022:05:26:04 +0000] "POST /api/v0/hook HTTP/1.1" 200 31 "-" "Go-http-client/1.1" "52.12.79.235" 0.026 0.024 . - 2022-02-02 05:26:33.089 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (0/100)! 2022-02-02 05:26:38.757 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (1/100)! 2022-02-02 05:26:44.425 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (2/100)! 2022-02-02 05:26:50.089 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (3/100)! 2022-02-02 05:26:55.754 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (4/100)! 2022-02-02 05:27:01.425 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (5/100)! 2022-02-02 05:27:03.708 | hook | Hook called 2022-02-02 05:27:03.712 | automator | Stream online for robcdee (retry 0) 2022-02-02 05:27:04.075 | job | Loading job capture_robcdee_2022-02-02T05_26_24Z_45376964893 failed, no json file 2022-02-02 05:27:04.076 | vodclass | Create VOD JSON: robcdee_2022-02-02T05_26_24Z_45376964893.json 2022-02-02 05:27:04.077 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 with no chapters!! 2022-02-02 05:27:04.078 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 (create json) 2022-02-02 05:27:04.080 | vodclass | JSON has been changed since loading of robcdee_2022-02-02T05_26_24Z_45376964893 2022-02-02 05:27:04.081 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 with no chapters!! 2022-02-02 05:27:04.082 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 (stream download) 2022-02-02 05:27:04.083 | vodclass | Refreshing JSON on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:27:04.086 | vodclass | No chapters on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:27:04.096 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 while not finalized! 2022-02-02 05:27:04.097 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 with no chapters!! 2022-02-02 05:27:04.098 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 (is_capturing set) 2022-02-02 05:27:04.099 | automator | Update game for robcdee_2022-02-02T05_26_24Z_45376964893 2022-02-02 05:27:04.103 | vodclass | Refreshing JSON on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:27:04.107 | vodclass | No chapters on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:27:04.110 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 while not finalized! 2022-02-02 05:27:04.110 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 with no chapters!! 2022-02-02 05:27:04.111 | vodclass | Saving JSON of robcdee_2022-02-02T05_26_24Z_45376964893 (dt_capture_started set) 2022-02-02 05:27:04.112 | automator | Starting capture with filename robcdee_2022-02-02T05_26_24Z_45376964893.ts 2022-02-02 05:27:04.116 | job | Save job capture_robcdee_2022-02-02T05_26_24Z_45376964893 with PID 14329 2022-02-02 05:27:04.126 | automator | Using process wait method 1 2022-02-02 05:27:06.744 | automator | Stream resolution for robcdee_2022-02-02T05_26_24Z_45376964893: 1080p60 2022-02-02 05:27:06.745 | automator | Capturing of robcdee_2022-02-02T05_26_24Z_45376964893, will try to remove ads! 2022-02-02 05:27:07.093 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (6/100)! 192.168.32.1 - - [02/Feb/2022:05:27:08 +0000] "POST /api/v0/hook HTTP/1.1" 499 0 "-" "Go-http-client/1.1" "54.184.54.118" 4.509 4.509 . - 2022-02-02 05:27:12.744 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (7/100)! 2022-02-02 05:27:18.410 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (8/100)! 2022-02-02 05:27:18.733 | hook | Hook called 2022-02-02 05:27:18.737 | automator | Stream online for robcdee (retry 1) 2022-02-02 05:27:18.799 | vodclass | No chapters on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:27:18.865 | vodclass | No chapters on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:27:18.869 | automator | VOD exists and is still capturing on robcdee_2022-02-02T05_26_24Z_45376964893 (retry 1) 192.168.32.1 - - [02/Feb/2022:05:27:18 +0000] "POST /api/v0/hook HTTP/1.1" 200 31 "-" "Go-http-client/1.1" "35.155.5.226" 0.155 0.155 . - 2022-02-02 05:27:24.073 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (9/100)! 2022-02-02 05:27:29.744 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (10/100)! 2022-02-02 05:27:35.413 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (11/100)! 2022-02-02 05:27:41.079 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (12/100)! 2022-02-02 05:27:46.749 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (13/100)! 2022-02-02 05:27:52.416 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (14/100)! 2022-02-02 05:27:58.085 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (15/100)! 2022-02-02 05:28:03.764 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (16/100)! 2022-02-02 05:28:09.432 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (17/100)! 2022-02-02 05:28:15.100 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (18/100)! 2022-02-02 05:28:20.771 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (19/100)! 2022-02-02 05:28:26.441 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (20/100)! 2022-02-02 05:28:32.111 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (21/100)! 2022-02-02 05:28:37.782 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (22/100)! 2022-02-02 05:28:43.450 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (23/100)! 2022-02-02 05:28:49.118 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (24/100)! 2022-02-02 05:28:54.787 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (25/100)! 2022-02-02 05:29:00.453 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (26/100)! 2022-02-02 05:29:06.119 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (27/100)! 2022-02-02 05:29:11.789 | automator | Chunk 404'd for robcdee_2022-02-02T04_00_07Z_45376221725 (28/100)! 2022-02-02 05:29:16.616 | automator | Finished capture with filename robcdee_2022-02-02T04_00_07Z_45376221725.ts 2022-02-02 05:29:16.618 | job | Clear job capture_robcdee_2022-02-02T04_00_07Z_45376221725 with PID 13080 2022-02-02 05:29:16.630 | automator | Add end timestamp for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:29:16.632 | vodclass | Refreshing JSON on robcdee_2022-02-02T04_00_07Z_45376221725! 2022-02-02 05:29:16.642 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 while not finalized! 2022-02-02 05:29:16.643 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 (stream capture end) 2022-02-02 05:30:16.645 | vodclass | Refreshing JSON on robcdee_2022-02-02T04_00_07Z_45376221725! 2022-02-02 05:30:16.655 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 while not finalized! 2022-02-02 05:30:16.657 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 (is_converting set) 2022-02-02 05:30:16.660 | vodclass | Refreshing JSON on robcdee_2022-02-02T04_00_07Z_45376221725! 2022-02-02 05:30:16.668 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 while not finalized! 2022-02-02 05:30:16.670 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 (dt_conversion_started set) 2022-02-02 05:30:16.671 | automator | Starting conversion of robcdee_2022-02-02T04_00_07Z_45376221725.ts to robcdee_2022-02-02T04_00_07Z_45376221725.mp4 2022-02-02 05:30:16.675 | job | Save job convert_robcdee_2022-02-02T04_00_07Z_45376221725 with PID 14384 2022-02-02 05:30:56.468 | job | Clear job convert_robcdee_2022-02-02T04_00_07Z_45376221725 with PID 14384 2022-02-02 05:30:56.885 | automator | Finished conversion of robcdee_2022-02-02T04_00_07Z_45376221725.ts to robcdee_2022-02-02T04_00_07Z_45376221725.mp4 2022-02-02 05:31:07.713 | automator | Conversion done, add segments to robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:31:07.715 | vodclass | Refreshing JSON on robcdee_2022-02-02T04_00_07Z_45376221725! 2022-02-02 05:31:07.725 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 while not finalized! 2022-02-02 05:31:07.727 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 (add segment) 2022-02-02 05:31:07.729 | automator | Cleanup old VODs for robcdee 2022-02-02 05:31:07.751 | vodclass | No chapters on robcdee_2022-02-02T05_26_24Z_45376964893! 2022-02-02 05:31:07.756 | automator | Total filesize for robcdee: 3.69 GB 2022-02-02 05:31:07.757 | automator | Amount for robcdee: 2/101 2022-02-02 05:31:07.758 | automator | Sleep 2 minutes for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:07.759 | automator | Do metadata on robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:07.769 | vodclass | Finalize robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:08.007 | vodclass | Saving lossless cut csv for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:08.010 | vodclass | Try to match twitch vod for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:08.283 | helper | Querying videos for streamer id 169185650 2022-02-02 05:33:08.288 | vodclass | Matched twitch vod for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:08.291 | vodclass | Saving JSON of robcdee_2022-02-02T04_00_07Z_45376221725 (finalized) 2022-02-02 05:33:08.293 | automator | Auto download chat on robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:08.293 | vodclass | Download chat for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:08.296 | job | Save job tcd_robcdee_2022-02-02T04_00_07Z_45376221725 with PID 14429 2022-02-02 05:33:45.609 | job | Clear job tcd_robcdee_2022-02-02T04_00_07Z_45376221725 with PID 14429 2022-02-02 05:33:45.619 | vodclass | Chat downloaded for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:33:45.624 | automator | All done for robcdee_2022-02-02T04_00_07Z_45376221725 2022-02-02 05:39:13.580 | hook | Hook called 2022-02-02 05:39:13.681 | vodclass | No chapters on robcdee_2022-02-02T05_26_24Z_45376964893!

Where can I check streamlink logs? I also have a stream that was supposed to be recording but streamlink crashed it seems.

[MrBrax]

Software logs are in logs/software but most likely still needs a setting enabled

[KurtzPT]

Software logs are in logs/software but most likely still needs a setting enabled

Found it.

No errors on the 1st stream:

$ /usr/bin/streamlink --hls-live-restart --hls-live-edge 99999 --hls-timeout 200 --hls-segment-timeout 200 --hls-segment-threads 5 --twitch-disable-hosting --twitch-disable-ads --retry-streams 10 --retry-max 5 --twitch-disable-reruns -o /var/www/twitchautomator/src/../public/vods/moonmoon/moonmoon_2022-02-01T23_30_38Z_40497374619.ts --url twitch.tv/moonmoon --default-stream best [cli][info] Found matching plugin twitch for URL twitch.tv/moonmoon [cli][info] Available streams: audio_only, 160p (worst), 360p, 480p, 720p60, 1080p60 (best) [cli][info] Opening stream: 1080p60 (hls) [plugins.twitch][info] Will skip ad segments

2nd stream had errors (on the 1st record that actually is marked as done, not the 2nd try):

$ /usr/bin/streamlink --hls-live-restart --hls-live-edge 99999 --hls-timeout 200 --hls-segment-timeout 200 --hls-segment-threads 5 --twitch-disable-hosting --twitch-disable-ads --retry-streams 10 --retry-max 5 --twitch-disable-reruns -o /var/www/twitchautomator/src/../public/vods/robcdee/robcdee_2022-02-02T04_00_07Z_45376221725.ts --url twitch.tv/robcdee --default-stream best [cli][info] Found matching plugin twitch for URL twitch.tv/robcdee [cli][info] Available streams: audio_only, 160p (worst), 360p, 480p, 720p, 720p60, 1080p60 (best) [cli][info] Opening stream: 1080p60 (hls) [plugins.twitch][info] Will skip ad segments [stream.hls][warning] Failed to reload playlist: Unable to open URL: https://video-weaver.lhr03.hls.ttvnw.net/v1/playlist/Cp4EXmTCT9mFn4Ab1D6P47TPsz6jLcsP8ZFZqtIyIE6hGaYi4EQGQSaYSWKybyyPYwJeOBtFxF5OzsTHoL5tRx8EgbpH0hMrOmlvzz281VD3CQusc7WEFYGE2awqSoV6yh4Fy0aTiD41hAX_7_i7YoKOGlDKi8p5Y1h4t5cRpL-IAHeEPUT2wWOV7vloqjIhx0atGzV4aywhWpSxjbZ3J_QBiNPcSdxrkW8a-pZ_wMzQecyZbKjcOrdHM1w-4Wu4CHeR24iSrmmG_D9vMJlib7N7i-_MEI0FN-h6jktzN59w0HlZKaWiWTnpbxmD_Sc206BJiA5u90n6XXn7cSeEJWXCTnCqCknxTypQGT2LbHyA0F1tx4Gp4oUyygK_f__Gwv_MkjlGpD-YdPsP8eysJfEfqpokzMlhOQS53m21b6HTPLY7pyhhhCYh6DhH8W9hwyMh7bVrXvZVaipDZ_bDfrUaflCiMPYpCy-mHq9RMIgW4qB0o2ZdLnfd3515E3mbmObnBJiFQTKctVT2O_1yF2Y8TnThS98MusRS-cW4ZiFMQdYZOF33DPxNgjYM400LN0V38V46GL5GsHEwvr9KEEyCIoIInhPZSsJuDxAMdPnRTCsLJCZjMmhQyWeMUrBQ1zgGwmG_osMxpEvrk-x9FavU6gkmPTxFOyVD-UF0zjIBspFEoAgc8gUWKZD683PV9EXnouAeSfns_jVylckYJpIaDI9fEjtL2rE8VXbSWyABKgl1cy1lYXN0LTIw9AI.m3u8 (404 Client weaver.lhr03.hls.ttvnw.net/v1/playlist/Cp4EXmTCT9mFn4Ab1D6P47TPsz6jLcsP8ZFZqtIyIE6hGaYi4EQGQSaYSWKybyyPYwJeOBtFxF5OzsTHoL5tRx8EgbpH0hMrOmlvzz281VD3CQusc7WEFYGE2awqSoV6yh4Fy0aTiD41hAX_7_i7YoKOGlDKi8p5Y1h4t5cRpL-IAHeEPUT2wWOV7vloqjIhx0atGzV4aywhWpSxjbZ3J_QBiNPcSdxrkW8a-pZ_wMzQecyZbKjcOrdHM1w-4Wu4CHeR24iSrmmG_D9vMJlib7N7i-_MEI0FN-h6jktzN59w0HlZKaWiWTnpbxmD_Sc206BJiA5u90n6XXn7cSeEJWXCTnCqCknxTypQGT2LbHyA0F1tx4Gp4oUyygK_f__Gwv_MkjlGpD-YdPsP8eysJfEfqpokzMlhOQS53m21b6HTPLY7pyhhhCYh6DhH8W9hwyMh7bVrXvZVaipDZ_bDfrUaflCiMPYpCy-mHq9RMIgW4qB0o2ZdLnfd3515E3mbmObnBJiFQTKctVT2O_1yF2Y8TnThS98MusRS-cW4ZiFMQdYZOF33DPxNgjYM400LN0V38V46GL5GsHEwvr9KEEyCIoIInhPZSsJuDxAMdPnRTCsLJCZjMmhQyWeMUrBQ1zgGwmG_osMxpEvrk-x9FavU6gkmPTxFOyVD-UF0zjIBspFEoAgc8gUWKZD683PV9EXnouAeSfns_jVylckYJpIaDI9fEjtL2rE8VXbSWyABKgl1cy1lYXN0LTIw9AI.m3u8) [stream.hls][warning] Failed to reload playlist: Unable to open URL: https://video-weaver.lhr03.hls.ttvnw.net/v1/playlist/Cp4EXmTCT9mFn4Ab1D6P47TPsz6jLcsP8ZFZqtIyIE6hGaYi4EQGQSaYSWKybyyPYwJeOBtFxF5OzsTHoL5tRx8EgbpH0hMrOmlvzz281VD3CQusc7WEFYGE2awqSoV6yh4Fy0aTiD41hAX_7_i7YoKOGlDKi8p5Y1h4t5cRpL-IAHeEPUT2wWOV7vloqjIhx0atGzV4aywhWpSxjbZ3J_QBiNPcSdxrkW8a-pZ_wMzQecyZbKjcOrdHM1w-4Wu4CHeR24iSrmmG_D9vMJlib7N7i-_MEI0FN-h6jktzN59w0HlZKaWiWTnpbxmD_Sc206BJiA5u90n6XXn7cSeEJWXCTnCqCknxTypQGT2LbHyA0F1tx4Gp4oUyygK_f__Gwv_MkjlGpD-YdPsP8eysJfEfqpokzMlhOQS53m21b6HTPLY7pyhhhCYh6DhH8W9hwyMh7bVrXvZVaipDZ_bDfrUaflCiMPYpCy-mHq9RMIgW4qB0o2ZdLnfd3515E3mbmObnBJiFQTKctVT2O_1yF2Y8TnThS98MusRS-cW4ZiFMQdYZOF33DPxNgjYM400LN0V38V46GL5GsHEwvr9KEEyCIoIInhPZSsJuDxAMdPnRTCsLJCZjMmhQyWeMUrBQ1zgGwmG_osMxpEvrk-x9FavU6gkmPTxFOyVD-UF0zjIBspFEoAgc8gUWKZD683PV9EXnouAeSfns_jVylckYJpIaDI9fEjtL2rE8VXbSWyABKgl1cy1lYXN0LTIw9AI.m3u8 (404 Client error: Error when reading from stream: Read timeout, exiting [cli][info] Stream ended [cli][info] Closing currently open stream...

The 3rd stream that I'm mentioning above that should still be recording doesn't have any errors too.

[MrBrax]

unable to open url spam is normal at the end of a stream, but at the point of having streamlink errors outside of that i'm not sure if i can do anything

[KurtzPT]

unable to open url spam is normal at the end of a stream, but at the point of having streamlink errors outside of that i'm not sure if i can do anything

I mean if streamlink is not running, I should have some kind of log to know what happened to that process? all examples above that are still marked as "recording" I don't have anything that shows what happened to streamlink

[MrBrax]

Then there must have happened a fatal PHP error between the recording and the finalization process

[KurtzPT]

Then there must have happened a fatal PHP error between the recording and the finalization process

Got nothing on the docker logs for that. Unless something changed and I'm not seeing fatal logs now with develop branch

[MrBrax]

Mine has been working fine for a while now, no stuck recordings. Docker bugging out?

[KurtzPT]

No idea, I'm blind here trying to understand what is happening.

[KurtzPT]

Can we add --loglevel debug on streamlink? Might be able to understand what is happening somehow with it.

[MrBrax]

if you enable debug mode in settings it applies to all software too if available

[MrBrax]

try using process wait method 2 too

[KurtzPT]

Got it I'll be adding debug option and wait again for this to happen.

[KurtzPT]

Funny thing is, sodapoppin streams don't seem to have this issue. So I'm thinking it might be something related with ads and streamlink.

[MrBrax]

it's possible, they could be doing some real janky shit behind the scenes

[KurtzPT]

What is the new endpoint to check subscriptions?

The below is not working:

Check /api/v0/subscriptions/list for subscription status.