Add/more logging information #432

lagoan · 2024-05-10T17:25:12Z

WIP Add more preservation events to logs

This work in progress adds more information about all logging events
to get a better idea of the behavior on PMPY.

Right now the preservation event loggers are initialized on startup
instead of being instantiated every time there is a preservation event.

All is done in the logger reader method. We could change it so the
preservation loggers are instantiated on their access.

3 placeholder tests need to be completed.

Currently we are only logging successful events with the method ``log_preservation_event``. We want to log more information to reflect the system current work state. For now we simple change the name to that method to: ``log_preservation_success``

This WIP commit adds the different methods that will be used for logging the specific preservation events. Next we will be adding them to the logic.

This work in progress adds more information about all logging events in order to get a better idea of the behavior on PMPY. Right now the preservation event loggers are initialized on startup instead of being instantiated every time there is a preservation event. All is done in the logger reader method. We could change it so the preservation loggers are instantiated on their own access. There are 3 placeholder tests that need to be completed.

pgwillia

Was there anything in particular you wanted feedback about? It looks like you're on the right track.

Trying this in my dev environment I'm probably missing a step, because I'm getting a lot of

Error of type: Errno::ECONNRESET
Error message: Connection reset by peer

I start jupiter ./bin/setup && ./bin/dev then in a new terminal set jupiter environment variables, ./bin/setup && bundle exec rake install, then bundle exec pushmi_pullyu. After than I open a new console to bundle exec rake jupiter:preserve_all_items_and_theses in jupiter. What did I miss?

lagoan · 2024-05-13T16:03:48Z

Thanks for taking a look @pgwillia .

I hope to get feedback on the loggers initialization. I am piggybacking on the original logger initializer for the preservaition event logs instead of opening and closing the log files on each preservation event.

The logger initializer is here:

pushmi_pullyu/lib/pushmi_pullyu/logging.rb

Lines 24 to 31 in ed1db2d

    
           def initialize_loggers(log_target: $stdout, events_target: $stdout, json_target: $stdout) 
        
             @preservation_logger = Logger.new(events_target) 
        
             @preservation_json_logger = Logger.new(json_target) 
        
             @logger = Logger.new(log_target) 
        
             @logger.level = Logger::INFO 
        
             @logger 
        
           end

I kept the rest of the behaviour as it was, returning the original logger.

Another approach can be to have another method to initialize the preservation event logs. This would simplify the methods but add an extra step.

This is a minor issue right now, but there might be something else I do not see.

Just add the tests for the new methods and make sure the JSON log includes its values in JSON format when needed.

lagoan · 2024-05-15T18:43:36Z

@pgwillia I run it a bit differently.

Sorry if I missed it, what application is giving you this error?

I will add my startup method with you.

pgwillia · 2024-05-15T22:04:30Z

@pgwillia I run it a bit differently.

Sorry if I missed it, what application is giving you this error?

I will add my startup method with you.

$ export JUPITER_API_KEY=3eeb395e-63b7-11ea-bc55-0242ac130003
$ export JUPITER_USER=ditech@ualberta.ca
$ bundle exec rake install
pushmi_pullyu 2.0.7 built to pkg/pushmi_pullyu-2.0.7.gem.
pushmi_pullyu (2.0.7) installed.
$ docker-compose up -d
Starting pushmi_pullyu_swift_1 ... done
$ bundle exec pushmi_pullyu

I think it's PMPY giving the error, but could be Swift. Jupiter looks fine.

Loading PushmiPullyu 2.0.7
Running in ruby 2.7.6p219 (2022-04-12 revision c9c2245c0a) [x86_64-linux]
Starting processing, hit Ctrl-C to stop
items will attempt to be deposited.
Here are the details of this preservation event:
	items uuid: 00a64095-8a04-4106-a76d-407d3536edb6	Retry attempt: 3

I, [2024-05-15T16:00:45.471699 #10640]  INFO -- : items will attempt to be deposited.
Here are the details of this preservation event:
	items uuid: 00a64095-8a04-4106-a76d-407d3536edb6	Retry attempt: 3

I, [2024-05-15T16:00:45.471714 #10640]  INFO -- : {"event_type":"attempt","event_time":"2024-05-15 16:00:45 -0600","entity_type":"items","entity_uuid":"00a64095-8a04-4106-a76d-407d3536edb6","retry_attempt":"3"},
[items - 00a64095-8a04-4106-a76d-407d3536edb6]: Retreiving data from Jupiter ...
[items - 00a64095-8a04-4106-a76d-407d3536edb6]: tmp/work/00a64095-8a04-4106-a76d-407d3536edb6/data/objects/metadata/object_metadata.n3 -- Downloading from aip/v1/items/00a64095-8a04-4106-a76d-407d3536edb6 ...
[items - 00a64095-8a04-4106-a76d-407d3536edb6]: tmp/work/00a64095-8a04-4106-a76d-407d3536edb6/data/objects/metadata/object_metadata.n3 -- Saved
[items - 00a64095-8a04-4106-a76d-407d3536edb6]: tmp/work/00a64095-8a04-4106-a76d-407d3536edb6/data/objects/metadata/files_metadata/file_order.xml -- Downloading from aip/v1/items/00a64095-8a04-4106-a76d-407d3536edb6/filesets ...
[items - 00a64095-8a04-4106-a76d-407d3536edb6]: tmp/work/00a64095-8a04-4106-a76d-407d3536edb6/data/objects/metadata/files_metadata/file_order.xml -- Saved
#<Errno::ECONNRESET: Connection reset by peer>
items failed to be deposited and will try again.
Here are the details of this preservation event:
	items uuid: 00a64095-8a04-4106-a76d-407d3536edb6	Readding to preservation queue with retry attempt: 4
	Error of type: Errno::ECONNRESET
	Error message: Connection reset by peer

pgwillia

The new tests look good! 👍

Did you run the new logging by Henry to see if it works for the Preservation team?

pgwillia · 2024-05-15T22:37:20Z

lib/pushmi_pullyu/logging.rb

@@ -21,14 +21,17 @@ class << self

    attr_writer :logger


I don't have a strong opinion on initializing the logs. I think what you've done works as well as anything else.

I was trying to find out if Ruby community has a best practice around attribute accessors vs instance variables because I see here that logger is declared this way. I couldn't find anything clear.

pgwillia

👍

ConnorSheremeta · 2024-05-23T16:01:14Z

spec/pushmi_pullyu/logging_spec.rb

+
+    it 'logs preservation event to both preservation log and application log' do
+      # Make sure we are initialize logger with expected file destinations and not default stdout destination
+      PushmiPullyu::Logging.initialize_loggers(events_target: "#{tmp_log_dir}/preservation_events.log",


I wonder if tagged logging could be used rather than two multiple log files/loggers? (https://api.rubyonrails.org/classes/ActiveSupport/TaggedLogging.html) I suppose it would depend on how the logs are used to troubleshoot and the content of the logs itself. I think how the logs are initialised are fine however and everything else looks good to me.

That is a good point @ConnorSheremeta . Having different loggers was done before this work was done. I believe the idea is to have the logs handled separately so they can be parsed based on need.

I will keep in mind your suggestion if we want to simplify logging at a later date.

lagoan added 3 commits March 29, 2024 14:45

Rename log_preservation_event method

6eca324

Currently we are only logging successful events with the method ``log_preservation_event``. We want to log more information to reflect the system current work state. For now we simple change the name to that method to: ``log_preservation_success``

WIP Add new logging methods

dc7876d

This WIP commit adds the different methods that will be used for logging the specific preservation events. Next we will be adding them to the logic.

lagoan requested review from ConnorSheremeta, henryzhang87, pgwillia and piyapongch as code owners May 10, 2024 17:25

pgwillia reviewed May 13, 2024

View reviewed changes

lagoan added 2 commits May 15, 2024 12:32

Add missing tests and cleanup log JSON format

c0c7370

Just add the tests for the new methods and make sure the JSON log includes its values in JSON format when needed.

Add CHANGELOG entry

6a6ea6a

lagoan changed the title ~~WIP Add/more logging information~~ Add/more logging information May 15, 2024

pgwillia reviewed May 15, 2024

View reviewed changes

pgwillia approved these changes May 21, 2024

View reviewed changes

ConnorSheremeta reviewed May 23, 2024

View reviewed changes

lagoan merged commit 4b0e3e4 into master May 23, 2024
2 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add/more logging information #432

Add/more logging information #432

lagoan commented May 10, 2024

pgwillia left a comment

lagoan commented May 13, 2024

lagoan commented May 15, 2024

pgwillia commented May 15, 2024 •

edited

pgwillia left a comment

pgwillia May 15, 2024

pgwillia left a comment

ConnorSheremeta May 23, 2024

lagoan May 23, 2024

Add/more logging information #432

Add/more logging information #432

Conversation

lagoan commented May 10, 2024

pgwillia left a comment

Choose a reason for hiding this comment

lagoan commented May 13, 2024

lagoan commented May 15, 2024

pgwillia commented May 15, 2024 • edited

pgwillia left a comment

Choose a reason for hiding this comment

pgwillia May 15, 2024

Choose a reason for hiding this comment

pgwillia left a comment

Choose a reason for hiding this comment

ConnorSheremeta May 23, 2024

Choose a reason for hiding this comment

lagoan May 23, 2024

Choose a reason for hiding this comment

pgwillia commented May 15, 2024 •

edited