这是笔者对项目进行容器化的时候发现的,简单写个文章来记录一下。

L1000861.jpg

容器里的日志时间跟当前时间对不上

以下是我的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.nowTime.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发送的请求。

总结

项目的容器化之路是一条不归路,路途十分遥远且艰难,有数不尽的深坑在前方等待。镜像所导致的日志时差问题仅仅是迈向深坑之前的一点小磕碰。笔者简单记录,并解决一下,读者请酌情参考。