Rails 记一次 Rails 项目异常排查

zhongfox · 2017年01月20日 · 最后由 seven.lee 回复于 2018年04月27日 · 6405 次阅读
本帖已被管理员设置为精华贴

背景

rails 项目data_service, 在线上部署了 2 台机器,两台都是 rake 的执行器,LX-hostYJ-host, 前者执行 rake 正常,但是后者执行 rake 总是报错:

$ bundle exec rake public:home_banner RAILS_ENV=production
rake aborted!
NoMethodError: undefined method `find_special_banner' for #<Class:0x007f1e1c96d728>
.../data_service/vendor/bundle/ruby/2.1.0/gems/activerecord-4.2.6/lib/active_record/dynamic_matchers.rb:26:in `method_missing'
.../data_service/lib/data_service/public/home_banner.rb:11:in `block in index_background'
......

开发同学在线下一直没法重现,因此怀疑是线上机器的问题,请求运维协助排查机器差异,但是线上机器系统,环境几乎一模一样,排查无果。


项目结构

data_service 是一个比较常规的 rails 4 项目,文件还是比较多,我只列出涉及到的文件结构,这是事后诸葛,开始排查时并不清楚哪些文件是有关联的:

├── app
│   ├── models
│   │   ├── home_banner.rb
│   │   ├── st_superscript.rb
├── config
│   ├── initializers
│   │   ├── data_service_monitor_register.rb
├── lib
│   ├── data_service
│   │   ├── base.rb
│   │   ├── public
│   │   │   ├── home_banner.rb
│   │   │   ├── st_superscript.rb
│   ├── tasks
│   │   ├── public.rake
│   └── website
│       └── util
│           ├── image_uploadable.rb

略了很多不相关的文件。


排查过程

因为开发线下没有重现,因此登陆线上堡垒机排查,为了不影响现有服务,我将项目复制了一份到/tmp 下。

rake 的入口在lib/tasks/public.rake, 代码很简单:

# lib/tasks/public.rake
desc '首页品牌广告'
task :brand_banners => :environment do
  DataService::BrandBanners.save
end

从上面的错误栈中可以看到异常抛出点在lib/data_service/public/home_banner.rb, 涉及代码如下:

# lib/data_service/public/home_banner.rb
class DataService::HomeBanner < DataService::Base
......
banner = HomeBanner.find_special_banner(banner_type, user_type).first
......
end

问题很明显,类 HomeBanner 没有找到find_special_banner这个类方法,HomeBanner 定义在app/models/home_banner.rb, 这个文件比较长,有 692 行,看了代码,其中的确定义了类方法find_special_banner:

# app/models/home_banner.rb
class HomeBanner < ActiveRecord::Base
  include Concerns::ImageUploadable
  .......
  class << self
    def find_special_banner(banner_type = "", user_type = "")
      ......
    end
  end
  .......
end

类是否一致:Object#object_id

首先想到的是lib/data_service/public/home_banner.rb 中使用的 HomeBanner 和app/models/home_banner.rb里定义的 HomeBanner 不是同一个类,因为ruby 常量查找有一个比较复杂的过程,经常会出现查找不正确的情况。

Ruby 提供了Object#object_id 可以作为对象的标识,因此先在以上 2 个文件中打印:

# lib/data_service/public/home_banner.rb
class DataService::HomeBanner < DataService::Base
  ......
  puts "1111111: #{HomeBanner.object_id}" # 调试代码
  puts "2222222: #{::HomeBanner.object_id}" # 调试代码
  banner = HomeBanner.find_special_banner(banner_type, user_type).first
  ......
end
# app/models/home_banner.rb
class HomeBanner < ActiveRecord::Base
  puts "3333333: #{HomeBanner.object_id}" # 调试代码
  include Concerns::ImageUploadable
  .......
  class << self
    def find_special_banner(banner_type = "", user_type = "")
      ......
    end
  end
  .......
end

输出如下:

3333333: 70249085971460
1111111: 70249085971460
2222222: 70249085971460
rake aborted!
NoMethodError: undefined method `find_special_banner' for #<Class:0x007fc847a15808>
......

结果显示 2 个类的 id 一致,排除常量查找问题。

检视单键方法:Object#singleton_methods(all=true)

直接问题是找不到类方法,那就到类方法的定义处去测试一下,ruby 的类方法就是类的单键方法,可以使用Object#singleton_methods(all=true)进行检视:

# app/models/home_banner.rb
class HomeBanner < ActiveRecord::Base
puts "3333333: #{HomeBanner.object_id}" # 调试代码
  include Concerns::ImageUploadable
.......
  class << self
    def find_special_banner(banner_type = "", user_type = "")
      ......
    end
    puts "all HomeBanner class methods: #{HomeBanner.singleton_methods(false)}" # 调试代码
  end
.......

输出如下:

3333333: 69955224157780
rake aborted!
NoMethodError: undefined method `find_special_banner' for #<Class:0x007f3f70927ca8>
......

不过非常意外的是,最下面的调试代码在 rake 报错前没有任何输出,但是上面一行调试代码却是有输出的。排查了一会,基本可以确定,rake 在加载 HomeBanner 这个类的中途发生了异常 (在定义类方法前), 但是这个异常被吃掉了,导致 HomeBanner 加载发生异常没有抛出。最终抛出的却是使用 HomeBanner 时缺乏类方法的错误。

确定代码调用栈 Kernel#caller

异常被 rescue 但是没有正确处理或者上报,是导致调试困难的常见原因,麻烦的是根本不知道异常是在哪里吃掉的,也就不知道在加载 HomeBanner 时发生了什么异常。

还好强大的 Ruby 提供了Kernel#caller, 可以输出代码的调用栈。从上面的排查可以看出,HomeBanner 的确是加载并执行了,只是在中途停止了,没有加载完,因此可以在文件头打印出调用栈,看看是哪行该死的代码吃掉了异常:

# app/models/home_banner.rb
puts caller # 调试代码
class HomeBanner < ActiveRecord::Base
  include Concerns::ImageUploadable
  .......
  class << self
    def find_special_banner(banner_type = "", user_type = "")
      ......
    end
  end
  .......
end

输出结果:

vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:274:in 'require'
vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:274:in 'block in require'
vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:240:in 'load_dependency'
vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:274:in 'require'
vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:360:in 'require_or_load'
vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:494:in 'load_missing_constant'
vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.6/lib/active_support/dependencies.rb:184:in 'const_missing'
lib/data_service/base.rb:81:in 'const_get'
lib/data_service/base.rb:81:in 'inherited'
lib/data_service/public/home_banner.rb:1:in '<top (required)>'

可以看到项目加载 HomeBanner 的入口在lib/data_service/base.rb:

# lib/data_service/base.rb
name = subclass.name.demodulize
top_model = Object.const_get(name) rescue nil

这里的确有rescue!, 这个需求是当获取不到 name 对应的 Activerecord 模型,就直接返回 nil. 只是这里结果并不是找不到 HomeBanner, 而是找到 HomeBanner 后,加载时,HomeBanner 里有异常。

检视异常堆栈:Exception#backtrace

rake 加载 HomeBanner 会出错,但是这个异常在 rails server 或者 rails console 里并没有重现,因此直接的办法是在异常点检视异常信息,Ruby 异常类 Exception 提供了丰富的检视方法,简化的调试代码如下:

# lib/data_service/base.rb
name = subclass.name.demodulize
begin
  top_model = Object.const_get(name)
rescue => e
  puts e.message
  puts e.backtrace
end

输出结果:

uninitialized constant Concerns::ImageUploadable
app/models/home_banner.rb:4:in `<class:HomeBanner>'
app/models/home_banner.rb:3:in `<top (required)>'
lib/data_service/base.rb:84:in `const_get'
lib/data_service/base.rb:84:in `inherited'
lib/data_service/public/home_banner.rb:1:in `<top (required)>'
config/initializers/data_service_monitor_register.rb:4:in `block (2 levels) in <top (required)>'

最终发现是app/models/home_banner.rbinclude Concerns::ImageUploadable 无法找到这个模块!

app/models/concerns/ 下找了一下,并没发现这个模块,最后通过 grep 发现这个文件躺在lib/website/util/image_uploadable.rb, 这是违反「约定大于配置」的后果。

猜测与验证

机器YJ-hostapp/models/home_banner.rb无法找到lib/website/util/image_uploadable.rb, 但是机器 LX-host是正常的,因此到正常的机器LX-host中,再次使用caller定位到lib/website/util/image_uploadable.rb 在另一个 model app/models/st_superscript.rb 中 require 了:

# app/models/st_superscript.rb
require "#{Rails.root}/lib/website/util/image_uploadable.rb"
class StSuperscript < ActiveRecord::Base

第一感觉是这里的 require 不同寻常,image_uploadable.rb是上传文件的通用 concern, 但是单单在其中一个使用 modelapp/models/st_superscript.rb中 require, app/models/home_banner.rb 中并没有 require.

到这里基本上可以猜测到,正常机器LX-host 是先加载了app/models/st_superscript.rb 然后再加载了app/models/home_banner.rb, 依赖的 concern 是在前者中进行 require, 而出错的机器YJ-host的加载顺序刚好相反,因此导致app/models/home_banner.rb无法找到依赖 concern.

在两台机器的st_superscript.rbhome_banner.rb分别增加调试代码,两台机器打印结果的顺序不同,证明了之前的猜测。

文件加载顺序

相同的代码,在几乎相同的机器上,文件加载顺序不一致,这个比较罕见,不过可能的原因也有很多,很多 shell 命令都不保证文件遍历的顺序。

通过caller 继续确定 2 个 model 的加载入口,在文件config/initializers/data_service_monitor_register.rb里:

# config/initializers/data_service_monitor_register.rb
DataService::Application.config.to_prepare do
  ......
  Dir[File.join(Rails.root, 'lib/data_service/public/*.rb')].each { |file| load file }
  ......
end

lib/data_service/public 下的home_banner.rbst_superscript.rb 会分别加载app/models下的同名文件。

看到Dir, 猜测很大的可能是这个 api 返回的文件列表顺序不一致,查看 api 文档:

Dir[ string [, string ...] ] → array
Equivalent to calling Dir.glob([string,...],0).

......

glob( pattern, [flags] ) → matches
glob( pattern, [flags] ) { |filename| block } → nil
Expands pattern, which is an Array of patterns or a pattern String, and returns the results as matches or as arguments given to the block.

Note that this pattern is not a regexp, it’s closer to a shell glob. See File.fnmatch for the meaning of the flags parameter. Note that case sensitivity depends on your system (so File::FNM_CASEFOLD is ignored), as does the order in which the results are returned.

可以看到的是,glob 并没有保证返回的顺序,返回顺序和机器,系统相关!

还是不放心?在两台机器的 irb 分别执行一下:

出错的机器:

> Dir['lib/data_service/public/*.rb'].grep /st_superscript|home_banner/
=> [
  "lib/data_service/public/home_banner.rb",
   "lib/data_service/public/st_superscript.rb"
]

正确机器:

> Dir['lib/data_service/public/*.rb'].grep /st_superscript|home_banner/
=> [
   "lib/data_service/public/st_superscript.rb",
  "lib/data_service/public/home_banner.rb"
]

顺序的确不同!


修复

通过排查过程,可以发现,代码至少违反了以下最佳实践:

  • 吃掉异常,屏蔽掉了底层异常的现象,导致出错后排查困难。

  • 违反了「约定大于配置」, Concern 模块image_uploadable.rb 按照约定应该放到app/models/concerns/, 这个目录属于eager_load_paths, 目录内的模块会被自动 require, 但是项目却把image_uploadable.rb放到了lib/website/util/image_uploadable.rb, 因此需要在使用的地方去手动 require, 但是没处理好加载顺序。导致异常。

  • 项目在开发测试阶段间接地依赖了Dir返回的文件顺序,虽然项目本意并不关心lib/data_service/public/下的文件加载顺序,程序在线下开发和测试测试阶段能正常运行完全是一个「巧合」. 如果依赖文件加载顺序,应该自己在结果后面进行 sort.

解决法办法很简单:把image_uploadable.rb 移到它应该在的位置app/models/concerns/image_uploadable.rb, 问题就解决了。


总结

  1. 你真的理解「约定大于配置」的原因吗?你真的尊重「约定大于配置」吗?

    违反 rails 的「约定」会带来不必要的代价,concern 不在它该在的位置,没法自动加载,需要在 model 写奇怪的代码进行手动 require.

    这个问题发生在一两个月前,导致若干 rake 异常,只有部分机器报错。开发排查,运维排查,开发运维扯皮,最后迫不得已上线调试,前后也花了将近 2 个小时。

  2. 开发应该对「奇怪」的代码有反感。

    我觉得这里项目里最奇怪的代码是在app/models/st_superscript.rb里,手动 require 了大部分 model 都要使用公共 Concern require "lib/website/util/image_uploadable.rb", 这应该是在开发途中,违反「约定大于配置」的一个补丁,开发应该对这种奇怪的代码多去刨根问底。

  3. 对涉及 IO 遍历的返回值,需要考虑一下顺序是否会影响最终结果,如果 api 文档没有保证顺序,那么就是不确定的,自己加上sort是个不赖的办法。不要让你的代码依赖「巧合」运行。

  4. Ruby 强大元编程非常利于调试,要善加利用。

    调试前后用到的主要技巧:

    • 判断对象一致性:Object#object_id
    • 检视单键方法:Object#singleton_methods
    • 确定代码调用栈:Kernel#caller
    • 检视异常堆栈:Exception#backtrace
  5. 调试还是需要一些合理猜测和验证。

  6. 尊重结果,按图索骥。

    以后遇到类似 bug, 不要轻易说「你的环境有问题吧?」 「在我这里可是好的」, 因为这一定是「你」的问题。 The First Rule of Programming: It's Always Your Fault

这种才是好棒的分享

曾经碰到诡异无法重现问题在半 PRD 环境装的 VS2005 搞 😂

可以评为年度好文了!

深度好文!

精彩,学习了

很精彩。

好文,说的很详细,管理员置成精华贴吧

这等好文不加精?

Rei 将本帖设为了精华贴。 01月23日 20:09

好文,异常排查的典范。

厉害,学习了。

👏 好文,学习了

排查思路清晰,总结到位,只是定位问题,debug 也许比打印更好 😂

我的问题是:在这个片段

检视单键方法:Object#singleton_methods(all=true)

的描述中,不是应该注意到很可能就是include Concerns::ImageUploadable的问题了吗?因为 2 个puts之间并没有几行代码啊。。。

#16 楼 @killernova 2 个 puts 之间其实有 200 多行代码,篇幅原因,在文章中省略掉了中间代码。当时是希望通过 singleton_methods 去判断类方法是否加上了,意外发现了第二个 puts 没有输出。

实战经验,手动点赞!!!

碰到过类似的,rack+grape 环境 也是因 Dir 的顺序问题导致启动失败

通常是文件系统返回文件列表的顺序不同。

我以前也遇到过,有些时候,是按照文件在目录里的创建顺序返回的,而不是按照字母顺序。

排查思路很清晰

好文,条理清晰

小白路过 赞一下

我觉得最主要的是千万不要这么写rescue nil

吃掉异常,哈。大部分新手都会这样做,正常的做法,至少要在日志里面记录一下。

还有一种解决方案可以试试,在 config/appliaction 中使用 autoload_paths 配置一下,

需要 登录 后方可回复, 如果你还没有账号请 注册新账号