Add common format for pipeline process logging

[kevin-bates]

This change uses a base class method log_pipeline_info() to issue consistently formatted log messages that can be used to help diagnose where bottlenecks may be occurring or help identify other issues as pipelines are being submitted and processed.

A similar pull request will be submitted for kfp-notebook, although the two changes are independent of each other.

A couple of bugs were fixed regarding the conversion of env_vars to a dictionary that this pull request includes since they were preventing local-mode from completing.

Fixes #939

Here is the output from a KFP pipeline submission and export, as well as a Local pipeline run:

KFP Submission:

[I 17:04:53.619 LabApp] kfp pipeline 'p2-1001170453' - submitting pipeline 
[I 17:04:53.624 LabApp] kfp pipeline 'p2-1001170453' - processing pipeline dependencies to: http://cloning1.fyre.ibm.com:31671 bucket: kbates folder: p2-1001170453 
[I 17:04:53.625 LabApp] kfp pipeline 'p2-1001170453' - operation 'node1' - processing operation dependencies for id: 17cdb879-d6e6-4e8d-b3b6-57ba38ff0d0e 
[I 17:04:53.647 LabApp] kfp pipeline 'p2-1001170453' - operation 'node1' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node1-17cdb879-d6e6-4e8d-b3b6-57ba38ff0d0e.tar.gz (0.021 secs)
[I 17:04:54.164 LabApp] kfp pipeline 'p2-1001170453' - operation 'node1' - uploaded dependency archive to: p2-1001170453/node1-17cdb879-d6e6-4e8d-b3b6-57ba38ff0d0e.tar.gz (0.151 secs)
[I 17:04:54.165 LabApp] kfp pipeline 'p2-1001170453' - operation 'node2' - processing operation dependencies for id: f43dcd72-a149-42dc-81eb-7e809ee505ae 
[I 17:04:54.178 LabApp] kfp pipeline 'p2-1001170453' - operation 'node2' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node2-f43dcd72-a149-42dc-81eb-7e809ee505ae.tar.gz (0.013 secs)
[I 17:04:54.544 LabApp] kfp pipeline 'p2-1001170453' - operation 'node2' - uploaded dependency archive to: p2-1001170453/node2-f43dcd72-a149-42dc-81eb-7e809ee505ae.tar.gz (0.148 secs)
[I 17:04:54.545 LabApp] kfp pipeline 'p2-1001170453' - operation 'node3' - processing operation dependencies for id: d16cc319-8201-4365-9d6c-c8e9a68e552d 
[I 17:04:54.552 LabApp] kfp pipeline 'p2-1001170453' - operation 'node3' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node3-d16cc319-8201-4365-9d6c-c8e9a68e552d.tar.gz (0.007 secs)
[I 17:04:54.926 LabApp] kfp pipeline 'p2-1001170453' - operation 'node3' - uploaded dependency archive to: p2-1001170453/node3-d16cc319-8201-4365-9d6c-c8e9a68e552d.tar.gz (0.155 secs)
[I 17:04:54.926 LabApp] kfp pipeline 'p2-1001170453' - pipeline dependencies processed (1.302 secs)
[I 17:04:55.876 LabApp] kfp pipeline 'p2-1001170453' - pipeline uploaded (0.918 secs)
[I 17:04:56.183 LabApp] kfp pipeline 'p2-1001170453' - pipeline submitted: http://cloning1.fyre.ibm.com:31380/pipeline/#/runs/details/66c8117f-9859-44b9-9700-2027223464e6 (2.567 secs)

KFP Export:

[I 15:21:02.255 LabApp] kfp pipeline 'p2' - exporting pipeline as a .yaml file
[I 15:21:02.259 LabApp] kfp pipeline 'p2' - processing pipeline dependencies to: http://cloning1.fyre.ibm.com:31671 bucket: kbates folder: p2 
[I 15:21:02.260 LabApp] kfp pipeline 'p2' - operation 'node1' - processing operation dependencies for id: 17cdb879-d6e6-4e8d-b3b6-57ba38ff0d0e 
[I 15:21:02.267 LabApp] kfp pipeline 'p2' - operation 'node1' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node1-17cdb879-d6e6-4e8d-b3b6-57ba38ff0d0e.tar.gz (0.008 secs)
[I 15:21:02.816 LabApp] kfp pipeline 'p2' - operation 'node1' - uploaded dependency archive to: p2/node1-17cdb879-d6e6-4e8d-b3b6-57ba38ff0d0e.tar.gz (0.315 secs)
[I 15:21:02.817 LabApp] kfp pipeline 'p2' - operation 'node2' - processing operation dependencies for id: f43dcd72-a149-42dc-81eb-7e809ee505ae 
[I 15:21:02.824 LabApp] kfp pipeline 'p2' - operation 'node2' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node2-f43dcd72-a149-42dc-81eb-7e809ee505ae.tar.gz (0.007 secs)
[I 15:21:03.238 LabApp] kfp pipeline 'p2' - operation 'node2' - uploaded dependency archive to: p2/node2-f43dcd72-a149-42dc-81eb-7e809ee505ae.tar.gz (0.190 secs)
[I 15:21:03.239 LabApp] kfp pipeline 'p2' - operation 'node3' - processing operation dependencies for id: d16cc319-8201-4365-9d6c-c8e9a68e552d 
[I 15:21:03.246 LabApp] kfp pipeline 'p2' - operation 'node3' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node3-d16cc319-8201-4365-9d6c-c8e9a68e552d.tar.gz (0.007 secs)
[I 15:21:03.612 LabApp] kfp pipeline 'p2' - operation 'node3' - uploaded dependency archive to: p2/node3-d16cc319-8201-4365-9d6c-c8e9a68e552d.tar.gz (0.151 secs)
[I 15:21:03.613 LabApp] kfp pipeline 'p2' - pipeline dependencies processed (1.354 secs)
[I 15:21:03.643 LabApp] kfp pipeline 'p2' - pipeline exported: elyra/pipeline1/p2.yaml (1.392 secs)

Local Run:

[I 16:17:06.652 LabApp] local pipeline 'p2' - processing pipeline 
[I 16:17:09.684 LabApp] local pipeline 'p2' - operation 'node1' - completed (3.032 secs)
[I 16:17:12.082 LabApp] local pipeline 'p2' - operation 'node2' - completed (2.398 secs)
[I 16:17:14.469 LabApp] local pipeline 'p2' - operation 'node3' - completed (2.386 secs)
[I 16:17:14.469 LabApp] local pipeline 'p2' - pipeline processed (7.817 secs)

Developer's Certificate of Origin 1.1

   By making a contribution to this project, I certify that:

   (a) The contribution was created in whole or in part by me and I
       have the right to submit it under the Apache License 2.0; or

   (b) The contribution is based upon previous work that, to the best
       of my knowledge, is covered under an appropriate open source
       license and I have the right under that license to submit that
       work with modifications, whether created in whole or in part
       by me, under the same open source license (unless I am
       permitted to submit under a different license), as indicated
       in the file; or

   (c) The contribution was provided directly to me by some other
       person who certified (a), (b) or (c) and I have not modified
       it.

   (d) I understand and agree that this project and the contribution
       are public and that a record of the contribution (including all
       personal information I submit with it, including my sign-off) is
       maintained indefinitely and may be redistributed consistent with
       this project or the open source license(s) involved.

[kevin-bates]

After trimming the preamble, these log entries look as follows:

[I 17:42:53.451 LabApp] kfp 'p1-1005174253' - submitting pipeline 
[I 17:42:53.546 LabApp] kfp 'p1-1005174253' - processing pipeline dependencies to: http://cloning1.fyre.ibm.com:31671 bucket: kbates folder: p1-1005174253 
[I 17:42:53.561 LabApp] kfp 'p1-1005174253':'node1' - processing operation dependencies for id: ca2daea1-6a52-49ba-a8ed-b19cf384215f 
[I 17:42:53.592 LabApp] kfp 'p1-1005174253':'node1' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node1-ca2daea1-6a52-49ba-a8ed-b19cf384215f.tar.gz (0.030 secs)
[I 17:42:54.135 LabApp] kfp 'p1-1005174253':'node1' - uploaded dependency archive to: p1-1005174253/node1-ca2daea1-6a52-49ba-a8ed-b19cf384215f.tar.gz (0.201 secs)
[I 17:42:54.141 LabApp] kfp 'p1-1005174253':'node2' - processing operation dependencies for id: 3a0f9329-da52-4b59-af9f-c773b9cff284 
[I 17:42:54.207 LabApp] kfp 'p1-1005174253':'node2' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node2-3a0f9329-da52-4b59-af9f-c773b9cff284.tar.gz (0.065 secs)
[I 17:42:54.637 LabApp] kfp 'p1-1005174253':'node2' - uploaded dependency archive to: p1-1005174253/node2-3a0f9329-da52-4b59-af9f-c773b9cff284.tar.gz (0.178 secs)
[I 17:42:54.644 LabApp] kfp 'p1-1005174253':'node3' - processing operation dependencies for id: 672c4f9d-b201-44f4-99d7-16b39d2b71fa 
[I 17:42:54.673 LabApp] kfp 'p1-1005174253':'node3' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node3-672c4f9d-b201-44f4-99d7-16b39d2b71fa.tar.gz (0.028 secs)
[I 17:42:56.099 LabApp] kfp 'p1-1005174253':'node3' - uploaded dependency archive to: p1-1005174253/node3-672c4f9d-b201-44f4-99d7-16b39d2b71fa.tar.gz (0.160 secs)
[I 17:42:56.111 LabApp] kfp 'p1-1005174253':'node4' - processing operation dependencies for id: e88a4a72-780b-4e3b-9967-8bb5031b1b33 
[I 17:42:56.146 LabApp] kfp 'p1-1005174253':'node4' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node4-e88a4a72-780b-4e3b-9967-8bb5031b1b33.tar.gz (0.034 secs)
[I 17:42:56.542 LabApp] kfp 'p1-1005174253':'node4' - uploaded dependency archive to: p1-1005174253/node4-e88a4a72-780b-4e3b-9967-8bb5031b1b33.tar.gz (0.159 secs)
[I 17:42:56.549 LabApp] kfp 'p1-1005174253':'node1' - processing operation dependencies for id: 43690b68-6259-4c91-a104-71184ed3a65e 
[I 17:42:56.560 LabApp] kfp 'p1-1005174253':'node1' - generated dependency archive: /var/folders/4w/qxgsbhyx1y93qlk9mnzwjryc0000gn/T/elyra/node1-43690b68-6259-4c91-a104-71184ed3a65e.tar.gz (0.011 secs)
[I 17:42:56.871 LabApp] kfp 'p1-1005174253':'node1' - uploaded dependency archive to: p1-1005174253/node1-43690b68-6259-4c91-a104-71184ed3a65e.tar.gz (0.085 secs)
[I 17:42:56.872 LabApp] kfp 'p1-1005174253' - pipeline dependencies processed (3.325 secs)
[I 17:42:57.944 LabApp] kfp 'p1-1005174253' - pipeline uploaded (0.690 secs)
[I 17:42:58.428 LabApp] kfp 'p1-1005174253' - pipeline submitted: http://cloning1.fyre.ibm.com:31380/pipeline/#/runs/details/f147049b-1aac-4fcf-9da8-7d865617e298 (5.029 secs)

[I 17:42:11.535 LabApp] local 'p1' - processing pipeline 
[I 17:42:14.117 LabApp] local 'p1':'node1' - completed elyra/pipeline1/node1.ipynb (2.580 secs)
[I 17:42:16.282 LabApp] local 'p1':'node2' - completed elyra/pipeline1/node2.ipynb (2.165 secs)
[I 17:42:17.165 LabApp] local 'p1':'node1' - completed elyra/pipeline1/node1.py (0.882 secs)
[I 17:42:19.139 LabApp] local 'p1':'node3' - completed elyra/pipeline1/node3.ipynb (1.973 secs)
[I 17:42:21.102 LabApp] local 'p1':'node4' - completed elyra/pipeline1/node4.ipynb (1.962 secs)
[I 17:42:21.103 LabApp] local 'p1' - pipeline processed (9.566 secs)

[lresende]

LGTM