Intermittent "Unauthorized Request" from the console REST API

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Intermittent "Unauthorized Request" from the console REST API

sodul
With the 5.2.0 console (and older versions) I've noticed a relatively high rate (10-25%) of "Unauthorized Request" errors from the console-cli. I doubt the problem is with the console-cli or that this is a network connectivity issue since we do get a response.

I have not configured ldap yet on this console so the user auth the straight default one, with the console behind an nginx http server.


This is the output from the console-cli side:
00:00:05.133 2013-09-03 23:54:13,335: QaStable.json loaded successfuly
00:00:05.134 2013-09-03 23:54:13,336: > ../console-cli/bin/console-cli.py -u jenkins -x ******** -c http://glucorp -f QaStable -p --all deploy
00:00:05.343 2013-09-03 23:54:13,546 [INFO] - gluconsole.rest.Client - executing plan: plan/2239610d-14b1-4c2b-a49b-444d32c91bf6/execution
00:00:05.401 2013-09-03 23:54:13,604 [INFO] - gluconsole.rest.Client - status url = plan/2239610d-14b1-4c2b-a49b-444d32c91bf6/execution/349
00:00:05.421 2013-09-03 23:54:13,624 [INFO] - gluconsole.rest.Client - InProgress: 0% complete
00:00:07.445 2013-09-03 23:54:15,647 [INFO] - gluconsole.rest.Client - InProgress: 3% complete
00:00:09.468 2013-09-03 23:54:17,670 [INFO] - gluconsole.rest.Client - InProgress: 15% complete
00:00:11.491 2013-09-03 23:54:19,694 [INFO] - gluconsole.rest.Client - InProgress: 15% complete
00:00:13.514 2013-09-03 23:54:21,717 [INFO] - gluconsole.rest.Client - InProgress: 21% complete
00:00:15.530 Traceback (most recent call last):
00:00:15.531   File "../console-cli/bin/console-cli.py", line 283, in <module>
00:00:15.532     sys.exit(main())
00:00:15.532   File "../console-cli/bin/console-cli.py", line 256, in main
00:00:15.533     action, system_filter, options.parallel, options.dryrun)
00:00:15.534   File "/shn/builder/workspace/deploy-stable-to-QaStable/console-cli/lib/python/gluconsole/rest.py", line 257, in execute_plan
00:00:15.535     return self._execute_plan(plan, dryrun)
00:00:15.535   File "/shn/builder/workspace/deploy-stable-to-QaStable/console-cli/lib/python/gluconsole/rest.py", line 203, in _execute_plan
00:00:15.536     progress_status = self._do_request(status_url, 'HEAD')
00:00:15.537   File "/shn/builder/workspace/deploy-stable-to-QaStable/console-cli/lib/python/gluconsole/rest.py", line 86, in _do_request
00:00:15.538     raise restkit.errors.Unauthorized('Unauthorized Request')
00:00:15.538 restkit.errors.Unauthorized: Unauthorized Request
00:00:15.546 Traceback (most recent call last):
00:00:15.546   File "./glu_model.py", line 588, in <module>
00:00:15.547     sys.exit(main(sys.argv))
00:00:15.548   File "./glu_model.py", line 574, in main
00:00:15.549     model.deploy()
00:00:15.550   File "./glu_model.py", line 388, in deploy
00:00:15.551     self.console_cli.deploy()
00:00:15.552   File "./glu_model.py", line 432, in deploy
00:00:15.553     exit_code, self.console_host))
00:00:15.554 __main__.Error: console-cli returned 1 when deploying from http://glucorp
00:00:15.579 Build step 'Execute shell' marked build as failure

And this is the jetty log:
2013/09/03 15:27:35.266 INFO [DeploymentServiceImpl] Auto-archived 1 deployments
2013/09/03 16:05:37.770 INFO [AbstractValidatingSessionManager] Validating all active sessions...
2013/09/03 16:05:37.770 INFO [AbstractValidatingSessionManager] Finished session validation.  No sessions were stopped.
2013/09/03 16:54:23.729 ERROR [JDBCExceptionReporter] The last packet successfully received from the server was 41,259,071 milliseconds ago.  The last packet sent successfully to the server was 41,259,072 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
2013/09/03 16:54:23.729 INFO [realm] Unable to authenticate with org.linkedin.glu.console.realms.ShiroLdapRealm - could not execute query; nested exception is org.hibernate.exception.JDBCConnectionException: could not execute query
2013/09/03 16:54:23.730 WARN [AuthFilters] Authorization failure: Authentication failed for token submission [org.apache.shiro.authc.UsernamePasswordToken - jenkins, rememberMe=false].  Possible unexpected error? (Typical or expected login exceptions should extend from AuthenticationException).
2013/09/03 16:54:23.731 ERROR [JDBCExceptionReporter] Already closed.
2013/09/03 16:54:23.731 ERROR [JDBCExceptionReporter] Already closed.
2013/09/03 16:59:35.265 INFO [DeploymentServiceImpl] Auto-archived 1 deployments
2013/09/03 17:01:35.265 INFO [DeploymentServiceImpl] Auto-archived 1 deployments

From what I read in the log it seems the jetty connection to mysql timed out and it makes the user check call fail. I guess I need to tune something in the DB connection settings, but I think the console should try to reconnect internally if the DB connection timed out and raise the issue to the client side only after 3 retries.
Reply | Threaded
Open this post in threaded view
|

Re: Intermittent "Unauthorized Request" from the console REST API

frenchyan
Administrator
It is unclear why this is happening. Could it be that the database needs an index for users? Do you have a lot of users?

In regards to the retry 3 times... are you talking about retrying 3 times for everything or just logging? I am afraid this would mask some other issues (with the database itself) and would rather determine what is wrong with the database before implementing this kind of strategy in glu.

Yan
Reply | Threaded
Open this post in threaded view
|

Re: Intermittent "Unauthorized Request" from the console REST API

sodul
We have 21 users. The errors says to use 'autoReconnect=true', should we do that?

The DB is on the same machine as the console, as well as some other processes. With 4 cores and 16GB of RAM on bare metal (not a VM) I doubt we have I/O congestion.
Reply | Threaded
Open this post in threaded view
|

Re: Intermittent "Unauthorized Request" from the console REST API

frenchyan
Administrator
21 users should definitely not require any index (even a full table scan should not timeout...)

Which database are you using?

Have you tried to correlate with the GC? Check the gc.log file to see if there is some heavy gc happening when you get this issue.

Yan


On Wed, Sep 4, 2013 at 12:02 PM, sodul [via glu] <[hidden email]> wrote:
We have 21 users. The errors says to use 'autoReconnect=true', should we do that?

The DB is on the same machine as the console, as well as some other processes. With 4 cores and 16GB of RAM on bare metal (not a VM) I doubt we have I/O congestion.


If you reply to this email, your message will be added to the discussion below:
http://glu.977617.n3.nabble.com/Intermittent-Unauthorized-Request-from-the-console-REST-API-tp4026048p4026050.html
To start a new topic under glu, email [hidden email]
To unsubscribe from glu, click here.
NAML

Reply | Threaded
Open this post in threaded view
|

Re: Intermittent "Unauthorized Request" from the console REST API

sodul
For the DB we use mysql server 5.1.67 on CentOS 6.3.
I will probably move the console to a dedicated Ubuntu 12.04 LTS VM which provides mysql server 5.5.32. Considering the current high rate of the issue, if I don't see it for a couple of days after the migration that would mean the problem is resolved. I'll keep you informed.
Reply | Threaded
Open this post in threaded view
|

Re: Intermittent "Unauthorized Request" from the console REST API

sodul
To follow up on this. I think it was related to this issue:
http://glu.977617.n3.nabble.com/MySql-timeout-issue-td3953965.html

I applied the recommended changes and it seem to do the trick so far.