Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
3.1.1, 4.0.0
-
None
-
None
Description
Opening beeline with DEBUG logs enables shows a pattern of doing. It looks like there is no httpclientcontext, the authCache is null and therefore cannot use cached credential information so it must reauthenticate with the actual username/pass.
- Authenticate with creds (status 200).
- HTTP request gets "HTTP/1.1 401 - Authentication failed" Credentials were missing
- Auth cache not set in the context
- Retry with creds (succeeds)
Reprod:
- Enable the beeline jdbc DEBUG logs
- Use beeline to enter your cluster through a public endpoint using username/password
Showing beeline console output with debug logs: Logs start with status 200 authenticating with username/pass, but then subsequent request leads to 401 and requires reauth again.
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << HTTP/1.1 200 OK
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Content-Type: application/x-thrift
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Content-Encoding: gzip
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Vary: Accept-Encoding, User-Agent
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << request-id: e9339125c2f84d0b857d36129b4851f2
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-active: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-http-host: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-http-gateway: gw0-cluster
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-host: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Strict-Transport-Security: max-age=31536000; includeSubDomains
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Set-Cookie: JSESSIONID=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net; expires=Wed, 20-Oct-2021 23:05:38 GMT; path=/; secure
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Set-Cookie: x-ms-hdi-host=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net; path=/; secure
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Set-Cookie: hive.server2.auth=cu=admin&rn=4735931476793922767&s=QNX50wcftWqEXyGNHVi9cjwP/A9awQsBtXF9fc5gamQ=;Version=0;Max-Age=86400; HttpOnly; path=/; secure; HttpOnly; SameSite=None
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Date: Tue, 19 Oct 2021 23:05:38 GMT
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Content-Length: 171
21/10/19 23:05:38 [main]: DEBUG execchain.MainClientExec: Connection can be kept alive indefinitely
21/10/19 23:05:38 [main]: DEBUG protocol.ResponseProcessCookies: Cookie accepted [JSESSIONID="hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net", version:0, domain:cluster40.azurehdinsight.net, path:/, expiry:Wed Oct 20 23:05:38 UTC 2021]
21/10/19 23:05:38 [main]: DEBUG protocol.ResponseProcessCookies: Cookie accepted [x-ms-hdi-host="hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net", version:0, domain:cluster40.azurehdinsight.net, path:/, expiry:null]
21/10/19 23:05:38 [main]: DEBUG protocol.ResponseProcessCookies: Cookie accepted [hive.server2.auth="cu=admin&rn=4735931476793922767&s=QNX50wcftWqEXyGNHVi9cjwP/A9awQsBtXF9fc5gamQ=", version:0, domain:cluster40.azurehdinsight.net, path:/, expiry:Wed Oct 20 23:05:38 UTC 2021]
21/10/19 23:05:38 [main]: DEBUG conn.BasicHttpClientConnectionManager: Releasing connection 10.0.0.5:34278<->13.72.83.213:443
21/10/19 23:05:38 [main]: DEBUG conn.BasicHttpClientConnectionManager: Connection can be kept alive indefinitely
21/10/19 23:05:38 [main]: DEBUG execchain.MainClientExec: Cancelling request execution
21/10/19 23:05:38 [main]: ERROR jdbc.HttpRequestInterceptorBase: cookie enable set retry key
21/10/19 23:05:38 [main]: ERROR jdbc.HttpRequestInterceptorBase: additionalHeaders
21/10/19 23:05:38 [main]: ERROR jdbc.HttpRequestInterceptorBase: customCookies
21/10/19 23:05:38 [main]: ERROR jdbc.HttpRequestInterceptorBase: process end
21/10/19 23:05:38 [main]: DEBUG protocol.RequestAddCookies: CookieSpec selected: default
21/10/19 23:05:38 [main]: DEBUG protocol.RequestAddCookies: Cookie [version: 0][name: JSESSIONID][value: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net][domain: cluster40.azurehdinsight.net][path: /][expiry: Wed Oct 20 23:05:38 UTC 2021] match [(secure)cluster40.azurehdinsight.net:443/hive2]
21/10/19 23:05:38 [main]: DEBUG protocol.RequestAddCookies: Cookie [version: 0][name: hive.server2.auth][value: cu=admin&rn=4735931476793922767&s=QNX50wcftWqEXyGNHVi9cjwP/A9awQsBtXF9fc5gamQ=][domain: cluster40.azurehdinsight.net][path: /][expiry: Wed Oct 20 23:05:38 UTC 2021] match [(secure)cluster40.azurehdinsight.net:443/hive2]
21/10/19 23:05:38 [main]: DEBUG protocol.RequestAddCookies: Cookie [version: 0][name: x-ms-hdi-host][value: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net][domain: cluster40.azurehdinsight.net][path: /][expiry: null] match [(secure)cluster40.azurehdinsight.net:443/hive2]
21/10/19 23:05:38 [main]: DEBUG protocol.RequestAuthCache: Auth cache not set in the context
21/10/19 23:05:38 [main]: DEBUG conn.BasicHttpClientConnectionManager: Get connection for route {s}->https://cluster40.azurehdinsight.net:443
21/10/19 23:05:38 [main]: DEBUG execchain.MainClientExec: Executing request POST /hive2 HTTP/1.1
21/10/19 23:05:38 [main]: DEBUG execchain.MainClientExec: Target auth state: UNCHALLENGED
21/10/19 23:05:38 [main]: DEBUG execchain.MainClientExec: Proxy auth state: UNCHALLENGED
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> POST /hive2 HTTP/1.1
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Content-Type: application/x-thrift
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Accept: application/x-thrift
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> User-Agent: Java/THttpClient/HC
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Cookie:
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Content-Length: 85
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Host: cluster40.azurehdinsight.net:443
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Connection: Keep-Alive
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Cookie: JSESSIONID=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net; hive.server2.auth=cu=admin&rn=4735931476793922767&s=QNX50wcftWqEXyGNHVi9cjwP/A9awQsBtXF9fc5gamQ=; x-ms-hdi-host=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> Accept-Encoding: gzip,deflate
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 >> X-XSRF-HEADER: true
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "POST /hive2 HTTP/1.1[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Content-Type: application/x-thrift[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Accept: application/x-thrift[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "User-Agent: Java/THttpClient/HC[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Cookie: [\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Content-Length: 85[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Host: cluster40.azurehdinsight.net:443[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Cookie: JSESSIONID=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net; hive.server2.auth=cu=admin&rn=4735931476793922767&s=QNX50wcftWqEXyGNHVi9cjwP/A9awQsBtXF9fc5gamQ=; x-ms-hdi-host=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "X-XSRF-HEADER: true[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 >> "[0x80][0x1][0x0][0x1][0x0][0x0][0x0][0x7]GetInfo[0x0][0x0][0x0][0x2][0xc][0x0][0x1][0xc][0x0][0x1][0xc][0x0][0x1][0xb][0x0][0x1][0x0][0x0][0x0][0x10][0xbc]La[0x84]j[0xe0]IU[0x86][0xb1]l2[0xd8][0xb0]0Y[0xb][0x0][0x2][0x0][0x0][0x0][0x10][0x1][0xea]^(y[0xba]H[0xcc][0xa6]_[0x2][0xc7][0xf9][0xe2][0x89]z[0x0][0x0][0x8][0x0][0x2][0x0][0x0][0x0][0x11][0x0][0x0]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "HTTP/1.1 401 - Authentication failed[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "Cache-Control: private[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "Transfer-Encoding: chunked[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "Content-Type: application/json; charset=utf-8[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "request-id: 6954f08be3f747b5aeefa41e44a0befd[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "x-ms-hdi-active: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "x-ms-hdi-http-host: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "x-ms-hdi-http-gateway: gw0-cluster[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "x-ms-hdi-host: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "WWW-Authenticate: Basic realm=HDInsight[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "x-ms-hdi-errorcode: Credentials were missing.[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "Strict-Transport-Security: max-age=31536000; includeSubDomains[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "Set-Cookie: x-ms-hdi-host=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net; path=/[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "Date: Tue, 19 Oct 2021 23:05:38 GMT[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "a3[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.wire: http-outgoing-0 << "{"Code":"Unauthorized","Message":"Credentials were missing.","CorrelationId":"6954f08be3f747b5aeefa41e44a0befd","ResponseTimestamp":"2021-10-19T23:05:38.6922494Z"}[\r][\n]"
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << HTTP/1.1 401 - Authentication failed
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Cache-Control: private
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Transfer-Encoding: chunked
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Content-Type: application/json; charset=utf-8
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << request-id: 6954f08be3f747b5aeefa41e44a0befd
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-active: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-http-host: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-http-gateway: gw0-cluster
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-host: hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << WWW-Authenticate: Basic realm=HDInsight
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << x-ms-hdi-errorcode: Credentials were missing.
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Strict-Transport-Security: max-age=31536000; includeSubDomains
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Set-Cookie: x-ms-hdi-host=hn0-cluster.hcxg3d3d41fu1ezwzrnpsapynf.bx.internal.cloudapp.net; path=/
21/10/19 23:05:38 [main]: DEBUG http.headers: http-outgoing-0 << Date: Tue, 19 Oct 2021 23:05:38 GMT
21/10/19 23:05:38 [main]: DEBUG execchain.MainClientExec: Connection can be kept alive indefinitely
21/10/19 23:05:38 [main]: DEBUG auth.HttpAuthenticator: Authentication required
21/10/19 23:05:38 [main]: DEBUG auth.HttpAuthenticator: cluster40.azurehdinsight.net:443 requested authentication