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 were accomplished in 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 Expertize 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 will be consistent and are also easily parsable.
About Logger Message
This class is a simple model intended to provide 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 can then be utilized when formatting the logs to ensure that this consistent information is presented and available for inspection without requiring additional developer effort. It allows any desired updates to the logger format to be easily modified 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 should be created and able to be inspected by an IT administrator, but it 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 should be 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 believe we can improve the logging for better observability into the system. To that end, we propose the following changes:
Writing more comprehensive automated tests and improving coverage
We've already created some basic automated tests and gotten them to run, but we want to add more to cover more cases. For example, we currently have some tests on the CRUD operations of models to test info-level logging. We'll add tests that check for logging at the other severity levels (warning, error, etc) as well. This will touch 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 will add 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). Our intention is to replace these with the appropriate logging level, so that errors go to one file, and info to another. This will expedite 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 aim for consistency across all logging messages, and will therefore choose one of two routes, whichever is more informative to developers, and add logging messages for that everywhere.
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, 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 aim to analyze these use cases and, where possible, standardize them in the reimplementation. We believe the user's session should be used everywhere if possible to ensure consistency.
Plan of Work
We plan to approach the work in the following order:
Comb through every controller and model file, and each method within those files
Add logging where relevant for creation, destruction, etc. Add logging for errors. For those files and methods which exist, but are unimplemented, we will develop a boilerplate statement to add to them, pointing future developers to references so they understand how best to add logging when they do implement the code.
Standardize log severity levels across the application
Review current log levels used in the reimplementation to ensure that appropriate severity levels (info, warning, error, etc.) are applied based on the context. For instance, success messages should use info level, whereas failures or issues in expected behavior should use warning or error levels as appropriate.
Refactor existing logging to use LoggerMessage consistently
Identify instances where the unity id parameter of LoggerMessage is passed in inconsistently. We will refactor the code to ensure that LoggerMessage is applied uniformly across the application, defaulting to session[:user].name for the unity ID unless context requires another source.
Implement automated tests for all logging behavior
We will create comprehensive automated tests for each logging action to verify that logs are generated as expected and with the correct severity level. Tests will cover different CRUD actions, error handling scenarios, and edge cases. We will likely place these tests in the spec/logs directory.
Document the logging strategy and guidelines for future developers
In this wiki, add a section detailing the logging strategy, including the severity levels used, when to apply specific log levels, and examples of correctly formatted log messages. This documentation will help ensure that future contributors can easily understand and follow the logging conventions.
Conduct code review and team walkthrough of the logging updates
Once the changes are implemented, we’ll hold a final code review to catch any inconsistencies or errors. At this point, we'll discuss and make any final adjustments.
Perform final testing after deploying our application to VCL or similar hosting
After implementing and testing the updates locally, we’ll deploy the app, with its frontend, and conduct end-to-end tests (e.g., doing something in the frontend and checking that the appropriate log file is updated as expected). This phase will help us identify any unforeseen issues in the logging setup and confirm that log messages are correctly output and stored.
References
- Expertiza on GitHub
- Reimplemented Frontend Github Project
- Reimplemented Backend GitHub Project
- Reimplemented Backend GitHub Project Repository Fork
- The live Expertiza website
- Project demo link
- Expertiza project documentation wiki
- Initial logging commit
- Reimplement Expertiza Logger
- Adding logging to ApplicationRecord