Skip to content
This repository has been archived by the owner on Sep 6, 2023. It is now read-only.

refactor(logging)!: rename log prefix from jsr223.jruby to org.openhab.automation.jruby #489

Merged
merged 1 commit into from
Jan 15, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 7 additions & 9 deletions docs/usage/misc/logging.md
Original file line number Diff line number Diff line change
Expand Up @@ -9,25 +9,23 @@ grand_parent: Usage

# Logging

Logging is available everywhere through the logger object.
Logging is available everywhere through the logger object.

Logging placed outside of a rule will have the name of the file appened to the logger name. The following entries are in a file named 'log_test.rb'

```ruby
logger.trace('Test logging at trace') # 2020-12-03 18:05:20.903 [TRACE] [jsr223.jruby.log_test ] - Test logging at trace
logger.debug('Test logging at debug') # 2020-12-03 18:05:32.020 [DEBUG] [jsr223.jruby.log_test ] - Test logging at debug
logger.warn('Test logging at warn') # 2020-12-03 18:05:41.817 [WARN ] [jsr223.jruby.log_test ] - Test logging at warn
logger.info('Test logging at info') # 2020-12-03 18:05:41.817 [INFO ] [jsr223.jruby.log_test ] - Test logging at info
logger.error('Test logging at error') # 2020-12-03 18:06:02.021 [ERROR] [jsr223.jruby.log_test ] - Test logging at error
logger.trace('Test logging at trace') # 2020-12-03 18:05:20.903 [TRACE] [org.openhab.automation.jruby.log_test] - Test logging at trace
logger.debug('Test logging at debug') # 2020-12-03 18:05:32.020 [DEBUG] [org.openhab.automation.jruby.log_test] - Test logging at debug
logger.warn('Test logging at warn') # 2020-12-03 18:05:41.817 [WARN ] [org.openhab.automation.jruby.log_test] - Test logging at warn
logger.info('Test logging at info') # 2020-12-03 18:05:41.817 [INFO ] [org.openhab.automation.jruby.log_test] - Test logging at info
logger.error('Test logging at error') # 2020-12-03 18:06:02.021 [ERROR] [org.openhab.automation.jruby.log_test] - Test logging at error
```

Logging inside of a rule will have the name of the rule appened to the logger name. The following entries are in a file named 'log_test.rb'

```ruby
rule 'foo' do
run { logger.trace('Test logging at trace') } # 2020-12-03 18:05:20.903 [TRACE] [jsr223.jruby.log_test.foo ] - Test logging at trace
run { logger.trace('Test logging at trace') } # 2020-12-03 18:05:20.903 [TRACE] [org.openhab.automation.jruby.log_test.foo] - Test logging at trace
on_start
end
```


9 changes: 3 additions & 6 deletions features/gem_install.feature
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,9 @@ Feature: gem_install
Given Clean OpenHAB with latest Ruby Libraries

@reset_library
# This will install the current release version from rubygems.org
# Running a rule here may cause errors if the new version is not
# compatible with the release version
Scenario: Install OpenHAB helper library
Given OpenHAB is stopped
And GEM_HOME is empty
Expand All @@ -14,12 +17,6 @@ Feature: gem_install
org.openhab.automation.jrubyscripting:gems=openhab-scripting=~>4.0
org.openhab.automation.jrubyscripting:rubylib=<%= ruby_lib_dir %>
"""
And code in a rules file:
"""
logger.info("OpenHAB helper library is at #{OpenHAB::VERSION}")
"""
When I start OpenHAB
Then It should log 'Installing Gem: openhab-scripting' within 180 seconds
And I deploy the rules file
Then It should log 'OpenHAB helper library is at' within 200 seconds

20 changes: 10 additions & 10 deletions features/logging.feature
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ Feature: logging
logger.info("Hello World!")
"""
When I deploy the rules file named "foo_bar.rb"
Then It should log only "Hello World!" at level "INFO" from 'jsr223.jruby.foo_bar' within 5 seconds
Then It should log only "Hello World!" at level "INFO" from 'org.openhab.automation.jruby.foo_bar' within 5 seconds


Scenario: Logging should include rule name inside a rule
Expand All @@ -49,7 +49,7 @@ Feature: logging
"""
When I deploy the rules file named "log_rule_test.rb"
Then It should log only "Log Test" at level "INFO" from 'jsr223.jruby.log_rule_test.log_test' within 5 seconds
Then It should log only "Log Test" at level "INFO" from 'org.openhab.automation.jruby.log_rule_test.log_test' within 5 seconds

Scenario: Methods called by a rule have the rule file and name in their log name
Given code in a rules file
Expand All @@ -65,38 +65,38 @@ Feature: logging
"""
When I deploy the rules file named "log_file.rb"
Then It should log only "Foo" at level "INFO" from 'jsr223.jruby.log_file.log_test' within 5 seconds
Then It should log only "Foo" at level "INFO" from 'org.openhab.automation.jruby.log_file.log_test' within 5 seconds

Scenario: Logs in after blocks (timers) should have file and rule name in log prefix
Given code in a rules file
"""
rule 'log test' do
on_start
run do
run do
after 1.second do
logger.info('Bar')
end
end
end
"""
When I deploy the rules file named "log_file.rb"
Then It should log only "Bar" at level "INFO" from 'jsr223.jruby.log_file.log_test' within 5 seconds
Then It should log only "Bar" at level "INFO" from 'org.openhab.automation.jruby.log_file.log_test' within 5 seconds

Scenario: Logs in blocks after trigger delays should have file and rule name in log prefix
Given items:
| type | name | state |
| Number | Foo | 0 |
Given items:
| type | name | state |
| Number | Foo | 0 |
Given a rule:
"""
rule 'log test' do
changed Foo, to: 5, for: 3.seconds
run do
run do
logger.info('Baz')
end
end
"""
When I deploy the rules file named "log_file.rb"
And item "Foo" state is changed to "5"
Then It should log only "Baz" at level "INFO" from 'jsr223.jruby.log_file.log_test' within 8 seconds
Then It should log only "Baz" at level "INFO" from 'org.openhab.automation.jruby.log_file.log_test' within 8 seconds


4 changes: 2 additions & 2 deletions features/step_definitions/openhab.rb
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@

# rubocop:disable Metrics/LineLength
Then('It should log only {string} at level {string} from {string} within {int} seconds') do |entry, level, logger, seconds|
# 2021-11-15 19:24:34.574 [INFO ] [jsr223.jruby.rules.log_test ] - Log Test
# 2021-11-15 19:24:34.574 [INFO ] [org.openhab.automation.jruby.rules.log_test] - Log Test
# Trim level to the right most 36 chars (per logging config)
logger_length = 36
logger = logger[-logger_length, logger_length] if logger.length > logger_length
Expand Down Expand Up @@ -233,7 +233,7 @@ def check_items(added:)
end

Given('(set )log level (to ){word}') do |level|
set_log_level('jsr223.jruby', level)
set_log_level('org.openhab.automation.jruby', level)
set_log_level('org.openhab.automation.jrubyscripting', level)
set_log_level('org.openhab.core.automation', level)
end
Expand Down
2 changes: 1 addition & 1 deletion features/support/env.rb
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ def prepare_openhab
end

After('@log_level_changed') do
set_log_level('jsr223.jruby', 'TRACE')
set_log_level('org.openhab.automation.jruby', 'TRACE')
set_log_level('org.openhab.automation.jrubyscripting', 'TRACE')
set_log_level('org.openhab.core.automation', 'TRACE')
end
Expand Down
2 changes: 1 addition & 1 deletion lib/openhab/log/configuration.rb
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@ module Log
# This module holds global configuration values
module Configuration
# -*- coding: utf-8 -*-
LOG_PREFIX = 'jsr223.jruby'
LOG_PREFIX = 'org.openhab.automation.jruby'

#
# Gets the log prefix
Expand Down
2 changes: 1 addition & 1 deletion rakelib/openhab.rake
Original file line number Diff line number Diff line change
Expand Up @@ -184,7 +184,7 @@ namespace :openhab do
# Set log levels
state(task.name) do
start
karaf('log:set TRACE jsr223')
karaf('log:set TRACE org.openhab.automation.jruby')
karaf('log:set TRACE org.openhab.core.automation')
karaf('log:set TRACE org.openhab.automation.jrubyscripting')
karaf('openhab:users add foo foo administrator')
Expand Down