解决Rails项目容器化途中日志时差问题
这是笔者对项目进行容器化的时候发现的,简单写个文章来记录一下。
容器里的日志时间跟当前时间对不上
以下是我的Rails项目的Dockfile
文件全貌
FROM ruby:2.7.2
RUN curl https://deb.nodesource.com/setup_14.x | bash
RUN apt-get update && apt-get install -y nodejs postgresql-client
RUN npm install --global yarn
RUN mkdir /app
WORKDIR /app
COPY Gemfile Gemfile.lock ./
RUN gem install bundler
# RUN bundle config set force_ruby_platform true
RUN bundle install
RUN yarn install
COPY . .
ENV RAILS_ENV=production
RUN rails assets:precompile
EXPOSE 3000
CMD ["rails", "server", "-b", "0.0.0.0"]
通过命令
> docker build -t lanzhiheng/stone .
就能构建出想要的镜像,先把项目跑起来
> docker run -it -p 4000:3000 lanzhiheng/stone
有意思的事情来了,我随便贴几条日志
I, [2022-12-26T14:17:24.775420 #1] INFO -- : [be1b63ce-4696-4f70-acd9-425c37bd9f0e] Processing by HomeController#index as HTML
D, [2022-12-26T14:17:24.799921 #1] DEBUG -- : [be1b63ce-4696-4f70-acd9-425c37bd9f0e] Rendering layout layouts/application.html.erb
D, [2022-12-26T14:17:24.801253 #1] DEBUG -- : [be1b63ce-4696-4f70-acd9-425c37bd9f0e] Rendering home/index.html.erb within layouts/application
笔者请求发送于北京时间2022-12-26 22:17:24
,然而日志记录到的时间是2022-12-26 14:17:24
相差了整整八个小时,如果没猜错容器里面使用的时间应该是格林威治时间,也就是常说的零时区。然而我查了一下Rails的配置
> docker run -it lanzhiheng/stone bin/rails c
> Rails.application.config.time_zone
=> "Asia/Shanghai"
> Time.current
=> Mon, 26 Dec 2022 22:23:06.614421836 CST +08:00
确认已经设置好东八区,这么看来,日志系统所认的时区可能跟Rails本身的设置没有太大关系。
Time.now还是Time.current
从Rails的配置信息可知,Rails的默认日志系统会依赖于Logger::Formatter
> Rails.application.config.log_formatter
=> #<Logger::Formatter:0x000000010ad622d8 @datetime_format=nil>
这是Ruby标准库所定义的类,再去窥探一下Ruby标准库的源代码,发现每次写日志都会调用这行代码
...
@logdev.write(
format_message(format_severity(severity), Time.now, progname, message))
调用的时候会获取当前时间。真相大白了,看来日志的时间是按照Time.now
来定,而不是笔者直觉所认为的Time.current
。
刚开始接触Rails的时候,有个前辈就告知我Time.now
跟Time.current
的不同。简单来说Time.current
会根据Rails系统设置的时区来返回当前时间,而Time.now
则不会。为啥这样?其实也很简单,毕竟Time.current
是Rails引入的扩展方法,而Time.now
是Ruby标准库里面固有的方法。
> irb
> Time.now
=> 2022-12-26 22:28:15.066059 +0800
> Time.current
Traceback (most recent call last):
.....
NoMethodError (undefined method `current' for Time:Class)
标准库本来就有的东西,确实没必要认Rails体系所设置的时区信息,它始终以所在系统时区为准。在Rails上下文中测试,两者确实是足足差了8个小时。
> bin/rails c
> Time.current
=> Mon, 26 Dec 2022 22:29:37.818203586 CST +08:00
> Time.now
=> 2022-12-26 14:29:39.691374504 +0000
简单解决一下
要解决这个问题其实也简单,毕竟容器技术的优势就在于我们可以灵活把控运行时的系统环境。既然Time.now
是根据系统的时区来返回当前时间,我们只需要把系统强行设置成东八区即可。简单修改Dockerfile
文件就能做到这一点
...
RUN mkdir /app
WORKDIR /app
COPY Gemfile Gemfile.lock ./
+
+ENV TZ="Asia/Shanghai"
+
RUN gem install bundler
...
添加一行来设置环境变量TZ="Asia/Shanghai"
,就能让我们得到一台时区为东八区的机器。我们在“新的机器”上再运行目标服务,应该就能看到上面的日志时间跟你自己电脑上的时间能对得上了。
> docker run -it -p 4000:3000 lanzhiheng/stone
看看这次日志对不对
D, [2022-12-28T21:48:08.376092 #1] DEBUG -- : [f01bea0d-a85b-4f85-b67a-1e9cfdb27801] Rendered application/_header.html.erb (Duration: 496.8ms | Allocations: 26874)
I, [2022-12-28T21:48:08.376501 #1] INFO -- : [f01bea0d-a85b-4f85-b67a-1e9cfdb27801] Rendered layout layouts/application.html.erb (Duration: 521.9ms | Allocations: 30795)
I, [2022-12-28T21:48:08.377159 #1] INFO -- : [f01bea0d-a85b-4f85-b67a-1e9cfdb27801] Completed 404 Not Found in 526ms (Views: 268.9ms | ActiveRecord: 256.2ms | Allocations: 31453)
这次就正常了,容器内外的时差消失了。笔者确实是在北京时间2022-12-28 21:48:08
发送的请求。
总结
项目的容器化之路是一条不归路,路途十分遥远且艰难,有数不尽的深坑在前方等待。镜像所导致的日志时差问题仅仅是迈向深坑之前的一点小磕碰。笔者简单记录,并解决一下,读者请酌情参考。