目录
现象描述
微信预约小程序的后端服务使用了shiro,来对用户的请求进行鉴权。但是经常有用户反馈微信小程序经常抛出“请求错误,请重试”,导致客户预订失败,客户问题反馈了很就,一直没有查出来。
问题排查
1 错误代码定位,由于使用shiro开源框架作为用户鉴权。onAccessDenied方法在什么情况下会触发呢?Shiro先会根据cookie的sessionId去获取用户会话的session,当用户的权限不满足时,会被拒绝并进行onAccessDenied方法。
2 日志定位。在后端服务代码中加了大量埋点日志,可以发现当用户请求被拒绝的,总有一段日志报错。
2020-06-28 11:32:14.892[http-nio-8080-exec-2][WARN ] o.a.s.m.AbstractRememberMeManager.onRememberedPrincipalFailure:449 There was a failure while trying to retrieve remembered principals. This could be due to a configuration problem or corrupted principals. This could also be due to a recently changed encryption key, if you are using a shiro.ini file, this property would be 'securityManager.rememberMeManager.cipherKey' see: http://shiro.apache.org/web.html#Web-RememberMeServices. The remembered identity will be forgotten and not used for this request.
2020-06-28 11:32:14.892[http-nio-8080-exec-2][WARN ] o.a.s.m.DefaultSecurityManager.getRememberedIdentity:617 Delegate RememberMeManager instance of type [org.apache.shiro.web.mgt.CookieRememberMeManager] threw an exception during getRememberedPrincipals().
org.apache.shiro.crypto.CryptoException: Unable to execute 'doFinal' with cipher instance [javax.crypto.Cipher@2379893e].
at org.apache.shiro.crypto.JcaCipherService.crypt(JcaCipherService.java:462)
at org.apache.shiro.crypto.JcaCipherService.crypt(JcaCipherService.java:445)
at org.apache.shiro.crypto.JcaCipherService.decrypt(JcaCipherService.java:390)
at org.apache.shiro.crypto.JcaCipherService.decrypt(JcaCipherService.java:382)
at org.apache.shiro.mgt.AbstractRememberMeManager.decrypt(AbstractRememberMeManager.java:482)
at org.apache.shiro.mgt.AbstractRememberMeManager.convertBytesToPrincipals(AbstractRememberMeManager.java:419)
at org.apache.shiro.mgt.AbstractRememberMeManager.getRememberedPrincipals(AbstractRememberMeManager.java:386)
at org.apache.shiro.mgt.DefaultSecurityManager.getRememberedIdentity(DefaultSecurityManager.java:612)
at org.apache.shiro.mgt.DefaultSecurityManager.resolvePrincipals(DefaultSecurityManager.java:500)
at org.apache.shiro.mgt.DefaultSecurityManager.createSubject(DefaultSecurityManager.java:346)
--
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.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:688)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1639)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
Caused by: javax.crypto.BadPaddingException: Given final block not properly padded. Such issues can arise if a bad key is used during decryption.
at com.sun.crypto.provider.CipherCore.unpad(CipherCore.java:975)
at com.sun.crypto.provider.CipherCore.fillOutputBuffer(CipherCore.java:1056)
at com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:853)
at com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:446)
at javax.crypto.Cipher.doFinal(Cipher.java:2164)
at org.apache.shiro.crypto.JcaCipherService.crypt(JcaCipherService.java:459)
这段日志的大概意思,由于Shiro组件的Cihper由于密钥不正确,导致解码错误而抛出异常。这段日志大概是发生,在shiro获取用户session,并且在解码时抛出的错误。
o.a.s.m.AbstractRememberMeManager.onRememberedPrincipalFailure:449 There was a failure while trying to retrieve remembered principals. This could be due to a configuration problem or corrupted principals
3 源码排查。根据错误的日志堆栈,shiro的AbstractRememberMeManager在decrypt(),会使用密钥去解码。
进一步扒源码,默认的CipherKey是随机生成的,cipherService.generateNewKey()。
有shiroConfig的CookieRememberMeManager没有设置cipherKey,则会shiro随机生成cipherKey。
怀疑点
1 由于后端采用分布式部署,不同机器随机生成的cipherKey不相同,假设用户A先通过服务B进行鉴权,使用服务B的cipherKey进行解密,用户A在预订时,请求直接打到服务器C,那么Shiro会使用服务器C的cipherKey进行解密服务B加密的session,那就会抛出以上的错误。
验证
线上部署的两台机器,用户的登陆请求打到了服务器B,当用户的请求打到服务器A时,就会出现cipher异常,这样就验证了怀疑点是正确的。
改进
分布式服务,如果采用shiro组件去做鉴权,在CookieRememberMeManager一定要设置统一的cipherKey。