diff --git a/ext/windows/service/daemon.rb b/ext/windows/service/daemon.rb index 718afaf22..70e9caf07 100755 --- a/ext/windows/service/daemon.rb +++ b/ext/windows/service/daemon.rb @@ -1,164 +1,163 @@ #!/usr/bin/env ruby require 'fileutils' require 'win32/daemon' require 'win32/dir' require 'win32/process' require 'win32/eventlog' class WindowsDaemon < Win32::Daemon CREATE_NEW_CONSOLE = 0x00000010 + EVENTLOG_ERROR_TYPE = 0x0001 + EVENTLOG_WARNING_TYPE = 0x0002 + EVENTLOG_INFORMATION_TYPE = 0x0004 @LOG_TO_FILE = false LOG_FILE = File.expand_path(File.join(Dir::COMMON_APPDATA, 'PuppetLabs', 'puppet', 'var', 'log', 'windows.log')) LEVELS = [:debug, :info, :notice, :err] LEVELS.each do |level| define_method("log_#{level}") do |msg| log(msg, level) end end def service_init end def service_main(*argsv) argsv = (argsv << ARGV).flatten.compact args = argsv.join(' ') @loglevel = LEVELS.index(argsv.index('--debug') ? :debug : :notice) @LOG_TO_FILE = (argsv.index('--logtofile') ? true : false) if (@LOG_TO_FILE) FileUtils.mkdir_p(File.dirname(LOG_FILE)) args = args.gsub("--logtofile","") end basedir = File.expand_path(File.join(File.dirname(__FILE__), '..')) # The puppet installer registers a 'Puppet' event source. For the moment events will be logged with this key, but # it may be a good idea to split the Service and Puppet events later so it's easier to read in the windows Event Log. # # Example code to register an event source; # eventlogdll = File.expand_path(File.join(basedir, 'puppet', 'ext', 'windows', 'eventlog', 'puppetres.dll')) # if (File.exists?(eventlogdll)) # Win32::EventLog.add_event_source( # 'source' => "Application", # 'key_name' => "Puppet Agent", # 'category_count' => 3, # 'event_message_file' => eventlogdll, # 'category_message_file' => eventlogdll # ) # end puppet = File.join(basedir, 'bin', 'puppet.bat') unless File.exists?(puppet) log_err("File not found: '#{puppet}'") return end log_debug("Using '#{puppet}'") log_notice('Service started') while running? do begin runinterval = %x{ "#{puppet}" agent --configprint runinterval }.to_i if runinterval == 0 runinterval = 1800 log_err("Failed to determine runinterval, defaulting to #{runinterval} seconds") end rescue Exception => e log_exception(e) runinterval = 1800 end if state == RUNNING or state == IDLE log_notice("Executing agent with arguments: #{args}") pid = Process.create(:command_line => "\"#{puppet}\" agent --onetime #{args}", :creation_flags => CREATE_NEW_CONSOLE).process_id log_debug("Process created: #{pid}") else log_debug("Service is paused. Not invoking Puppet agent") end log_debug("Service waiting for #{runinterval} seconds") sleep(runinterval) log_debug('Service woken up') end log_notice('Service stopped') rescue Exception => e log_exception(e) end def service_stop log_notice('Service stopping') Thread.main.wakeup end def service_pause # The service will not stay in a paused stated, instead it will go back into a running state after a short period of time. This is an issue in the Win32-Service ruby code # Raised bug https://github.com/djberg96/win32-service/issues/11 and is fixed in version 0.8.3. # Because the Pause feature is so rarely used, there is no point in creating a workaround until puppet uses 0.8.3. log_notice('Service pausing. The service will not stay paused. See Puppet Issue PUP-1471 for more information') end def service_resume log_notice('Service resuming') end def service_shutdown log_notice('Host shutting down') end # Interrogation handler is just for debug. Can be commented out or removed entirely. # def service_interrogate # log_debug('Service is being interrogated') # end def log_exception(e) log_err(e.message) log_err(e.backtrace.join("\n")) end def log(msg, level) if LEVELS.index(level) >= @loglevel if (@LOG_TO_FILE) File.open(LOG_FILE, 'a') { |f| f.puts("#{Time.now} Puppet (#{level}): #{msg}") } end case level - when :debug - report_windows_event(Win32::EventLog::INFO,0x01,msg.to_s) - when :info - report_windows_event(Win32::EventLog::INFO,0x01,msg.to_s) - when :notice - report_windows_event(Win32::EventLog::INFO,0x01,msg.to_s) + when :debug, :info, :notice + report_windows_event(EVENTLOG_INFORMATION_TYPE,0x01,msg.to_s) when :err - report_windows_event(Win32::EventLog::ERR,0x03,msg.to_s) + report_windows_event(EVENTLOG_ERROR_TYPE,0x03,msg.to_s) else - report_windows_event(Win32::EventLog::WARN,0x02,msg.to_s) + report_windows_event(EVENTLOG_WARNING_TYPE,0x02,msg.to_s) end end end def report_windows_event(type,id,message) begin eventlog = nil eventlog = Win32::EventLog.open("Application") eventlog.report_event( :source => "Puppet", - :event_type => type, # Win32::EventLog::INFO or WARN, ERROR + :event_type => type, # EVENTLOG_ERROR_TYPE, etc :event_id => id, # 0x01 or 0x02, 0x03 etc. :data => message # "the message" ) rescue Exception => e # Ignore all errors ensure if (!eventlog.nil?) eventlog.close end end end end if __FILE__ == $0 WindowsDaemon.mainloop end diff --git a/lib/puppet/util/log/destinations.rb b/lib/puppet/util/log/destinations.rb index 932007099..6c5cc7f23 100644 --- a/lib/puppet/util/log/destinations.rb +++ b/lib/puppet/util/log/destinations.rb @@ -1,228 +1,232 @@ Puppet::Util::Log.newdesttype :syslog do def self.suitable?(obj) Puppet.features.syslog? end def close Syslog.close end def initialize Syslog.close if Syslog.opened? name = "puppet-#{Puppet.run_mode.name}" options = Syslog::LOG_PID | Syslog::LOG_NDELAY # XXX This should really be configurable. str = Puppet[:syslogfacility] begin facility = Syslog.const_get("LOG_#{str.upcase}") rescue NameError raise Puppet::Error, "Invalid syslog facility #{str}", $!.backtrace end @syslog = Syslog.open(name, options, facility) end def handle(msg) # XXX Syslog currently has a bug that makes it so you # cannot log a message with a '%' in it. So, we get rid # of them. if msg.source == "Puppet" msg.to_s.split("\n").each do |line| @syslog.send(msg.level, line.gsub("%", '%%')) end else msg.to_s.split("\n").each do |line| @syslog.send(msg.level, "(%s) %s" % [msg.source.to_s.gsub("%", ""), line.gsub("%", '%%') ] ) end end end end Puppet::Util::Log.newdesttype :file do require 'fileutils' def self.match?(obj) Puppet::Util.absolute_path?(obj) end def close if defined?(@file) @file.close @file = nil end end def flush @file.flush if defined?(@file) end attr_accessor :autoflush def initialize(path) @name = path # first make sure the directory exists # We can't just use 'Config.use' here, because they've # specified a "special" destination. unless Puppet::FileSystem.exist?(Puppet::FileSystem.dir(path)) FileUtils.mkdir_p(File.dirname(path), :mode => 0755) Puppet.info "Creating log directory #{File.dirname(path)}" end # create the log file, if it doesn't already exist file = File.open(path, File::WRONLY|File::CREAT|File::APPEND) # Give ownership to the user and group puppet will run as begin FileUtils.chown(Puppet[:user], Puppet[:group], path) unless Puppet::Util::Platform.windows? rescue ArgumentError, Errno::EPERM Puppet.err "Unable to set ownership of log file" end @file = file @autoflush = Puppet[:autoflush] end def handle(msg) @file.puts("#{msg.time} #{msg.source} (#{msg.level}): #{msg}") @file.flush if @autoflush end end Puppet::Util::Log.newdesttype :logstash_event do require 'time' def format(msg) # logstash_event format is documented at # https://logstash.jira.com/browse/LOGSTASH-675 data = {} data = msg.to_hash data['version'] = 1 data['@timestamp'] = data['time'] data.delete('time') data end def handle(msg) message = format(msg) $stdout.puts message.to_pson end end Puppet::Util::Log.newdesttype :console do require 'puppet/util/colors' include Puppet::Util::Colors def initialize # Flush output immediately. $stderr.sync = true $stdout.sync = true end def handle(msg) levels = { :emerg => { :name => 'Emergency', :color => :hred, :stream => $stderr }, :alert => { :name => 'Alert', :color => :hred, :stream => $stderr }, :crit => { :name => 'Critical', :color => :hred, :stream => $stderr }, :err => { :name => 'Error', :color => :hred, :stream => $stderr }, :warning => { :name => 'Warning', :color => :hred, :stream => $stderr }, :notice => { :name => 'Notice', :color => :reset, :stream => $stdout }, :info => { :name => 'Info', :color => :green, :stream => $stdout }, :debug => { :name => 'Debug', :color => :cyan, :stream => $stdout }, } str = msg.respond_to?(:multiline) ? msg.multiline : msg.to_s str = msg.source == "Puppet" ? str : "#{msg.source}: #{str}" level = levels[msg.level] level[:stream].puts colorize(level[:color], "#{level[:name]}: #{str}") end end # Log to a transaction report. Puppet::Util::Log.newdesttype :report do attr_reader :report match "Puppet::Transaction::Report" def initialize(report) @report = report end def handle(msg) @report << msg end end # Log to an array, just for testing. module Puppet::Test class LogCollector def initialize(logs) @logs = logs end def <<(value) @logs << value end end end Puppet::Util::Log.newdesttype :array do match "Puppet::Test::LogCollector" def initialize(messages) @messages = messages end def handle(msg) @messages << msg end end Puppet::Util::Log.newdesttype :eventlog do + Puppet::Util::Log::DestEventlog::EVENTLOG_ERROR_TYPE = 0x0001 + Puppet::Util::Log::DestEventlog::EVENTLOG_WARNING_TYPE = 0x0002 + Puppet::Util::Log::DestEventlog::EVENTLOG_INFORMATION_TYPE = 0x0004 + def self.suitable?(obj) Puppet.features.eventlog? end def initialize @eventlog = Win32::EventLog.open("Application") end def to_native(level) case level when :debug,:info,:notice - [Win32::EventLog::INFO, 0x01] + [self.class::EVENTLOG_INFORMATION_TYPE, 0x01] when :warning - [Win32::EventLog::WARN, 0x02] + [self.class::EVENTLOG_WARNING_TYPE, 0x02] when :err,:alert,:emerg,:crit - [Win32::EventLog::ERROR, 0x03] + [self.class::EVENTLOG_ERROR_TYPE, 0x03] end end def handle(msg) native_type, native_id = to_native(msg.level) @eventlog.report_event( :source => "Puppet", :event_type => native_type, :event_id => native_id, :data => (msg.source and msg.source != 'Puppet' ? "#{msg.source}: " : '') + msg.to_s ) end def close if @eventlog @eventlog.close @eventlog = nil end end end diff --git a/spec/unit/util/log/destinations_spec.rb b/spec/unit/util/log/destinations_spec.rb index a91236dba..82b647647 100755 --- a/spec/unit/util/log/destinations_spec.rb +++ b/spec/unit/util/log/destinations_spec.rb @@ -1,183 +1,221 @@ #! /usr/bin/env ruby require 'spec_helper' require 'json' require 'puppet/util/log' describe Puppet::Util::Log.desttypes[:report] do before do @dest = Puppet::Util::Log.desttypes[:report] end it "should require a report at initialization" do @dest.new("foo").report.should == "foo" end it "should send new messages to the report" do report = mock 'report' dest = @dest.new(report) report.expects(:<<).with("my log") dest.handle "my log" end end describe Puppet::Util::Log.desttypes[:file] do include PuppetSpec::Files before do File.stubs(:open) # prevent actually creating the file File.stubs(:chown) # prevent chown on non existing file from failing @class = Puppet::Util::Log.desttypes[:file] end it "should default to autoflush false" do @class.new(tmpfile('log')).autoflush.should == true end describe "when matching" do shared_examples_for "file destination" do it "should match an absolute path" do @class.match?(abspath).should be_true end it "should not match a relative path" do @class.match?(relpath).should be_false end end describe "on POSIX systems", :as_platform => :posix do let (:abspath) { '/tmp/log' } let (:relpath) { 'log' } it_behaves_like "file destination" end describe "on Windows systems", :as_platform => :windows do let (:abspath) { 'C:\\temp\\log.txt' } let (:relpath) { 'log.txt' } it_behaves_like "file destination" end end end describe Puppet::Util::Log.desttypes[:syslog] do let (:klass) { Puppet::Util::Log.desttypes[:syslog] } # these tests can only be run when syslog is present, because # we can't stub the top-level Syslog module describe "when syslog is available", :if => Puppet.features.syslog? do before :each do Syslog.stubs(:opened?).returns(false) Syslog.stubs(:const_get).returns("LOG_KERN").returns(0) Syslog.stubs(:open) end it "should open syslog" do Syslog.expects(:open) klass.new end it "should close syslog" do Syslog.expects(:close) dest = klass.new dest.close end it "should send messages to syslog" do syslog = mock 'syslog' syslog.expects(:info).with("don't panic") Syslog.stubs(:open).returns(syslog) msg = Puppet::Util::Log.new(:level => :info, :message => "don't panic") dest = klass.new dest.handle(msg) end end describe "when syslog is unavailable" do it "should not be a suitable log destination" do Puppet.features.stubs(:syslog?).returns(false) klass.suitable?(:syslog).should be_false end end end describe Puppet::Util::Log.desttypes[:logstash_event] do describe "when using structured log format with logstash_event schema" do before :each do @msg = Puppet::Util::Log.new(:level => :info, :message => "So long, and thanks for all the fish.", :source => "a dolphin") end it "format should fix the hash to have the correct structure" do dest = described_class.new result = dest.format(@msg) result["version"].should == 1 result["level"].should == :info result["message"].should == "So long, and thanks for all the fish." result["source"].should == "a dolphin" # timestamp should be within 10 seconds Time.parse(result["@timestamp"]).should >= ( Time.now - 10 ) end it "format returns a structure that can be converted to json" do dest = described_class.new hash = dest.format(@msg) JSON.parse(hash.to_json) end it "handle should send the output to stdout" do $stdout.expects(:puts).once dest = described_class.new dest.handle(@msg) end end end describe Puppet::Util::Log.desttypes[:console] do let (:klass) { Puppet::Util::Log.desttypes[:console] } describe "when color is available" do before :each do subject.stubs(:console_has_color?).returns(true) end it "should support color output" do Puppet[:color] = true subject.colorize(:red, 'version').should == "\e[0;31mversion\e[0m" end it "should withhold color output when not appropriate" do Puppet[:color] = false subject.colorize(:red, 'version').should == "version" end it "should handle multiple overlapping colors in a stack-like way" do Puppet[:color] = true vstring = subject.colorize(:red, 'version') subject.colorize(:green, "(#{vstring})").should == "\e[0;32m(\e[0;31mversion\e[0;32m)\e[0m" end it "should handle resets in a stack-like way" do Puppet[:color] = true vstring = subject.colorize(:reset, 'version') subject.colorize(:green, "(#{vstring})").should == "\e[0;32m(\e[mversion\e[0;32m)\e[0m" end it "should include the log message's source/context in the output when available" do Puppet[:color] = false $stdout.expects(:puts).with("Info: a hitchhiker: don't panic") msg = Puppet::Util::Log.new(:level => :info, :message => "don't panic", :source => "a hitchhiker") dest = klass.new dest.handle(msg) end end end + + +describe ":eventlog", :if => Puppet::Util::Platform.windows? do + let(:klass) { Puppet::Util::Log.desttypes[:eventlog] } + + def expects_message_with_type(klass, level, eventlog_type, eventlog_id) + eventlog = stub('eventlog') + eventlog.expects(:report_event).with(has_entries(:source => "Puppet", :event_type => eventlog_type, :event_id => eventlog_id, :data => "a hitchhiker: don't panic")) + Win32::EventLog.stubs(:open).returns(eventlog) + + msg = Puppet::Util::Log.new(:level => level, :message => "don't panic", :source => "a hitchhiker") + dest = klass.new + dest.handle(msg) + end + + it "supports the eventlog feature" do + expect(Puppet.features.eventlog?).to be_true + end + + it "logs to the Application event log" do + eventlog = stub('eventlog') + Win32::EventLog.expects(:open).with('Application').returns(stub('eventlog')) + + klass.new + end + + it "logs :debug level as an information type event" do + expects_message_with_type(klass, :debug, klass::EVENTLOG_INFORMATION_TYPE, 0x1) + end + + it "logs :warning level as an warning type event" do + expects_message_with_type(klass, :warning, klass::EVENTLOG_WARNING_TYPE, 0x2) + end + + it "logs :err level as an error type event" do + expects_message_with_type(klass, :err, klass::EVENTLOG_ERROR_TYPE, 0x3) + end +end