search

zowe / api-layer

The API Mediation Layer provides a single point of access for mainframe service REST APIs.
Eclipse Public License 2.0
56 stars 63 forks source link

Unable to authenticate with gateway auth service - response is 500 internal server error #731

Closed jordanCain closed 4 years ago

jordanCain commented 4 years ago

Describe the bug When trying to use the gateway/auth/login endpoint I get the response:

{
"messages":[
{
"messageType": "ERROR",
"messageNumber": "ZWEAG100E",
"messageContent": "Authentication exception: 'A failure occurred when authenticating.' for URL '/api/v1/gateway/auth/login'",
"messageKey": "org.zowe.apiml.security.generic"
}
]
}

Steps to Reproduce

  1. attempt to login using gateway auth service
  2. see login fai

Expected behavior Login without issue

Details

API Catalog Web UI (in case of API Catalog issue): API Gateway shows: Version 1.11.0 build # 130

REST API client (in case of REST API issue):

Additional context Add any other context about the problem here.

https://github.com/zowe/api-layer/wiki/Issue-management

jordanCain commented 4 years ago

When running the gateway with debug output enabled the below is what is output

2020-07-06 19:23:50.867 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-9 << "end of stream"
2020-07-06 19:23:50.867 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-9: Close connection
2020-07-06 19:23:50.867 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Connection leased: [id: 11][route: {s}->https://host:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 2 of 20]
2020-07-06 19:23:50.867 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.e.MainClientExec) Opening connection {s}->https://host:443
2020-07-06 19:23:50.867 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.DefaultHttpClientConnectionOperator) Connecting to /host:443
2020-07-06 19:23:50.867 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory) Connecting socket to /host:443 with timeout 0
2020-07-06 19:23:51.796 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  negotiated cipher suite: TLS_RSA_WITH_AES_128_CBC_SHA256
2020-07-06 19:23:51.796 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  peer principal: CN=izusvr.mopvsC4, OU=IZUDFLT, O=IBM
2020-07-06 19:23:51.796 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  issuer principal: CN=z/OSMF CertAuth for Security Domain, OU=IZUDFLT
2020-07-06 19:23:51.796 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.DefaultHttpClientConnectionOperator) Connection established 9.211.126.126:58514<->host:443
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.e.MainClientExec) Executing request GET /zosmf/info HTTP/1.1
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> GET /zosmf/info HTTP/1.1
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> Accept: application/json, application/*+json
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> X-CSRF-ZOSMF-HEADER: 
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> Host: host:443
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> Connection: Keep-Alive
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_201)
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 >> Accept-Encoding: gzip,deflate
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "GET /zosmf/info HTTP/1.1[\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "Accept: application/json, application/*+json[\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "X-CSRF-ZOSMF-HEADER: [\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "Host: host:443[\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "Connection: Keep-Alive[\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "User-Agent: Apache-HttpClient/4.5.6 (Java/1.8.0_201)[\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "Accept-Encoding: gzip,deflate[\r][\n]"
2020-07-06 19:23:51.797 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 >> "[\r][\n]"
2020-07-06 19:23:52.385 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "HTTP/1.1 200 OK[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "X-Powered-By: Servlet/3.0[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "Content-Type: text/plain;charset=ISO-8859-1[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "Content-Language: en-US[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "Transfer-Encoding: chunked[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "Date: Mon, 06 Jul 2020 19:23:51 GMT[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "4d3[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "{"zos_version":"04.25.00","zosmf_port":"443","zosmf_version":"25","zosmf_hostname":"","plugins":[{"pluginVersion":"hsma223;pi54902;2016-01-13T08:24:31","pluginDefaultName":"WorkloadManagement","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma224;PI54116;2016-02-23T05:25:38","pluginDefaultName":"Software Deployment","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma225;pi57159;2016-04-11T05:21:49","pluginDefaultName":"IncidentLog","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma226;PI44441;2015-07-10T10:54:27","pluginDefaultName":"Capacity Provisioning","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma227;pi59619;2016-05-20T03:51:49","pluginDefaultName":"Workflow","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma22a;PI62852;2016-06-14T12:56:51","pluginDefaultName":"ConfigurationAssistant","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma221;pi58734;2016-04-22T07:55:28","pluginDefaultName":"ISPF","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma220;pi61131;2016-05-05T05:41:33","pluginDefaultName":"Import Manager","pluginStatus":"ACTIVE"},{"pluginVersion":"hsma222;PI53796;2016-03-02T13:39:11","pluginDefaultName":"ResourceMonitoring","pluginStatus":"ACTIVE"}],"zosmf_saf_realm":"SAFRealm","zosmf_full_version":"25.0","api_version":"1"}[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 << HTTP/1.1 200 OK
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 << X-Powered-By: Servlet/3.0
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 << Content-Type: text/plain;charset=ISO-8859-1
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 << Content-Language: en-US
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 << Transfer-Encoding: chunked
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.headers) http-outgoing-11 << Date: Mon, 06 Jul 2020 19:23:51 GMT
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.http.wire) http-outgoing-11 << "0[\r][\n]"
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Connection [id: 11][route: {s}->https://host:443] can be kept alive indefinitely
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-11: set socket timeout to 0
2020-07-06 19:23:52.386 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Connection released: [id: 11][route: {s}->https://host:443][total kept alive: 1; route allocated: 1 of 2; total allocated: 2 of 20]
2020-07-06 19:23:52.387 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-8:9072> jordan ERROR (o.z.a.g.s.s.z.ZosmfServiceFacade) ZWEAG100E Authentication exception: 'Could not extract response: no suitable HttpMessageConverter found for response type [class org.zowe.apiml.gateway.security.service.zosmf.ZosmfServiceFacade$ZosmfInfo] and content type [text/plain;charset=ISO-8859-1]' for URL 'https://host:443/zosmf/info'
2020-07-06 19:23:52.413 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.DefaultHttpClientConnectionOperator) Connect to localhost/127.0.0.1:10014 timed out. Connection will be retried using another IP address
2020-07-06 19:23:52.413 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.DefaultHttpClientConnectionOperator) Connecting to localhost/0:0:0:0:0:0:0:1:10014
2020-07-06 19:23:52.413 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory) Connecting socket to localhost/0:0:0:0:0:0:0:1:10014 with timeout 30000
2020-07-06 19:23:52.414 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-10: Shutdown connection
2020-07-06 19:23:52.414 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.e.MainClientExec) Connection discarded
2020-07-06 19:23:52.414 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Connection released: [id: 10][route: {s}->https://localhost:10014][total kept alive: 1; route allocated: 0 of 2; total allocated: 1 of 20]
2020-07-06 19:23:52.415 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Connection request: [route: {s}->https://localhost:10014][total kept alive: 1; route allocated: 0 of 2; total allocated: 1 of 20]
2020-07-06 19:23:52.415 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.PoolingHttpClientConnectionManager) Connection leased: [id: 12][route: {s}->https://localhost:10014][total kept alive: 1; route allocated: 1 of 2; total allocated: 2 of 20]
2020-07-06 19:23:52.415 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.e.MainClientExec) Opening connection {s}->https://localhost:10014
2020-07-06 19:23:52.415 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.i.c.DefaultHttpClientConnectionOperator) Connecting to localhost/127.0.0.1:10014
2020-07-06 19:23:52.415 <ZWEAGW1:https-jsse-nio-127.0.0.1-10010-exec-4:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory) Connecting socket to localhost/127.0.0.1:10014 with timeout 30000
2020-07-06 19:23:58.364 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultClientConnection) Connection 0.0.0.0:58252<->127.0.0.1:10011 closed
2020-07-06 19:23:58.365 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultClientConnectionOperator) Connecting to localhost:10011
2020-07-06 19:23:58.366 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory) Connecting socket to localhost:10011 with timeout 5000
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  peer principal: CN=Zowe Service, OU=API Mediation Layer, O=Zowe Sample, L=Prague, ST=Prague, C=CZ
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  peer alternative names: [localhost.localdomain, localhost]
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.s.SSLConnectionSocketFactory)  issuer principal: CN=Zowe Development Instances Certificate Authority, OU=API Mediation Layer, O=Zowe Sample, L=Prague, ST=Prague, C=CZ
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.p.RequestAddCookies) CookieSpec selected: default
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.c.p.RequestAuthCache) Auth cache not set in the context
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultHttpClient) Attempt 1 to execute request
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultClientConnection) Sending request: PUT /eureka/apps/GATEWAY/localhost:gateway:10010?status=UP&lastDirtyTimestamp=1594062718060 HTTP/1.1
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "PUT /eureka/apps/GATEWAY/localhost:gateway:10010?status=UP&lastDirtyTimestamp=1594062718060 HTTP/1.1[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "DiscoveryIdentity-Name: DefaultClient[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "DiscoveryIdentity-Version: 1.4[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "DiscoveryIdentity-Id: 127.0.0.1[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "Accept-Encoding: gzip[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "Content-Length: 0[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "Host: localhost:10011[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "Connection: Keep-Alive[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "User-Agent: Java-EurekaClient/v1.9.13[\r][\n]"
2020-07-06 19:23:58.369 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "[\r][\n]"
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> PUT /eureka/apps/GATEWAY/localhost:gateway:10010?status=UP&lastDirtyTimestamp=1594062718060 HTTP/1.1
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> DiscoveryIdentity-Name: DefaultClient
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> DiscoveryIdentity-Version: 1.4
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> DiscoveryIdentity-Id: 127.0.0.1
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> Accept-Encoding: gzip
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> Content-Length: 0
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> Host: localhost:10011
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> Connection: Keep-Alive
2020-07-06 19:23:58.370 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> User-Agent: Java-EurekaClient/v1.9.13
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "HTTP/1.1 200 [\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "X-Content-Type-Options: nosniff[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "X-XSS-Protection: 1; mode=block[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Cache-Control: no-cache, no-store, max-age=0, must-revalidate[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Pragma: no-cache[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Expires: 0[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "X-Frame-Options: DENY[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Content-Type: application/xml[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Content-Length: 0[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Date: Mon, 06 Jul 2020 19:23:58 GMT[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "[\r][\n]"
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultClientConnection) Receiving response: HTTP/1.1 200 
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << HTTP/1.1 200 
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << X-Content-Type-Options: nosniff
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << X-XSS-Protection: 1; mode=block
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Cache-Control: no-cache, no-store, max-age=0, must-revalidate
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Pragma: no-cache
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Expires: 0
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << X-Frame-Options: DENY
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Content-Type: application/xml
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Content-Length: 0
2020-07-06 19:23:58.372 <ZWEAGW1:DiscoveryClient-HeartbeatExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Date: Mon, 06 Jul 2020 19:23:58 GMT
2020-07-06 19:23:58.416 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultClientConnection) Connection 0.0.0.0:58273<->127.0.0.1:10011 closed
2020-07-06 19:23:58.418 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.i.c.DefaultClientConnection) Sending request: GET /eureka/apps/delta HTTP/1.1
2020-07-06 19:23:58.419 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "GET /eureka/apps/delta HTTP/1.1[\r][\n]"
2020-07-06 19:23:58.419 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.http.wire)  >> "Accept: application/json[\r][\n]"
2020-07-06 19:23:58.419 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> GET /eureka/apps/delta HTTP/1.1
2020-07-06 19:23:58.419 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.headers) >> Accept: application/json
2020-07-06 19:23:58.420 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Content-Encoding: gzip[\r][\n]"
2020-07-06 19:23:58.420 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Content-Type: application/json[\r][\n]"
2020-07-06 19:23:58.420 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "Content-Length: 86[\r][\n]"
2020-07-06 19:23:58.421 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Content-Encoding: gzip
2020-07-06 19:23:58.421 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Content-Type: application/json
2020-07-06 19:23:58.421 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.h.headers) << Content-Length: 86
2020-07-06 19:23:58.421 <ZWEAGW1:DiscoveryClient-CacheRefreshExecutor-0:9072> jordan DEBUG (o.a.http.wire)  << "[0x1f][0x8b][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x0][0xab]VJ,([0xc8][0xc9]LN,[0xc9][0xcc][0xcf]+V[0xb2][0xaa]V*K-*[0x6][0xb1][0xe3][0xe3]SRsJ[0x12][0x95][0xac][0x94][0xc][\r][0x95]t@[0xca][0x80]B[0x19][0x89][0xc5][0x19][0xc9][0xf9])[0xa9]@[0xd1][0xd0][0x80]x[0xcb]x[0x88][0x4]L[0xbf][0x92]Utlm-[0x0]9[0xeb]G[0xc3]S[0x0][0x0][0x0]"
jordanCain commented 4 years ago

The only thing I see in the output that rings alarm bells is:

ZWEAG100E Authentication exception: 'Could not extract response: no suitable HttpMessageConverter found for response type [class org.zowe.apiml.gateway.security.service.zosmf.ZosmfServiceFacade$ZosmfInfo] and content type [text/plain;charset=ISO-8859-1]' for URL 'https://host:443/zosmf/info'

Looking at the response headers of a server where I dont see this problem the only difference is the content-Type header. On this server with the problem it's text/plain;charset=ISO-8859-1 whereas on working server it comes back as application/json

jordanCain commented 4 years ago

The exception is getting thrown at https://github.com/zowe/api-layer/blob/master/gateway-service/src/main/java/org/zowe/apiml/gateway/security/service/zosmf/ZosmfServiceFacade.java#L118

balhar-jakub commented 4 years ago

It seems that the Zosmf isn't properly set in this specific case.

Maybe I missed it, but what is actually expected? Some warning message?

jordanCain commented 4 years ago

z/OSMF on the system was functioning but the APIML auth service was unable to communicate with it. I wasn't able to see what configuration was different with this z/OSMF installation compared to one that did work with the APIML.

I think the correct behaviour in this case would be a more descriptive warning message, the actual failure occurred when trying to parse the response of the z/OSMF info endpoint and I think it would be helpful to highlight that to a user.

This issue may get resolved by the work that will be carried out in https://github.com/zowe/api-layer/issues/772 as there's a chance we may not query the info endpoint anymore

jordanCain commented 4 years ago

The system I was able to reproduce this issue on has now been decommissioned, the issue was also on z/OS 2.2 which is now out of official support I'll close this issue as no longer reproducible on a supported environement