Closed russelg closed 8 months ago
Looks like it's failing to kill the chat download for some reason. Do you see the "found pid
Yep
{"level":"debug","time":"2024-01-09T15:33:51+08:00","message":"found pid 53\n for chat_downloader"}
{"level":"debug","time":"2024-01-09T22:02:04+08:00","message":"found pid 104\n for chat_downloader"}
{"level":"debug","time":"2024-01-09T23:02:12+08:00","message":"found pid 111\n for chat_downloader"}
{"level":"debug","time":"2024-01-10T15:07:17+08:00","message":"found pid 179\n for chat_downloader"}
{"level":"debug","time":"2024-01-11T07:23:05+08:00","message":"found pid 53\n216\n for chat_downloader"}
{"level":"debug","time":"2024-01-11T22:02:18+08:00","message":"found pid 104\n254\n for chat_downloader"}
{"level":"debug","time":"2024-01-12T13:24:55+08:00","message":"found pid 53\n216\n291\n for chat_downloader"}
{"level":"debug","time":"2024-01-12T15:57:38+08:00","message":"found pid 53\n216\n291\n329\n for chat_downloader"}
{"level":"debug","time":"2024-01-13T15:22:31+08:00","message":"found pid 53\n216\n291\n329\n368\n for chat_downloader"}
There are corresponding success logs for some of them
{"level":"info","time":"2024-01-09T15:33:51+08:00","message":"killed chat downloader for channel 420jenkins"}
{"level":"info","time":"2024-01-09T22:02:04+08:00","message":"killed chat downloader for channel mogra"}
{"level":"info","time":"2024-01-09T23:02:12+08:00","message":"killed chat downloader for channel otographic"}
{"level":"info","time":"2024-01-10T15:07:17+08:00","message":"killed chat downloader for channel midnightsnacksfm"}
I was able to reproduce locally, only when the stream ended. Does this seem to occur only when the stream ends for you?
Does this seem to occur only when the stream ends for you?
That seems to be the case, but I haven't been watching the logs while a stream ends so can't say for sure.
Agree - I see this here too:
I believe I have found the issue. The chat download task was getting cancelled but the post-tasks were never running. I have some changes in https://github.com/Zibbp/ganymede/pull/357 if anyone is able to test these changes. I did some testing and the context and chat download processing is fixed but would like to get some others to test as well.
I would like to test it, how can I pull it in docker? I tried ghcr.io/zibbp/ganymede:pr-357
as shown in the action logs, but that doesn't work.
Pull requests don't publish the images to save on storage. You'll need to clone the repository and checkout the branch and build the image locally.
Alright, got it running locally. I've added a bunch of random live archives, will report back after a couple of them end.
Almost certainly a different issue, but while testing this, my internet went out :/. Anyway, that caused the live video downloads to end, which is expected. But even though the video download task in the queue is marked complete, it's not moving on to video convert/move. And chat download is stuck in progress still.
Looks like the video download workflow failed due to the fetch VOD ID failing. Perhaps we can just ignore that failure? Granted, this isn't the normal flow. Once my internet returns I'll test with a normal stream ending, not due to the internet going out :P
{"level":"debug","time":"2024-01-15T09:37:55+08:00","message":"workflow id b45d1f90-b346-11ee-a650-0242ac12000f started for live stream 43418657787"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_5","Namespace":"default","RunID":"148902df-f5e8-4456-bcdd-3e78cf9936dc","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"b45d1f90-b346-11ee-a650-0242ac12000f","WorkflowType":"CreateDirectoryWorkflow","time":"2024-01-15T09:37:55+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","ActivityID":"5","ActivityType":"CreateDirectory","Attempt":1,"Namespace":"default","RunID":"99d578de-03b1-41e4-8830-5a6d05017d66","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_5","WorkflowType":"CreateDirectoryWorkflow","time":"2024-01-15T09:37:55+08:00","message":"ExecuteActivity"}
{"level":"debug","time":"2024-01-15T09:37:55+08:00","message":"creating folder: lyricaldota/2024-01-15 - (LIVE)_Nouns_vs_BammySoy [43418657787][live][b45d1f90-b346-11ee-a650-0242ac12000f]"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_14","Namespace":"default","RunID":"148902df-f5e8-4456-bcdd-3e78cf9936dc","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"b45d1f90-b346-11ee-a650-0242ac12000f","WorkflowType":"DownloadTwitchLiveThumbnailsWorkflow","time":"2024-01-15T09:37:55+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","ActivityID":"5","ActivityType":"DownloadTwitchLiveThumbnails","Attempt":1,"Namespace":"default","RunID":"3386fbbf-4186-42ec-8fd8-135da3bacf5e","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_14","WorkflowType":"DownloadTwitchLiveThumbnailsWorkflow","time":"2024-01-15T09:37:55+08:00","message":"ExecuteActivity"}
{"level":"debug","time":"2024-01-15T09:37:57+08:00","message":"checking if tasks are done for video 43418657787"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_23","Namespace":"default","RunID":"148902df-f5e8-4456-bcdd-3e78cf9936dc","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"b45d1f90-b346-11ee-a650-0242ac12000f","WorkflowType":"SaveTwitchLiveVideoInfoWorkflow","time":"2024-01-15T09:37:57+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","ActivityID":"5","ActivityType":"SaveTwitchLiveVideoInfo","Attempt":1,"Namespace":"default","RunID":"b9b520dd-703d-40ab-9697-3751e87de7f2","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_23","WorkflowType":"SaveTwitchLiveVideoInfoWorkflow","time":"2024-01-15T09:37:57+08:00","message":"ExecuteActivity"}
{"level":"debug","time":"2024-01-15T09:37:57+08:00","message":"checking if tasks are done for video 43418657787"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_32","Namespace":"default","RunID":"148902df-f5e8-4456-bcdd-3e78cf9936dc","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"b45d1f90-b346-11ee-a650-0242ac12000f","WorkflowType":"ArchiveTwitchLiveChatWorkflow","time":"2024-01-15T09:37:57+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","time":"2024-01-15T09:37:57+08:00","message":"Live chat archive workflow ID: 148902df-f5e8-4456-bcdd-3e78cf9936dc_32"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_37","Namespace":"default","RunID":"148902df-f5e8-4456-bcdd-3e78cf9936dc","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"b45d1f90-b346-11ee-a650-0242ac12000f","WorkflowType":"DownloadTwitchLiveChatWorkflow","time":"2024-01-15T09:37:57+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","time":"2024-01-15T09:37:57+08:00","message":"Live chat workflow ID: 148902df-f5e8-4456-bcdd-3e78cf9936dc_37"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_42","Namespace":"default","RunID":"148902df-f5e8-4456-bcdd-3e78cf9936dc","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"b45d1f90-b346-11ee-a650-0242ac12000f","WorkflowType":"ArchiveTwitchLiveVideoWorkflow","time":"2024-01-15T09:37:57+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","Attempt":1,"ChildWorkflowID":"6a89acb8-12eb-4b80-a595-8155f9fcde77_5","Namespace":"default","RunID":"6a89acb8-12eb-4b80-a595-8155f9fcde77","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_42","WorkflowType":"DownloadTwitchLiveVideoWorkflow","time":"2024-01-15T09:37:57+08:00","message":"ExecuteChildWorkflow"}
{"level":"debug","time":"2024-01-15T09:37:57+08:00","message":"starting heartbeat download-livevideo-43418657787"}
{"level":"debug","time":"2024-01-15T09:37:58+08:00","message":"streamlink live args: [--progress=force --force https://twitch.tv/lyricaldota best,best --http-header Authorization=OAuth ... --twitch-low-latency --twitch-disable-hosting -o /tmp/43418657787_b45d1f90-b346-11ee-a650-0242ac12000f-video.mp4]"}
{"level":"debug","time":"2024-01-15T09:37:58+08:00","message":"running: streamlink --progress=force --force https://twitch.tv/lyricaldota best,best --http-header Authorization=OAuth ... --twitch-low-latency --twitch-disable-hosting -o /tmp/43418657787_b45d1f90-b346-11ee-a650-0242ac12000f-video.mp4"}
{"level":"debug","ActivityID":"9","ActivityType":"DownloadTwitchLiveChat","Attempt":1,"Namespace":"default","RunID":"560112a8-0ea4-4357-9e0f-82c74d712328","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_37","WorkflowType":"DownloadTwitchLiveChatWorkflow","time":"2024-01-15T09:37:58+08:00","message":"ExecuteActivity"}
{"level":"debug","time":"2024-01-15T09:37:58+08:00","message":"starting heartbeat download-livechat-43418657787"}
{"level":"debug","time":"2024-01-15T09:44:59+08:00","message":"finished downloading live video for 43418657787"}
{"level":"error","ActivityType":"DownloadTwitchLiveVideo","Attempt":1,"Error":"failed to get twitch videos: Get \"https://api.twitch.tv/helix/videos?user_id=90937535&type=archive&first=100\": dial tcp: lookup api.twitch.tv on 127.0.0.11:53: read udp 127.0.0.1:41249->127.0.0.11:53: i/o timeout","Namespace":"default","RunID":"d9e1e6ad-08aa-4efe-b883-e76a30fa4d86","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"6a89acb8-12eb-4b80-a595-8155f9fcde77_5","time":"2024-01-15T09:45:09+08:00","message":"Activity error."}
{"level":"debug","time":"2024-01-15T09:45:09+08:00","message":"stopping heartbeat download-livevideo-43418657787"}
{"level":"warn","ActivityID":"9","ActivityType":"DownloadTwitchLiveChat","Attempt":1,"Error":"workflow execution already completed","Namespace":"default","RunID":"560112a8-0ea4-4357-9e0f-82c74d712328","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_37","WorkflowType":"DownloadTwitchLiveChatWorkflow","time":"2024-01-15T09:45:19+08:00","message":"RecordActivityHeartbeat with error"}
{"level":"warn","ActivityID":"9","ActivityType":"DownloadTwitchLiveChat","Attempt":1,"Error":"context canceled","Namespace":"default","RunID":"560112a8-0ea4-4357-9e0f-82c74d712328","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_37","WorkflowType":"DownloadTwitchLiveChatWorkflow","time":"2024-01-15T09:46:19+08:00","message":"RecordActivityHeartbeat with error"}
{"level":"warn","ActivityID":"9","ActivityType":"DownloadTwitchLiveChat","Attempt":1,"Error":"context canceled","Namespace":"default","RunID":"560112a8-0ea4-4357-9e0f-82c74d712328","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"148902df-f5e8-4456-bcdd-3e78cf9936dc_37","WorkflowType":"DownloadTwitchLiveChatWorkflow","time":"2024-01-15T09:47:19+08:00","message":"RecordActivityHeartbeat with error"}
<above repeated every minute>
Ok, a stream ended naturally now. Failed at ending the chat downloader, multiple PIDs again. Could likely be due to the previous failures mentioned above. I didn't restart any of the containers after my internet came back.
Queue got stuck like so:
Now the video convert/move steps are still not running. Before, when the chat download failed to finish, the other steps would still continue.
{"level":"debug","time":"2024-01-15T11:22:15+08:00","message":"finished downloading live video for 50168626509"}
{"level":"debug","time":"2024-01-15T11:22:15+08:00","message":"getting video duration"}
{"level":"debug","time":"2024-01-15T11:22:16+08:00","message":"video duration: 4378"}
{"level":"info","time":"2024-01-15T11:22:16+08:00","message":"no vod found for livestream 50168626509, keeping live stream ID as external id"}
{"level":"debug","time":"2024-01-15T11:22:16+08:00","message":"stopping heartbeat download-livevideo-50168626509"}
{"level":"debug","ActivityID":"11","ActivityType":"KillTwitchLiveChatDownload","Attempt":1,"Namespace":"default","RunID":"86576e28-a6e3-485e-b111-a5ef41792282","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"8c7b60c5-2205-4218-a296-f42aef18ba0e_5","WorkflowType":"DownloadTwitchLiveVideoWorkflow","time":"2024-01-15T11:22:16+08:00","message":"ExecuteActivity"}
{"level":"info","time":"2024-01-15T11:22:16+08:00","message":"killing chat downloader for channel idubbbz"}
{"level":"debug","time":"2024-01-15T11:22:16+08:00","message":"found pid 100\n132\n for chat_downloader"}
{"level":"error","ActivityType":"KillTwitchLiveChatDownload","Attempt":1,"Error":"exit status 1","Namespace":"default","RunID":"86576e28-a6e3-485e-b111-a5ef41792282","TaskQueue":"archive","WorkerID":"b183487d2851","WorkflowID":"8c7b60c5-2205-4218-a296-f42aef18ba0e_5","time":"2024-01-15T11:22:16+08:00","message":"Activity error."}
{"level":"debug","time":"2024-01-15T11:22:16+08:00","message":"Error notification is disabled"}
I will start testing again with a fresh temporal db and restarted containers.
After fresh temporal and restarting, seems the queue is progressing as expected now. I went live with a test stream, while also recording another stream.
The correct chat downloader was killed, and the queue item for my test stream finished as expected. The other livestream was unaffected, also as expected.
Ending the other livestream on the queue page (the X button): ended the capture, killed the chat download, and completed the queue, as expected.
Seems like the fixes work for me!
I'll make another issue for the issue that came up when my internet dropped, i.e. queue fails due to VOD ID not being retrievable after stream ends.
I believe the multiple PID issue is that the chat downloader never got killed before (before the changes in the PR) so the processes just stuck around. Restarting the container clears those up for proper testing with the PR.
If anyone else wants to test the fixes, they are now available using the :main
image tag for the API container.
On most (not every) live archive that runs for me, the Chat Download task does not mark itself as finished. However, Chat Convert/Render/Move all occur and succeed afterwards. Due to this, the queue entry is never finished, and I've had to go and set the queue entry and the vod to not processing.
These lines are the most relevant:
From inside temporal:
Here is a full log for all mentions of a certain vod, and the chat download workflow that is "cancelled" as well.
Furthermore, the below is being logged every second, 1 line per each stuck chat downloading task.