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.

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

Auth timeout streaming to a specific channel #124

Open
clone1018 opened this issue Apr 19, 2021 · 1 comment
Open

Auth timeout streaming to a specific channel #124

clone1018 opened this issue Apr 19, 2021 · 1 comment
Labels
bug Something isn't working

Comments

@clone1018
Copy link
Member

Hi there, looks like we're experiencing an issue when trying to stream to the /Glimesh channel. We experienced the problem today when mitori tried to start the Glimesh University event, he attempted to start the stream in OBS and after a couple of seconds got an error message. I checked the logs and it looks like the auth sequence is timing out.

The last time we streamed to the channel successfully was last Monday. I also restarted Janus on the ingest to try and clear out any bad state. The issue persisted.

I can see the channel's LIVE tag pop-up after OBS attempts to connect, however it leaves the Glimesh.tv DB in a bad state because it does not send a endStream notice.

There is a potential this was introduced on the Glimesh.tv side, but we have not heard of any specific issues with other users yet.

[...] mitori trying to stream to /Glimesh [...]

[2021-04-19 21:12:01.908] [info] New FTL control connection is pending from <MITORI_IP>
[2021-04-19 21:12:02.146] [info] <MITORI_IP> authenticated as Channel 2752 successfully.
[2021-04-19 21:12:02.165] [warning] Received unrecognized attribute from client: ProtocolVersion: 0.9
[2021-04-19 21:12:06.921] [info] <MITORI_IP> didn't authenticate within 5000ms, closing
[2021-04-19 21:12:07.232] [warning] Glimesh service connection HTTP request failed with error 4
[2021-04-19 21:12:07.232] [warning] Attempt 1 / 10: Glimesh GraphQL query failed. Retrying in 3000 ms...
[2021-04-19 21:12:15.288] [warning] Glimesh service connection HTTP request failed with error 4
[2021-04-19 21:12:15.288] [warning] Attempt 2 / 10: Glimesh GraphQL query failed. Retrying in 3000 ms...
[2021-04-19 21:12:23.348] [warning] Glimesh service connection HTTP request failed with error 4
[2021-04-19 21:12:23.348] [warning] Attempt 3 / 10: Glimesh GraphQL query failed. Retrying in 3000 ms...
[2021-04-19 21:12:31.400] [warning] Glimesh service connection HTTP request failed with error 4
[2021-04-19 21:12:31.400] [warning] Attempt 4 / 10: Glimesh GraphQL query failed. Retrying in 3000 ms...

[...] clone1018 trying to reproduce the issue to /Glimesh [...]

[2021-04-19 21:12:33.056] [info] New FTL control connection is pending from <CLONE_IP>
[2021-04-19 21:12:33.381] [info] <CLONE_IP> authenticated as Channel 2752 successfully.
[2021-04-19 21:12:33.481] [warning] Received unrecognized attribute from client: ProtocolVersion: 0.9
[2021-04-19 21:12:38.086] [info] <CLONE_IP> didn't authenticate within 5000ms, closing
[2021-04-19 21:12:39.466] [warning] Glimesh service connection HTTP request failed with error 4
[2021-04-19 21:12:39.466] [warning] Attempt 5 / 10: Glimesh GraphQL query failed. Retrying in 3000 ms...
[2021-04-19 21:12:47.389] [info] Publishing channel 2752 / stream 78973 to Orchestrator...
[2021-04-19 21:12:47.389] [info] Registered new stream: Channel 2752 / Stream 78973.
[2021-04-19 21:12:47.389] [info] Channel 2752 / Stream 78973 control connection was removed before a media port could be assigned.
[2021-04-19 21:12:52.343] [info] Existing Stream 78973 exists for Channel 2752 - stopping...
[2021-04-19 21:12:52.343] [info] Unpublishing channel 2752 / stream 78973 from Orchestrator
[2021-04-19 21:12:52.343] [info] Stream ended. Channel 2752 / stream 78973
[2021-04-19 21:12:52.343] [warning] FtlServer::eventStopStream couldn't find stream to remove.
[2021-04-19 21:12:52.565] [info] Publishing channel 2752 / stream 78974 to Orchestrator...
[2021-04-19 21:12:52.565] [info] Registered new stream: Channel 2752 / Stream 78974.
[2021-04-19 21:12:52.565] [error] Stream ended from channel 2752 had unexpected stream id 78973, expected 78974
[2021-04-19 21:12:52.565] [info] Channel 2752 / Stream 78974 control connection was removed before a media port could be assigned.
[2021-04-19 21:12:52.565] [info] Unpublishing channel 2752 / stream 78974 from Orchestrator
[2021-04-19 21:12:52.565] [info] Stream ended. Channel 2752 / stream 78974
[2021-04-19 21:12:52.778] [info] Start Stream Relay request from Orchestrator: Channel 2752, Stream 78973, Target do-nyc3-edge6.kjfk.live.glimesh.tv
[2021-04-19 21:12:52.778] [error] Orchestrator requested a relay for channel that is not streaming.Target hostname: do-nyc3-edge6.kjfk.live.glimesh.tv, Channel ID: 2752

[...] clone1018 trying again [...]

[2021-04-19 21:13:32.675] [info] New FTL control connection is pending from <CLONE_IP>
[2021-04-19 21:13:32.940] [info] <CLONE_IP> authenticated as Channel 2752 successfully.
[2021-04-19 21:13:33.044] [warning] Received unrecognized attribute from client: ProtocolVersion: 0.9
[2021-04-19 21:13:37.693] [info] <CLONE_IP> didn't authenticate within 5000ms, closing
[2021-04-19 21:13:38.213] [info] Publishing channel 2752 / stream 78977 to Orchestrator...
[2021-04-19 21:13:38.214] [info] Registered new stream: Channel 2752 / Stream 78977.
[2021-04-19 21:13:38.214] [info] Channel 2752 / Stream 78977 control connection was removed before a media port could be assigned.
[2021-04-19 21:13:38.214] [info] Unpublishing channel 2752 / stream 78977 from Orchestrator
[2021-04-19 21:13:38.214] [info] Stream ended. Channel 2752 / stream 78977
[2021-04-19 21:13:38.436] [info] Start Stream Relay request from Orchestrator: Channel 2752, Stream 78977, Target do-nyc3-edge6.kjfk.live.glimesh.tv
[2021-04-19 21:13:38.436] [error] Orchestrator requested a relay for channel that is not streaming.Target hostname: do-nyc3-edge6.kjfk.live.glimesh.tv, Channel ID: 2752
@haydenmc
Copy link
Member

Per offline discussion, the current theory is that the startStream query is taking longer than 5000ms to return, causing the connection to time out before the FTL handshake is completed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants