Open kgk-bytes opened 5 years ago
That seems to be a local connectivity issue with an outgoing proxy:
2019-03-05 07:08:54,383 urllib3.connectionpool:DEBUG Starting new HTTP connection (1): www-proxy-hqdc.us.oracle.com:80
2019-03-05 07:08:54,427 urllib3.connectionpool:DEBUG http://www-proxy-hqdc.us.oracle.com:80 "GET http://slc12ldo.us.oracle.com:7777/oauth2/rest/security HTTP/1.1" 502 2798
Thank you for your response "zandbelt" In the same tool (which is few months old), we are not seeing any issue running behind the proxy. Please see the logs below,
2019-03-12 03:21:55,062 oidctest.optt:INFO ent:10.191.44.222, vpath: ['OP-Response-code']
2019-03-12 03:21:55,064 oic.utils.keyio:DEBUG loading keys for issuer: http://slc12ldo.us.oracle.com:7777/oauth2
2019-03-12 03:21:55,064 oic.utils.keyio:DEBUG pcr: {'id_token_signing_alg_values_supported': ['RS256'], 'token_endpoint_auth_methods_supported': ['client_secret_basic', 'client_secret_jwt'], 'response_types_supported': ['code', 'token', 'id_token', 'token id_token'], 'subject_types_supported': ['public'], 'jwks_uri': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/security', 'authorization_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/authorize', 'ui_locales_supported': ['en'], 'token_endpoint_auth_signing_alg_values_supported': ['RS256'], 'claims_supported': ['aud', 'exp', 'iat', 'iss', 'jti', 'sub'], 'userinfo_signing_alg_values_supported': ['none'], 'userinfo_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/userinfo', 'grant_types_supported': ['password', 'client_credentials', 'urn:ietf:params:oauth:grant-type:jwt-bearer', 'authorization_code', 'refresh_token', 'implicit'], 'scopes_supported': ['openid', 'profile', 'email', 'address', 'phone'], 'end_session_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/userlogout', 'issuer': 'http://slc12ldo.us.oracle.com:7777/oauth2', 'token_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/token'}
2019-03-12 03:21:55,064 oidctest.session:INFO session_setup
2019-03-12 03:21:55,065 otest.aus.tool:INFO <=<=<=<=< OP-Response-code >=>=>=>=>
2019-03-12 03:21:55,065 otest.aus.tool:INFO <--<-- 0 --- Webfinger -->-->
2019-03-12 03:21:55,065 otest.aus.tool:INFO <--<-- 1 --- Discovery -->-->
2019-03-12 03:21:55,065 otest.aus.tool:INFO <--<-- 2 --- Registration -->-->
2019-03-12 03:21:55,065 otest.aus.tool:INFO <--<-- 3 --- AsyncAuthn -->-->
2019-03-12 03:21:55,067 cherrypy.access.140141143240152:INFO 10.191.44.222 - - [12/Mar/2019:03:21:55] "GET /OP-Response-code HTTP/1.1" 303 496 "https://op_test:60001/" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.121 Safari/537.36"
2019-03-12 03:22:01,132 otest.aus.tool:INFO <--<-- 3 --- <class 'oidctest.op.oper.AsyncAuthn'>
2019-03-12 03:22:01,132 otest.aus.request:INFO Response: {'code': 'ZGRtWGtOeVU2QU9FSzB1WmRjcDZXZz09fnB4bGlYZkpKZDYvOHV3WEdDOUE1b2QvNFA1bDBrMG1xdDRqSFdaQTBvYzF4WlBnWWp6N25Gei9XUVNGSGl5d01lK3dHaFRrNDFTU1ZPQzBUdTAvSU11RmFyVlk5L2dNU1c4R3FKRExpNGpIdTZZMHlJeUtWanIxOGxLMkhVRmF2Mk81SUpLZjAwTm1ObXpMK09iL0o4a01WeURhYlNjc2xEUkpaYi9sTFBiODdIeWNaeW4zaXJUN2VVVEYvc0M2dWJLVVFpbDAwSmdORk4xNmw5dmJIQ3A0RjRTSkdXY3Z4WCtrS3ZaNkk3bjZWdE9YMHdmRWd4STVFdlZsNlhZRWoycWN3QWVuNlNxeWpZdDdwdXFNQ0loNmxXVHJzY3dHSW9YQ0d6eTJ3YmdXVmZMeFVZelpya2F5YUMzSnJFV2psaGhaWloxa0dBNWxIVkd5SmdYc3VsOEVjY2EwcFBaV3gwTEpiUzVIMzY5TkRsMlZlRW9IWHJHRldKdjlxZDhrZFlOTGZBQURDSTlwL2s3L1Y5ZDlCRHArckFnaWt5Zmovd0QwWllha2R1M09pTEUySkttRGFqUFA2SS84ZmdzTEUxT3N4T0JlS3V6NWFpblhtbmplTTQ5Z2owNGVZeTEvSDBBQTVSOWNrK1gvVmNjWDNoRDN5MjZPUmVmbGlPTFB3dEwxSFR4QUJqNDJDekJSYjVjbVJHOHNhS2JueXk5aGUxc3U0TjlDRzVpdGVuQndMTzB6ZjErNDF5dEZodXFyVEhzTTVqVmpEeXNQZ2xKUG5wOUN1QlE9PQ==', 'state': 'tT8W8anfeouNmnRS'}
2019-03-12 03:22:01,133 oic.oauth2:DEBUG Initial response parsing => "{'code': '
I'm sorry but the difference is in your environment(s): the http://www-proxy-hqdc.us.oracle.com:80
outgoing proxy is obvious from the newer instance and is not something made up by the test suite... You should try and find the differences between the two instances (machines, OSes, configs, IP addresses etc).
I am able to setup the OIDC test tool using the latest image from github successfully.
Now, when i execute response=id_token testcases,am seeing the below exception (OP-Response-id_token) - Request with response_type=id_token
The following takes place,
Exception see
2019-03-05 07:08:38,175 oidctest.optt:INFO ent:10.240.229.247, vpath: ['OP-Response-id_token'] 2019-03-05 07:08:38,177 oic.utils.keyio:DEBUG loading keys for issuer: http://slc12ldo.us.oracle.com:7777/oauth2 2019-03-05 07:08:38,177 oic.utils.keyio:DEBUG pcr: {'issuer': 'http://slc12ldo.us.oracle.com:7777/oauth2', 'authorization_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/authorize', 'jwks_uri': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/security', 'response_types_supported': ['code', 'token', 'id_token', 'token id_token'], 'subject_types_supported': ['public'], 'id_token_signing_alg_values_supported': ['RS256'], 'claims_supported': ['aud', 'exp', 'iat', 'iss', 'jti', 'sub'], 'end_session_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/userlogout', 'grant_types_supported': ['password', 'client_credentials', 'urn:ietf:params:oauth:grant-type:jwt-bearer', 'authorization_code', 'refresh_token', 'implicit'], 'scopes_supported': ['openid', 'profile', 'email', 'address', 'phone'], 'token_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/token', 'token_endpoint_auth_methods_supported': ['client_secret_basic', 'client_secret_jwt'], 'token_endpoint_auth_signing_alg_values_supported': ['RS256'], 'ui_locales_supported': ['en'], 'userinfo_endpoint': 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/userinfo', 'userinfo_signing_alg_values_supported': ['none']} 2019-03-05 07:08:38,177 oidctest.session:INFO session_setup 2019-03-05 07:08:38,177 otest.aus.tool:INFO <=<=<=<=< OP-Response-id_token >=>=>=>=> 2019-03-05 07:08:38,177 otest.aus.tool:INFO <--<-- 0 --- Webfinger -->--> 2019-03-05 07:08:38,177 otest.aus.tool:INFO <--<-- 1 --- Discovery -->--> 2019-03-05 07:08:38,178 otest.aus.tool:INFO <--<-- 2 --- Registration -->--> 2019-03-05 07:08:38,178 otest.aus.tool:INFO <--<-- 3 --- AsyncAuthn -->--> 2019-03-05 07:08:38,179 cherrypy.access.140629376080416:INFO 10.240.229.247 - - [05/Mar/2019:07:08:38] "GET /OP-Response-id_token HTTP/1.1" 303 504 "https://op-test:60001/" "Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0" 2019-03-05 07:08:54,307 cherrypy.access.140629376080416:INFO 10.240.229.247 - - [05/Mar/2019:07:08:54] "GET /authz_cb HTTP/1.1" 200 545 "http://slc12ldo.us.oracle.com:7777/oam/pages/consent.jsp?state=UnlIVVlJcXpUYnJyMnd1SHZhbzdZdz09fmRvYmc4N0hvdG5JNnk2U3NoZzYzZ3lwcHBjYmlYYlpGc3hacHVKOENVWHcrZmxYNTFjZThaSXl2em8yN2ZZSnRuUGxlcTExcWZSLzJWaFBHbGJTajFNcFdVOGVGT3dxNnQ0d0x4TUIwR2Q3cFpCZDlWckRnVE5YNlpaSUpRbWVkL3VrRS9ZbldnSmlNMzdzOGY5eE9KOXdadHBkUk5RZkNNWmg4cFFHNEZnZDVmdld4Z0Rocll4NWl5UHQ5L2tuYw==&scopes=openid&client_id=APKRISHNAOAUTHIDCLIENT10" "Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0" 2019-03-05 07:08:54,380 otest.aus.tool:INFO <--<-- 3 --- <class 'oidctest.op.oper.AsyncAuthn'> 2019-03-05 07:08:54,380 otest.aus.request:INFO Response: id_token=eyJraWQiOiJLUklTSE5BSURET01BSU4xMCIsIng1dCI6IjZnZzg3YnFOemRzaW9Qc1E5UWl6ejlTRlJoOCIsImFsZyI6IlJTMjU2In0.eyJpc3MiOiJodHRwOi8vc2xjMTJsZG8udXMub3JhY2xlLmNvbTo3Nzc3L29hdXRoMiIsInN1YiI6IndlYmxvZ2ljIiwiYXVkIjpbIkFQS1JJU0hOQUlERE9NMDAiLCJodHRwOi8vc2xjMTJsZG8udXMub3JhY2xlLmNvbTo3Nzc3L29hdXRoMiJdLCJleHAiOjE1NTE4Njk2OTQsImlhdCI6MTU1MTc2OTczNCwibm9uY2UiOiJ3YXRlcmlzZ29vZCIsImp0aSI6InVBemtjYlppVVRKakdQU18yVEl6bGciLCJhenAiOiJBUEtSSVNITkFJRERPTTAwIiwiYWNyIjoiMiIsInNpZCI6Im5pSHJKUS9ER2VCNUhldXlITnFjaFE9PX5QZ0Q1YVBuUDVaY2ZGeDVmVzJWYXI3clRoM0w5L2dkdlNBTnRQQXdKWTcwWTBLV3BpcmxWYUhzN0pUajlSVk5nZlNFdkNLNkIyNTBReEZlS3FjelVZYWttR0VyaG5RUzFuTjBEeGJOMjBjMElhQ0RKV2Vob1JyUFNPUHNGZkVucyIsImF1dGhfdGltZSI6IjE1NTE3Njk3MzA2NzMiLCJhbXIiOlsicHdkIl19.DnP6Gwsrgio-zUWyjJMF_Dxio8vtCvA_eOH77SYUBt8H40xZjbETCdawV7aMMiQoa6fIiCaL2OZexkW3oy9CTwK1y_4jvzBXpYGcjzUNIflt28lC5JE_r6RFaIQYJmaxxdOWeqSkE2N0-Et0mH3biVnF4pGaR8scMrvp1rnErkg9skSmOJy4DC2F8mdzPgqBjG7mdtWmyvgZNo_65VsEycF8kmNkiRmC5YzNc5yS9pApyevIab0QxN5YS-gx3a7n8Qfhj8Zwha0Ea0Kvgq9IvXKpVXWGsvZRmDACRNBDvGpKfK7GPm2pAjqT9oG-M92RLF_yopO0LXHbtiOwJJDBdw&state=9KDba6k7K6zq91Wq 2019-03-05 07:08:54,381 oic.oauth2:DEBUG Initial response parsing => "{'id_token': 'eyJraWQiOiJLUklTSE5BSURET01BSU4xMCIsIng1dCI6IjZnZzg3YnFOemRzaW9Qc1E5UWl6ejlTRlJoOCIsImFsZyI6IlJTMjU2In0.eyJpc3MiOiJodHRwOi8vc2xjMTJsZG8udXMub3JhY2xlLmNvbTo3Nzc3L29hdXRoMiIsInN1YiI6IndlYmxvZ2ljIiwiYXVkIjpbIkFQS1JJU0hOQUlERE9NMDAiLCJodHRwOi8vc2xjMTJsZG8udXMub3JhY2xlLmNvbTo3Nzc3L29hdXRoMiJdLCJleHAiOjE1NTE4Njk2OTQsImlhdCI6MTU1MTc2OTczNCwibm9uY2UiOiJ3YXRlcmlzZ29vZCIsImp0aSI6InVBemtjYlppVVRKakdQU18yVEl6bGciLCJhenAiOiJBUEtSSVNITkFJRERPTTAwIiwiYWNyIjoiMiIsInNpZCI6Im5pSHJKUS9ER2VCNUhldXlITnFjaFE9PX5QZ0Q1YVBuUDVaY2ZGeDVmVzJWYXI3clRoM0w5L2dkdlNBTnRQQXdKWTcwWTBLV3BpcmxWYUhzN0pUajlSVk5nZlNFdkNLNkIyNTBReEZlS3FjelVZYWttR0VyaG5RUzFuTjBEeGJOMjBjMElhQ0RKV2Vob1JyUFNPUHNGZkVucyIsImF1dGhfdGltZSI6IjE1NTE3Njk3MzA2NzMiLCJhbXIiOlsicHdkIl19.DnP6Gwsrgio-zUWyjJMF_Dxio8vtCvA_eOH77SYUBt8H40xZjbETCdawV7aMMiQoa6fIiCaL2OZexkW3oy9CTwK1y_4jvzBXpYGcjzUNIflt28lC5JE_r6RFaIQYJmaxxdOWeqSkE2N0-Et0mH3biVnF4pGaR8scMrvp1rnErkg9skSmOJy4DC2F8mdzPgqBjG7mdtWmyvgZNo_65VsEycF8kmNkiRmC5YzNc5yS9pApyevIab0QxN5YS-gx3a7n8Qfhj8Zwha0Ea0Kvgq9IvXKpVXWGsvZRmDACRNBDvGpKfK7GPm2pAjqT9oG-M92RLF_yopO0LXHbtiOwJJDBdw', 'state': '9KDba6k7K6zq91Wq'}" 2019-03-05 07:08:54,381 oic.oauth2:DEBUG Verify response with {'keyjar': <KeyJar(issuers=['', 'http://slc12ldo.us.oracle.com:7777/oauth2'])>, 'client_id': 'APKRISHNAIDDOM00', 'iss': 'http://slc12ldo.us.oracle.com:7777/oauth2'} 2019-03-05 07:08:54,381 oic.oauth2.message:DEBUG Raw JSON: {'iss': 'http://slc12ldo.us.oracle.com:7777/oauth2', 'sub': 'weblogic', 'aud': ['APKRISHNAIDDOM00', 'http://slc12ldo.us.oracle.com:7777/oauth2'], 'exp': 1551869694, 'iat': 1551769734, 'nonce': 'waterisgood', 'jti': 'uAzkcbZiUTJjGPS_2TIzlg', 'azp': 'APKRISHNAIDDOM00', 'acr': '2', 'sid': 'niHrJQ/DGeB5HeuyHNqchQ==~PgD5aPnP5ZcfFx5fW2Var7rTh3L9/gdvSANtPAwJY70Y0KWpirlVaHs7JTj9RVNgfSEvCK6B250QxFeKqczUYakmGErhnQS1nN0DxbN20c0IaCDJWehoRrPSOPsFfEns', 'auth_time': '1551769730673', 'amr': ['pwd']} 2019-03-05 07:08:54,382 oic.oauth2.message:DEBUG JWS header: {'kid': 'KRISHNAIDDOMAIN10', 'x5t': '6gg87bqNzdsioPsQ9Qizz9SFRh8', 'alg': 'RS256'} 2019-03-05 07:08:54,382 root:DEBUG KeyBundle fetch keys from: http://slc12ldo.us.oracle.com:7777/oauth2/rest/security 2019-03-05 07:08:54,383 urllib3.connectionpool:DEBUG Starting new HTTP connection (1): www-proxy-hqdc.us.oracle.com:80 2019-03-05 07:08:54,427 urllib3.connectionpool:DEBUG http://www-proxy-hqdc.us.oracle.com:80 "GET http://slc12ldo.us.oracle.com:7777/oauth2/rest/security HTTP/1.1" 502 2798 2019-03-05 07:08:54,428 otest.handling:ERROR [run_sequence] ExcList: Traceback (most recent call last): File "/usr/local/lib/python3.6/dist-packages/otest-0.7.3-py3.6.egg/otest/aus/request.py", line 331, in parse_response keyjar=_conv.entity.keyjar # , algs=algs File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/oauth2/init.py", line 562, in parse_response verf = resp.verify(kwargs) File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/oic/message.py", line 347, in verify idt = IdToken().from_jwt(str(self["id_token"]), args) File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/oauth2/message.py", line 670, in from_jwt _jw, **kwargs) File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/oauth2/message.py", line 556, in get_verify_keys _key = keyjar.get_key_by_kid(_kid, _iss) File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/utils/keyio.py", line 597, in get_key_by_kid _key = kb.get_key_with_kid(kid) File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/utils/keyio.py", line 327, in get_key_with_kid self.update() File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/utils/keyio.py", line 258, in update res = self.do_remote() File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/utils/keyio.py", line 204, in do_remote REMOTE_FAILED.format(self.source, r.status_code)) File "/usr/local/lib/python3.6/dist-packages/oic-0.14.0-py3.6.egg/oic/utils/keyio.py", line 40, in raise_exception raise excep(_err, 'application/json') oic.utils.keyio.UpdateFailed: {"error": "service_error", "error_description": "Remote key update from 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/security' failed, HTTP status 502"}
2019-03-05 07:08:54,429 otest.handling:ERROR [run_sequence] Exception: {"error": "service_error", "error_description": "Remote key update from 'http://slc12ldo.us.oracle.com:7777/oauth2/rest/security' failed, HTTP status 502"}