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

Deadlock in API authentication #976

Closed
1 task done
dermotduffy opened this issue Aug 19, 2020 · 3 comments · Fixed by #1036
Closed
1 task done

Deadlock in API authentication #976

dermotduffy opened this issue Aug 19, 2020 · 3 comments · Fixed by #1036
Labels
Bug

Comments

@dermotduffy
Copy link
Contributor

dermotduffy commented Aug 19, 2020 •
edited
Loading

  • I confirm that this is an issue rather than a question.

Bug report

  • Authenticating with a token in the API appears to deadlock the server, and the webinterfaces becomes non-responsive.

Steps to reproduce

  • Enable API authentication in the UI.
  • Create a token in the UI.
  • Run this, fill in the real token.
echo '{"command": "authorize", "subcommand": "login", "token": "<TOKEN>"}' | nc  hyperion 19444

What is expected?

The login should succeed.

What is actually happening?

Server returns no response, and hangs. Logs:

Aug 18 20:49:37 pi-kitchen hyperiond[5765]: 2020-08-18T20:49:37.457 hyperiond JSONSERVER   : <DEBUG> JsonServer.cpp:103:newConnection() | New connection from: ::ffff:10.100.0.44
Aug 18 20:49:37 pi-kitchen hyperiond[5765]: 2020-08-18T20:49:37.464 hyperiond JSONCLIENTCO : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.0.20' switch to Hyperion instance 0
Aug 18 20:49:37 pi-kitchen hyperiond[5765]: QMetaMethod::invoke: Dead lock detected in BlockingQueuedConnection: Receiver is AuthManager(0x985d40)
Aug 18 20:49:42 pi-kitchen hyperiond[5765]: 2020-08-18T20:49:42.447 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:238:setInputImage() | Priority 250 is now inactive
Aug 18 20:49:42 pi-kitchen hyperiond[5765]: 2020-08-18T20:49:42.455 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:333:setCurrentTime() | Set visible priority to 254

Another example:

Aug 18 20:29:06 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:06.818 hyperiond WEBSERVER    : <INFO> Started on port 8092 name 'Hyperion Webserver'
Aug 18 20:29:06 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:06.990 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:198:setInput() | Priority 254 is now active
Aug 18 20:29:07 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:07.006 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:238:setInputImage() | Priority 0 is now active
Aug 18 20:29:09 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:09.197 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:298:setCurrentTime() | Timeout clear for priority 0
Aug 18 20:29:09 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:09.447 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:333:setCurrentTime() | Set visible priority to 250
Aug 18 20:29:13 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:13.209 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:30:WebSocketClient() | New connection from ::ffff:10.100.0.21
Aug 18 20:29:13 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:13.223 hyperiond WEBSOCKET    : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.0.21' switch to Hyperion instance 0
Aug 18 20:29:13 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:13.638 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:30:WebSocketClient() | New connection from ::ffff:10.100.0.21
Aug 18 20:29:13 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:13.655 hyperiond WEBSOCKET    : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.0.21' switch to Hyperion instance 0
Aug 18 20:29:13 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:13.776 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:30:WebSocketClient() | New connection from ::ffff:10.100.0.21
Aug 18 20:29:13 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:13.779 hyperiond WEBSOCKET    : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.0.21' switch to Hyperion instance 0
Aug 18 20:29:19 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:19.682 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:30:WebSocketClient() | New connection from ::ffff:10.100.1.235
Aug 18 20:29:19 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:19.699 hyperiond WEBSOCKET    : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.1.235' switch to Hyperion instance 0
Aug 18 20:29:33 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:33.538 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:204:sendClose() | send close: 1000
Aug 18 20:29:34 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:34.812 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:30:WebSocketClient() | New connection from ::ffff:10.100.1.235
Aug 18 20:29:34 pi-kitchen hyperiond[5585]: 2020-08-18T20:29:34.833 hyperiond WEBSOCKET    : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.1.235' switch to Hyperion instance 0
Aug 18 20:32:09 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:09.747 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:204:sendClose() | send close: 1000
Aug 18 20:32:10 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:10.962 hyperiond WEBSOCKET    : <DEBUG> WebSocketClient.cpp:30:WebSocketClient() | New connection from ::ffff:10.100.1.235
Aug 18 20:32:10 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:10.976 hyperiond WEBSOCKET    : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.1.235' switch to Hyperion instance 0
Aug 18 20:32:21 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:21.841 hyperiond JSONSERVER   : <DEBUG> JsonServer.cpp:103:newConnection() | New connection from: ::ffff:10.100.0.44
Aug 18 20:32:21 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:21.846 hyperiond JSONCLIENTCO : <DEBUG> JsonAPI.cpp:107:handleInstanceSwitch() | Client '::ffff:10.100.0.20' switch to Hyperion instance 0
Aug 18 20:32:22 pi-kitchen hyperiond[5585]: QMetaMethod::invoke: Dead lock detected in BlockingQueuedConnection: Receiver is AuthManager(0xcf4d20)
Aug 18 20:32:27 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:27.447 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:238:setInputImage() | Priority 250 is now inactive
Aug 18 20:32:27 pi-kitchen hyperiond[5585]: 2020-08-18T20:32:27.452 hyperiond HYPERION     : <DEBUG> PriorityMuxer.cpp:333:setCurrentTime() | Set visible priority to 254

System

Hyperion Server: 
- Build:       master (GitHub-f719f0b/838092e-1597257777)
- Build time:  Aug 16 2020 17:10:43
- Git Remote:  https://github.com/hyperion-project/hyperion.ng.git
- Version:     2.0.0-alpha.7
- UI Lang:     auto (BrowserLang: en-US)
- UI Access:   default
- Avail Capt:  dispmanx,v4l2,framebuffer,qt

Hyperion Server OS: 
- Distribution: Raspbian GNU/Linux 10 (buster)
- Arch:         arm
- Kernel:       linux (5.4.51+ (WS: 32))
- Browser:      Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/53
@m-seker
Copy link
Contributor

m-seker commented Aug 19, 2020 •
edited
Loading

This is the line causing deadlock :

hyperion.ng/libsrc/api/API.cpp

Line 469 in c00d8e6

QMetaObject::invokeMethod(_authManager, "isTokenAuthorized", Qt::BlockingQueuedConnection, Q_RETURN_ARG(bool, res), Q_ARG(QString, token));

JsonAPI is instantiated in multiple places.

hyperion.ng/libsrc/webserver/WebJsonRpc.cpp

Line 16 in c00d8e6

_jsonAPI = new JsonAPI(client, _log, localConnection, this, true);

hyperion.ng/libsrc/webserver/WebSocketClient.cpp

Line 26 in c00d8e6

_jsonAPI = new JsonAPI(client, _log, localConnection, this);

hyperion.ng/libsrc/jsonserver/JsonClientConnection.cpp

Line 18 in c00d8e6

_jsonAPI = new JsonAPI(socket->peerAddress().toString(), _log, localConnection, this);

WebJsonRpc and WebSocketClient lives in WebServer thread.
JsonClientConnection lives in main thread.
AuthManager lives in main thread.

If AuthManager::isTokenAuthorized(blocking invoke method) is called from a thread other than main thread(WebJsonRpc, WebSocketClient ) it works OK. If it is called from main thread(JsonClientConnection) it causes deadlock (because we are doing a blocking invoke method to the same thread).

Simple fix is comparing the thread IDs and doing ````invokeMethod``` or a direct call based on thread IDs but this is not the best solution. We can do better than this :)

Paulchen-Panther added a commit to Paulchen-Panther/hyperion.ng that referenced this issue Oct 8, 2020
@Paulchen-Panther
Fix issue hyperion-project#976
f2bd314
@Paulchen-Panther
Copy link
Member

@dermotduffy @m-seker
I have included the provisional fix in my PR #1036 .
If you want you can test it.

@Paulchen-Panther Paulchen-Panther mentioned this issue Oct 8, 2020
Merged
14 tasks
@Paulchen-Panther Paulchen-Panther linked a pull request Oct 8, 2020 that will close this issue
Fix issues #1022, #1019, #997, #993, #992, #976, #969, #964, #980 #1036
Merged
14 tasks
@dermotduffy
Copy link
Contributor Author

@Paulchen-Panther Verified fixed! Thank you!

Paulchen-Panther added a commit that referenced this issue Oct 18, 2020
@Paulchen-Panther
Fix issues #1022, #1019, #997, #993, #992, #976, #969, #964, #980 (#1036
aa465c0 
)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix issues #1022, #1019, #997, #993, #992, #976, #969, #964, #980 Paulchen-Panther/hyperion.ng
3 participants
@dermotduffy @m-seker @Paulchen-Panther