Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Transcoding session ended by the Broadcaster when no sessions were transcoded #2755

Closed
papabear99 opened this issue Feb 12, 2023 · 5 comments · Fixed by #2777
Closed

Transcoding session ended by the Broadcaster when no sessions were transcoded #2755

papabear99 opened this issue Feb 12, 2023 · 5 comments · Fixed by #2777
Assignees
@mjh1
Labels
area: broadcasting status: core contributors working on it in progress

Comments

@papabear99
Copy link
Contributor

Since the update to 0.5.37 Os have been receiving Transcoding session ended by the Broadcaster messages in their logs even when no sessions have been transcoded. They don't appear to cause any issues but several of us are wondering what they mean.

Below is a log from one of my Os that hadn't had a session in over 30 mins.

Feb 12 13:33:57 us1 livepeer[2892108]: I0212 13:33:57.679178 2892108 block_watcher.go:567] Polling blocks from=60368672 to=60368688
Feb 12 13:34:02 us1 livepeer[2892108]: I0212 13:34:02.683114 2892108 block_watcher.go:567] Polling blocks from=60368690 to=60368702
Feb 12 13:34:07 us1 livepeer[2892108]: I0212 13:34:07.672923 2892108 block_watcher.go:567] Polling blocks from=60368707 to=60368722
Feb 12 13:34:12 us1 livepeer[2892108]: I0212 13:34:12.689514 2892108 block_watcher.go:567] Polling blocks from=60368726 to=60368742
Feb 12 13:34:17 us1 livepeer[2892108]: I0212 13:34:17.691441 2892108 block_watcher.go:567] Polling blocks from=60368746 to=60368762
Feb 12 13:34:22 us1 livepeer[2892108]: I0212 13:34:22.702086 2892108 block_watcher.go:567] Polling blocks from=60368766 to=60368779
Feb 12 13:34:27 us1 livepeer[2892108]: I0212 13:34:27.671883 2892108 block_watcher.go:567] Polling blocks from=60368783 to=60368798
Feb 12 13:34:28 us1 livepeer[2892108]: I0212 13:34:28.079656 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=39b68ed1
Feb 12 13:34:28 us1 livepeer[2892108]: I0212 13:34:28.299858 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=8189a3dc
Feb 12 13:34:31 us1 livepeer[2892108]: I0212 13:34:31.427539 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=90b3de8b
Feb 12 13:34:32 us1 livepeer[2892108]: I0212 13:34:32.673208 2892108 block_watcher.go:567] Polling blocks from=60368800 to=60368816
Feb 12 13:34:33 us1 livepeer[2892108]: I0212 13:34:33.934319 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=926d9596
Feb 12 13:34:37 us1 livepeer[2892108]: I0212 13:34:37.673950 2892108 block_watcher.go:567] Polling blocks from=60368818 to=60368835
Feb 12 13:34:41 us1 livepeer[2892108]: I0212 13:34:41.915399 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=11d5cb4c
Feb 12 13:34:42 us1 livepeer[2892108]: I0212 13:34:42.687813 2892108 block_watcher.go:567] Polling blocks from=60368837 to=60368855
Feb 12 13:34:47 us1 livepeer[2892108]: I0212 13:34:47.681498 2892108 block_watcher.go:567] Polling blocks from=60368857 to=60368874
Feb 12 13:34:52 us1 livepeer[2892108]: I0212 13:34:52.686336 2892108 block_watcher.go:567] Polling blocks from=60368876 to=60368891
Feb 12 13:34:58 us1 livepeer[2892108]: I0212 13:34:58.203148 2892108 block_watcher.go:567] Polling blocks from=60368895 to=60368912
Feb 12 13:35:02 us1 livepeer[2892108]: I0212 13:35:02.675116 2892108 block_watcher.go:567] Polling blocks from=60368916 to=60368928
Feb 12 13:35:07 us1 livepeer[2892108]: I0212 13:35:07.672984 2892108 block_watcher.go:567] Polling blocks from=60368932 to=60368949
Feb 12 13:35:09 us1 livepeer[2892108]: I0212 13:35:09.224000 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=4f2bd5c0
Feb 12 13:35:12 us1 livepeer[2892108]: I0212 13:35:12.695817 2892108 block_watcher.go:567] Polling blocks from=60368953 to=60368965
Feb 12 13:35:17 us1 livepeer[2892108]: I0212 13:35:17.686753 2892108 block_watcher.go:567] Polling blocks from=60368969 to=60368985
Feb 12 13:35:19 us1 livepeer[2892108]: I0212 13:35:19.900135 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=4895375e
Feb 12 13:35:22 us1 livepeer[2892108]: I0212 13:35:22.693885 2892108 block_watcher.go:567] Polling blocks from=60368987 to=60369005
Feb 12 13:35:27 us1 livepeer[2892108]: I0212 13:35:27.476130 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=76c96a1a
Feb 12 13:35:27 us1 livepeer[2892108]: I0212 13:35:27.500393 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=1fa280b5
Feb 12 13:35:27 us1 livepeer[2892108]: I0212 13:35:27.676542 2892108 block_watcher.go:567] Polling blocks from=60369007 to=60369025
Feb 12 13:35:32 us1 livepeer[2892108]: I0212 13:35:32.685359 2892108 block_watcher.go:567] Polling blocks from=60369027 to=60369045
Feb 12 13:35:37 us1 livepeer[2892108]: I0212 13:35:37.690485 2892108 block_watcher.go:567] Polling blocks from=60369047 to=60369057
Feb 12 13:35:42 us1 livepeer[2892108]: I0212 13:35:42.685420 2892108 block_watcher.go:567] Polling blocks from=60369059 to=60369072
Feb 12 13:35:47 us1 livepeer[2892108]: I0212 13:35:47.681168 2892108 block_watcher.go:567] Polling blocks from=60369076 to=60369091
Feb 12 13:35:52 us1 livepeer[2892108]: I0212 13:35:52.637093 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=ef104023
Feb 12 13:35:52 us1 livepeer[2892108]: I0212 13:35:52.693933 2892108 block_watcher.go:567] Polling blocks from=60369095 to=60369109
Feb 12 13:35:57 us1 livepeer[2892108]: I0212 13:35:57.676075 2892108 block_watcher.go:567] Polling blocks from=60369113 to=60369126
Feb 12 13:36:02 us1 livepeer[2892108]: I0212 13:36:02.695545 2892108 block_watcher.go:567] Polling blocks from=60369129 to=60369144
Feb 12 13:36:05 us1 livepeer[2892108]: I0212 13:36:05.176197 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=e52a55a8
Feb 12 13:36:05 us1 livepeer[2892108]: I0212 13:36:05.557142 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=61e83daf
Feb 12 13:36:07 us1 livepeer[2892108]: I0212 13:36:07.672356 2892108 block_watcher.go:567] Polling blocks from=60369148 to=60369160
Feb 12 13:36:12 us1 livepeer[2892108]: I0212 13:36:12.685090 2892108 block_watcher.go:567] Polling blocks from=60369163 to=60369177
Feb 12 13:36:14 us1 livepeer[2892108]: I0212 13:36:14.441874 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=a5fd2ddd
Feb 12 13:36:16 us1 livepeer[2892108]: I0212 13:36:16.781026 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=64424e57
Feb 12 13:36:17 us1 livepeer[2892108]: I0212 13:36:17.671644 2892108 block_watcher.go:567] Polling blocks from=60369179 to=60369197
Feb 12 13:36:18 us1 livepeer[2892108]: I0212 13:36:18.446975 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=1edc09dd
Feb 12 13:36:22 us1 livepeer[2892108]: I0212 13:36:22.310390 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=e76fdca3
Feb 12 13:36:22 us1 livepeer[2892108]: I0212 13:36:22.694481 2892108 block_watcher.go:567] Polling blocks from=60369199 to=60369217
Feb 12 13:36:27 us1 livepeer[2892108]: I0212 13:36:27.677060 2892108 block_watcher.go:567] Polling blocks from=60369219 to=60369235
Feb 12 13:36:32 us1 livepeer[2892108]: I0212 13:36:32.692232 2892108 block_watcher.go:567] Polling blocks from=60369237 to=60369265
Feb 12 13:36:35 us1 livepeer[2892108]: I0212 13:36:35.078115 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=d7ea2ea4
Feb 12 13:36:37 us1 livepeer[2892108]: I0212 13:36:37.674182 2892108 block_watcher.go:567] Polling blocks from=60369270 to=60369281
Feb 12 13:36:42 us1 livepeer[2892108]: I0212 13:36:42.687453 2892108 block_watcher.go:567] Polling blocks from=60369284 to=60369298
Feb 12 13:36:47 us1 livepeer[2892108]: I0212 13:36:47.692350 2892108 block_watcher.go:567] Polling blocks from=60369302 to=60369314
Feb 12 13:36:52 us1 livepeer[2892108]: I0212 13:36:52.370509 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=97cb1e2c
Feb 12 13:36:52 us1 livepeer[2892108]: I0212 13:36:52.685983 2892108 block_watcher.go:567] Polling blocks from=60369318 to=60369332
Feb 12 13:36:57 us1 livepeer[2892108]: I0212 13:36:57.132763 2892108 orchestrator.go:997] Transcoding session ended by the Broadcaster for sessionID=1f0248dd
Feb 12 13:36:57 us1 livepeer[2892108]: I0212 13:36:57.669818 2892108 block_watcher.go:567] Polling blocks from=60369335 to=60369344
@github-actions github-actions bot added the status: triage this issue has not been evaluated yet label Feb 12, 2023
@leszko
Copy link
Contributor

leszko commented Feb 13, 2023

I think they are related to this PR: #2685, so it's just an additional debug log message.

Closing, feel free to reopen if this log causes any issues.

@leszko leszko closed this as completed Feb 13, 2023
@papabear99
Copy link
Contributor Author

I think they are related to this PR: #2685, so it's just an additional debug log message.

Closing, feel free to reopen if this log causes any issues.

What I don't understand is why is there a message stating that Transcoding session ended by the Broadcaster when there isn't a session to end? The original request was to have better error reporting that explained why a session ended.

Are these messages that a Broadcaster did not choose the O for the job during discovery and is therefore ending the session? If that's the case a better message would be Orchestrator not chosen during discovery to receive session by Broadcaster or something along those lines.

@leszko
Copy link
Contributor

leszko commented Feb 14, 2023

@mjh1 Any thoughts on that?

@mjh1
Copy link
Contributor

mjh1 commented Feb 23, 2023

Ah yep the logging change definitely isn't behaving as expected. I have a feeling I know what's happening, I have tried to reproduce locally with no luck though. I'll update when I know more.

@mjh1 mjh1 reopened this Feb 23, 2023
@mjh1 mjh1 self-assigned this Feb 23, 2023
@thomshutt thomshutt added area: broadcasting status: core contributors working on it in progress and removed status: triage this issue has not been evaluated yet labels Mar 7, 2023
@mjh1 mjh1 mentioned this issue Mar 23, 2023
Merged
5 tasks
@mjh1
Copy link
Contributor

mjh1 commented Mar 24, 2023

This should be fixed now, we tested on some live Orchestrators to verify it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mjh1 mjh1

Labels
area: broadcasting status: core contributors working on it in progress
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Only write session end log message if session exists livepeer/go-livepeer
4 participants
@thomshutt @leszko @mjh1 @papabear99