RedHatSatellite/katello-cvmanager

sequential 4 seems to delay log output

Closed this issue · 1 comments

pcfe commented

the promote action seems to output it's logs delayed when using :sequential: 4 in cvmanager.yaml

steps to reproduce:

  1. use a cvmanager (git pull-ed 2017-09-12)

  2. set :sequential: 4 in cvmanager.yaml

  3. have some (about 18 in this case) CCV to promote defined in cvmanager.yaml

  4. have time ./cvmanager --wait promote --to-lifecycle-environment 30 in a wrapper script (cvauto.sh also calls time ./cvmanager --wait publish and time ./cvmanager --wait update plus some other non-cvmanager commands)

  5. /root/katello-cvmanager/cvauto.sh | tee /root/katello-cvmanager/cvauto_$(date +"%Y-%m-%d_%H-%M-%S").log

  6. try to follow a Satellite task in the webUI by gettng it's ID from the cvmanager output

actual result:

Tasks get scheduled and executed in batches of 4 as intended.
But I can follow Synchronize repository … Tasks in the Satellite webUI way before they show up in the shell. Some may finish before I see them in the cvmanager output
e.g. 2df778d3-e553-4c36-8bc1-befd0a36bac8 ran as follows:

Started at: 2017-09-12 18:56:40 UTC
Ended at: 2017-09-12 19:11:04 UTC

but in the tee I saw it only some time after 19:16 UTC

What I get is long period of silence and when there is output it's about many tasks followed by another long (double digit minutes) period of silence.

expected result:

seeing output like the following around the time the tasks are queued, not many minutes later.

Inspecting ccv-demo-rhel6-qpid
 Promoting latest version to lifecycle-environment 30
waiting 10 for pending tasks: ["b552cc77-173b-4ea9-b4d2-27d882dd42bf"]
waiting 20 for pending tasks: ["b552cc77-173b-4ea9-b4d2-27d882dd42bf"]

addition info:

  • Thanks for adding the sequential option, I find it extremely useful!
  • Other output from the script show up in the tee fluid as expected.
  • To me this delayed output does not matter much, normally the wrapper script runs at night from cron as /root/katello-cvmanager/cvauto.sh > /root/katello-cvmanager/cvauto_$(date +"%Y-%m-%d_%H-%M-%S").log 2>&1 and the logs are looked at in the morning, but I figured you'd want to know.
  • I see the same delayed log chunks on the clean action. Did not notice on other actions (e.g. update) yet, but then again I did not attentively follow the other actions called by the wrapper script.
  • the clean action triggered, amongst others, "5c70e2f1-8443-4a30-8191-9b72443952f4" which ran from 19:23:32 UTC to 19:23:36 UTC yet shell output about the task was only some time after 19:27, with many other clean tasks in the same log burst (that had mostly also already finished).
  • the terminal I ran this in remains perfectly usable, so it's not my connection. ;-) Maybe I'm just using tee wrong.