自定义realm出现doGetAuthorizationInfo多次重复调用

前言：此次排查的过程，主要是利用debug模式下，深入源码打断点才发现问题所在。

一、问题描述：

练习shiro认证授权，发现授权方法中相关的sql语句多次重复执行了。于是，各种排查，为什么会有多次重复执行相同的sql查询，这岂不是很影响性能。于是有了下面的排查过程。

二、发现问题，截图如下：

三、排查过程

（过程1）：肯定是先从shiro的配置文件逐个排查过了，没有任何发现，还是解决不了问题。

（过程2）：既然是多次sql语句执行，那考虑到是某个方法重复调用了。于是定位到了下边的这个方法。

a）debug模式启动，断点来到上边的Set<String> roleNames = roleDAO.queryRoleNamesByUsername(username);。

b）于是从逆向思维出发，是谁调用了protected AuthorizationInfo doGetAuthorizationInfo(PrincipalCollection principalCollection)方法。

借助调试工具，Step Out (Shift + F8)：步出，从步入的方法内退出到方法调用处，此时方法已执行完毕，只是还没有完成赋值。

c）借助调式工具，Step Out看看是谁调用了doGetAuthorizationInfo()方法。
来到AuthorizingRealm类的isPermitted(PrincipalCollection principals, String permission)方法。

d）继续Step Out，来到同类下的isPermitted(PrincipalCollection principals, Permission permission);

e）继续Step Out，来到同类下的info = this.doGetAuthorizationInfo(principals);

e）继续Step Out多次…，来到了一个循环do{}while()循环，如下。

f）到了这一步，多少看出一点猫腻了，这个permission：“sys:c:delete”，就是来自数据库的权限内容。

g）于是好奇重复执行了多少次该sql的执行。
在doGetAuthorizationInfo(PrincipalCollection principalCollection)方法体内定义一个变量，看看到底执行了多少次。
定义的变量如下：

执行结果如下：

发现都是次数1，这就奇怪了，说明都是一个新的对象调用该方法。
h）接着数了下，一共执行了11次，然后回到数据库，查看有没有什么记录是11次的。发现还是没有，到这里就又觉得没思绪了。

i）最后，想到了前端是用的thymeleaf模板中用到了shiro的授权标签。

数了下，恰好是11个，这就跟控制台打印的sql方法执行的个数相符合了。

j）为了确认下，是由于前端这个11个shiro授权标签导致的。继续操作到步骤e）来，然后释放掉当前断点，又来到当前断点，这其实是第二次来到相同的地方，现象如下：
第一次：sys:c:delete

第二次：sys:c:update

第三次：sys:c:find

多次…
这个过程，permission就跟thymeleaf中shiro授权标签对应上了。

四、确定问题所在

至此，可以确定，控制台中打印的sql查询，是由于前端thymeleaf模板中，多次使用的shiro授权标签导致的，这也就印证了为什么doGetAuthorizationInfo(PrincipalCollection principalCollection)方法中定义的i变量，重复打印出的结果是1了。

五、总结

由于学shiro是通过视频学的，这样容易发现学得不系统，没方法领会到问题的关键所在。即使在排查过程中，百度有回答说是调用subject.isPermitted()就会触发doGetAuthorizationInfo(PrincipalCollection principalCollection)方法执行，但还是联想不到是自己使用了多个shiro的授权标签，从而多次调用了doGetAuthorizationInfo(PrincipalCollection principalCollection)方法。

但更加体会到，掌握debug和深入源码去排查问题方法的重要性，只有亲身体会，才会发觉深入了解源码的重要性。

— end