Làm chủ quản lý log: Tránh rối loạn không đọc được

Khi bạn gặp một bug lạ, dường như không thể giải quyết, cải thiện logging có thể là bước tốt nhất bạn có thể thực hiện. Logging tốt là cách dễ dàng nhất để phát hiện và sửa toàn bộ các loại bug. Khi bạn log đủ thông tin, bạn có thể thấy dữ liệu của mình thay đổi như thế nào trong một request. Bạn có thể theo dõi các cuộc gọi bạn thực hiện đến các dịch vụ khác, và điều tra phản hồi. Thực tế, khi debugger thất bại, logging đã giúp tôi sửa bug khó nhất tôi từng gặp.

Nhưng log quá nhiều, và file log của bạn sẽ nhanh chóng biến thành một đống lộn xộn các thông điệp không đọc được, không hữu ích. Làm sao bạn có thể lọc chỉ thông tin bạn quan tâm từ đống dữ liệu đó? Bạn có thể in thông điệp theo cách dễ dàng lọc sau?

Đánh dấu tin nhắn log của bạn

Rails bao gồm TaggedLogging, giúp bạn nhanh chóng phân loại các tin nhắn log liên quan. Khi bạn tag một logger, bạn sẽ nhận được một dấu hiệu ở đầu thông điệp. Vì vậy thay vì:

Finding people... Person Load (0.3ms) SELECT "people".* FROM "people" Found 0 people!

Bạn có thể tag Rails logger:

logger.tagged("People") do logger.debug "Finding people..." @people = Person.all logger.debug "Found #{@people.length} people!" end

Và bạn sẽ thấy gì đó như thế này:

[People] Finding people... [People] Person Load (0.3ms) SELECT "people".* FROM "people" [People] Found 0 people!

Bây giờ, tin nhắn log quan tâm đến những thứ khác nhau có thể trông khác nhau.

Một số ví dụ tagged logger

Khi bạn log thường xuyên hơn, và log những thứ phức tạp hơn, bạn sẽ tự nhiên nhận ra những khu vực mà những tag đó sẽ làm cho thông điệp của bạn rõ ràng hơn. Nhưng có một vài nơi tôi thấy tagged logging đặc biệt hữu ích. Tôi thường tag những nơi đó ngay lập tức.

Bạn có thể log các request bạn thực hiện đến các API khác:

logger.tagged("GitHub API") do uri = URI("https://api.github.com/repos/rails/rails/tags") logger.info { "Fetching #{uri}" } tags = JSON.parse(Net::HTTP.get(uri)) logger.info { "First tag: #{tags.first["name"]}" } end

[GitHub API] Fetching https://api.github.com/repos/rails/rails/tags [GitHub API] First tag: v4.2.4.rc1

Bằng cách đó, bạn có thể dễ dàng thấy ứng dụng của bạn đang nói chuyện với API đó như thế nào và khi nào.

(Điều này hoạt động đặc biệt tốt với Faraday middleware, hoặc nếu bạn chỉ giao tiếp với máy chủ qua một Gateway).

Background job cũng hoạt động tốt với tagged logging:

require "active_support/tagged_logging" Resque.logger = ActiveSupport::TaggedLogging.new(Resque.logger) module LoggedJob def around_perform_log_job(*args) logger.tagged(name) do logger.info { "Performing #{name} with #{args.inspect}" } yield end end end class MyJob extend LoggedJob def self.perform(*args) ... end end

Bây giờ, bất kỳ job nào kế thừa LoggedJob sẽ có tất cả tin nhắn log của nó được tag với tên lớp của job.

Và nếu bạn có một user đã đăng nhập, bạn có thể tag thông điệp với user ID của họ:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do logger.debug "Finding people..." @people = Person.all logger.debug "Found #{@people.length} people!" end

[user-123] Finding people... [user-123] Person Load (0.3ms) SELECT "people".* FROM "people" [user-123] Found 0 people!

Cuối cùng, nếu bạn thêm một dòng vào config/environments/production.rb (hoặc development.rb), bạn có thể để Rails tự động tag thông điệp của bạn:

config.log_tags = [ :subdomain, :uuid ]

log_tags liệt kê các tag bạn muốn xuất hiện ở đầu mỗi mục log Rails. Mỗi symbol tham chiếu đến một phương thức trên ActionDispatch::Request, vì vậy :uuid nghĩa là request.uuid.

Bạn cũng có thể truyền một Proc nhận đối tượng request:

config.log_tags = [ :subdomain, :uuid, lambda { |request| request.headers["User-Agent"] } ]

Nhưng tôi không thấy điều đó thường xuyên.

Những tag mặc định này rất hay: uuid có thể gắn kết tất cả các mục log xảy ra trong một request, và nếu bạn giữ session trên máy chủ, session ID cũng hữu ích. Với những tag đó, và đủ thông điệp, bạn có thể truy vết những đường đi rất phức tạp qua ứng dụng của bạn. Và thường, đó là những gì cần để tìm ra bug xấu xí đó đã xảy ra như thế nào.

Bạn dùng Rails logger trong ứng dụng của mình bao nhiêu? Bạn đã thử tagged logging chưa? Nếu chưa, hãy thử tìm một chỗ cho nó. Tagging hành động của user là khởi đầu tốt. Nó sẽ giúp bạn lần sau khi bạn phải debug một bug đa bước điên rồ.

Nếu bạn muốn học thêm về logging và các kỹ thuật debug khác, tôi đã dành một chương toàn bộ của Practicing Rails cho việc tìm và sửa lỗi bạn sẽ gặp khi tạo ứng dụng. Lấy chương đầu tiên miễn phí ở đây.