Enhance logging

[jawrainey]

1. No output is logged when a pipeline is complete. The is generally useful, but more so for BTF where multiple pipelines may be ran back-to-back
2. No output when a checksum is being created.
3. BTF logs too many request.headers

Anything else @davidverweij ?

[davidverweij]

Where possible, an additional aggregate of logs will help mitigating mismatches quicker. For example, I imagine at the end of a pipeline run:

[data_transfer.devices.byteflies:DEBUG] X records created and Y NOT this session.
[data_transfer.devices.byteflies:DEBUG] The Y NOT created are due to: 
    {
        'unknown devices' : {A, B, C, D, E, F}, 
        'unknown patient ids' : {1, 2, 3, 4, 5}, 
        'other reasons' : [
            {'reason': {metadata}},
            {'reason': {metadata}},
            ....
            ]
    }

Since we basically check for either device_id and patient_id, this would only involve us appending an item to the list when either is unknown. I don't foresee any 'other reasons', but just thought of it if any pop up.

So in our code, we would add something like:

unknown += 1
unkown_causes['unkown devices'].append(_device_id)

Alternatively, we could add a bit more detail per pipeline depending on the API payload (e.g. dot_id)

thoughts?

[jawrainey]

Sounds great and given we log this info at the end download_metadata then it would not appear at the end of the pipeline, but would be searchable in the log. As this relates directly to the metadata stage we could do as you suggested to get a nice overview of known issues. This may not be ideal in the case of BTF where there are hundreds of unknown patients/devices?

In the future, for aggregated summarises and visualisations we could use an ELK stack or some other existing solution to process and visualise the logs -- outside the scope of this issue though.

[davidverweij]

After a quick discussion with @jawrainey, it would be good to reduce some arbitrary logs; such as Reading Record. It would also be good to highlight the size of the (to be) uploaded file using - for example - the return payload from the DMP

[davidverweij]

Also not to forget to forward the logs to the container logs - instead manually to a file. See this stackoverflow solution using >> /proc/1/fd/1

[davidverweij]

I also noticed that fatal errors (e.g. TypeError, KeyboardInterrupt and alike) are not being caught by the logger - or are not being output to the indicated file. Locally, I can see the error being thrown, though this is not being caught in the output. @jawrainey, I suspect this has to do since we only forward the stdout to a file, not the stderr.

I tested, and would suggest as a 'quick fix' while we look into try/excepting a whole DAG (or similar), we add the stderr onto the Docker logs, using

python data_transfer/main.py $DEVICE $STUDYSITE -1 >> /proc/1/fd/1 2>&1

Thoughts?

[jawrainey]

Sounds like you're right that stdout but not stderr is being logged. I'd not try/catch whole DAGs as it's probably best if the DAG fails so we can investigate.

I agree for now your solution looks great when running a pipeline manually. An alternative would be to setup the cron jobs now for BTF/DRM/TFA as they will automatically output to stdout/stderr?