keycloak请求阻塞解决
2023-01-20 本文已影响0人
定金喜
1.问题描述
公司有的项目使用keycloak作为统一身份认证、权限控制的方法，后端使用的是springboot，所以一般是使用springboot+集成keycloak作为统一登录的方案，具体搭建流程可以参考官方文档，一直没有遇到问题，但是某天客户反馈说页面突然打不开了，但是过了一阵子就好了，有时候没来得及定位问题就恢复了。
问题出现的前端展示情况
有一次持续了几分钟，而且其他项目(使用springboot集成keycloak)都有概率出现这种问题，这种情况分析一般原因是因为接口比较耗时，所以进入容器jstack后打印出了当前的堆栈信息，堆栈信息比较长，我只粘贴了出问题的部分：
"http-nio-8081-exec-9" #61 daemon prio=5 os_prio=0 tid=0x00007efc702c1000 nid=0x4c waiting for monitor entry [0x00007efc778f6000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.keycloak.adapters.rotation.JWKPublicKeyLocator.getPublicKey(JWKPublicKeyLocator.java:60)
- waiting to lock <0x00000003f1888968> (a org.keycloak.adapters.rotation.JWKPublicKeyLocator)
at org.keycloak.adapters.rotation.AdapterTokenVerifier.getPublicKey(AdapterTokenVerifier.java:121)
at org.keycloak.adapters.rotation.AdapterTokenVerifier.createVerifier(AdapterTokenVerifier.java:111)
at org.keycloak.adapters.rotation.AdapterTokenVerifier.verifyToken(AdapterTokenVerifier.java:47)
at org.keycloak.adapters.BearerTokenRequestAuthenticator.authenticateToken(BearerTokenRequestAuthenticator.java:103)
at org.keycloak.adapters.BearerTokenRequestAuthenticator.authenticate(BearerTokenRequestAuthenticator.java:88)
at org.keycloak.adapters.RequestAuthenticator.authenticate(RequestAuthenticator.java:67)
at org.keycloak.adapters.springsecurity.filter.KeycloakAuthenticationProcessingFilter.attemptAuthentication(KeycloakAuthenticationProcessingFilter.java:154)
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:212)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.keycloak.adapters.springsecurity.filter.KeycloakPreAuthActionsFilter.doFilter(KeycloakPreAuthActionsFilter.java:96)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:92)
at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
....
这应该后端请求keycloak获取publicKey出现了阻塞。
2.问题原因分析
初步分析是调用keycloak出现了问题，进入JWKPublicKeyLocator的60行，代码如下：
Check if we are allowed to send request
synchronized (this) {
currentTime = Time.currentTime();
if (currentTime > lastRequestTime + minTimeBetweenRequests) {
sendRequest(deployment);
lastRequestTime = currentTime;
} else {
log.debug("Won't send request to realm jwks url. Last request time was " + lastRequestTime);
}
return lookupCachedKey(publicKeyCacheTtl, currentTime, kid);
}
因为当前JWKPublicKeyLocator是单例，同一个进程所有线程公用这个实例，所以当一个线程程序无法退出时，其他线程执行到synchronized只能阻塞，继续去看sendRequest函数，该函数会调用keycloak接口获取publicKey，协议是http。
抛出问题：
1.调用获取publicKey接口为啥会出现长时间未返回？
2.是否有设置超时时间，当接口超出时间未返回时快速失败？
我们后端使用springboot自动配置keycloak，配置文件主要有三个参数
keycloak.realm=realmId
keycloak.resource=clientId
keycloak.auth-server-url=http://127.0.0.1:8180/auth
这几个参数是KeycloakSpringBootProperties配置类自动注入的，其中keycloak.auth-server-url配置的就是keycloak调用的baseurl，客户环境该参数是域名形式，不是ip+端口格式，所以调用时会走域名解析，负载均衡等过程，如果客户的外网环境很差，出现网络抖动等问题，通过这种方式调用还是可能会出现数据长时间未返回的情况。通过代码分析，这里的调用设置的超时时间等参数用的是默认值,可以查看org.apache.http.client.config.RequestConfig类，默认是使用
public static final RequestConfig DEFAULT = (new RequestConfig.Builder()).build();
构建默认值，Builder里面的默认值，有关超时的三个参数
private int connectionRequestTimeout = -1;
private int connectTimeout = -1;
private int socketTimeout = -1;
-1表示不超时，所以我们的接口默认是不会超时的，当一个请求阻塞住没法释放锁，其它请求都没办法响应，只能等待锁释放。
3.问题解决方案
总结一下避免此类问题的办法
1.如果keycloak部署在同一个局域网环境中，配置的keycloak的地址参数可以使用内网ip参数，不使用域名或者外网，这样不会出现由于网络问题导致的接口长时间不返回；
2.调用外部接口时，必须设置超时时间，避免由于一次调用超时导致整个服务的不可用
本来以为直接将keycloak.auth-server-url参数配置成内网地址就可以用了，部署了之后又发现了其他问题，所以第一步就准备对超时时间进行设置，先查看keycloak jdk包中调用的部分源码：
HttpGet和httpClient都未对超时时间进行设置，而且未提供比较明显的扩展配置去设置这个时间，而且deployment这个实例虽然全局唯一，但是未使用spring容器托管，没法直接注入，但是可以通过其他spring托管的bean间接找到deployment这个实例，然后获取httpclient进行参数修改，因为HttpGet是每次请求都会创建的，没法通过其他方式改变其内部的数据。通过分析代码发现，AdapterDeploymentContext实例是spring托管的，而且能通过它找到deployment实例。接下来就是确定怎么拦截这个请求，一般有两种方式filter或者interceptor，在此场景中使用filter会更方便点（因为keycloak jdk本身就定义了很多filter，而且支持自定义filter），例如jdk中自带的org.keycloak.adapters.springsecurity.filter.KeycloakPreAuthActionsFilter，参考这个filter，我们自定义filter，代码如下：
@Component
public class ChangeTimeOutFilter implements Filter {
@Resource
private AdapterDeploymentContext deploymentContext;
private volatile boolean deploymentChanged = false;
@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
HttpFacade facade = new SimpleHttpFacade((HttpServletRequest)request, (HttpServletResponse)response);
KeycloakDeployment deployment = deploymentContext.resolveDeployment(facade);
if (deployment == null) {
chain.doFilter(request, response);
return;
}
//deployment是全局唯一，只需要修改一次
if (deploymentChanged) {
chain.doFilter(request, response);
return;
}
/**
* 设置超时时间
*/
HttpParams params = deployment.getClient().getParams();
params.setIntParameter(CoreConnectionPNames.SO_TIMEOUT, 10000);
params.setIntParameter(CoreConnectionPNames.CONNECTION_TIMEOUT, 10000);
params.setLongParameter(ClientPNames.CONN_MANAGER_TIMEOUT, 10000L);
deploymentChanged=true;
chain.doFilter(request, response);
}
代码部署后，发现有时候错误日志会输出：
Error when sending request to retrieve realm keys
org.keycloak.adapters.HttpClientAdapterException: IO error
at org.keycloak.adapters.HttpAdapterUtils.sendJsonHttpRequest(HttpAdapterUtils.java:57)
at org.keycloak.adapters.rotation.JWKPublicKeyLocator.sendRequest(JWKPublicKeyLocator.java:99)
at org.keycloak.adapters.rotation.JWKPublicKeyLocator.getPublicKey(JWKPublicKeyLocator.java:63)
at org.keycloak.adapters.rotation.AdapterTokenVerifier.getPublicKey(AdapterTokenVerifier.java:121)
at org.keycloak.adapters.rotation.AdapterTokenVerifier.createVerifier(AdapterTokenVerifier.java:111)
at org.keycloak.adapters.rotation.AdapterTokenVerifier.verifyToken(AdapterTokenVerifier.java:47)
at org.keycloak.adapters.BearerTokenRequestAuthenticator.authenticateToken(BearerTokenRequestAuthenticator.java:103)
at org.keycloak.adapters.BearerTokenRequestAuthenticator.authenticate(BearerTokenRequestAuthenticator.java:88)
at org.keycloak.adapters.RequestAuthenticator.authenticate(RequestAuthenticator.java:67)
......
at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
说明超时时间设置已经生效了，接下来解决参数设置内网报错问题
设置内网登录失败
先看错误日志（此日志级别是debug，非error，所以这块对源码是有疑问的）
2022-04-01 16:45:33.069 [http-nio-8081-exec-3] DEBUG o.k.adapters.BearerTokenRequestAuthenticator - Found [1] values in authorization header, selecting the first value for Bearer.
2022-04-01 16:45:33.069 [http-nio-8081-exec-3] DEBUG o.k.adapters.BearerTokenRequestAuthenticator - Verifying access_token
2022-04-01 16:45:33.071 [http-nio-8081-exec-3] DEBUG o.k.adapters.BearerTokenRequestAuthenticator - Failed to verify token
2022-04-01 16:45:33.071 [http-nio-8081-exec-3] DEBUG org.keycloak.adapters.RequestAuthenticator - Bearer FAILED
2022-04-01 16:45:33.071 [http-nio-8081-exec-3] DEBUG o.k.a.s.f.KeycloakAuthenticationProcessingFilter - Auth outcome: FAILED
2022-04-01 16:45:33.071 [http-nio-8081-exec-3] DEBUG o.k.a.s.f.KeycloakAuthenticationProcessingFilter - Authentication request failed: org.keycloak.adapters.springsecurity.KeycloakAuthenticationException: Invalid authorization header, see WWW-Authenticate header for details
org.keycloak.adapters.springsecurity.KeycloakAuthenticationException: Invalid authorization header, see WWW-Authenticate header for details
at org.keycloak.adapters.springsecurity.filter.KeycloakAuthenticationProcessingFilter.attemptAuthentication(KeycloakAuthenticationProcessingFilter.java:162)
at org.springframework.security.web.authentication.AbstractAuthenticationProcessingFilter.doFilter(AbstractAuthenticationProcessingFilter.java:212)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.keycloak.adapters.springsecurity.filter.KeycloakPreAuthActionsFilter.doFilter(KeycloakPreAuthActionsFilter.java:96)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:103)
最终定位到是有一个RealmUrlCheck校验逻辑没通过导致
分析出这两个值，一个是内网地址，一个是域名地址，虽然指向同一个地方，但是值不同，校验失败，为什么会出现这两个不同的地址，可以从前后端交互逻辑说起：
