diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml new file mode 100644 index 0000000..0c7e453 --- /dev/null +++ b/.github/workflows/main.yml @@ -0,0 +1,31 @@ +name: Test + +on: + push: + branches: + - master + + pull_request: + +jobs: + build: + runs-on: ubuntu-latest + name: Ruby ${{ matrix.ruby }} + strategy: + matrix: + ruby: + - '2.6' + - '2.7' + - '3.0' + - '3.1' + - '3.2' + + steps: + - uses: actions/checkout@v3 + - name: Set up Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: ${{ matrix.ruby }} + bundler-cache: true + - name: Run the default task + run: bundle exec rake diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..5c249f1 --- /dev/null +++ b/.gitignore @@ -0,0 +1,13 @@ +/.bundle/ +/.yardoc +/_yardoc/ +/coverage/ +/doc/ +/pkg/ +/spec/reports/ +/tmp/ + +# rspec failure tracking +.rspec_status + +Gemfile.lock diff --git a/.rspec b/.rspec new file mode 100644 index 0000000..34c5164 --- /dev/null +++ b/.rspec @@ -0,0 +1,3 @@ +--format documentation +--color +--require spec_helper diff --git a/.rubocop.yml b/.rubocop.yml new file mode 100644 index 0000000..7a6cfff --- /dev/null +++ b/.rubocop.yml @@ -0,0 +1,29 @@ +AllCops: + TargetRubyVersion: 2.6 + +Style/StringLiterals: + Enabled: true + EnforcedStyle: double_quotes + +Style/StringLiteralsInInterpolation: + Enabled: true + EnforcedStyle: double_quotes + +Layout/LineLength: + Max: 120 + +Layout/FirstHashElementIndentation: + EnforcedStyle: consistent + +Layout/ArgumentAlignment: + EnforcedStyle: with_fixed_indentation + +Layout/MultilineMethodCallBraceLayout: + EnforcedStyle: new_line + +Style/Documentation: + Enabled: false + +Metrics/BlockLength: + Exclude: + - spec/**/*.rb diff --git a/CHANGELOG.md b/CHANGELOG.md new file mode 100644 index 0000000..0366df4 --- /dev/null +++ b/CHANGELOG.md @@ -0,0 +1,9 @@ +## [Unreleased] + +## [1.0.0] - 2023-07-31 + +- Public Release + +## [0.1.0] - 2023-07-03 + +- Initial release diff --git a/CODE_OF_CONDUCT.md b/CODE_OF_CONDUCT.md new file mode 100644 index 0000000..88cd68a --- /dev/null +++ b/CODE_OF_CONDUCT.md @@ -0,0 +1,24 @@ + +# Contributor Code of Conduct + +As contributors and maintainers of this project, and in the interest of fostering an open and welcoming community, we pledge to respect all people who contribute through reporting issues, posting feature requests, updating documentation, submitting pull requests or patches, and other activities. + +We are committed to making participation in this project a harassment-free experience for everyone, regardless of level of experience, gender, gender identity and expression, sexual orientation, disability, personal appearance, body size, race, ethnicity, age, religion, or nationality. + +Examples of unacceptable behavior by participants include: + +* The use of sexualized language or imagery +* Personal attacks +* Trolling or insulting/derogatory comments +* Public or private harassment +* Publishing other's private information, such as physical or electronic addresses, without explicit permission +* Other unethical or unprofessional conduct + +Project maintainers have the right and responsibility to remove, edit, or reject comments, commits, code, wiki edits, issues, and other contributions that are not aligned to this Code of Conduct. By adopting this Code of Conduct, project maintainers commit themselves to fairly and consistently applying these principles to every aspect of managing this project. Project maintainers who do not follow or enforce the Code of Conduct may be permanently removed from the project team. + +This code of conduct applies both within project spaces and in public spaces when an individual is representing the project or its community. + +Instances of abusive, harassing, or otherwise unacceptable behavior may be reported by opening an issue or contacting one or more of the project maintainers. + +This Code of Conduct is adapted from the [Contributor Covenant](https://www.contributor-covenant.org), version 1.2.0, available at https://www.contributor-covenant.org/version/1/2/0/code-of-conduct.html + diff --git a/Gemfile b/Gemfile new file mode 100644 index 0000000..038c930 --- /dev/null +++ b/Gemfile @@ -0,0 +1,18 @@ +# frozen_string_literal: true + +source "https://rubygems.org" + +# Specify your gem's dependencies in m_logger.gemspec +gemspec + +gem "rake", "~> 13.0" + +gem "rspec", "~> 3.0" + +gem "rubocop", "~> 1.21" + +gem "timecop" + +gem "pry-byebug" + +gem "parallel" diff --git a/LICENSE.txt b/LICENSE.txt new file mode 100644 index 0000000..9a6ea00 --- /dev/null +++ b/LICENSE.txt @@ -0,0 +1,21 @@ +The MIT License (MIT) + +Copyright (c) 2023 DeNA + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in +all copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +THE SOFTWARE. diff --git a/README.md b/README.md new file mode 100644 index 0000000..3cef7d1 --- /dev/null +++ b/README.md @@ -0,0 +1,79 @@ +# MLogger + +MLogger is a simple logger featuring an alternative log rotation strategy, specially designed to handle high traffic loads and transient environments. + +To use MLogger, initiate a new logger with `MLogger.new('log/production.log', shift_period_suffix: '%Y%m%d_%H')`. + +## Log Rotation Strategy + +Here's how ordinary log rotation strategy works: + +1. Logs are consistently written to the same file (e.g., `production.log`). +2. The file is renamed once a specified time or size limit is reached (e.g., `production.log` becomes `production.log.20230701`). + +In contrast, MLogger employs a different log rotation strategy: + +1. Each log message is written to a time-stamped file (e.g., `production.log.20230701_11`). +2. Upon reaching a time threshold, logging is switched to a new file with the updated timestamp (e.g., `production.log.20230701_12`). + +Key advantages of using MLogger include: + +1. Support for hourly and shorter shift periods, accommodating heavy traffic loads. +2. Log lines always exist within the appropriately time-stamped path, even in cases where there are no logs or when there is an overflow of logs beyond shift periods. + +## Additional Features + +1. For systems expecting an IO-like interface, you can utilize `MLogger::LoggerDevice` (`MLogger::LoggerDevice#write`). +2. To facilitate line-based operations, MLogger skips writing a log header (e.g., `# Logfile created on %s by %s`). + +## Installation + +Install the gem and add to the application's Gemfile by executing: + + $ bundle add m_logger + +If bundler is not being used to manage dependencies, install the gem by executing: + + $ gem install m_logger + +## Usage + +```ruby +# Log to File +hourly_logger = MLogger.new('log/my_log', shift_period_suffix: '%Y%m%d_%H') # hourly rotate +hourly_logger.debug('fuga') + +daily_logger = MLogger.new('log/my_log', shift_period_suffix: '%Y%m%d') # daily rotate +daily_logger.debug('fuga') + +# Log in Rack::Middleware +logger_device = MLogger::Device.new('log/rack_ltsv', shift_period_suffix: '%Y%m%d_%H') +Rails.configuration.middleware.insert(0, Rack::LtsvLogger, logger_device) + +# Log to Stdout (You don't have to change logger class.) +logger = MLogger.new(STDOUT) +logger.info('hoge') +``` + +## Development + +After checking out the repo, run `bin/setup` to install dependencies. Then, run `rake spec` to run the tests. You can also run `bin/console` for an interactive prompt that will allow you to experiment. + +To install this gem onto your local machine, run `bundle exec rake install`. To release a new version, update the version number in `version.rb`, and then run `bundle exec rake release`, which will create a git tag for the version, push git commits and the created tag, and push the `.gem` file to [rubygems.org](https://rubygems.org). + +## Contributing + +Bug reports and pull requests are welcome on GitHub at https://github.com/DeNA/m_logger. This project is intended to be a safe, welcoming space for collaboration, and contributors are expected to adhere to the [code of conduct](https://github.com/DeNA/m_logger/blob/master/CODE_OF_CONDUCT.md). + +## License + +The gem is available as open source under the terms of the [MIT License](https://opensource.org/licenses/MIT). + +## Code of Conduct + +Everyone interacting in the MLogger project's codebases, issue trackers, chat rooms and mailing lists is expected to follow the [code of conduct](https://github.com/DeNA/m_logger/blob/master/CODE_OF_CONDUCT.md). + +## Special Thanks + +External log file specification originates from Mobage and Sakasho series in DeNA. +Thanks for those who have contributed to these products. diff --git a/Rakefile b/Rakefile new file mode 100644 index 0000000..cca7175 --- /dev/null +++ b/Rakefile @@ -0,0 +1,12 @@ +# frozen_string_literal: true + +require "bundler/gem_tasks" +require "rspec/core/rake_task" + +RSpec::Core::RakeTask.new(:spec) + +require "rubocop/rake_task" + +RuboCop::RakeTask.new + +task default: %i[spec rubocop] diff --git a/bin/console b/bin/console new file mode 100755 index 0000000..4485b74 --- /dev/null +++ b/bin/console @@ -0,0 +1,11 @@ +#!/usr/bin/env ruby +# frozen_string_literal: true + +require "bundler/setup" +require "m_logger" + +# You can add fixtures and/or initialization code here to make experimenting +# with your gem easier. You can also use a different console, if you like. + +require "irb" +IRB.start(__FILE__) diff --git a/bin/setup b/bin/setup new file mode 100755 index 0000000..dce67d8 --- /dev/null +++ b/bin/setup @@ -0,0 +1,8 @@ +#!/usr/bin/env bash +set -euo pipefail +IFS=$'\n\t' +set -vx + +bundle install + +# Do any other automated setup that you need to do here diff --git a/lib/m_logger.rb b/lib/m_logger.rb new file mode 100644 index 0000000..2f8859b --- /dev/null +++ b/lib/m_logger.rb @@ -0,0 +1,41 @@ +# frozen_string_literal: true + +require "logger" + +require_relative "m_logger/version" +require_relative "m_logger/log_device" + +class MLogger < ::Logger + # rubocop:disable Lint/MissingSuper,Metrics/MethodLength,Metrics/ParameterLists + def initialize(logdev, shift_age = 0, shift_size = 1_048_576, level: DEBUG, + progname: nil, formatter: nil, datetime_format: nil, + binmode: false, shift_period_suffix: "%Y%m%d") + + self.level = level + self.progname = progname + @default_formatter = Formatter.new + self.datetime_format = datetime_format + self.formatter = formatter + @logdev = nil + @level_override = {} + + return unless logdev && logdev != File::NULL + + # Only this part is different from original ::Logger + @logdev = if RUBY_VERSION >= "2.7.0" + MLogger::LogDevice.new(logdev, + shift_age: shift_age, + shift_size: shift_size, + shift_period_suffix: shift_period_suffix, + binmode: binmode + ) + else + MLogger::LogDevice.new(logdev, + shift_age: shift_age, + shift_size: shift_size, + shift_period_suffix: shift_period_suffix + ) + end + end + # rubocop:enable Lint/MissingSuper,Metrics/MethodLength,Metrics/ParameterLists +end diff --git a/lib/m_logger/log_device.rb b/lib/m_logger/log_device.rb new file mode 100644 index 0000000..71b3313 --- /dev/null +++ b/lib/m_logger/log_device.rb @@ -0,0 +1,35 @@ +# frozen_string_literal: true + +require "logger" + +class MLogger + class LogDevice < ::Logger::LogDevice + def initialize(log = nil, *args, shift_period_suffix: nil, **kwargs) + # When the output is file, save original name, and append shift_period_suffix. + is_file = log && !(log.respond_to?(:write) && log.respond_to?(:close)) + if is_file + @original_filename = log + log = m_logger_filename(shift_period_suffix) + end + + super(log, *args, shift_period_suffix: shift_period_suffix, **kwargs) + end + + private + + def check_shift_log + # Switch to a new file, when the time has come. + return unless @filename && @filename < (f = m_logger_filename(@shift_period_suffix)) + + reopen(f) + end + + def add_log_header(_file) + # skip writing log header + end + + def m_logger_filename(suffix) + "#{@original_filename}.#{Time.now.strftime(suffix)}" + end + end +end diff --git a/lib/m_logger/version.rb b/lib/m_logger/version.rb new file mode 100644 index 0000000..03d37fb --- /dev/null +++ b/lib/m_logger/version.rb @@ -0,0 +1,7 @@ +# frozen_string_literal: true + +require "logger" + +class MLogger < ::Logger + VERSION = "0.1.0" +end diff --git a/m_logger.gemspec b/m_logger.gemspec new file mode 100644 index 0000000..27c5b2c --- /dev/null +++ b/m_logger.gemspec @@ -0,0 +1,38 @@ +# frozen_string_literal: true + +require_relative "lib/m_logger/version" + +Gem::Specification.new do |spec| + spec.name = "m_logger" + spec.version = MLogger::VERSION + spec.authors = ["Takumasa Ochi"] + + spec.summary = "Simple Logger with Alternative Log Rotation Strategy" + spec.description = "Simple Logger with Alternative Log Rotation Strategy" + spec.homepage = "https://github.com/DeNA/m_logger" + spec.license = "MIT" + spec.required_ruby_version = ">= 2.6.0" + + # spec.metadata["allowed_push_host"] = "" + + spec.metadata["homepage_uri"] = spec.homepage + spec.metadata["source_code_uri"] = "https://github.com/DeNA/m_logger" + spec.metadata["changelog_uri"] = "https://github.com/DeNA/m_logger/blob/master/CHANGELOG.md" + + # Specify which files should be added to the gem when it is released. + # The `git ls-files -z` loads the files in the RubyGem that have been added into git. + spec.files = Dir.chdir(__dir__) do + `git ls-files -z`.split("\x0").reject do |f| + (File.expand_path(f) == __FILE__) || f.start_with?(*%w[bin/ test/ spec/ features/ .git .circleci appveyor]) + end + end + spec.bindir = "exe" + spec.executables = spec.files.grep(%r{\Aexe/}) { |f| File.basename(f) } + spec.require_paths = ["lib"] + + # Uncomment to register a new dependency of your gem + # spec.add_dependency "example-gem", "~> 1.0" + + # For more information and examples about making a new gem, check out our + # guide at: https://bundler.io/guides/creating_gem.html +end diff --git a/sig/m_logger.rbs b/sig/m_logger.rbs new file mode 100644 index 0000000..e898791 --- /dev/null +++ b/sig/m_logger.rbs @@ -0,0 +1,7 @@ +class MLogger < ::Logger + VERSION: String + # See the writing guide of rbs: https://github.com/ruby/rbs#guides + + class LogDevice < ::Logger::LogDevice + end +end diff --git a/spec/m_logger/log_device_spec.rb b/spec/m_logger/log_device_spec.rb new file mode 100644 index 0000000..5582302 --- /dev/null +++ b/spec/m_logger/log_device_spec.rb @@ -0,0 +1,32 @@ +# frozen_string_literal: true + +require "pathname" +require "tmpdir" + +require "timecop" + +RSpec.describe MLogger::LogDevice do + let(:tmp_path) do + Pathname.new(Dir.mktmpdir) + end + + before do + tmp_path + end + + after do + tmp_path.rmtree + Timecop.return # Always return + end + + describe "#write" do + it "can directly write to the file" do + Timecop.freeze(Time.local(1996, 12, 25, 12, 34)) + + log_device = MLogger::LogDevice.new(tmp_path.join("access_log"), shift_period_suffix: "%Y%m%d_%H") + log_device.write("this is access log") + + expect(tmp_path.join("access_log.19961225_12").read).to eq "this is access log" + end + end +end diff --git a/spec/m_logger_spec.rb b/spec/m_logger_spec.rb new file mode 100644 index 0000000..7c1fa8b --- /dev/null +++ b/spec/m_logger_spec.rb @@ -0,0 +1,203 @@ +# frozen_string_literal: true + +require "pathname" +require "tmpdir" +require "stringio" + +require "timecop" +require "parallel" + +# Since initialization timing of Logger and MLogger are critical, we intentionally avoid using let, before, and after. + +RSpec.describe MLogger do + let(:tmp_path) do + Pathname.new(Dir.mktmpdir) + end + + before do + tmp_path + end + + after do + tmp_path.rmtree + Timecop.return # Always return + end + + describe "log file path" do + context "without shift_period_suffix" do + it "creates a file with default suffix" do + Timecop.freeze(Time.local(1996, 12, 25)) + MLogger.new(tmp_path.join("production.log")) + + expect(tmp_path.children).to eq [tmp_path.join("production.log.19961225")] + end + end + + context "with shift_period_suffix" do + it "creates a file with specified suffix" do + Timecop.freeze(Time.local(1996, 12, 25, 12, 34, 56)) + MLogger.new(tmp_path.join("production.log"), shift_period_suffix: "%Y%m%d_%H") + + expect(tmp_path.children).to eq [tmp_path.join("production.log.19961225_12")] + end + end + end + + describe "log header" do + it "does not write header" do + Timecop.freeze(Time.local(2023, 7, 1)) + MLogger.new(tmp_path.join("some_log")) + + expect(tmp_path.join("some_log.20230701").read.size).to eq 0 + end + end + + describe "log rotation" do + let(:simple_formatter) do + lambda do |_severity, datetime, _progname, msg| + datetime_str = datetime.strftime("%Y-%m-%d %H:%M:%S") + "[#{datetime_str}] #{msg}\n" + end + end + + context "when time changes within the same period" do + it "writes to the same log file" do + Timecop.freeze(Time.local(2023, 7, 1, 16)) + logger = MLogger.new(tmp_path.join("production.log"), formatter: simple_formatter, + shift_period_suffix: "%Y%m%d_%H" + ) + + logger.info("period begins") + + Timecop.freeze(Time.local(2023, 7, 1, 16, 59, 59)) + logger.info("period ends") + + expect(tmp_path.join("production.log.20230701_16").read).to eq <<~LOG + [2023-07-01 16:00:00] period begins + [2023-07-01 16:59:59] period ends + LOG + end + end + + context "when time changes over periods" do + it "writes to the appropriate log file" do + Timecop.freeze(Time.local(2023, 7, 1, 16)) + logger = MLogger.new(tmp_path.join("production.log"), formatter: simple_formatter, + shift_period_suffix: "%Y%m%d_%H" + ) + + logger.info("period begins") + + Timecop.freeze(Time.local(2023, 7, 1, 23)) + logger.info("new period begins") + + expect(tmp_path.join("production.log.20230701_16").read).to eq <<~LOG + [2023-07-01 16:00:00] period begins + LOG + + expect(tmp_path.join("production.log.20230701_23").read).to eq <<~LOG + [2023-07-01 23:00:00] new period begins + LOG + end + end + + context "when other shift-related options are specified" do + it "ignores other options" do + Timecop.freeze(Time.local(1996, 12, 25)) + logger = MLogger.new(tmp_path.join("production.log"), "daily", 1, shift_period_suffix: "%Y") + + logger.info("first log in 1996") + + Timecop.freeze(Time.local(1996, 12, 31)) + logger.info("last log in 1996") + + Timecop.freeze(Time.local(2022, 12, 25)) + logger.info("first log in 2022") + + expect(tmp_path.join("production.log.1996").read).to match(/first log in 1996/) + expect(tmp_path.join("production.log.1996").read).to match(/last log in 1996/) + expect(tmp_path.join("production.log.2022").read).to match(/first log in 2022/) + end + end + end + + describe "thread-safe and process-safe" do + let(:simple_formatter) do + lambda do |_severity, datetime, _progname, msg| + datetime_str = datetime.strftime("%Y-%m-%d %H:%M:%S") + "[#{datetime_str}] #{msg}\n" + end + end + + context "when multiple thread writes (you can change threshold if this fails)" do + it "writes correct logs" do + items = (0...2000).to_a + + Timecop.travel(Time.local(2022, 12, 24, 23, 59, 59.99)) # 10ms to 12/25 + logger = MLogger.new(tmp_path.join("production.log")) + + Parallel.each(items, in_threads: 10) do |i| + logger.info("#{"a" * 5000} #{i}") + end + + previous_log = tmp_path.join("production.log.20221224") + current_log = tmp_path.join("production.log.20221225") + + expect(previous_log.exist?).to be true + expect(current_log.exist?).to be true + + written_numbers = [] + previous_log.each_line { |line| written_numbers << /a{5000} (\d+)\n$/.match(line)[1].to_i } + current_log.each_line { |line| written_numbers << /a{5000} (\d+)\n$/.match(line)[1].to_i } + + expect(written_numbers.sort).to eq items + end + end + + context "when multiple process writes (you can change threshold if this fails)" do + it "writes correct logs" do + items = (0...2000).to_a + + Timecop.travel(Time.local(2022, 12, 24, 23, 59, 59.99)) # 10ms to 12/25 + logger = MLogger.new(tmp_path.join("production.log")) + + Parallel.each(items, in_processes: 10) do |i| + logger.info("#{"a" * 5000} #{i}") + end + + previous_log = tmp_path.join("production.log.20221224") + current_log = tmp_path.join("production.log.20221225") + + expect(previous_log.exist?).to be true + expect(current_log.exist?).to be true + + written_numbers = [] + previous_log.each_line { |line| written_numbers << /a{5000} (\d+)\n$/.match(line)[1].to_i } + current_log.each_line { |line| written_numbers << /a{5000} (\d+)\n$/.match(line)[1].to_i } + + expect(written_numbers.sort).to eq items + end + end + end + + describe "non-file logger" do + context "with nil logger" do + it "can be used as a logger" do + logger = MLogger.new(nil) + + expect(logger.info("hoge")).to be true + end + end + + context "with IO object" do + it "can be used as a logger" do + sio = StringIO.new + + logger = MLogger.new(sio) + logger.error("some log") + + expect(sio.tap(&:rewind).read).to match(/E, \[.+?\] ERROR -- : some log/) + end + end + end +end diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb new file mode 100644 index 0000000..68a7056 --- /dev/null +++ b/spec/spec_helper.rb @@ -0,0 +1,16 @@ +# frozen_string_literal: true + +require "m_logger" +require "pry-byebug" + +RSpec.configure do |config| + # Enable flags like --only-failures and --next-failure + config.example_status_persistence_file_path = ".rspec_status" + + # Disable RSpec exposing methods globally on `Module` and `main` + config.disable_monkey_patching! + + config.expect_with :rspec do |c| + c.syntax = :expect + end +end