记一次服务日志乱码异常的排查过程

见贤思齐

记一次服务日志乱码异常的排查过程问题浮现某天工作中，突然接收到了用户对于内部测试环境上java进程服务日志乱码异常的反馈，经过查看相关文件，发现中文字体无法正常显示，严重影响到了用户的日常工作，因此开始处理该问题。排查过程通过查看Java进程的详细信息，发现编码设置成了ASCII编码，【图中的ANS_X3.4.是JDK对ASCII的别名】但是服务包含的所有文件均编码正常，为正常的UTF-8。因此并不是服务本身导致的问题，由于Java服务的编码发生异常，并且转转内部的Java服务启动时并没有指定编码，从官方文档上入手，确认在默认情况下的JVM对编码的处理，基于文档中对于编码参数解释，服务的编码将会读取系统的配置进而确定服务的编码配置.因此我怀疑可能是这台机器上的配置被进行了修改，是个例问题，首先，我先设置了服务编码配置-Dfile.encoding=UTF-8，指定编码为UTF-8后，服务的日志输出立刻恢复了正常，后续，在业务使用的低峰期时，去掉编码配置，对这台服务器进行了重启。重启后观察服务重启的状态，发现服务状态依旧正常，日志输出正常，便认为这次的问题已经解决。但是仅仅几天后，用户又开始频繁的反馈，再次出现了编码异常的问题，并且异常的机器较之上次，又有新机器出现了这种异常情况，这就确认了遇到的编码异常问题并不是简单的指定编码和重启机器就能彻底有效的解决该问题。深入排查在转转内部的测试环境中，我们分别使用KVM虚拟机和Docker容器来作为测试机器使用，而Docker容器未出现该问题，出现问题的机器均是KVM机器。在KVM虚拟机上我们都部署了一个自研的agent，借助该agent，我们可以打印出进程在运行中使用的环境变量，因此我们可以拿到机器上的环境变量，通过针对问题机器和正常机器的对比。发现LC_CTYPE的设置和LANG的配置存在差异，为了定位问题的源头，我将问题机器上的LC_CTYPE环境变量硬编码为en_US.UTF-8,随后再次进行测试，发现问题机器的编码恢复正常，日志输出正常。可怀疑问题的源头是由机器上的LC_CTYPE发生了错误设置，进而导致Java服务设置默认编码时错误的设置为ASCII。Linux上的LC_CTYPE变量的作用是会去更改文字，符号的编码，将其变成我们设置的编码值。但是异常机器上的LC_CTYPE的编码是怎么被设置成UTF-8呢？在针对MacOS上常用的开源终端软件ITerm2的一个Issue的问题讨论中：在ssh连接中的LC_CTYPE错误设置，发现了关键的信息，Issue主要讨论的是ssh指令登录服务器的时候,默认会将本地的环境变量传递到远程机器，尝试同步两方的环境变量设置，至此，我们可以确认问题的根源是由于环境变量的错误同步导致的。其中客户端传递哪些变量取决于本地的ssh_config文件中的SendEnv配置，而远程机器接收哪些变量取决于服务端sshd_config文件的AcceptEnv配置，详细信息可以查看文档以了解。问题处理当我们了解了问题的根源，对于问题的解决也十分的清晰，最终的问题解决方案应该从三个方向出发，分别是客户端不发送错误的编码&服务端不接收错误的编码&执行兜底，避免异常情况客户端不发送错误的编码：设置iterm2，不让iterm2给远程主机发送UTF-8编码尝试进行同步直接修改客户端(本地)的ssh_config配置，如果你有本地的管理员权限，可以修改/etc/ssh/路径下ssh_config文件中的SendEnv，如果你不想对远端机器发送任何变量同步，可以直接注释该行。不接收错误的编码：如果你有远程机器的管理员权限，可以修改远程机器/etc/ssh/路径下的sshd_config文件，去掉你不想接收的变量升级agent，在agent侧在服务启动前兜底处理，检查是否存在"LC_CTYPE"："UTF-8"的设置，如果存在，修改为"en_US.UTF-8",让JVM读取到正确的环境变量。抽丝剥茧即使Iterm2错误设置导致了远程机器上的LC_CTYPE变成了UTF-8，和Java服务的编码变成ASCII有什么因果关系吗？让我们看一下Linux官方文档。在关于locale的官方文档中,有这么一句话,意思为如果程序设置locale环境变量，将会调用setlocale()函数，为其传递对应的正确参数。继续深挖，让我们看一下setlocale()函数的细节，这里我们能够发现两个重点在程序启动期间，会在所有的用户代码执行之前，默认执行一次 setlocale(LC_ALL,"C")setlocale函数存在于locale.h头文件里，接收两个参数，第一个参数是用于标识是哪个lcoale环境变量例如“LC_ALL/LC_CTYPE等等”，第二个参数是变量真实的值。当我们错误的从本地向远程机器发出同步环境变量LC_CTYPE命令，setlocale函数尝试为LC_CTYPE设置UTF-8的值，但是发现UTF-8并不是一个合法的期望值。这是因为LC_COLLATE,LC_CTYPE,LC_MESSAGES,LC_MONETARY,LC_NUMERIC,LC_TIME这些变量对于设置的value是有格式要求的!具体格式为：[language[_territory][.codeset][@modifier]]，其中@modifier是一个可选的附加字段。例如en_US.UTF-8就是正常的，符合要求的格式。当我们设置了一个不合法的变量，基于linux中的setlocale文档,我们可以发现如下结果：当我们调用setlocale函数时，传入的UTF-8是一个不合法的值，这时对于该项环境变量的操作不作改动，函数返回null。这时LC_CTYPE便会沿用我们之前设置的setlocale(LC_ALL,"C")；LC_CTYPE的值被设置成为了“C”语言环境。在这个语言环境下LC_CTYPE等价于7位的ASCII码，只支持128个字符。因此结合之前LC_CTYPE的作用，它将会更改文字，符号，将其变为你设置的编码。这种情况下Java服务的编码被错误的设置为了ASCII。个人收获在工作过程中，我们总会遇到各种各样的问题，但更重要的是遇到问题时，不要将就逃避，当问题发生了，一定要抱着严谨的态度去彻底解决，并对于遇到的问题也多进行总结。想了解更多转转公司的业务实践，点击关注下方的公众号吧！