"ceph-salt deploy --non-interactive" does not display progress reliably

[smithfarm]

I use "ceph-salt deploy --non-interactive" a lot and I've noticed that it does not display progress messages reliably. Sometimes a message that definitely was supposed to be issued, is not displayed. Other times, a message gets duplicated.

Here is an example of the latter case:

    admin: [2020-02-26 12:20:30.639116] [admin.mini.com  ] [STAGE] [BEGIN] Ceph tools
    admin: [2020-02-26 12:20:30.639116] [admin.mini.com  ] [STAGE] [BEGIN] Ceph tools
    admin: [2020-02-26 12:22:35.684218] [admin.mini.com  ] [STAGE] [END  ] Ceph tools

The "BEGIN" message is duplicated. I've seen messages getting "triplicated" and "quadruplicated" too...

Other times, messages I would expect to see, are not seen. For example, in one run I see:

    admin: [2020-02-26 10:57:27.763910] [admin.mini.com  ] [STAGE] [BEGIN] Ceph tools
    admin: [2020-02-26 10:57:27.776911] [admin.mini.com  ] [STEP ] [BEGIN] Install cephadm and other packages
    admin: [2020-02-26 10:58:40.017343] [admin.mini.com  ] [STEP ] [END  ] Install cephadm and other packages
    admin: [2020-02-26 10:58:40.034019] [admin.mini.com  ] [STEP ] [BEGIN] Download ceph container image

while in another run I see "Ceph tools" step, but "Install cephadm and other packages" and "Download cpeh container image" messages are not seen at all.

I have not yet discerned any patterns in the occurrence of this phenomenon - it seems random.

[bk201]

Does this happen when manually running ceph-salt deploy --non-interactive or via sesdev? sesdev turn off the stdout buffer size when deploying: stdbuf -o0 ceph-salt -ldebug deploy --non-interactive

Not sure if this helps.

[ricardoasmarques]

Salt does not guarantee that events are delivered by the same order they were fired.

In interactive mode, we update the whole UI when a new Salt event is received, so we will never see duplicates or missing events.

In non-interactive mode, we just print the event when we receive it, so we need to find a clever way of processing events in this mode.

One possible solution is to have some kind of event queue to postpone the print of events that were received out of order.

[sebastian-philipp]

What about just showing the END messages and omit the BEGIN messages?

[smithfarm]

What about just showing the END messages and omit the BEGIN messages?

That wouldn't work well - if a step hangs, we would have to enable logging and refer to the log file to figure out which one it is.

[ricardoasmarques]

If salt events have a "creation timestamp", maybe we can make use of it. I need some further investigation.