CSC/ECE 517 Fall 2024 - E2471. Reimplement logger
E2471. Reimplement logger
This page provides a description of the Expertiza based OSS project.
About Expertiza
Expertiza is an open source project based on Ruby on Rails framework. Expertiza allows the instructor to create new assignments and customize new or existing assignments. It also allows the instructor to create a list of topics the students can sign up for. Students can form teams in Expertiza to work on various projects and assignments. Students can also peer review other students' submissions. Expertiza supports submission across various document types, including the URLs and wiki pages. As the project has progressed, there has developed a need to reimplement the project using different frameworks. Our project specifically assists in this goal as it implements a logger for the reimplemented backend. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest frontend reimplementation has used Typescript and React to create the UI.
Problem Statement
The following tasks have been accomplished as part of this project:
- Created an ExpertizaLogger to customize logging behavior in the new backend.
- Created special formats for the logging that is being performed to include the desired information.
- Created info, warn, error, fatal, and debug logging levels.
- Created hooks to log CRUD database transactions.
- Utilize hooks to automatically log all model CRUD operations.
These tasks establish a uniform logging experience for all of the CRUD operations, and they provide the ability to log other specific details as desired manually. This ensures that we have a base implementation that complies with the database CRUD operation logging requirement while allowing developers to include manual logging such as error flows or other information that may be helpful for an administrator to consult. Moving forward, all ApplicationRecords will automatically log the CRUD operations, and developers can easily utilize "ExpertizaLogger.warn(message)" to log an info message, for example.
Implementation Details
Our implementation primarily involved creating four new components:
- Expertiza Logger class
- Expertiza Log Formatter class
- Logger Message class
- Logging concern
These components are now explained in greater detail below.
About Expertiza Logger
This logger is responsible for providing the desired log levels in the Expertiza reimplemented backend. It specifically contains the info, warn, error, fatal, and debug logging levels. These logs are then stored in files named "expertiza_info.log", "expertiza_warn.log", etc. It utilizes the Expertiza Log Formatter, which is utilized to format all of the desired log messages.
About Expertiza Log Formatter
This class is a log formatter to provide a uniform style that contains all of the information desired. This is a critical class, as it allows the logs to be effectively searched for the given information logged. It ensures that all logs are consistent and are also easily parsable.
About Logger Message
This class is a simple model that provides the content for the message that is being formatted by Expertiza Logger. It includes such values as the Unity ID, a message, remote IP address, etc. This information is utilized when formatting the logs to ensure that this consistent information is presented and available for inspection without requiring additional developer effort. It makes it easy to modify the logger format because the information will remain consistent, while the Expertiza Log Formatter can adjust the output format easily for all subsequent logs without modifying log commands spread throughout the project.
About Logging Concern
This concern was created as an easy way to ensure that critical events are logged by default in the application. In particular, our goal was to log the database CRUD events. This concern sets up the hooks necessary to call the log methods required to log these events. By including this concern in any model, it will automatically perform the desired CRUD logging. We have leveraged this combined with the model hierarchy of classes depending on ApplicationRecord to ensure logging compliance. That is, we have included the logging concern in ApplicationRecord, allowing any class that inherits from ApplicationRecord to benefit from the automatic logging configuration. This ensures that this architecture is sustainable in the future by ensuring that the desired CRUD operations will be logged without requiring additional developer configuration.
Testing from UI
It is not possible to test and observe this behavior from the UI. This is intentional because users should not be able to access any of the runtime information that is being logged. This information could include users' personal information, etc. that only an admin should be able to inspect. These log files are created and are able to be inspected by an IT administrator, but should not be available for user inspection.
If, however, the admin would like to test the implementation, they can interact with the backend using the frontend, Postman, etc. The actions they perform are logged and can then be inspected in the recorded logs.
For example, here are a few test cases with respect to our code changes that can be tried: 1. Log in to the webpage. Inspecting the logs should show that the user's account information was retrieved from the database.
2. Create a new assignment. Inspecting the logs will demonstrate that the desired information is persisted to the database.
3. Edit the created assignment. Inspecting the logs will demonstrate that the newly updated information is persisted to the database.
4. Delete the assignment. Inspecting the logs will reveal that the assignment was deleted.
Final Design Document
Proposed Changes
From observing the current state of the logging implementation, which includes most functionality from the original Expertiza, we have improved the logging for better observability into the system. To that end, we have implemented the following changes:
Writing more comprehensive automated tests and improving coverage
We have written and executed automated tests to cover a range of logging scenarios. Tests on the CRUD operations of models now ensure the functionality of info-level logging. We've also added tests that check for logging at the other severity levels (warning, error, etc). These tests are stored as files in the spec/logs directory. One example of a testing method is this one, which we've recently written:
RSpec.describe Api::V1::UsersController, type: :controller do
let(:user) { build(:user, name: "Jane", email: "jdoe@ncsu.edu", full_name: "Jane Doe") }
let(:params) do { user: {
"name": "Jane Doe",
"full_name": "Jane Doe",
"email": "jane.doe@example.com",
"role_id": 1,
"institution_id": 1,
"password": "password",
"password_confirmation": "password" } }
end
it "logs when user is created" do
allow(Rails.logger).to receive(:info)
expect(Rails.logger).to receive(:info)
post :create, params: params
end
Enhancing error logging by capturing new cases
Some functionality has changed between the old implementation and the reimplementation of the backend. For example, the reimplementation has different ways of performing error checking in some of the controller methods than the original implementation had. For these cases and others, we added logging to ensure that when a controller method fails, a detailed log message is produced and stored in the appropriate log file.
Correcting the use of the info log level for errors
In the original backend implementation, the info severity level is used almost universally, even when logging errors. For example, in the original implementation of the bookmarks controller, the create method logs errors that occur like so: ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request). We have replaced these with the appropriate logging level, so that errors go to one file, and info to another. This expedites the debugging process for developers, as they will know where to look to find errors vs info.
Standardizing error messages to avoid mixed hardcoded strings and object outputs
In the original backend implementation, sometimes the content of an error object was passed into logging messages, and sometimes hardcoded strings specific to the situation were. For example, in the original implementation of the student teams controller, the create method uses hardcoded strings specifically indicating why the request failed - ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request). However, in the bookmarks controller, the error info was logged like so: ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request). We've increased the consistency across all logging messages to include detailed, context-specific error messages, as that is more informative to developers, and have added logging messages in that style everywhere they are relevant.
Ensuring consistent use of LoggerMessage (e.g., defaulting to session[:user].name unless context demands otherwise)
Both implementations of logging use a LoggerMessage object to standardize information produced in logs. The LoggerMessage object takes, among other things, the unity id of the logger as a parameter. However, in the old backend, that parameter is sometimes passed in from the user's session like session[:user].name and sometimes passed in through other means, such as @participant.name or requested_user.name. We have standardized these in the reimplementation such that the user's session is used everywhere possible to ensure consistency.
Design Patterns
For this project, we used multiple design patterns to create an efficient, sustainable implementation of the logging functionality. In particular, we used the Singleton, Strategy, and Template Method patterns.
We used the singleton pattern to create a single instance of the loggers that we defer to. For example, we create the info_log logger the first time the ExpertizaLogger.info() method is called, but it will reuse the info_log logger instance for all subsequent ExpertizaLogger.info() method calls. This ensures that only one instance of the logger is used for each level created and avoids the additional IO overhead that would be involved with creating a new logger and opening the file for each invocation. Instead, we can re-use the object and ensure that only version for each level can be created throughout the application's lifecycle.
We also used the strategy pattern in our implementation and use of ExpertizaLogFormatter. We defined how we wanted our logs to be formatted with custom formatting, and we created this in the ExpertizaLogFormatter, utilizing polymorphism to override the call implementation provided by Logger::Formatter. This encapsulates our desired behavior and allows us to potentially create several strategies over time as the needs of the project evolve. For future versions, we can simply create a new LogFormatter that overrides call to define our new algorithmic behavior. When desired, we can modify add_formatter to provide our new preferred implementation to the logger instances. This allows us to easily modify the formatting behavior without modifying core logging logic and allows us to abide by the Open/Closed Principle by further extending to achieve desired functionality without modifying pre-existing or core implementations whenever we want to use a different strategy.
In our specific implementation of ExpertizaLogFormatter, we use the template method design pattern to utilize a template of the formatter while deferring specific behavioral steps to subclasses. In this case, it allows us to override the Logger::Formatter call method to replace that step's implementation with our own formatting. It allows us to take the default template implementation and further customize it to suit our needs without modifying the inherited Logger::Formatter structure.
These design patterns will greatly help the efficiency of our project and encourage sustainable development that is predictable and easy for future developers. We implemented common design patterns using intuitive methods and anticipate this design to support and encourage future development with increasing functionality and project growth.
Tests Explained
This section will explain the tests we've written to varying levels of specificity. Where reasonable, we've omitted tests that are repetitive to reduce redundancy - for example, we only explain the info level logging tests in spec/logs/expertiza_logger_spec.rb. While we have separate tests in that file for the other severity levels, they're very similar, and do not warrant separate explanation.
Expertiza Log Formatter Tests
The Expertiza Log Formatter is designed to ensure consistent log formatting across various logging scenarios. The tests in spec/logs/expertiza_log_formatter_spec.rb are designed to check this functionality.
Before the tests, a few helpful variables are defined as such:
let(:formatter) { ExpertizaLogFormatter.new }
let(:timestamp) { Time.now }
let(:severity) { 'INFO' }
let(:progname) { 'Expertiza' }
The first two tests, included below, check that the log formatter can format messages correctly. The first test invokes the call method on the formatter with info level severity, the current time as timestamp, 'Expertiza' as the program name, and a simple string as the message parameter. Given these simple parameters, we can easily check that the produced message, returned by the call method, matches our expectations. The second test is very similar, but checks that a message with a newline produces a log without one. The ExpertizaLogFormatter is designed to take all newlines and replace them with space characters, so that log files aren't unnecessarily messy.
context 'when the message is a plain string' do
let(:message) { 'Test message with more text' }
it 'formats the message correctly' do
formatted_message = formatter.call(severity, timestamp, progname, message)
expect(formatted_message).to include("TST=[#{timestamp}] SVT=[#{severity}] PNM=[#{progname}] OIP=[] RID=[] CTR=[] UID=[] MSG=[Test message with more text]")
end
end
context 'when the message is a plain string with newline' do
let(:message) { "Test message with newline\nto more text" }
it 'formats the message correctly' do
formatted_message = formatter.call(severity, timestamp, progname, message)
expect(formatted_message).to include("TST=[#{timestamp}] SVT=[#{severity}] PNM=[#{progname}] OIP=[] RID=[] CTR=[] UID=[] MSG=[Test message with newline to more text]")
end
end
The final two tests similarly check formatting, except instead of passing in a simple string, they instead pass in a LoggerMessage object. LoggerMessage is a class designed to hold more complex information than just a simple message. LoggerMessage objects can hold a reference to a 'generator' (typically the name of the controller the log comes from), the unity id of the generating user, a string message, and a request (made up of a remote ip address and a unique identifier/uuid). The first test here uses a LoggerMessage without a request, and ensures the resulting log contains the information from that object. The second test uses a LoggerMessage that does contain a request, and ensures the formatting and data integrity of the created log message similarly.
context 'when the message is a LoggerMessage object' do
let(:logger_message) do
LoggerMessage.new('gen1', 'unityid1', 'Test message')
end
it 'formats the message correctly' do
formatted_message = formatter.call(severity, timestamp, progname, logger_message)
expect(formatted_message).to include("TST=[#{timestamp}] SVT=[#{severity}] PNM=[#{progname}] OIP=[] RID=[] CTR=[gen1] UID=[unityid1] MSG=[Test message]")
end
end
context 'when the message is a LoggerMessage object with request' do
let(:logger_message) do
LoggerMessage.new('gen1', 'unityid1', 'Test message', double("request", remote_ip: "192.168.1.1", uuid: "12345"))
end
it 'formats the message correctly' do
formatted_message = formatter.call(severity, timestamp, progname, logger_message)
expect(formatted_message).to include("TST=[#{timestamp}] SVT=[#{severity}] PNM=[#{progname}] OIP=[192.168.1.1] RID=[12345] CTR=[gen1] UID=[unityid1] MSG=[Test message]")
end
end
Expertiza Logger Tests
The Expertiza Logger is designed to log information at varying severity levels, depending on which of its methods are called, while following standardized log formatting. To do so, it creates and stores one instance of Ruby's Logger class for each severity level, and uses the aforementioned ExpertizaLogFormatter to format incoming messages. Depending on the method called, ExpertizaLogger logs to a file that corresponds to a specific logging level. The tests in spec/logs/expertiza_logger_spec.rb are designed to check this functionality.
Before the tests, a few helpful variables are defined as such, including a mocked instance of the Logger class.
let(:message) { 'Test message' }
let(:timestamp) { Time.now }
# Create a mock logger instance
let(:mock_logger) { instance_double(Logger) }
This test also uses a before block to enable the Logger to receive a request for a new instance of itself and to return a mock logger, which can in turn receive various requests. This is important to avoid directly testing the ExpertizaLogFormatter. The test is designed to rely on expected behavior from that class, rather than directly testing it, as that's outside the scope of these tests.
before do allow(Logger).to receive(:new).and_return(mock_logger) allow(mock_logger).to receive(:formatter) allow(mock_logger).to receive(:formatter=).with(an_instance_of(ExpertizaLogFormatter)) allow(mock_logger).to receive(:info) allow(mock_logger).to receive(:warn) allow(mock_logger).to receive(:error) allow(mock_logger).to receive(:fatal) allow(mock_logger).to receive(:debug) end
Then for each severity level, there is a test like this one. We're only including the info-level test here. The test calls the info method of the ExpertizaLogger class, which is expected to then call the new method on the Logger class, passing in the appropriate log file for this severity level (expertiza_info.log). The test expects that the formatter attribute of this new Logger instance, referred to as mock_logger, will be set equal to an instance of the ExpertizaLogFormatter and that the mock_logger receives a call to its info method with the right message parameter.
describe '.info' do
it 'logs the message to the correct file with info severity' do
ExpertizaLogger.info(message)
expect(Logger).to have_received(:new).with(Rails.root.join('log', 'expertiza_info.log'))
expect(mock_logger).to have_received(:formatter=).with(an_instance_of(ExpertizaLogFormatter))
expect(mock_logger).to have_received(:info).with(message)
end
end
References
- Expertiza on GitHub
- Reimplemented Frontend Github Project
- Reimplemented Backend GitHub Project
- Reimplemented Backend GitHub Project Repository Fork
- The live Expertiza website
- Part 1 Project demo link
- Part 2 Project demo link
- Expertiza project documentation wiki
- Initial logging commit
- Reimplement Expertiza Logger
- Adding logging to ApplicationRecord