Expertiza_Wiki - User contributions [en]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T15:00:59Z

Cshimes: /* Tests Explained */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. We have standardized these in the reimplementation such that the user's session is used everywhere possible to ensure consistency.

==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 <code>spec/logs/expertiza_logger_spec.rb</code>. 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 <code>spec/logs/expertiza_log_formatter_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such:
<pre>
let(:formatter) { ExpertizaLogFormatter.new }
let(:timestamp) { Time.now }
let(:severity) { 'INFO' }
let(:progname) { 'Expertiza' }
</pre>

The first two tests, included below, check that the log formatter can format messages correctly. The first test invokes the <code>call</code> 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 <code>call</code> method, matches our expectations. The second test is very similar, but checks that a message with a newline produces a log without one. The <code>ExpertizaLogFormatter</code> is designed to take all newlines and replace them with space characters, so that log files aren't unnecessarily messy.

<pre>
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
</pre>

The final two tests similarly check formatting, except instead of passing in a simple string, they instead pass in a <code>LoggerMessage</code> object. <code>LoggerMessage</code> is a class designed to hold more complex information than just a simple message. <code>LoggerMessage</code> 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 <code>LoggerMessage</code> without a request, and ensures the resulting log contains the information from that object. The second test uses a <code>LoggerMessage</code> that does contain a request, and ensures the formatting and data integrity of the created log message similarly.

<pre>
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
</pre>

===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 <code>Logger</code> class for each severity level, and uses the aforementioned <code>ExpertizaLogFormatter</code> to format incoming messages. Depending on the method called, <code>ExpertizaLogger</code> logs to a file that corresponds to a specific logging level. The tests in <code>spec/logs/expertiza_logger_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such, including a mocked instance of the <code>Logger</code> class.
<pre>
let(:message) { 'Test message' }
let(:timestamp) { Time.now }

# Create a mock logger instance
let(:mock_logger) { instance_double(Logger) }
</pre>

This test also uses a before block to enable the <code>Logger</code> 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 <code>ExpertizaLogFormatter</code>. 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.

<pre>
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
</pre>

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 <code>info</code> method of the <code>ExpertizaLogger</code> class, which is expected to then call the <code>new</code> method on the <code>Logger</code> class, passing in the appropriate log file for this severity level (<code>expertiza_info.log</code>). The test expects that the <code>formatter</code> attribute of this new <code>Logger<code> instance, referred to as <code>mock_logger</code>, will be set equal to an instance of the <code>ExpertizaLogFormatter</code> and that the <code>mock_logger</code> receives a call to its <code>info</code> method with the right message parameter.

<pre>
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
</pre>

==References==

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T15:00:24Z

Cshimes: /* Tests Explained */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. We have standardized these in the reimplementation such that the user's session is used everywhere possible to ensure consistency.

==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 <code>spec/logs/expertiza_logger_spec.rb</code>. 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 <code>spec/logs/expertiza_log_formatter_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such:
<pre>
let(:formatter) { ExpertizaLogFormatter.new }
let(:timestamp) { Time.now }
let(:severity) { 'INFO' }
let(:progname) { 'Expertiza' }
</pre>

The first two tests, included below, check that the log formatter can format messages correctly. The first test invokes the <code>call</code> 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 <code>call</code> method, matches our expectations. The second test is very similar, but checks that a message with a newline produces a log without one. The <code>ExpertizaLogFormatter</code> is designed to take all newlines and replace them with space characters, so that log files aren't unnecessarily messy.

<pre>
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
</pre>

The final two tests similarly check formatting, except instead of passing in a simple string, they instead pass in a <code>LoggerMessage</code> object. <code>LoggerMessage</code> is a class designed to hold more complex information than just a simple message. <code>LoggerMessage</code> 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 <code>LoggerMessage</code> without a request, and ensures the resulting log contains the information from that object. The second test uses a <code>LoggerMessage</code> that does contain a request, and ensures the formatting and data integrity of the created log message similarly.

<pre>
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 <code>Logger</code> class for each severity level, and uses the aforementioned <code>ExpertizaLogFormatter</code> to format incoming messages. Depending on the method called, <code>ExpertizaLogger</code> logs to a file that corresponds to a specific logging level. The tests in <code>spec/logs/expertiza_logger_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such, including a mocked instance of the <code>Logger</code> class.
<pre>
let(:message) { 'Test message' }
let(:timestamp) { Time.now }

# Create a mock logger instance
let(:mock_logger) { instance_double(Logger) }
</pre>

This test also uses a before block to enable the <code>Logger</code> 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 <code>ExpertizaLogFormatter</code>. 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.

<pre>
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
</pre>

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 <code>info</code> method of the <code>ExpertizaLogger</code> class, which is expected to then call the <code>new</code> method on the <code>Logger</code> class, passing in the appropriate log file for this severity level (<code>expertiza_info.log</code>). The test expects that the <code>formatter</code> attribute of this new <code>Logger<code> instance, referred to as <code>mock_logger</code>, will be set equal to an instance of the <code>ExpertizaLogFormatter</code> and that the <code>mock_logger</code> receives a call to its <code>info</code> method with the right message parameter.

<pre>
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
</pre>

==References==

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T15:00:05Z

Cshimes: /* Expertiza Log Formatter Tests */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. We have standardized these in the reimplementation such that the user's session is used everywhere possible to ensure consistency.

==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 <code>spec/logs/expertiza_logger_spec.rb</code>. 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 <code>spec/logs/expertiza_log_formatter_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such:
<pre>
let(:formatter) { ExpertizaLogFormatter.new }
let(:timestamp) { Time.now }
let(:severity) { 'INFO' }
let(:progname) { 'Expertiza' }
</pre>

The first two tests, included below, check that the log formatter can format messages correctly. The first test invokes the <code>call</code> 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 <code>call</code> method, matches our expectations. The second test is very similar, but checks that a message with a newline produces a log without one. The <code>ExpertizaLogFormatter</code> is designed to take all newlines and replace them with space characters, so that log files aren't unnecessarily messy.

<pre>
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
</pre>

The final two tests similarly check formatting, except instead of passing in a simple string, they instead pass in a <code>LoggerMessage</code> object. <code>LoggerMessage</code> is a class designed to hold more complex information than just a simple message. <code>LoggerMessage</code> 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 <code>LoggerMessage</code> without a request, and ensures the resulting log contains the information from that object. The second test uses a <code>LoggerMessage</code> that does contain a request, and ensures the formatting and data integrity of the created log message similarly.

<pre>
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

==References==

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T14:58:38Z

Cshimes: /* Tests Explained */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. We have standardized these in the reimplementation such that the user's session is used everywhere possible to ensure consistency.

==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 <code>spec/logs/expertiza_logger_spec.rb</code>. 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 <code>spec/logs/expertiza_log_formatter_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such:
<pre>
let(:formatter) { ExpertizaLogFormatter.new }
let(:timestamp) { Time.now }
let(:severity) { 'INFO' }
let(:progname) { 'Expertiza' }
</pre>

The first two tests, included below, check that the log formatter can format messages correctly. The first test invokes the <code>call</code> 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 <code>call</code> method, matches our expectations. The second test is very similar, but checks that a message with a newline produces a log without one. The <code>ExpertizaLogFormatter</code> is designed to take all newlines and replace them with space characters, so that log files aren't unnecessarily messy.

<pre>
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
</pre>

The final two tests similarly check formatting, except instead of passing in a simple string, they instead pass in a <code>LoggerMessage</code> object. <code>LoggerMessage</code> is a class designed to hold more complex information than just a simple message. <code>LoggerMessage</code> 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 <code>LoggerMessage</code> without a request, and ensures the resulting log contains the information from that object. The second test uses a <code>LoggerMessage</code> that does contain a request, and ensures the formatting and data integrity of the created log message similarly.

<pre>
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 <code>Logger</code> class for each severity level, and uses the aforementioned <code>ExpertizaLogFormatter</code> to format incoming messages. Depending on the method called, <code>ExpertizaLogger</code> logs to a file that corresponds to a specific logging level. The tests in <code>spec/logs/expertiza_logger_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such, including a mocked instance of the <code>Logger</code> class.
<pre>
let(:message) { 'Test message' }
let(:timestamp) { Time.now }

# Create a mock logger instance
let(:mock_logger) { instance_double(Logger) }
</pre>

This test also uses a before block to enable the <code>Logger</code> 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 <code>ExpertizaLogFormatter</code>. 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.

<pre>
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
</pre>

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 <code>info</code> method of the <code>ExpertizaLogger</code> class, which is expected to then call the <code>new</code> method on the <code>Logger</code> class, passing in the appropriate log file for this severity level (<code>expertiza_info.log</code>). The test expects that the <code>formatter</code> attribute of this new <code>Logger<code> instance, referred to as <code>mock_logger</code>, will be set equal to an instance of the <code>ExpertizaLogFormatter</code> and that the <code>mock_logger</code> receives a call to its <code>info</code> method with the right message parameter.

<pre>
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
</pre>

==References==

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T14:38:02Z

Cshimes: /* Final Design Document */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. We have standardized these in the reimplementation such that the user's session is used everywhere possible to ensure consistency.

==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 <code>spec/logs/expertiza_logger_spec.rb</code>. 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 <code>spec/logs/expertiza_log_formatter_spec.rb</code> are designed to check this functionality.

Before the tests, a few helpful variables are defined as such:
<pre>
let(:formatter) { ExpertizaLogFormatter.new }
let(:timestamp) { Time.now }
let(:severity) { 'INFO' }
let(:progname) { 'Expertiza' }
</pre>

The first two tests, included below, check that the log formatter can format messages correctly. The first test invokes the <code>call</code> 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 <code>call</code> method, matches our expectations. The second test is very similar, but checks that a message with a newline produces a log without one. The <code>ExpertizaLogFormatter</code> is designed to take all newlines and replace them with space characters, so that log files aren't unnecessarily messy.

<pre>
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
</pre>

The final two tests similarly check formatting, except instead of passing in a simple string, they instead pass in a <code>LoggerMessage</code> object. <code>LoggerMessage</code> is a class designed to hold more complex information than just a simple message. <code>LoggerMessage</code> 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 <code>LoggerMessage</code> without a request, and ensures the resulting log contains the information from that object. The second test uses a <code>LoggerMessage</code> that does contain a request, and ensures the formatting and data integrity of the created log message similarly.

<pre>
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
</pre>

==References==

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T14:19:55Z

Cshimes: /* Final Design Document */

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-26T14:09:50Z

Cshimes: /* Final Design Document */

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-25T20:19:11Z

Cshimes: /* E2471. Reimplement logger */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. 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 <code>LoggerMessage</code> consistently====
Identify instances where the unity id parameter of <code>LoggerMessage</code> is passed in inconsistently. We will refactor the code to ensure that <code>LoggerMessage</code> is applied uniformly across the application, defaulting to <code>session[:user].name</code> 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===

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]

CSC/ECE 517 Fall 2024 - E2471. Reimplement logger

2024-11-11T14:58:56Z

Cshimes: /* E2471. Reimplement logger */

==E2471. Reimplement logger==

This page provides a description of the Expertiza based OSS project.

__TOC__

===About Expertiza===

[http://expertiza.ncsu.edu/ Expertiza] is an open source project based on [http://rubyonrails.org/ 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 [https://github.com/expertiza/reimplementation-back-end reimplemented backend]. This new backend utilizes Rails API to create a RESTful API that can be accessed by frontend implementations. The latest [https://github.com/expertiza/reimplementation-front-end 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 <code>spec/logs</code> directory. One example of a testing method is this one, which we've recently written:

<pre>
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
</pre>

====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 <code>create</code> method logs errors that occur like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>create</code> method uses hardcoded strings specifically indicating why the request failed - <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, 'Team name missing while creating team', request)</code>. However, in the bookmarks controller, the error info was logged like so: <code>ExpertizaLogger.info LoggerMessage.new(controller_name, session[:user].name, $ERROR_INFO, request)</code>. 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 <code>LoggerMessage</code> (e.g., defaulting to session[:user].name unless context demands otherwise)====
Both implementations of logging use a <code>LoggerMessage</code> object to standardize information produced in logs. The <code>LoggerMessage</code> 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 <code>session[:user].name</code> and sometimes passed in through other means, such as <code>@participant.name</code> or <code>requested_user.name</code>. 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 <code>LoggerMessage</code> consistently====
Identify instances where the unity id parameter of <code>LoggerMessage</code> is passed in inconsistently. We will refactor the code to ensure that <code>LoggerMessage</code> is applied uniformly across the application, defaulting to <code>session[:user].name</code> 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===

#[https://github.com/expertiza/expertiza Expertiza on GitHub]
#[https://github.com/expertiza/reimplementation-front-end Reimplemented Frontend Github Project]
#[https://github.com/expertiza/reimplementation-back-end Reimplemented Backend GitHub Project]
#[https://github.com/camhimes/reimplementation-back-end Reimplemented Backend GitHub Project Repository Fork]
#[http://expertiza.ncsu.edu/ The live Expertiza website]
#[https://drive.google.com/file/d/1JnMWG1d7P_yLQ_un_R7kMbTrBk5YoA87/view?usp=share_link Project demo link]
#[https://wiki.expertiza.ncsu.edu/index.php?title=Main_Page Expertiza project documentation wiki]
#[https://github.com/camhimes/reimplementation-back-end/commit/aa84e46135d4f660c6a981f5d032cdf2a4b2f25e Initial logging commit]
#[https://github.com/camhimes/reimplementation-back-end/commit/1e0ee7a0d7f6e6d48e9a82753ee0fa0afdf8440f Reimplement Expertiza Logger]
#[https://github.com/camhimes/reimplementation-back-end/commit/ceee53b4d9ed4281ac2f0201873a40b90bceb039 Adding logging to ApplicationRecord]