Kevin Cheung created HIVE-25627:
-----------------------------------
Summary: Subsequent post success to hive endpoint results in 401,
then reauth with credentials
Key: HIVE-25627
URL: https://issues.apache.org/jira/browse/HIVE-25627
Project: Hive
Issue Type: Bug
Components: JDBC
Affects Versions: 3.1.1, 4.0.0
Reporter: Kevin Cheung
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.
[https://github.com/apache/httpcomponents-client/blob/a0b85d44c26430ff8354a0af5a1b7d58e2e5bce5/httpclient/src/main/java/org/apache/http/client/protocol/RequestAuthCache.java#L77]
# 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)
Showing beeline console output with debug logs: Above 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
{color:#de350b}21/10/19 23:05:38 [main]: DEBUG protocol.RequestAddCookies:
CookieSpec selected: default{color}
{color:#de350b}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]{color}
{color:#de350b}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]{color}
{color:#de350b}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]{color}
{color:#de350b}21/10/19 23:05:38 [main]: DEBUG protocol.RequestAuthCache: Auth
cache not set in the context{color}
21/10/19 23:05:38 [main]: DEBUG conn.BasicHttpClientConnectionManager: Get
connection for route
\{s}->[https://cluster40.azurehdinsight.net:443|https://cluster40.azurehdinsight.net/]
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
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
