[AG-1041] Adds timestamp logging for processing runs

[BWMac]

This PR adds a new module to agoradatatools: logs.py. The new module contains the log_time decorator function along with a couple of helper functions. log_time` works by decorating a function like so:

@log_time(func_name="process_dataset", logger=logger)
def process_dataset():
     ...

It takes the name of the function (for configuring the logging output) and the logger instance for the module that it is being used in as arguments. At the moment, log_time has configurations for process_dataset and process_all_files, so that we can time and timestamp the processing of each dataset and data processing as a whole.

In practice, when you run adt test_config.yaml, you should see an output like this for each dataset:

INFO | 2023-05-04 16:05:00 | Now processing genes_biodomains dataset

##################################################
 Uploading file to Synapse storage 
##################################################

INFO | 2023-05-04 16:05:12 | 
##################################################
 Uploading file to Synapse storage 
##################################################

 / INFO | 2023-05-04 16:05:13 | Processing complete for genes_biodomains dataset
INFO | 2023-05-04 16:05:13 | Elapsed time: 00:00:13 for genes_biodomains dataset

And like this for the whole process:

INFO | 2023-05-04 16:04:47 | Agora Data Tools processing has started
...
...
...
...
INFO | 2023-05-04 16:07:12 | Elapsed time: 00:02:11 for all data processing

[thomasyu888]

So I've been thinking about this more, and configuring logging has always been a tiny bit confusing. BUT... I think initializing the logging can potentially be done in __init__.py. For example:

In __init__.py

logging.basicConfig(
    stream=sys.stdout, level=logging.INFO, format="INFO: %(message)s"
)

Basically, you may not need to initialize the logger everytime.

[thomasyu888]

🎉 LGTM! Nice addition of logging!

[JessterB]

This looks good to me, and including the processing times in addition to the timestamps is a nice bonus!

I am curious why we are logging the "Uploading file to synapse storage" block twice per dataset (once without, and then again with, the timestamp), but ultimately that's harmless...

[BWMac]

@JessterB Yeah I was wondering about that myself, but that has to do with the syn.load() functionality rather than anything in this repo. I tried to silence the Synapse logging, but it caused issues with our new logging functionality. This is likely a Synapse client bug, Tom and I discussed that in this resolved comment thread.

[jaclynbeck-sage]

This looks great!