api-layer icon indicating copy to clipboard operation
api-layer copied to clipboard
verified publisher icon zowe

Gateway login failure generates 2 failures instead of 1

Open 1000TurquoisePogs opened this issue 3 years ago • 3 comments

Describe the bug Users have seen their accounts get locked due to invalid password attempts faster than they would have expected. Upon checking logs, they find that the message ICH408I about login failure is issued twice per gateway login failure, instead of once. The result is that a user accidentally typing their password wrong can be locked out when using the gateway when otherwise would not have been.

Steps to Reproduce

  1. Setup the gateway to use zosmf as auth
  2. Try to login to the api catalog with invalid password for a real user
  3. Observe the zosmf job log to see the amount of ICH408I that happen. With this bug, you will see 2 instead of 1.
  4. Type your password correctly so that you don't get locked out
  5. Logout to clear your zosmf cookies
  6. Try a bad login to zosmf directly without the gateway, by going to the zosmf homepage
  7. Observe in the zosmf job log that only 1 ICH408I happens

Expected behavior Only 1 ICH408I should be generated for 1 invalid password login attempt

Logs

When I attempted a bad login from the api catalog:

15.47.35 S0689043  ICH408I USER(MYUSER  ) GROUP(MYUSER ) NAME(ME         )  606    
   606               LOGON/JOB INITIATION - INVALID PASSWORD                                 
15.47.35 S0689043  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                     
15.47.35 S0689043  ICH408I USER(MYUSER  ) GROUP(MYUSER ) NAME(ME      )  608    
   608               LOGON/JOB INITIATION - INVALID PASSWORD                                 
15.47.35 S0689043  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.

When I attempted a bag login from zosmf directly:

15.48.52 S0689043  ICH408I USER(MYUSER  ) GROUP(MYUSER ) NAME(ME      )  630    
   630               LOGON/JOB INITIATION - INVALID PASSWORD                                 
15.48.52 S0689043  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.

Details

  • Version and build number: Zowe 2.4, but actually this has been reported for much longer and only recently understood. I suspect this may date back to even 1.20
  • Test environment: Within my company

Willingness to help I can test any builds you'd like.

I also suspect this may be caused by the authentication process being proactive, as in, trying to do an action during the authentication process assuming that the login succeeded, or attempting a retry via a different method.

Actually, up until v1.27 we had three ICH408I at one point because the app-server would try to login to the gateway with credentials first (causing these 2), and then upon seeing a failure, would retry with a cookie if a cookie came from the browser (+1)

1000TurquoisePogs avatar Nov 17 '22 21:11 1000TurquoisePogs

I second this for importance

DivergentEuropeans avatar Nov 18 '22 17:11 DivergentEuropeans

I turned gateway debug on and got these messages at the same time as the problem occurs. I removed some identifying information including cookies and basic auth. I see 2 calls to the same zosmf endpoint. on the first call, its basic auth appears nearly empty. on the second call, it has a different basic auth. i have no idea why but also i have no idea why there are 2 and that seems related to the problem.

.109 10:(o.z.a.g.f.p.LocationFilter) Routing: The request was routed to /apicatalog/auth/login
.110 10: WARN  (o.s.c.n.z.f.r.s.AbstractRibbonCommand) The Hystrix timeout of 600000ms for the command apicatalog is set lower than the combination of the Ribbon read and connect timeout, 7200000ms.
.111 10:(o.z.a.g.r.l.LoadBalancerRuleAdapter) Choosing server: apicatalog
.111 10:(o.z.a.g.r.l.LoadBalancerRuleAdapter) Path: /apicatalog/api/v1/auth/login, List of servers from LoadBalancer: [myhost:discoport]
.111 10:(o.z.a.g.r.l.LoadBalancerRuleAdapter) Running Zuul predicates
.111 10:(o.z.a.g.r.l.LoadBalancerRuleAdapter) Selected server: myhost:discoport



.111 10:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection request: [route: {s}->https://myhost:discoport][total available: 6; route allocated: 4 of 100; total allocated: 6 of 1000]
.111 10:(o.a.h.i.c.CPool) Connection [id:9][route:{s}->https://myhost:discoport][state:null] expired @ Fri Nov 18 14:29:44 GMT-05:00 2022 .111 10:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-9: Close connection
.112 10:(o.a.h.i.c.CPool) Connection [id:7][route:{s}->https://myhost:discoport][state:null] expired @ Fri Nov 18 14:29:44 GMT-05:00 2022 .112 10:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-7: Close connection
.112 10:(o.a.h.i.c.CPool) Connection [id:11][route:{s}->https://myhost:discoport][state:null] expired @ Fri Nov 18 14:29:46 GMT-05:00 2022.112 10:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-11: Close connection
.112 10:(o.a.h.i.c.CPool) Connection [id:10][route:{s}->https://myhost:discoport][state:null] expired @ Fri Nov 18 14:29:46 GMT-05:00 2022.112 10:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-10: Close connection
.112 10:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection leased: [id: 12][route: {s}->https://myhost:discoport][total available: 2; route allocated: 1 of 100; total allocated: 3 of 1000]
.112 10:(o.a.h.i.e.MainClientExec) Opening connection {s}->https://myhost:discoport                                                       .112 10:(o.a.h.i.c.DefaultHttpClientConnectionOperator) Connecting to myhost/myip:discoport
.113 10:(o.a.h.c.s.SSLConnectionSocketFactory) Connecting socket to myhost/myip:discoport with timeout 600000                    .115 10:(o.a.h.c.s.SSLConnectionSocketFactory) Enabled protocols: [TLSv1.2]
.115 10:(o.a.h.c.s.SSLConnectionSocketFactory) Enabled cipher suites:[SSL_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, SSL_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384, SSL_ECDHE_RSA_WITH_AES_128_GCM_SHA256, SSL_DHE_RSA_WITH_AES_256_GCM_SHA384, SSL_DHE_DSS_WITH_AES_256_GCM_SHA384, SSL_DHE_RSA_WITH_AES_128_GCM_SHA256, SSL_DHE_DSS_WITH_AES_128_GCM_SHA256, SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA384, SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA256, SSL_DHE_RSA_WITH_AES_256_CBC_SHA256, SSL_DHE_DSS_WITH_AES_256_CBC_SHA256, SSL_DHE_RSA_WITH_AES_128_CBC_SHA256, SSL_DHE_DSS_WITH_AES_128_CBC_SHA256, SSL_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, SSL_ECDH_RSA_WITH_AES_256_GCM_SHA384, SSL_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, SSL_ECDH_RSA_WITH_AES_128_GCM_SHA256, SSL_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, SSL_ECDH_RSA_WITH_AES_256_CBC_SHA384, SSL_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, SSL_ECDH_RSA_WITH_AES_128_CBC_SHA256, SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA, SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA, SSL_DHE_RSA_WITH_AES_256_CBC_SHA, SSL_DHE_DSS_WITH_AES_256_CBC_SHA, SSL_DHE_RSA_WITH_AES_128_CBC_SHA, SSL_DHE_DSS_WITH_AES_128_CBC_SHA, SSL_ECDH_ECDSA_WITH_AES_256_CBC_SHA, SSL_ECDH_RSA_WITH_AES_256_CBC_SHA, SSL_ECDH_ECDSA_WITH_AES_128_CBC_SHA, SSL_ECDH_RSA_WITH_AES_128_CBC_SHA, SSL_RSA_WITH_AES_256_GCM_SHA384, SSL_RSA_WITH_AES_128_GCM_SHA256, SSL_RSA_WITH_AES_256_CBC_SHA256, SSL_RSA_WITH_AES_128_CBC_SHA256, SSL_RSA_WITH_AES_256_CBC_SHA, SSL_RSA_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
.115 10:(o.a.h.c.s.SSLConnectionSocketFactory) Starting handshake
.124 10:(o.a.h.c.s.SSLConnectionSocketFactory) Secure session established
.124 10:(o.a.h.c.s.SSLConnectionSocketFactory)  negotiated protocol: TLSv1.2
.124 10:(o.a.h.c.s.SSLConnectionSocketFactory)  negotiated cipher suite: SSL_ECDHE_RSA_WITH_AES_128_GCM_SHA256
.124 10:(o.a.h.c.s.SSLConnectionSocketFactory)  peer principal: CN=Zowe Service, OU=API Mediation Layer, O=Zowe Sample, L=Prague, ST=Prague, C=CZ
.125 10:(o.a.h.c.s.SSLConnectionSocketFactory)  peer alternative names: [myhost, localhost.localdomain, localhost, 127.0.0.1]
.125 10:(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
.125 10:(o.a.h.i.c.DefaultHttpClientConnectionOperator) Connection established myip:55007<->myip:discoport
.125 10:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-12: set socket timeout to 600000



.125 10:(o.a.h.i.e.MainClientExec) Executing request POST /apicatalog/auth/login HTTP/1.1
.125 10:(o.a.h.i.e.MainClientExec) Target auth state: UNCHALLENGED
.125 10:(o.a.h.i.e.MainClientExec) Proxy auth state: UNCHALLENGED
.125 10:(o.a.h.headers) http-outgoing-12 >> POST /apicatalog/auth/login HTTP/1.1
.125 10:(o.a.h.headers) http-outgoing-12 >> accept: */*
.125 10:(o.a.h.headers) http-outgoing-12 >> accept-language: en-US,en;q=0.5
.125 10:(o.a.h.headers) http-outgoing-12 >> accept-encoding: gzip, deflate, br
.125 10:(o.a.h.headers) http-outgoing-12 >> referer: https://myhost:gatewayport/apicatalog/ui/v1/
.125 10:(o.a.h.headers) http-outgoing-12 >> content-type: application/json
.125 10:(o.a.h.headers) http-outgoing-12 >> access-control-allow-origin: https://myhost:gatewayport
.125 10:(o.a.h.headers) http-outgoing-12 >> access-control-allow-credentials: true
.125 10:(o.a.h.headers) http-outgoing-12 >> x-requested-with: XMLHttpRequest
.125 10:(o.a.h.headers) http-outgoing-12 >> origin: https://myhost:gatewayport
.125 10:(o.a.h.headers) http-outgoing-12 >> dnt: 1
.126 10:(o.a.h.headers) http-outgoing-12 >> sec-fetch-dest: empty
.126 10:(o.a.h.headers) http-outgoing-12 >> sec-fetch-mode: cors
.126 10:(o.a.h.headers) http-outgoing-12 >> sec-fetch-site: same-origin
.126 10:(o.a.h.headers) http-outgoing-12 >> x-forwarded-host: myhost:gatewayport
.126 10:(o.a.h.headers) http-outgoing-12 >> x-forwarded-proto: https
.126 10:(o.a.h.headers) http-outgoing-12 >> x-forwarded-prefix: /apicatalog/api/v1
.126 10:(o.a.h.headers) http-outgoing-12 >> x-forwarded-port: gatewayport
.126 10:(o.a.h.headers) http-outgoing-12 >> x-forwarded-for: clientip
.126 10:(o.a.h.headers) http-outgoing-12 >> Content-Length: 38
.126 10:(o.a.h.headers) http-outgoing-12 >> Host: myhost:discoport
.126 10:(o.a.h.headers) http-outgoing-12 >> Connection: Keep-Alive
.126 10:(o.a.http.wire) http-outgoing-12 >> "POST /apicatalog/auth/login HTTP/1.1[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "accept: */*[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "accept-language: en-US,en;q=0.5[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "accept-encoding: gzip, deflate, br[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "referer: https://myhost:gatewayport/apicatalog/ui/v1/[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "content-type: application/json[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "access-control-allow-origin: https://myhost:gatewayport[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "access-control-allow-credentials: true[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "x-requested-with: XMLHttpRequest[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "origin: https://myhost:gatewayport[\r][\n]"
.126 10:(o.a.http.wire) http-outgoing-12 >> "dnt: 1[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "sec-fetch-dest: empty[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "sec-fetch-mode: cors[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "sec-fetch-site: same-origin[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "x-forwarded-host: myhost:gatewayport[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "x-forwarded-proto: https[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "x-forwarded-prefix: /apicatalog/api/v1[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "x-forwarded-port: gatewayport[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "x-forwarded-for: clientip[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "Content-Length: 38[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "Host: myhost:discoport[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "Connection: Keep-Alive[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "[\r][\n]"
.131 10:(o.a.http.wire) http-outgoing-12 >> "{"username":"me","password":***}"




.165 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection request: [route: {s}->https://myhost:zosmfport][total available: 2; route allocated: 1 of 100; total allocated: 3 of 1000]
.165 6:(o.a.h.i.c.CPool) Connection [id:8][route:{s}->https://myhost:zosmfport][state:null] expired @ Fri Nov 18 14:29:36 GMT-05:00 2022
.165 6:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-8: Close connection
.165 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection leased: [id: 13][route: {s}->https://myhost:zosmfport][total available: 1; route allocated: 1 of 100; total allocated: 3 of 1000]
.165 6:(o.a.h.i.e.MainClientExec) Opening connection {s}->https://myhost:zosmfport
.166 6:(o.a.h.i.c.DefaultHttpClientConnectionOperator) Connecting to myhost/myip:zosmfport
.166 6:(o.a.h.c.s.SSLConnectionSocketFactory) Connecting socket to myhost/myip:zosmfport with timeout 600000
.170 6:(o.a.h.c.s.SSLConnectionSocketFactory) Enabled protocols: [TLSv1.2]
.170 6:(o.a.h.c.s.SSLConnectionSocketFactory) Enabled cipher suites:[SSL_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, SSL_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,
SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384, SSL_ECDHE_RSA_WITH_AES_128_GCM_SHA256, SSL_DHE_RSA_WITH_AES_256_GCM_SHA384, SSL_DHE_DSS_WITH_AES_256_GCM_SHA384, SSL_DHE_RSA_WITH_AES_128_GCM_SHA256, SSL_DHE_DSS_WITH_AES_128_GCM_SHA256, SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA384, SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA256, SSL_DHE_RSA_WITH_AES_256_CBC_SHA256, SSL_DHE_DSS_WITH_AES_256_CBC_SHA256, SSL_DHE_RSA_WITH_AES_128_CBC_SHA256, SSL_DHE_DSS_WITH_AES_128_CBC_SHA256, SSL_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, SSL_ECDH_RSA_WITH_AES_256_GCM_SHA384, SSL_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, SSL_ECDH_RSA_WITH_AES_128_GCM_SHA256, SSL_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, SSL_ECDH_RSA_WITH_AES_256_CBC_SHA384, SSL_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, SSL_ECDH_RSA_WITH_AES_128_CBC_SHA256, SSL_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, SSL_ECDHE_RSA_WITH_AES_256_CBC_SHA, SSL_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, SSL_ECDHE_RSA_WITH_AES_128_CBC_SHA, SSL_DHE_RSA_WITH_AES_256_CBC_SHA, SSL_DHE_DSS_WITH_AES_256_CBC_SHA, SSL_DHE_RSA_WITH_AES_128_CBC_SHA, SSL_DHE_DSS_WITH_AES_128_CBC_SHA, SSL_ECDH_ECDSA_WITH_AES_256_CBC_SHA, SSL_ECDH_RSA_WITH_AES_256_CBC_SHA, SSL_ECDH_ECDSA_WITH_AES_128_CBC_SHA, SSL_ECDH_RSA_WITH_AES_128_CBC_SHA, SSL_RSA_WITH_AES_256_GCM_SHA384, SSL_RSA_WITH_AES_128_GCM_SHA256, SSL_RSA_WITH_AES_256_CBC_SHA256, SSL_RSA_WITH_AES_128_CBC_SHA256, SSL_RSA_WITH_AES_256_CBC_SHA, SSL_RSA_WITH_AES_128_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
.170 6:(o.a.h.c.s.SSLConnectionSocketFactory) Starting handshake
.181 6:(o.a.h.c.s.SSLConnectionSocketFactory) Secure session established
.181 6:(o.a.h.c.s.SSLConnectionSocketFactory)  negotiated protocol: TLSv1.2
.181 6:(o.a.h.c.s.SSLConnectionSocketFactory)  negotiated cipher suite: SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384
.181 6:(o.a.h.i.c.DefaultHttpClientConnectionOperator) Connection established myip:55009<->myip:zosmfport
.181 6:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-13: set socket timeout to 10000
.181 6:(o.a.h.i.e.MainClientExec) Executing request POST /zosmf/services/authenticate HTTP/1.1
.181 6:(o.a.h.i.e.MainClientExec) Proxy auth state: UNCHALLENGED
.181 6:(o.a.h.headers) http-outgoing-13 >> POST /zosmf/services/authenticate HTTP/1.1
.181 6:(o.a.h.headers) http-outgoing-13 >> Accept: text/plain, application/xml, text/xml, application/json, application/cbor, application/*+xml, application/*+json, */*
.181 6:(o.a.h.headers) http-outgoing-13 >> X-CSRF-ZOSMF-HEADER:
.181 6:(o.a.h.headers) http-outgoing-13 >> Content-Length: 0
.181 6:(o.a.h.headers) http-outgoing-13 >> Host: myhost:zosmfport
.181 6:(o.a.h.headers) http-outgoing-13 >> Connection: Keep-Alive
.181 6:(o.a.h.headers) http-outgoing-13 >> User-Agent: Apache-HttpClient/4.5.13 (Java/1.8.0_341)
.181 6:(o.a.h.headers) http-outgoing-13 >> Accept-Encoding: gzip,deflate
.181 6:(o.a.http.wire) http-outgoing-13 >> "POST /zosmf/services/authenticate HTTP/1.1[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "Accept: text/plain, application/xml, text/xml, application/json, application/cbor, application/*+xml, application/*+json, */*[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "X-CSRF-ZOSMF-HEADER: [\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "Authorization: Basic Og==[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "Content-Length: 0[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "Host: myhost:zosmfport[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "Connection: Keep-Alive[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "User-Agent: Apache-HttpClient/4.5.13 (Java/1.8.0_341)[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "Accept-Encoding: gzip,deflate[\r][\n]"
.181 6:(o.a.http.wire) http-outgoing-13 >> "[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "HTTP/1.1 401 Unauthorized[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "X-Powered-By: Servlet/3.1[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "X-Content-Type-Options: nosniff[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "X-XSS-Protection: 1; mode=block[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "Strict-Transport-Security: max-age=31536000; includeSubDomains[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "Content-Type: application/json;charset=ISO-8859-1[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "Content-Language: en-US[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "Transfer-Encoding: chunked[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "Date: Fri, 18 Nov 2022 19:29:47 GMT[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "b7[\r][\n]"
.183 6:(o.a.http.wire) http-outgoing-13 << "{"returnCode":8,"reasonCode":1,"message":"Login failed. Check if the user ID and password you use for the Basic Auth is correct, and if the user ID has the required SAF permissions."}[\r][\n]"
.183 6:(o.a.h.headers) http-outgoing-13 << HTTP/1.1 401 Unauthorized
.183 6:(o.a.h.headers) http-outgoing-13 << X-Powered-By: Servlet/3.1
.183 6:(o.a.h.headers) http-outgoing-13 << X-Content-Type-Options: nosniff
.183 6:(o.a.h.headers) http-outgoing-13 << X-XSS-Protection: 1; mode=block
.183 6:(o.a.h.headers) http-outgoing-13 << Strict-Transport-Security: max-age=31536000; includeSubDomains
.183 6:(o.a.h.headers) http-outgoing-13 << Content-Type: application/json;charset=ISO-8859-1
.183 6:(o.a.h.headers) http-outgoing-13 << Content-Language: en-US
.183 6:(o.a.h.headers) http-outgoing-13 << Transfer-Encoding: chunked
.183 6:(o.a.h.headers) http-outgoing-13 << Date: Fri, 18 Nov 2022 19:29:47 GMT




.183 6:(o.a.h.i.e.MainClientExec) Connection can be kept alive for 2000 MILLISECONDS
.183 6:(o.a.h.i.a.HttpAuthenticator) Authentication required
.183 6:(o.a.h.i.a.HttpAuthenticator) myhost:zosmfport requested authentication
.183 6:(o.a.h.i.a.HttpAuthenticator) Response contains no authentication challenges
.184 6:(o.a.http.wire) http-outgoing-13 << "0[\r][\n]"
.184 6:(o.a.http.wire) http-outgoing-13 << "[\r][\n]"
.184 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection [id: 13][route: {s}->https://myhost:zosmfport] can be kept alive for 2.0 seconds
.184 6:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-13: set socket timeout to 0
.184 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection released: [id: 13][route: {s}->https://myhost:zosmfport][total available: 2; route allocated: 1 of 100; total allocated: 3 of 1000]
.184 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection request: [route: {s}->https://myhost:zosmfport][total available: 2; route allocated: 1 of 100; total allocated: 3 of 1000]
.184 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection leased: [id: 13][route: {s}->https://myhost:zosmfport][total available: 1; route allocated: 1 of 100; total allocated: 3 of 1000]
.184 6:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-13: set socket timeout to 0
.184 6:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-13: set socket timeout to 10000
.184 6:(o.a.h.i.e.MainClientExec) Executing request POST /zosmf/services/authenticate HTTP/1.1
.184 6:(o.a.h.i.e.MainClientExec) Proxy auth state: UNCHALLENGED
.184 6:(o.a.h.headers) http-outgoing-13 >> POST /zosmf/services/authenticate HTTP/1.1
.184 6:(o.a.h.headers) http-outgoing-13 >> Accept: text/plain, application/xml, text/xml, application/json, application/cbor, application/*+xml, application/*+json, */*
.185 6:(o.a.h.headers) http-outgoing-13 >> X-CSRF-ZOSMF-HEADER:
.185 6:(o.a.h.headers) http-outgoing-13 >> Content-Length: 0
.185 6:(o.a.h.headers) http-outgoing-13 >> Host: myhost:zosmfport
.185 6:(o.a.h.headers) http-outgoing-13 >> Connection: Keep-Alive
.185 6:(o.a.h.headers) http-outgoing-13 >> User-Agent: Apache-HttpClient/4.5.13 (Java/1.8.0_341)
.185 6:(o.a.h.headers) http-outgoing-13 >> Accept-Encoding: gzip,deflate
.185 6:(o.a.http.wire) http-outgoing-13 >> "POST /zosmf/services/authenticate HTTP/1.1[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "Accept: text/plain, application/xml, text/xml, application/json, application/cbor, application/*+xml, application/*+json, */*[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "Authorization: Basic c2dyYWR5Onp4Yw==[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "X-CSRF-ZOSMF-HEADER: [\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "Content-Length: 0[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "Host: myhost:zosmfport[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "Connection: Keep-Alive[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "User-Agent: Apache-HttpClient/4.5.13 (Java/1.8.0_341)[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "Accept-Encoding: gzip,deflate[\r][\n]"
.185 6:(o.a.http.wire) http-outgoing-13 >> "[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "HTTP/1.1 401 Unauthorized[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "X-Powered-By: Servlet/3.1[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "X-Content-Type-Options: nosniff[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "X-XSS-Protection: 1; mode=block[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "Strict-Transport-Security: max-age=31536000; includeSubDomains[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "Content-Type: application/json;charset=ISO-8859-1[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "Content-Language: en-US[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "Transfer-Encoding: chunked[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "Date: Fri, 18 Nov 2022 19:29:47 GMT[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "b7[\r][\n]"
.189 6:(o.a.http.wire) http-outgoing-13 << "{"returnCode":8,"reasonCode":1,"message":"Login failed. Check if the user ID and password you use for the Basic Auth is correct, and if the user ID has the required SAF permissions."}[\r][\n]"
.189 6:(o.a.h.headers) http-outgoing-13 << HTTP/1.1 401 Unauthorized
.189 6:(o.a.h.headers) http-outgoing-13 << X-Powered-By: Servlet/3.1
.189 6:(o.a.h.headers) http-outgoing-13 << X-Content-Type-Options: nosniff
.189 6:(o.a.h.headers) http-outgoing-13 << X-XSS-Protection: 1; mode=block
.189 6:(o.a.h.headers) http-outgoing-13 << Strict-Transport-Security: max-age=31536000; includeSubDomains
.189 6:(o.a.h.headers) http-outgoing-13 << Content-Type: application/json;charset=ISO-8859-1
.189 6:(o.a.h.headers) http-outgoing-13 << Content-Language: en-US
.189 6:(o.a.h.headers) http-outgoing-13 << Transfer-Encoding: chunked
.189 6:(o.a.h.headers) http-outgoing-13 << Date: Fri, 18 Nov 2022 19:29:47 GMT




.189 6:(o.a.h.i.e.MainClientExec) Connection can be kept alive for 2000 MILLISECONDS
.189 6:(o.a.h.i.a.HttpAuthenticator) Authentication required
.189 6:(o.a.h.i.a.HttpAuthenticator) myhost:zosmfport requested authentication
.189 6:(o.a.h.i.a.HttpAuthenticator) Response contains no authentication challenges
.190 6:(o.a.http.wire) http-outgoing-13 << "0[\r][\n]"
.190 6:(o.a.http.wire) http-outgoing-13 << "[\r][\n]"
.190 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection [id: 13][route: {s}->https://myhost:zosmfport] can be kept alive for 2.0 seconds
.190 6:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-13: set socket timeout to 0
.190 6:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection released: [id: 13][route: {s}->https://myhost:zosmfport][total available: 2; route allocated: 1 of 100; total allocated: 3 of 1000]
.539 6:(o.z.a.s.c.h.FailedAuthenticationHandler) Unauthorized access to '/gateway/api/v1/auth/login' endpoint
.539 6:(o.z.a.s.c.e.AuthExceptionHandler) 400 Status Code: Bad credentials
.542 10:(o.a.http.wire) http-outgoing-12 << "HTTP/1.1 401 [\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "X-Content-Type-Options: nosniff[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "X-XSS-Protection: 1; mode=block[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Cache-Control: no-cache, no-store, max-age=0, must-revalidate[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Pragma: no-cache[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Expires: 0[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Content-Type: application/json;charset=ISO-8859-1[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Content-Length: 323[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Date: Fri, 18 Nov 2022 19:29:47 GMT[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Keep-Alive: timeout=60[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "Connection: keep-alive[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "[\r][\n]"
.542 10:(o.a.http.wire) http-outgoing-12 << "{"messages":[{"messageType":"ERROR","messageNumber":"ZWEAS120E","messageContent":"Invalid username or password for URL '/apicatalog/auth/login'","messageAction":"Provide a valid username and password.","messageReason":"The username or password is invalid.","messageKey":"org.zowe.apiml.security.login.invalidCredentials"}]}"
.542 10:(o.a.h.headers) http-outgoing-12 << HTTP/1.1 401
.542 10:(o.a.h.headers) http-outgoing-12 << X-Content-Type-Options: nosniff
.542 10:(o.a.h.headers) http-outgoing-12 << X-XSS-Protection: 1; mode=block
.542 10:(o.a.h.headers) http-outgoing-12 << Cache-Control: no-cache, no-store, max-age=0, must-revalidate
.542 10:(o.a.h.headers) http-outgoing-12 << Pragma: no-cache
.542 10:(o.a.h.headers) http-outgoing-12 << Expires: 0
.542 10:(o.a.h.headers) http-outgoing-12 << Content-Type: application/json;charset=ISO-8859-1
.542 10:(o.a.h.headers) http-outgoing-12 << Content-Length: 323
.542 10:(o.a.h.headers) http-outgoing-12 << Date: Fri, 18 Nov 2022 19:29:47 GMT
.542 10:(o.a.h.headers) http-outgoing-12 << Keep-Alive: timeout=60
.542 10:(o.a.h.headers) http-outgoing-12 << Connection: keep-alive
.543 10:(o.a.h.i.e.MainClientExec) Connection can be kept alive for 60000 MILLISECONDS
.543 10:(o.a.h.i.a.HttpAuthenticator) Authentication required
.543 10:(o.a.h.i.a.HttpAuthenticator) myhost:discoport requested authentication
.543 10:(o.a.h.i.a.HttpAuthenticator) Response contains no authentication challenges
.543 10:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection [id: 12][route: {s}->https://myhost:discoport] can be kept alive for
60.0 seconds
.543 10:(o.a.h.i.c.DefaultManagedHttpClientConnection) http-outgoing-12: set socket timeout to 0
.543 10:(o.z.a.s.ApimlPoolingHttpClientConnectionManager) Connection released: [id: 12][route: {s}->https://myhost:discoport][total available: 3; route allocated: 1 of 100; total allocated: 3 of 1000]

1000TurquoisePogs avatar Nov 18 '22 19:11 1000TurquoisePogs

We will work with you in replicating. After some changes, it seemed that we fixed the issue, but as it still exists, this is something we need to resolve.

balhar-jakub avatar Nov 21 '22 09:11 balhar-jakub

Hi, team, We encountered this issue on Zowe 1.25. When we input invalid password, we see the amount of ICH408I until revoke. Is there any workaround to reduce login attempts?

karai-rocket avatar Jan 13 '23 18:01 karai-rocket

Hello,

We have analysed the code for this issue. Out of 2 calls to the URL, one with the basic auth appears nearly empty is just to verify if the login end points exists which runs with empty credentials, the second one is where the actual authentication validation happens.
This is an expected behaviour. Please let us know if you need further assistance.

Thanks,

Shobhajayanna avatar Feb 01 '23 09:02 Shobhajayanna

@1000TurquoisePogs , could you, please, confirm the above?

anton-brezina avatar Feb 01 '23 13:02 anton-brezina

@karai-rocket As for 1.25 there was a bug that was fixed later. So the recommendation is to update to the latest 1.x release

@1000TurquoisePogs Shobhajayanna run the tests and explored the code and wrote above our understanding of what is happening. What else do you need from us?

balhar-jakub avatar Mar 02 '23 13:03 balhar-jakub

Hello, yes this bug DOES still exist on my system, on zowe 2.7. @Shobhajayanna

We have analysed the code for this issue. Out of 2 calls to the URL, one with the basic auth appears nearly empty is just to verify if the login end points exists which runs with empty credentials, the second one is where the actual authentication validation happens. This is an expected behaviour. Please let us know if you need further assistance.

Thank you for the explanation, but that is not the problem that is happening on my system. I am getting 2 real login attempts on zosmf for every 1 login attempt I do to the gateway. There may be an empty credential login attempt as you explain, but if so it's unrelated to what I see. There really is a double-login attempt shown on zosmf when issued from the gateway because it does lock my account in the number of tries it prints. I've had the error on every version of Zowe for as long as I can remember.

It's entirely possible that what I'm seeing is a bug of zosmf rather than of apiml, but I don't have the data to tell the difference yet.

Which URL is used by APIML to login to ZOSMF in this situation? I will try it directly.

I also tried to get info about which zosmf version I have, but I don't know if this is the right info:

Launching zosmfServer (z/OSMF 2.5.0/wlp-1.0.68.cl220920220815-1900) on IBM J9 VM, version 8.0.7.20 - pmz6480sr7fp20-20221020_01(SR7 FP20) (en_US)   

AUDIT     CWWKF0015I: The server has the following interim fixes active in the runtime: PH46816. For a full listing of installed fixes run: productInfo version

Here's what I see in the meantime.

Control behavior: When I login to the desktop and only app-server and zss are enabled, If I type a bad password, I do not get into the desktop, but I also do not get a double-auth failure. I get no message from zosmf, because zss doesnt talk to zosmf for this.

Test behavior: I enable gateway, discovery, and api-catalog. Repeating the steps from the original post, I do see 2 login attempts in zosmf logs for every attempt at the api-catalog login screen.

I checked my RACF setup and saw that it would lock me out upon 10 incorrect password attempts. So, I slowly did 5 incorrect prompts in api-catalog, and yes, it locked my account. So, the double-login I see from zosmf is real, not just duplicate messages.

Here is the config I used for gateway:

zOSMF:
 host: "myhost"
 port: zosmfhost
 applId: "IZUDFLT"
components:
 gateway:
   enabled: false
   port: 7554
   debug: false
   apiml:
     security:
       auth:
         provider: "zosmf"
         zosmf:
           jwtAutoconfiguration: "auto"
           serviceId: “zosmf”

        authorization:
         endpoint:
           enabled: false
         provider: ""
       x509:
         enabled: false
   server:
     internal:
       enabled: false
       port: 7550
       ssl:
         enabled: false

here's what I see from zosmf:

STDOUT

AUDIT     CWWKF0011I: The zosmfServer server is ready to run a smarter planet. The zosmfServer server started in 12.953 seconds.         
AUDIT     CWWKS1100A: Authentication did not succeed for user ID MYUSER. An invalid user ID or password was specified.                    
AUDIT     CWWKS1100A: Authentication did not succeed for user ID MYUSER. An invalid user ID or password was specified.

JESYSMSG

IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.
IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.

JESMSGLG

06.22.26 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  781        
  781               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.22.26 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.22.26 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  783        
  783               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.22.26 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.

which eventually leads to lockout:

06.24.29 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  502        
  502               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.24.29 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.24.29 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  504        
  504               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.24.29 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.25.54 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  537        
  537               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.25.54 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.25.54 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  539        
  539               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.25.54 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.28.48 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  665        
  665               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.28.48 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.28.48 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  667        
  667               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.28.48 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                          
06.36.00 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  527        
  527               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.36.00 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.36.00 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  529        
  529               LOGON/JOB INITIATION - INVALID PASSWORD                                     
06.36.00 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                         
06.39.21 S0002997  ICH70003I YOU HAVE EXCEEDED THE MAXIMUM NUMBER OF RACF PASSWORD ATTEMPTS.     
06.39.21 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  071        
  071               LOGON/JOB INITIATION - EXCESSIVE PASSWORD OR PASS PHRASE ATTEMPTS           
06.39.21 S0002997  ICH408I USER(MYUSER   ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  072        
  072               LOGON/JOB INITIATION - REVOKED USER ACCESS ATTEMPT

1000TurquoisePogs avatar Apr 05 '23 10:04 1000TurquoisePogs

Hi again, Is the URL used POST /zosmf/services/authenticate? If so, then I believe I have found this as a zosmf issue.

I just did that over postman, and got:

07.09.56 S0002997  ICH408I USER(MYUSER  ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  064   
   064               LOGON/JOB INITIATION - INVALID PASSWORD                                
07.09.56 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.                    
07.09.56 S0002997  ICH408I USER(MYUSER  ) GROUP(MYGROUP  ) NAME(SEAN GRADY          )  066   
   066               LOGON/JOB INITIATION - INVALID PASSWORD                                
07.09.56 S0002997  IRR013I  VERIFICATION FAILED. INVALID PASSWORD GIVEN.

That is, the same result as with gateway, but without involving gateway. Do you know if this was an issue previously fixed in zosmf, and that we may just not have the fix? Or, if we must report this as a bug to them.

1000TurquoisePogs avatar Apr 05 '23 11:04 1000TurquoisePogs

Hi,

I confirm the authentication URL end point is /zosmf/services/authenticate.

Thanks, Shobha

Shobhajayanna avatar Apr 05 '23 11:04 Shobhajayanna

Ok great. So, if you do a POST with a wrong password directly to zosmf, without zowe, do you see this same issue that I see when I inspect the JESMSGLG of the zosmf server task?

I'm thinking, maybe I am missing some apar that you have, so maybe you dont see this behavior when I do. Are you familiar with such an apar to fix this problem? I will report the issue to zosmf soon if we don't know.

1000TurquoisePogs avatar Apr 05 '23 12:04 1000TurquoisePogs

Hi,

I am not aware of any missing apar. I tried logging in to ZOSMF instance with wrong password and verified the JESMSGLG. I only see one occurrence of failure.

@balhar-jakub @achmelo Hi, do you know anyone from ZOSMF team who could help us with this issue?

Thanks, Shobha

Shobhajayanna avatar Apr 05 '23 14:04 Shobhajayanna

Hi, I did open a case on zosmf and they said they can reproduce and are working on a fix.

1000TurquoisePogs avatar May 12 '23 12:05 1000TurquoisePogs

@1000TurquoisePogs as there is a case on zosmf, do you want to keep this issue open?

achmelo avatar Jun 12 '23 12:06 achmelo

No, we can close it because there's nothing we can do on our side. I'll close it for now.

1000TurquoisePogs avatar Jul 13 '23 17:07 1000TurquoisePogs