Google上查不到，该如何排查这个问题？——记录Archiva踩坑过程

Google上查不到，该如何排查这个问题？——记录Archiva踩坑过程

12 2019-07-11 20:28:18

## 背景
maven deploy的过程中Archiva一直响应没有权限，于是想起来Archiva系统有个比较怪的点——默认是需要定期修改密码的。
一旦之前设置的密码过期，就必须通过“忘记密码”流程修改，而这个流程需要发送邮件，不过可能这个邮件发送有什么问题，一直收不到。
于是乎就必须走重新创建用户的流程，即删除Archiva的用户信息目录后重启。我的用户目录在`/usr/local/data/databases/users`。
查阅资料后，发现可以在Archiva的WebUI中`User Runtime Configuration`-`Properties第三页`-`security.policy.password.expiration.enabled`选项设置为false关闭密码过期策略。

### 惨痛的掉坑过程
原以为关闭过期策略就万事大吉，没想到后续的这一系列操作直接把CI/CD流程整瘫痪了：
1. 删除用户目录并重启，在WebUI关闭了密码过期策略
2. 部署博客服务后服务启动失败，仅瞟了一眼日志就误以为内存不够用了
**ps.这里特别说明一下，服务器内存比较小（穷），在扩容内存之前是经常不够用的，于是惯性思维，认为确实内存不够用了。而后来定位到真正的原因是服务器maven package过程中jar未更新。**
3. 把Archiva所使用的Tomcat关闭，释放内存资源
4. 服务仍然启动失败，发现原来是jar有问题，于是尝试修复jar中的问题（当然，实际上是jar未更新）
5. 需要部署jar，因此又启动Archiva，这时Archiva启动不了，报错

至此，整个状态是：博客服务由于依赖问题无法启动；Archiva服务无法启动；Jenkins正常但由于Archiva瘫痪无法打包发布。

### Archiva报错内容
核心错误日志：
```text
...	# 服务无法启动
...	# 一些bean无法创建
...Error creating bean with name 'ldapConnectionFactory#archiva'...	# 一些ldap相关的bean无法创建
...	# 一些其他的原因
Caused by: javax.naming.InvalidNameException: Invalid name: lee	# 异常root，这个name是Archiva登录用户名
    at javax.naming.ldap.Rfc2253Parser.doParse(Rfc2253Parser.java:111)
    at javax.naming.ldap.Rfc2253Parser.parseDn(Rfc2253Parser.java:70)
    at javax.naming.ldap.LdapName.parse(LdapName.java:785)
    at javax.naming.ldap.LdapName.<init>(LdapName.java:123)
    at org.apache.archiva.redback.common.ldap.connection.LdapConnectionConfiguration.setBindDn(LdapConnectionConfiguration.java:198)
    at org.apache.archiva.web.runtime.ldap.ArchivaLdapConnectionFactory.initialize(ArchivaLdapConnectionFactory.java:68)
    ... 117 more
```

简而言之，一些LDAP相关的内容创建失败，最核心的原因是某个地方的用户名验证出错了，而这个用户名是当时关闭密码过期策略时登录的Archiva用户名。

## 排查过程
**0. 搜索引擎**
由于Archiva参考资料较少，同时这个异常抛出来相关信息非常少，跟Archiva相关的仅两行，绞尽脑汁用了各种关键词组合也找不出几个相关的内容。万能的Google也失灵了。

**1. 查看Rfc2253Parser.doParse方法**
追踪代码，发现抛异常的原因是用户名中不包含等号。可是为什么要包含等号？

**2. 查看LdapName.<init>方法**
LdapName的构造方法中有入参name，直接透传至Rfc2253Parser.doParse方法中。

**3. 查看ArchivaLdapConnectionFactory.initialize方法**
没办法，信息太少，只能硬着头皮上——把Archiva源码拉下来找。
追踪到该方法中有调用`ldapConnectionConfiguration.setBindDn`方法，在这里传入了name。
看上下文，这是一个读取配置文件的工具类，由于配置文件变动导致了服务启动异常。

通过资料了解到LDAP是一个目录访问协议，可以简单理解为通过一系列KV Pair实现树形的目录层次结构，在这之中baseDn可以理解为根目录，bindDn也就是报错的setter目标可以理解为根目录下绑定的一个子目录。这能够解释为何传入的bindDn格式上必须包含等号（KV Pair）。

到这里就很奇怪了，在掉坑过程中我并没有修改过配置文件，即使通过WebUI修改的配置也是布尔型数据，为何把登录用户名写入了这个根本不相关的配置项里？况且现在Archiva启动不了，要把密码过期策略重新打开恢复修改前的状态也不行了。

排查源码过程中发现Archiva中LDAP相关的配置文件分为两处，即`{appBase}/conf/archiva.xml`和`~/.m2/archiva.xml`，然而在这其中都“没有”相关的配置。尤其是因为Archiva的部署和配置方式都很奇怪，配置文件散落各处，导致排查难度提高。

**4. 再次搜索**
了解到核心原因后再次使用各种关键词组合进行搜索，终于在某个角落里发现了一句话（Google首屏最后两条，关键词`ArchivaLdapConnectionFactory archiva configuration`）：
![](/img/pic/2019071120205445500_png_714_329_51802)
> How can I undo my configuration so that Archiva starts again without LDAP?

这位受害人的描述跟我的经历一模一样，连报错都是一样的。
几经辗转，最终通过这个标题在Apache Issues中看到了最终的解决方案。

## 问题解决
在[参考资料](https://issues.apache.org/jira/browse/MRM-1907?page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel&focusedCommentId=15580166#comment-15580166)中受害人自述的帮助下我解决了这个问题：删除`~/.m2/archiva.xml`文件中的LDAP相关配置后重启Archiva解决。

![](/img/pic/2019071120231428401_png_578_935_20128)
> ~/.m2/archiva.xml文件，中间有很多空行，第一眼看以为根本没什么内容，直接导致排查方向出错

而这个自述及相关评论也完全表述了我的心声。
- 不知情的情况下Archiva修改了LDAP中bindDn的配置（有说是浏览器自动填充用户名密码导致的，我倒认为是bug，也没细看）
- 启动时未做配置文件预先验证
- 异常抛出信息过少，不看源码不知道是配置有问题
- 配置文件分散且相关说明少，不看源码根本不知道配置文件在哪
- 配置文件中间空行过多，容易误导排查方向
- 两年前2.2.0版本的bug，2.2.3版本还没有修复（有提到修复版本在不使用LDAP的情况下配置出错也可正常启动，但非预期的配置修改这个bug还在）

总的来说，非预期且无相关性的配置改动、重要的debug信息被吞会导致排查过程及其困难，这一点在我们自己的日常开发中也非常值得注意。
陷入排查困境时查看源码可能会有额外收获，更有利于提取问题本质（更好Google）。

## 参考资料
[[MRM-1907] Archiva won't start due to a misconfigured Redback Runtime Configuration - ASF JIRA](https://issues.apache.org/jira/browse/MRM-1907?page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel&focusedCommentId=15580166#comment-15580166)