Module: Xolo::Server::Log

Included in:
Xolo::Server
Defined in:
lib/xolo/server/log.rb

Overview

constants and methods for writing to the log

Constant Summary collapse

DATETIME_FORMAT = 
'%F %T'
LEVELS =

Easier for reporting level changes - the index is the severity number

%w[DEBUG INFO WARN ERROR FATAL UNKNOWN].freeze
LOG_FORMATTER =

THe log format - we use ‘progname’ to hole the session object, if there is one.

proc do |severity, datetime, progname, msg|
  progname &&= " #{progname}"
  "#{datetime.strftime DATETIME_FORMAT} #{severity}#{progname}: #{msg}\n"
end
LOG_DIR = 
Xolo::Server::Constants::DATA_DIR + 'logs'
LOG_FILE_NAME = 
'xoloserver.log'
LOG_FILE = 
LOG_DIR + LOG_FILE_NAME
DFT_LOG_DAYS_TO_KEEP =

keep this many days of logs total

30
DFT_LOG_COMPRESS_AFTER_DAYS =

compress the log files when they are this many days old

7
BZIP2 =

shell out to bzip2 - no need for another gem requirement.

'/usr/bin/bzip2'
BZIPPED_EXTNAME =

compressed files have this extension

'.bz2'
LAST_ROTATION_FILE =

This file is touched after each log rotation run. Its mtime is used to decide if we should to it again

LOG_DIR + 'last_log_rotation'
TEMP_LOG_FILE =

When we rotate the main log to .0 we repoint the logger to this temp filename, then rename the main log to .0, then rename this temp file to the main log. This way the logger never has to be reinitialized.

LOG_DIR + 'temp_xoloserver.log'

Class Method Summary collapse

Class Method Details

.compress_log(file) ⇒ Object 



251
252
253
254
255
256
257
258
259
260
 
# File 'lib/xolo/server/log.rb', line 251

def self.compress_log(file)
  zipout = `/usr/bin/bzip2  #{file.to_s.shellescape}`

  if $CHILD_STATUS.success?
    logger.info "Compressed log file: #{file}"
  else
    logger.error "Failed to compress log file: #{file}"
    zipout.lines.each { |l| logger.error ".. #{l.chomp}" }
  end # if success?
end

.included(includer) ⇒ Object

when this module is included



19
20
21
 
# File 'lib/xolo/server/log.rb', line 19

def self.included(includer)
  Xolo.verbose_include includer, self
end

.log_rotation_timer_task ⇒ Concurrent::TimerTask

Log rotation is done by a Concurrent::TimerTask, which checks every 5 minutes to see if it should do anything. It will only do a rotation if the current time is in the midnight hour (00:00 - 00:59) AND if the last rotation was more than 23 hours ago.



113
114
115
116
117
118
119
120
121
 
# File 'lib/xolo/server/log.rb', line 113

def self.log_rotation_timer_task
  return @log_rotation_timer_task if @log_rotation_timer_task

  @log_rotation_timer_task =
    Concurrent::TimerTask.new(execution_interval: 300) { rotate_logs }

  logger.info 'Created Concurrent::TimerTask for nightly log rotation.'
  @log_rotation_timer_task
end

.logger ⇒ Object

top-level logger for the server as a whole



66
67
68
69
70
71
72
73
74
75
76
77
78
79
 
# File 'lib/xolo/server/log.rb', line 66

def self.logger
  return @logger if @logger

  LOG_DIR.mkpath
  LOG_FILE.pix_touch

  @logger = Logger.new(
    LOG_FILE,
    datetime_format: DATETIME_FORMAT,
    formatter: LOG_FORMATTER
  )

  @logger
end

.rotate_live_log(compress_zero) ⇒ void

This method returns an undefined value.

Rotate the current log file without losing any log entries



202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
 
# File 'lib/xolo/server/log.rb', line 202

def self.rotate_live_log(compress_zero)
  # first, delete any old tmp file
  TEMP_LOG_FILE.delete if TEMP_LOG_FILE.file?

  # then repoint the logger to the temp file
  logger.reopen TEMP_LOG_FILE

  # make sure it has data in it
  logger.info 'Starting New Log'

  # then rename the main log to .0
  zero_file = LOG_DIR + "#{LOG_FILE_NAME}.0"
  logger.info "Moving log file #{LOG_FILE_NAME} => #{zero_file.basename}"

  LOG_FILE.rename zero_file

  # then rename the temp file to the main log.
  # The logger will still log to it because it holds a
  # filehandle to it, and doesn't care about its name.
  TEMP_LOG_FILE.rename LOG_FILE

  # compress the zero file if we should
  compress_log(zero_file) if compress_zero
end

.rotate_logs(force: false) ⇒ void

This method returns an undefined value.

rotate the log file, keeping some number of old ones and possibly compressing them after some time. The log rotation built into ruby’s Logger class doesn’t allow this kind of behavior, And I don’t want to require yet another 3rd party gem.



132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
 
# File 'lib/xolo/server/log.rb', line 132

def self.rotate_logs(force: false)
  return unless rotate_logs_now?(force: force)

  # TODO: Use Concurrent ruby rather than this instance variable
  mutex = Xolo::Server::Log.rotation_mutex

  if mutex.locked?
    log_warn 'Log rotation already running, skipping this run'
    return
  end

  mutex.lock

  logger.info 'Starting Log Rotation'

  # how many to keep?
  days_to_keep = Xolo::Server.config.log_days_to_keep || Xolo::Server::Log::DFT_LOG_DAYS_TO_KEEP

  # when to compress?
  compress_after = Xolo::Server.config.log_compress_after_days || Xolo::Server::Log::DFT_LOG_COMPRESS_AFTER_DAYS

  # no compression if compress_after is less than zero or greater/equal to days to keeps
  compress_after = nil if compress_after.negative? || compress_after >= days_to_keep

  # work down thru the number to keep
  days_to_keep.downto(1) do |age|
    # the previous file to the newly aged file
    # if we're moving to a newly aged .3, this is .2
    prev_age = age - 1

    # rename a previous file to n+1, e.g. file.2 becomes file.3
    # This will overwrite an existing new_file, which is how we
    # delete the oldest
    prev_file = LOG_DIR + "#{LOG_FILE_NAME}.#{prev_age}"
    new_file = LOG_DIR + "#{LOG_FILE_NAME}.#{age}"
    if prev_file.file?
      logger.info "Moving log file #{prev_file.basename} => #{new_file.basename}"
      prev_file.rename new_file
    end

    # Do the same for any already compressed files
    prev_compressed_file = LOG_DIR + "#{LOG_FILE_NAME}.#{prev_age}#{BZIPPED_EXTNAME}"
    new_compressed_file = LOG_DIR + "#{LOG_FILE_NAME}.#{age}#{BZIPPED_EXTNAME}"
    if prev_compressed_file.file?
      logger.info "Moving log file #{prev_compressed_file.basename} => #{new_compressed_file.basename}"
      prev_compressed_file.rename new_compressed_file
    end

    next unless compress_after

    # compress the one we just moved if we should
    compress_log(new_file) if age >= compress_after && new_file.file?
  end # downto

  # now for the current logfile...
  rotate_live_log compress_after&.zero?

  # touch the last rotation file
  LAST_ROTATION_FILE.pix_touch
rescue => e
  logger.error "Error rotating logs: #{e}"
  e.backtrace.each { |l| logger.error "..#{l}" }
ensure
  Xolo::Server::Log.rotation_mutex.unlock if Xolo::Server::Log.rotation_mutex.owned?
end

.rotate_logs_now?(force: false) ⇒ Boolean

should we rotate the logs right now?



231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
 
# File 'lib/xolo/server/log.rb', line 231

def self.rotate_logs_now?(force: false)
  return true if force

  now = Time.now
  # only during the midnight hour
  return false unless now.hour.zero?

  # only if the last rotation was more than 23 hrs ago
  # if no rotation_file, assume 24 hrs ago.
  rotation_file = Xolo::Server::Log::LAST_ROTATION_FILE
  last_rotation = rotation_file.file? ? rotation_file.mtime : (now - (24 * 3600))

  twenty_three_hrs_ago = now - (23 * 3600)

  # less than (<) means its been more than 23 hrs
  # since the last rotation was before 23 hrs ago.
  last_rotation < twenty_three_hrs_ago
end

.rotation_mutex ⇒ Mutex

A mutex for the log rotation process

TODO: use Concrrent Ruby instead of Mutex



87
88
89
 
# File 'lib/xolo/server/log.rb', line 87

def self.rotation_mutex
  @rotation_mutex ||= Mutex.new
end