前言
最近在新公司从事内部系统的后台开发工作,遇到一个诡异的问题,上午一切正常的版本,下发修改了yml配置后,生成的镜像发到测试环境后,只要访问就会触发容器重启。通过和维护人员沟通,发现是程序挂掉之后被k8s重新拉起,导致给人一种反复重启的错觉。
问题发现
通过查看业务日志发现程序在抛出一段错误日志之后紧接着打出了jvm崩溃写hr_err文件的日志,由于k8s再检测到进程挂掉之后,短时间就会用新镜像来覆盖,dump日志也会消失,因此只能通过cat hr_err将内容打出来看一下,核心内容如下:
应用日志:
hr_err日志:
Stack: [0x00007fc8a55f2000,0x00007fc8a56f3000], sp=0x00007fc8a56e86f0, free space=985k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [libc.so.6+0x10b294] __clock_gettime+0x24
C [libc.so.6+0x8865b]
[error occurred during error reporting (printing native stack), id 0xb]
Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
j sun.font.FontConfigManager.getFontConfig(Ljava/lang/String;Lsun/font/FontConfigManager$FontConfigInfo;[Lsun/font/FontConfigManager$FcCompFont;Z)V+0
j sun.font.FontConfigManager.initFontConfigFonts(Z)V+178
j sun.font.FontConfigManager.loadFontConfig()[Lsun/font/FontConfigManager$FcCompFont;+2
j sun.font.FcFontConfiguration.init()Z+39
j sun.font.FcFontConfiguration.<init>(Lsun/font/SunFontManager;)V+16
j sun.awt.X11FontManager.createFontConfiguration()Lsun/awt/FontConfiguration;+53
j sun.font.SunFontManager$2.run()Ljava/lang/Object;+205
v ~StubRoutines::call_stub
J 1135 java.security.AccessController.doPrivileged(Ljava/security/PrivilegedAction;)Ljava/lang/Object; (0 bytes) @ 0x00007fc8ec9d070f [0x00007fc8ec9d06c0+0x4f]
j sun.font.SunFontManager.<init>()V+222
j sun.awt.FcFontManager.<init>()V+1
j sun.awt.X11FontManager.<init>()V+1
v ~StubRoutines::call_stub
J 2422 sun.reflect.NativeConstructorAccessorImpl.newInstance0(Ljava/lang/reflect/Constructor;[Ljava/lang/Object;)Ljava/lang/Object; (0 bytes) @ 0x00007fc8ece1e723 [0x00007fc8ece1e6c0+0x63]
J 2096 C1 sun.reflect.NativeConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object; (89 bytes) @ 0x00007fc8ecd6d1bc [0x00007fc8ecd6c180+0x103c]
J 1910 C1 sun.reflect.DelegatingConstructorAccessorImpl.newInstance([Ljava/lang/Object;)Ljava/lang/Object; (9 bytes) @ 0x00007fc8eccf4e2c [0x00007fc8eccf4dc0+0x6c]
J 1909 C1 java.lang.reflect.Constructor.newInstance([Ljava/lang/Object;)Ljava/lang/Object; (87 bytes) @ 0x00007fc8eccf52e4 [0x00007fc8eccf51a0+0x144]
J 5527 C1 java.lang.Class.newInstance()Ljava/lang/Object; (155 bytes) @ 0x00007fc8ecee4574 [0x00007fc8ecee4200+0x374]
j sun.font.FontManagerFactory$1.run()Ljava/lang/Object;+21
v ~StubRoutines::call_stub
J 1135 java.security.AccessController.doPrivileged(Ljava/security/PrivilegedAction;)Ljava/lang/Object; (0 bytes) @ 0x00007fc8ec9d070f [0x00007fc8ec9d06c0+0x4f]
j sun.font.FontManagerFactory.getInstance()Lsun/font/FontManager;+17
j sun.font.SunFontManager.getInstance()Lsun/font/SunFontManager;+0
j sun.font.FontDesignMetrics.getMetrics(Ljava/awt/Font;Ljava/awt/font/FontRenderContext;)Lsun/font/FontDesignMetrics;+0
j sun.java2d.SunGraphics2D.getFontMetrics()Ljava/awt/FontMetrics;+21
j io.springboot.captcha.ArithmeticCaptcha.graphicsImage([CLjava/io/OutputStream;)Z+80
j io.springboot.captcha.ArithmeticCaptcha.out(Ljava/io/OutputStream;)Z+13
通过日志大概定位了就是程序在生成验证码的时候出现了异常。
问题定位过程
一、
通过业务日志结合测试环境代码debug,发现程序崩溃和业务日志中的java.io.FileNotFoundException: /tmpactionj.ttf (Permission denied) 好像关系不大,这句异常最终查下来主要是两个原因:
1、captcha-core.jar在生成验证码时会从jar包resouce根目录下获取action.ttf字体文件做为临时文件复制到系统临时目录,即/tmp下,但是程序在拼接时未做判断导致最终拼接出的临时文件名为/tmpaction.ttf.
2、如果运行程序的系统用户无root权限,则无权限在系统根目录创建文件,因此会抛出异常。 如果运行程序的系统用户是root用户或者拥有在根目录创建文件的权限则不会抛出异常。
对应的解决方法:
启动程序时指定临时目录:-Djava.io.tmpdir=/tmp/
二、
当我把第一个问题解决之后,发现只要访问获取验证码接口还是会jvm崩溃。于是我开始分析hr_err日志,通过日志中的堆栈信息大概判断出这是再读取系统的字体库时出现了问题,于是我重新部署了之前可以正常生成验证码的镜像,通过多次比对发现一个差异(差异见下图),/usr/share/fonts目录不一样,通过网上查资料可以知道该目录下存放的是系统的字体库。于是我有了一个大胆的猜测,如果目录存在程序就会优先从fonts目录下加载字体,如果不存在则会在第一个问题中提到的临时目录中去加载。于是重新打包代码在生成镜像时将/usr/share/fonts目录删除,果然验证码可以正常生成了。
可以正常生成验证码:
生成验证失败并jvm崩溃:
问题解决
上述问题其实是两个问题。两个问题可以独立发生且第一个问题不会影响验证码生成。
1、启动命令中添加参数:-Djava.io.tmpdir=/tmp/
2、镜像生成时删除/usr/share/fonts目录。
截止到现在问题虽然解决了。但是还有一些疑问需要后续持续跟踪:
①、为什么基于同一个基础镜像生成的镜像目录结构会不一样?
②、为什么captcha-core-2.2.3.jar从系统临时文件获取字体文件时会范这么低级的错误?我一度怀疑这个是我使用不规范的问题。