Rails 记一次 Rails 项目异常排查

zhongfox · 发布于 2017年01月20日 · 最后由 wangekko 回复于 2017年02月20日 · 3153 次阅读
1914
本帖已被设为精华帖!

背景

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

共收到 27 条回复
15

这种才是好棒的分享

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

6829

可以评为年度好文了!

23224

好精彩

8134

深度好文!

3363

精彩,学习了

12381

手工点赞

1959

很精彩。

674

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

8886

这等好文不加精?

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

好文,异常排查的典范。

96

厉害,学习了。

5575

👏 好文,学习了

2973

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

18855

精彩!

16793

我的问题是:在这个片段

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

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

1914

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

96

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

5390

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

3469

好文!

15139

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

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

487

排查思路很清晰

3679

好文,条理清晰

30343

小白路过 赞一下

14823

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

96

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

96

受教了🤗

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