Eye fails to log certain things.

rgaufman commented 6 years ago

I have this code:

require 'semantic_logger'
SemanticLogger.add_appender(file_name: '/tmp/eye.log')

# Eye self-configuration section
Eye.config do
  logger SemanticLogger['eye']
end

Eye.application 'test' do
  logger.warn("Test Logging 1")
  process :testsleep do
    logger.warn("Test Logging 2")
    start_command 'sleep 60'
    pid_file '/tmp/testspeed.pid'
    daemonize true
  end
end

When I run eye l testeye.rb, I see this in the logs:

2018-05-29 14:34:57.092954 I [32437:70122502697500] eye -- [test:__default__] call:
2018-05-29 14:34:57.092989 I [32437:70122502697500] eye -- [test:__default__] schedule :monitor (load by user)
2018-05-29 14:34:57.093064 I [32437:70122502697500] eye -- [test:__default__] => monitor  (load by user)
2018-05-29 14:34:57.093077 I [32437:70122502697500] eye -- [test:__default__] starting async with 0.2s chain monitor
2018-05-29 14:34:57.093402 I [32437:70122501662800] eye -- [Eye] <= loading: ["/Users/hackeron/Dropbox/Development/Xanview/testeye.rb"]
2018-05-29 14:34:57.099212 I [32437:70122501662800] eye -- [Eye] <= command: load /Users/hackeron/Dropbox/Development/Xanview/testeye.rb (0.128373s)
2018-05-29 14:34:57.099398 I [32437:70122502693940] eye -- [test:testsleep] schedule :monitor (monitor by user)
2018-05-29 14:34:57.099457 I [32437:70122502693940] eye -- [test:testsleep] => monitor  (monitor by user)
2018-05-29 14:34:57.100135 I [32437:70122502697500] eye -- [test:__default__] <= monitor
2018-05-29 14:34:57.204894 I [32437:70122502693940] eye -- [test:testsleep] load_external_pid_file: pid_file not found
2018-05-29 14:34:57.205105 I [32437:70122502693940] eye -- [test:testsleep] switch :starting [:unmonitored => :starting] monitor by user
2018-05-29 14:34:57.207434 I [32437:70122502693940] eye -- [test:testsleep] daemonizing: `sleep 60` with start_grace: 2.5s, env: '', <32444> (in )
2018-05-29 14:34:57.207466 I [32437:70122502693940] eye -- [test:testsleep] sleeping for :start_grace 2.5
2018-05-29 14:34:59.712174 I [32437:70122502693940] eye -- [test:testsleep] switch :started [:starting => :up] monitor by user
2018-05-29 14:34:59.712483 I [32437:70122502693940] eye -- [test:testsleep] <= monitor

The "Test Logging 1" and "Test Logging 2" are both missing from the log file despite having logger.warn("Test Logging 1") and logger.warn("Test Logging 2") in my source.

Any ideas?

kostya commented 6 years ago

Eye.config section executed after config evaluated, so this messages executed before logger settled (on parsing stage), on the second eye load, there is this messages.

workaround:

LOGGER = ...

# Eye self-configuration section
Eye.config do
  logger LOGGER
end

Eye.application 'test' do
  LOGGER.warn("Test Logging 1")
end

rgaufman commented 6 years ago

Ah, thank you, the workaround works :)

kostya / eye

Eye fails to log certain things. #212