Policy always return false and custom script print do not log

By: Pek Templeton user 29 Mar 2017 at 11:12 a.m. CDT

12 Responses
Pek Templeton gravatar
Hello, I have an issue when I try to check an RPT validity by the AS(oxauth). When I had no script enabled the authorization was granted but when I enabled the default script which I got from the ldap from a linux install, I always get false from the authorization mechanism. And this even if I set the needed user to the policy param and even when I created another dummy script doing only "return True". So I absolutely don't understand why it doesn't work. Another issue is that I have no way of debug because it doesn't seem that any python exception is logged and contrary to the doc, the print inside a python script seems to not be set in any log file (neither in oxauth.log or oxauth_script.log). For information I use oxauth from commit 8994bf4dd1c8485ad72a3d4fda893e1dcc5bcbb6 (from 2017-03-06). I troubleshooted the authorization issue to the line doing the call to the authorize function and for information the "customScriptConfiguration" var does contain the enabled script. The scripts used are: ``` from org.xdi.model.custom.script.type.uma import AuthorizationPolicyType from org.xdi.util import StringHelper, ArrayHelper from java.util import Arrays, ArrayList, HashSet from org.xdi.oxauth.service.uma.authorization import AuthorizationContext import java class AuthorizationPolicy(AuthorizationPolicyType): def __init__(self, currentTimeMillis): self.currentTimeMillis = currentTimeMillis def init(self, configurationAttributes): print "UMA authorization policy. Initialization" self.clientsSet = self.prepareClientsSet(configurationAttributes) print "UMA authorization policy. Initialization. Count authorized clients: %s" % self.clientsSet.size() print "UMA authorization policy. Initialized successfully" return True def destroy(self, configurationAttributes): print "UMA authorization policy. Destroy" print "UMA authorization policy. Destroyed successfully" return True def getApiVersion(self): return 1 # Process policy rule # authorizationContext is org.xdi.oxauth.service.uma.authorization.AuthorizationContext # configurationAttributes is java.util.Map<String, SimpleCustomProperty> def authorize(self, authorizationContext, configurationAttributes): print "UMA Authorization policy. Attempting to authorize client" client_id = authorizationContext.getGrant().getClientId() print "UMA Authorization policy. Client: ", client_id if (self.clientsSet.contains(client_id)): print "UMA Authorization policy. Authorizing client" return True else: print "UMA Authorization policy. Client isn't authorized" return False print "UMA Authorization policy. Authorizing client" return True def prepareClientsSet(self, configurationAttributes): clientsSet = HashSet() if (not configurationAttributes.containsKey("allowed_clients")): return clientsSet allowedClientsList = configurationAttributes.get("allowed_clients").getValue2() if (StringHelper.isEmpty(allowedClientsList)): print "UMA authorization policy. Initialization. The property allowed_clients is empty" return clientsSet allowedClientsListArray = StringHelper.split(allowedClientsList, ",") if (ArrayHelper.isEmpty(allowedClientsListArray)): print "UMA authorization policy. Initialization. There aren't clients specified in allowed_clients property" return clientsSet # Convert to HashSet to quick search i = 0 count = len(allowedClientsListArray) while (i < count): client = allowedClientsListArray[i] clientsSet.add(client) i = i + 1 return clientsSet ``` And dummy ``` from org.xdi.model.custom.script.type.uma import AuthorizationPolicyType from org.xdi.util import StringHelper, ArrayHelper from java.util import Arrays, ArrayList, HashSet from org.xdi.oxauth.service.uma.authorization import AuthorizationContext import java class AuthorizationPolicy(AuthorizationPolicyType): def __init__(self, currentTimeMillis): self.currentTimeMillis = currentTimeMillis def init(self, configurationAttributes): print "UMA authorization policy. Initialization" print "UMA authorization policy. Initialization. Count authorized clients: %s" % self.clientsSet.size() print "UMA authorization policy. Initialized successfully" return True def destroy(self, configurationAttributes): print "UMA authorization policy. Destroy" print "UMA authorization policy. Destroyed successfully" return True def getApiVersion(self): return 1 # Process policy rule # authorizationContext is org.xdi.oxauth.service.uma.authorization.AuthorizationContext # configurationAttributes is java.util.Map<String, SimpleCustomProperty> def authorize(self, authorizationContext, configurationAttributes): return True ``` Thanks in advance, Pek Templeton
OS Version : N/A
closed

Answers

By Michael Schwartz Account Admin 29 Mar 2017 at 1:04 p.m. CDT

Copy
Michael Schwartz gravatar
Can you attach the `/opt/gluu/jetty/oxauth/logs/oxauth_script.log`

By Pek Templeton user 29 Mar 2017 at 2:23 p.m. CDT

Copy
Pek Templeton gravatar
Yes of course. Here it is. An endless list of nearly identical lines (didn't include all of them but its the same, the [whole on pastebin](https://pastebin.com/b0Vj60YR)) ``` 2017-03-29 18:00:57,096 TRACE [pool-2-thread-8] [org.xdi.service.custom.script.CustomScriptManager] (CustomScriptManager.java:113) - Last finished time '29/03/17 18:00' . . . 2017-03-29 18:13:26,975 TRACE [pool-2-thread-1] [org.xdi.service.custom.script.CustomScriptManager] (CustomScriptManager.java:113) - Last finished time '29/03/17 18:13' ``` Thanks for your attention. Pek

By Michael Schwartz Account Admin 29 Mar 2017 at 2:30 p.m. CDT

Copy
Michael Schwartz gravatar
I don't see any of the print statements, so it seems the script is never being called. Are you sure the scope associates the policy? And that the resource set registers the scope properly? I think we need more details about how you are configured to call the script...

By Pek Templeton user 29 Mar 2017 at 4:14 p.m. CDT

Copy
Pek Templeton gravatar
OK. Here are the ldap conf for resource, scope and policy. **Resource Set** ![Resouce Set](http://img4.hostingpics.net/pics/779563ressourceset.png "Resouce Set") **Scope** ![scope](http://img4.hostingpics.net/pics/884664scope.png "scope") **Policy** ![Policy](http://img4.hostingpics.net/pics/206838policy.png "Policy") And here is the content of customScript configuration just before execution. It shows that the script is found because the load and selection of enabled script is a step done before that moment. **customScriptConfiguration** ![customScriptConfiguration](http://img4.hostingpics.net/pics/198724customScriptConfig.png "customScriptConfiguration") And here is the content of configurationAttributes. I'm not sure of the content which it's supposed to have maybe it can help. ![configurationAttributes](http://img4.hostingpics.net/pics/904250configAttribute.png "configurationAttributes") Hope it will help. Pek PS: Not sure to know how the include picture works so I added links.

By Michael Schwartz Account Admin 29 Mar 2017 at 6:24 p.m. CDT

Copy
Michael Schwartz gravatar
Are you trying to obtain an UMA or GAT token?

By Pek Templeton user 30 Mar 2017 at 5:02 a.m. CDT

Copy
Pek Templeton gravatar
In that case I tried to obtain a UMA Token (which mean that the data shown are from a UMA token request). For info I tried to also use GAT token and the problem is the same, when the policy try to check authorization it always return "False". Moreover I found an issue with GAT verification policy and oxTrust Scope generation. I found out that oxAuth need the field "oxUrl" to find the scope in LDAP. But oxTrust doesn't generate it. Pek

By Yuriy Zabrovarnyy staff 30 Mar 2017 at 10:07 a.m. CDT

Copy
Yuriy Zabrovarnyy gravatar
Hi Pek, ### Logging It's weird that there are no logs printed. Do you see at least any logs in `oxauth.log` file, e.g. about oxauth starting or at least something? If yes, then lets try to workaround it, in `authorize()` method there is `AuthorizationContext` which extends `ExternalScriptContext`, so you can just take logger object via `authorizationContext.getLog()`. `https://github.com/GluuFederation/oxAuth/blob/master/Server/src/main/java/org/xdi/oxauth/service/external/context/ExternalScriptContext.java#L50-50 ` ### Scope identification It seems you are referring to this oxauth code `https://github.com/GluuFederation/oxAuth/blob/master/Server/src/main/java/org/xdi/oxauth/service/uma/ScopeService.java#L123-123` This method handles two type of scopes: - internal (those hosted by AS) - filtered by `oxType` - external (those hosted somewhere else and we keep only reference to them) - filtered by `oxUrl`. Via oxTrust it's allowed to add scopes which are automatically hosted by AS (hence considered as internal), therefore oxTrust does not set `oxUrl`. In case you are interested, external scopes are added automatically (if auto addition is enabled) during resource_set registration and therefore populated by oxauth (AS). I hope it helps, let us know whether you was able to make logging work. Thanks, Yuriy

By Pek Templeton user 03 Apr 2017 at 9:57 a.m. CDT

Copy
Pek Templeton gravatar
Hi Yuriy, Sorry for taking so much time to respond but I was quite busy and also took some time to verify some things about what you said and what I saw. So first about scope identification and permission process. >This method handles two type of scopes: > - internal (those hosted by AS) - filtered by oxType > - external (those hosted somewhere else and we keep only reference to them) - filtered by oxUrl. I already knew about the concept of internal and external scope and thanks to pointing on the ``` ScopeService ``` class, I discovered a lot of things concerning the ``` ResourceSetPermission ``` and indeed the whole process of ticket and RPT generation uses the function which you cited which disciminate the type of scopes and works fine. But my point was about an authorization process with a GAT type token (in this case not in the rest of the posts) which uses the folowing function ``` https://github.com/GluuFederation/oxAuth/blob/master/Server/src/main/java/org/xdi/oxauth/service/uma/authorization/AuthorizationService.java#L54 - allowToAddPermissionForGat ``` which call ``` https://github.com/GluuFederation/oxAuth/blob/master/Server/src/main/java/org/xdi/oxauth/service/uma/ScopeService.java#L189 - getScopesByUrls ``` which uses scope search by _oxUrl_ only. It means that if you did'nt set **oxUrl ** or used an **external** scope which **has oxUrl and is present in local LDAP**, yout can't use GAT. That's it for the clarification about that part. The more problematic part is about the policy problem. To respond to your question > Do you see at least any logs in oxauth.log file, e.g. about oxauth starting or at least something? Yes I do, I think I have a complete log, up to _TRACE_ level. So I tried your solution > in authorize() method there is AuthorizationContext which extends ExternalScriptContext, so you can just take logger object via authorizationContext.getLog() But it absolutely did nothing (for info I did the following : _authorizationContext.getLog().debug("azerty")_) in neither _oauth.log_ or _oauth-script.log_. So whats your next advice or idea? Thanks, Pek PS: I just saw that it did not use my python script but instead this class ``` https://github.com/GluuFederation/oxCore/blob/master/oxService/src/main/java/org/xdi/model/custom/script/type/uma/DummyAuthorizationPolicyType.java ```(I'm sure of it because I set return to "True" and it worked). And I don't know why...

By Pek Templeton user 03 Apr 2017 at 11:48 a.m. CDT

Copy
Pek Templeton gravatar
I believe I might have found the area of error and it is probably related to an ENV variable issue, I'll work deeper on it. Taking you informed of further development (probably not before tomorrow). Pek

By Yuriy Zabrovarnyy staff 03 Apr 2017 at 5:29 p.m. CDT

Copy
Yuriy Zabrovarnyy gravatar
Pek, Thanks for catching this, I fixed oxTrust, now on UMA scope creation or modification `oxUrl` is always set: `https://github.com/GluuFederation/oxTrust/commit/85eb839c53a0bbbb338d73635079bd20cb8e8a76` If in general logs appear in `oxauth.log` then it should also appear in case of `authorizationContext.getLog().debug("azerty")`. Lets us know about your progress with logging. Thanks, Yuriy

By Pek Templeton user 04 Apr 2017 at 6:33 a.m. CDT

Copy
Pek Templeton gravatar
Thanks for the update. So concerning the script issue, the problem was indeed that I did not set the ``` PYTHON_HOME ``` environment variable. After setting it at the **Jython** install folder, the custom authorization policy script executed normally and the print were logged in **oxauth_script.log**. Also, the ``` authorizationContext.getLog().debug("azerty") ``` successfully logged into **oxauth.log**. To better identify the issue I think it might be interesting to modify the log trace at ``` https://github.com/GluuFederation/oxCore/blob/master/oxService/src/main/java/org/xdi/service/custom/script/CustomScriptManager.java#L329 ``` which give ``` 2017-04-04 11:47:12,501 DEBUG [pool-2-thread-1] [org.xdi.service.custom.script.CustomScriptManager] (CustomScriptManager.java:329) - Using default external type class ``` into **oxauth_script.log** to a more explicit message for example : **_Using default external type class due to a problem during CustomScript initialization_** . You could also set a log into ``` https://github.com/GluuFederation/oxCore/blob/master/oxService/src/main/java/org/xdi/model/custom/script/type/uma/DummyAuthorizationPolicyType.java ``` to make clear that it is used with for example a message such as **_Dummy authorization_** in **authorize()**. Furthermore it might be interesting to update the doc, here for example [https://gluu.org/docs/ce/3.0.1/developer-guide/oxtrust-eclipse/#jython](https://gluu.org/docs/ce/3.0.1/developer-guide/oxtrust-eclipse/#jython) and add as its scpecified for java that it is necessary to set the ``` PYTHON_HOME ```. In order to avoid such issue to everyone. I'll close the ticket because my problem is solved. Tanks for your time and have a good day. Pek

By Yuriy Zabrovarnyy staff 04 Apr 2017 at 8:13 a.m. CDT

Copy
Yuriy Zabrovarnyy gravatar
Pek, Glad to hear problem is solved. Agreed, we will definitely update doc to make it clear and avoid same issue for others. Thanks for your feedback! BR, Yuriy

Post an answer