Skip to content

Commit

Permalink
Merge pull request #466 from epimorphics/hotfix/reduce-log-noise
Browse files Browse the repository at this point in the history
Feature: Improved Logging
  • Loading branch information
jonrandahl authored Feb 17, 2025
2 parents d961635 + 3c6a4f3 commit 19900b7
Show file tree
Hide file tree
Showing 30 changed files with 478 additions and 137 deletions.
56 changes: 56 additions & 0 deletions .githooks/pre-commit
Original file line number Diff line number Diff line change
@@ -0,0 +1,56 @@
#!/bin/sh
# caveat: this script assumes all modifications to a file were staged in the commit
# beware if you are in the habit of committing only partial modifications to a file:
# THIS HOOK WILL ADD ALL MODIFICATIONS TO A FILE TO THE COMMIT IF ANY FILE WAS CHANGED BY LINTING

list="issue spike task"

listRE="^($(printf '%s\n' "$list" | tr ' ' '|'))/"

BRANCH_NAME=$(git branch --show-current | grep -E "$listRE" | sed 's/* //')

printf '\n\033[0;105mChecking "%s"... \033[0m\n' "$BRANCH_NAME"

if echo "$BRANCH_NAME" | grep -q '^(rebase)|(production)*$'; then
printf '\n\033[0;32mNo checks necessary on "%s", pushing now... 🎉\033[0m\n' "$BRANCH_NAME"
exit 0
fi

RUBY_FILES="$(git diff --diff-filter=d --name-only --cached | grep -E '(Gemfile|Rakefile|\.(rb|rake|ru))$')"
PRE_STATUS="$(git status | wc -l)"

WORK_DONE=0

if [ -z "$RUBY_FILES" ]; then
printf '\n\033[0;31mThere are currently no updated files in "%s". 🤨\033[0m\n' "$BRANCH_NAME"
fi

if [ -n "$RUBY_FILES" ]; then
printf '\n\033[0;33mRunning Rubocop...\033[0m\n'
for file in $RUBY_FILES; do
git show :"$file" | bundle exec rubocop -A --stdin "$file"
done
RUBOCOP_EXIT_CODE=$?
WORK_DONE=1
else
printf '\n\033[0;32mContinuing as there are no changes to check... 🎉\033[0m\n'
RUBOCOP_EXIT_CODE=0
fi

POST_STATUS="$(git status | wc -l)"

if [ ! $RUBOCOP_EXIT_CODE -eq 0 ]; then
git reset HEAD
printf '\n\033[0;31mLinting has uncorrectable errors; please fix and restage your commit. 😖\033[0m\n'
exit 1
fi

if [ "$PRE_STATUS" != "$POST_STATUS" ]; then
git add "$RUBY_FILES"
fi

if [ $WORK_DONE -eq 1 ]; then
printf '\n\033[0;32mLinting completed successfully! 🎉\033[0m\n'
fi

exit 0
57 changes: 57 additions & 0 deletions .githooks/pre-push
Original file line number Diff line number Diff line change
@@ -0,0 +1,57 @@
#!/bin/bash

list="issue spike task"

listRE="^($(printf '%s\n' "$list" | tr ' ' '|'))/"

BRANCH_NAME=$(git branch --show-current | grep -E "$listRE" | sed 's/* //')

printf '\n\033[0;105mChecking "%s"... \033[0m\n' "$BRANCH_NAME"

if echo "$BRANCH_NAME" | grep -q '^(rebase)|(production)*$'; then
printf '\n\033[0;32mNo checks necessary on "%s", pushing now... 🎉\033[0m\n' "$BRANCH_NAME"
exit 0
fi

# Check for existence of "new or modified" test files
TEST_FILES="$(git diff --diff-filter=ACDM --name-only --cached | grep -E '(./test/*)$')"
RUBY_FILES="$(git diff --diff-filter=ACDM --name-only --cached | grep -E '(_test\.rb)$')"
PRE_STATUS="$(git status | wc -l)"

WORK_DONE=0

if [ -z "$TEST_FILES" ]; then
printf '\n\033[0;31mThere are currently no new tests found in "%s". 🤨\033[0m\n' "$BRANCH_NAME"
printf '\n\033[0;31mContinuing without new tests... 😖\033[0m\n'
fi


if [ -n "$RUBY_FILES" ]; then
printf '\nRunning Rails Tests...'
bundle exec rails test
RUBY_TEST_EXIT_CODE=$?
WORK_DONE=1
else
RUBY_TEST_EXIT_CODE=0
fi

if [ -n "$RUBY_FILES" ]; then
printf '\nRunning System Tests...'
bundle exec rails test:system
RUBY_SYSTEM_EXIT_CODE=$?
WORK_DONE=1
else
RUBY_SYSTEM_EXIT_CODE=0
fi


if [ ! $RUBY_TEST_EXIT_CODE -eq 0 ] || [ ! $RUBY_SYSTEM_EXIT_CODE -eq 0 ]; then
printf '\n\033[0;31mCannot push, tests are failing. Use --no-verify to force push. 😖\033[0m\n'
exit 1
fi

if [ $WORK_DONE = 1 ]; then
printf '\n\033[0;32mAll tests are green, pushing... 🎉\033[0m\n'
fi

exit 0
32 changes: 29 additions & 3 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,24 @@

## Unreleased

## 2.0.1 - 2025-01

## 2.0.1 - 2025-02

- (Jon) Updated the logging to utilise a call-flow diagram to display the
sequence of messages that are sent between the app and the api.
[GH-478](https://github.com/epimorphics/ukhpi/issues/478)
- (Jon) Updated visibility and search input types
- Added conditional class for hiding elements in non-dev environments.
- Changed text fields to search fields for better UX.
- Cleaned up HTML structure for improved readability.
- (Jon) Added pre-commit and pre-push hooks
- Introduced a pre-commit hook to run Rubocop on staged Ruby files.
- Implemented a pre-push hook to run Rails tests before pushing.
- (Jon) Changed time measurement from microseconds to milliseconds in the main
query method
- (Jon) Removed duplicated gem entry
- (Jon) Added dynamic `LOG_LEVEL` env variable
- Defaults to `debug` in development and `info` in production/test.
- (Jon) Enhanced Sentry logging on both Rails and VUE/JS implementations
- (Jon) Refactored UI code to use if/elsif/else in error page responses to
ensure a message is displayed at all times no matter what status is passed in
as per best practices
Expand Down Expand Up @@ -36,6 +52,16 @@
- (Dan) Updates ruby version to 2.7.8 and alpine version to 3.16
[GH-455](https://github.com/epimorphics/ukhpi/issues/455)

## 1.7.6 - 2024-10

- (Jon) Split the error logging into it's own method as well as adjusted the
logged message to be either the response message or the response status
- (Jon) Renamed `render_error` method to `handle_error`
- (Jon) Set the Internal Error Instrumentation to an `unless` statement to
ensure the application does not report internal errors to the Prometheus
metrics when the error is a 404 thereby reducing the noise in the Slack alerts
channel

## 1.7.5 - 2024-09

- (Jon) Created a `local` makefile target to allow for local development without
Expand Down Expand Up @@ -137,7 +163,7 @@
- (Bogdan) Added alt text to application logo
[GH-404](https://github.com/epimorphics/ukhpi/issues/404)

## 1.7.4 - 2024-04-19
## 1.7.4 - 2024-05-01

- (Jon) Updated print presenter to use
[`.try(:first)`](https://apidock.com/rails/Object/try) which resolves by
Expand Down
5 changes: 3 additions & 2 deletions Gemfile
Original file line number Diff line number Diff line change
Expand Up @@ -49,10 +49,11 @@ group :development, :test do
end

group :development do
# Devtools panel for Rails development
# https://chromewebstore.google.com/detail/rails-panel/gjpfobpafnhjhbajcjgccbbdofdckggg?pli=1
gem 'meta_request'
# Access an IRB console on exception pages or by using <%= console %> in views
gem 'web-console'
# Rails Panel is a Chrome extension for Rails development that will end your tailing of development.log.
gem 'meta_request'
# Spring speeds up development by keeping your application running in the background. Read more: https://github.com/rails/spring
gem 'spring'
end
Expand Down
17 changes: 8 additions & 9 deletions Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -37,8 +37,11 @@ ${GITHUB_TOKEN}:
@echo ${PAT} > ${GITHUB_TOKEN}

assets:
@echo "Installing bundler packages ..."
@./bin/bundle install
@echo "Installing yarn packages ..."
@yarn install
@echo "Cleaning and precompiling static assets ..."
@./bin/rails assets:clean assets:precompile

auth: ${GITHUB_TOKEN} ${BUNDLE_CFG}
Expand Down Expand Up @@ -68,14 +71,6 @@ image: auth
lint: assets
@./bin/bundle exec rubocop

local:
@echo "Installing bundler packages ..."
@./bin/bundle install
@echo "Installing yarn packages ..."
@yarn install
@echo "Starting local server ..."
@./bin/rails server -p ${PORT}

publish: image
@echo Publishing image: ${REPO}:${TAG} ...
@docker tag ${NAME}:${TAG} ${REPO}:${TAG} 2>&1
Expand All @@ -89,8 +84,12 @@ run: start
@if docker network inspect dnet > /dev/null 2>&1; then echo "Using docker network dnet"; else echo "Create docker network dnet"; docker network create dnet; sleep 2; fi
@docker run -p ${PORT}:3000 -e API_SERVICE_URL=${API_SERVICE_URL} --network dnet --rm --name ${SHORTNAME} ${NAME}:${TAG}

server:
secret:
@echo "Creating secret ..."
@export SECRET_KEY_BASE=$(./bin/rails secret)

server:
@echo "Starting local server ..."
@API_SERVICE_URL=${API_SERVICE_URL} ./bin/rails server -p ${PORT}

start:
Expand Down
6 changes: 6 additions & 0 deletions app/assets/stylesheets/_lr-common.scss
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,12 @@ $lr-green-nav-darkened: darken( $lr-green-nav, 20% );

/* settings */

ol, ul, nav ol, nav ul {
list-style: unset;
list-style-type: none;
list-style-position: inside;
}

/* elements */

a {
Expand Down
59 changes: 36 additions & 23 deletions app/controllers/application_controller.rb
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ def log_request_result
start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
yield
duration = Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond) - start
detailed_request_log(duration)
detailed_log_result(duration)
end

# Handle specific types of exceptions and render the appropriate error page
Expand Down Expand Up @@ -85,7 +85,7 @@ def render_500(_exception = nil) # rubocop:disable Naming/VariableNumber
render_error(500)
end

def render_error(status, sentry_code = nil) # rubocop:disable Metrics/AbcSize
def render_error(status, sentry_code = nil)
reset_response

status = Rack::Utils::SYMBOL_TO_STATUS_CODE[status] if status.is_a?(Symbol)
Expand All @@ -98,7 +98,7 @@ def render_error(status, sentry_code = nil) # rubocop:disable Metrics/AbcSize
end
end

def render_html_error_page(status, sentry_code) # rubocop:disable Metrics/MethodLength
def render_html_error_page(status, sentry_code)
render 'exceptions/error_page',
locals: { status: status, sentry_code: sentry_code },
layout: true,
Expand All @@ -111,42 +111,55 @@ def reset_response

private

# rubocop:disable Metrics/AbcSize, Metrics/MethodLength
def detailed_request_log(duration)
env = request.env
# rubocop:disable Metrics/AbcSize, Metrics/MethodLength, Layout/LineLength, Metrics/PerceivedComplexity, Metrics/CyclomaticComplexity
def detailed_log_result(duration)
# prevent OK responses from being logged as they're logged elsewhere
return unless response&.status != 200

env = request.env
query = env['QUERY_STRING'] || URI.parse(env['REQUEST_URI']).query
log_fields = {
duration: duration,
message: response.message || Rack::Utils::HTTP_STATUS_CODES[response.status],
path: env['REQUEST_PATH'] || URI.parse(env['REQUEST_URI']).path,
request_id: env['X_REQUEST_ID'],
forwarded_for: env['X_FORWARDED_FOR'],
path: env['REQUEST_PATH'],
query_string: env['QUERY_STRING'],
user_agent: env['HTTP_USER_AGENT'],
accept: env['HTTP_ACCEPT'],
body: request.body.gets&.gsub("\n", '\n'),
request_time: (duration / 1000) || env['REQUEST_TIME'], # in milliseconds
method: request.method,
status: response.status,
message: Rack::Utils::HTTP_STATUS_CODES[response.status]
status: response.status
}

case response.status
when 500..599
log_fields[:query_string] = query if query.present?

if env['HTTP_USER_AGENT'] && Rails.env.production?
log_fields[:user_agent] = env['HTTP_USER_AGENT']
end

if (500..599).include?(Rack::Utils::SYMBOL_TO_STATUS_CODE[response.status])
log_fields[:message] = env['action_dispatch.exception'].to_s
Rails.logger.error(JSON.generate(log_fields))
log_fields[:backtrace] = env['action_dispatch.backtrace'].join("\n") unless Rails.env.production?
end

log_response(response.status, log_fields.sort.to_h)
end
# rubocop:enable Metrics/AbcSize, Metrics/MethodLength, Layout/LineLength

# Log the error with the appropriate log level based on the status code
def log_response(status, error_log)
case status
when 500..599
Rails.logger.error(JSON.generate(error_log))
when 400..499
Rails.logger.warn(JSON.generate(log_fields))
Rails.logger.warn(JSON.generate(error_log))
else
Rails.logger.info(JSON.generate(log_fields))
Rails.logger.info(JSON.generate(error_log))
end
end
# rubocop:enable Metrics/AbcSize, Metrics/MethodLength

# Notify subscriber(s) of an internal error event with the payload of the
# exception once done
# @param [exc] exp the exception that caused the error
# @return [ActiveSupport::Notifications::Event] provides an object-oriented
# interface to the event
# rubocop:disable Metrics/AbcSize, Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity, Metrics/MethodLength
# rubocop:disable Metrics/AbcSize
def instrument_internal_error(exc, status = nil)
err = {
message: exc&.message || exc,
Expand All @@ -167,5 +180,5 @@ def instrument_internal_error(exc, status = nil)
# Return the event id for the internal error event
sevent&.event_id
end
# rubocop:enable Metrics/AbcSize, Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity, Metrics/MethodLength
# rubocop:enable Metrics/AbcSize, Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity
end
1 change: 1 addition & 0 deletions app/controllers/browse_controller.rb
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ def show
elsif explain_non_json?(user_selections)
redirect_to_html_view(user_selections)
else
LoggingHelper.log_request({ params: params })
render_view_state(setup_view_state(user_selections))
end
end
Expand Down
5 changes: 5 additions & 0 deletions app/controllers/compare_controller.rb
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,11 @@ def perform_query(user_compare_selections) # rubocop:disable Metrics/MethodLengt
)

user_compare_selections.selected_locations.each do |location|
msg = 'Received Data Services API request from UKHPI service'
msg += " for #{location.label}" if location
log_fields = { params: base_selection.with('location', location.uri) }
log_fields[:message] = msg
LoggingHelper.log_request(log_fields)
query_results[location.label] = query_with(base_selection, location)
end

Expand Down
18 changes: 12 additions & 6 deletions app/javascript/packs/ukhpi_vue.js
Original file line number Diff line number Diff line change
Expand Up @@ -49,13 +49,19 @@ if (i18n.locale === 'cy') {
}

document.addEventListener('DOMContentLoaded', () => {
// Sentry.io logging
Sentry.init({
dsn: 'https://[email protected]/251669',
debug: process.env.NODE_ENV === 'development',
environment: process.env.NODE_ENV,
integrations: [
new Integrations.Vue({ Vue, attachProps: true })
],
release: window.ukhpi.version || '1.0.0',
ignoreErrors: ['Non-Error promise rejection captured']
})

if (process.env.NODE_ENV === 'production') {
// Sentry.io logging
Sentry.init({
dsn: 'https://[email protected]/251669',
integrations: [new Integrations.Vue({ Vue, attachProps: true })],
release: window.ukhpi.version || 'unknown-version'
})
Sentry.configureScope(scope => {
scope.setTag('app', 'ukhpi-js')
})
Expand Down
Loading

0 comments on commit 19900b7

Please sign in to comment.