User feedback when calling initialise and run

m8pple commented 3 years ago

When calling run, there is a quite a gap between typing run and receiving output from the device:

POETS>initialise /app = *
POETS> 10:27:55.03:  23(I) initialise /app = *
POETS> 10:27:55.03:  20(I) The microlog for the command 'initialise /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_27_55p0.plog'.
POETS>run /app = *
POETS> 10:27:57.03:  23(I) run /app = *
POETS> 10:27:57.03:  20(I) The microlog for the command 'run /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_27_57p0.plog'.
POETS> 10:28:06.03: 510(I) Log from device di1 (Thread 0x0): Init/dt1!:

This happens in a single-device graph that calls handler_log in OnInit. Code is here: https://github.com/POETSII/Orchestrator/blob/25be74445ef08bb23140c4a02a9078d3317dc801/Tests/ReferenceXML/v4/PEP20/tests/valid/L4-run-time/single-device-print-hello.xml

If I call initialise and then wait a while before doing run, then we get the handler_log message after initialise but before run:

POETS>initialise /app = *
POETS> 10:20:36.02:  23(I) initialise /app = *
POETS> 10:20:36.02:  20(I) The microlog for the command 'initialise /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_20_36p0.plog'.
POETS> 10:20:47.02: 510(I) Log from device di1 (Thread 0x0): Init/dt1!: 
POETS>run /app = *
POETS> 10:22:38.04:  23(I) run /app = *
POETS> 10:22:38.04:  20(I) The microlog for the command 'run /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_22_38p0.plog'.
POETS>

From the users perspective (i.e. the "monkey" who is expected to be sitting at the terminal, watching the output), it is a bit surprising, because the documentation suggestions that deploy is sending the binaries, initialise is setting things up and calling init, and then when you call run it is just shouting "go" at the threads. So from the users point of view it's not clear what the state of the system is, or the progress of the commands.

This might be expected behaviour given the design with a queue, but it is surprising behaviour from the point of view of the user:

Earlier commands explicitly say whether they have completed, e.g.: POETS> 10:27:52.03: 804(I) Graph instance 'gi' composed successfully.
Later commands don't say whether they have finished, e.g. there is no message I can see to tell you whether things like run and initialise have finished. It doesn't seem to come back on the terminal, and there is nothing in the microlog either.
Finishing a step is important, but it would also be useful to know whether it has started, i.e. what is in the invisible queue.

I tried running the command using a batch file, then using the show /batch command, but at the point that it I call show /batch the microlog shows the queue is empty, despite initialisation clearly not being finish yet, and (presumably?) run not having started:

OETS> 10:38:35.02: 803(I) Composing graph instance 'gi'...
POETS> 10:38:35.02: 804(I) Graph instance 'gi' composed successfully.
POETS> 10:38:35.02:  20(I) The microlog for the command 'deploy /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_38_35p0.plog'.
POETS> 10:38:35.02:  20(I) The microlog for the command 'initialise /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_38_35p1.plog'.
POETS> 10:38:35.02:  20(I) The microlog for the command 'run /app = *' will be written to '../Output/Microlog/Microlog_2021_06_23T10_38_35p2.plog'.
POETS>show /batch
POETS> 10:38:37.03:  23(I) show /batch
POETS> 10:38:37.03:  20(I) The microlog for the command 'show /batch' will be written to '../Output/Microlog/Microlog_2021_06_23T10_38_37p0.plog'.
POETS> 10:38:49.03: 510(I) Log from device di1 (Thread 0x0): Init/dt1!: 
POETS>

The microlog for show /batch is:

========================================================================================================================
23/06/2021 10:38:37.03 file ../Output/Microlog/Microlog_2021_06_23T10_38_37p0.plog
command [show /batch]
from console
========================================================================================================================

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

Batch processsing subsystem status at 10:38:37.03 on 23/06/2021

Batch echo OFF
Batch call stack has 0 entries :
+-----+-------------------------------------------------------+
+-----+-------------------------------------------------------+
Batch command queue has 0 entries :
+-------------+-----------------------------------------------+
+-------------+-----------------------------------------------+

------------------------------------------------------------------------------------------------------------------------

Which appears to complete 10 seconds before the handler_log appears. Presumably (?) if OnInit has not yet happened in the device, the initialise has not yet completed, so run has not yet started?

Possibly this is related to #203, but I can't tell if it is the same thing.

I guess the problem can be summarised as:

If a user wants to ensure that initialise has completed before executing run, how do they do that?

heliosfa commented 3 years ago

This is already captured (less eloquently) in #245 and fixed by #253.

The "historic" reason for getting no direct feedback for these commands is that they are staged for later execution (e.g. so that you can issue deploy/init/run in quick succession and things will happen when it is ready) and there was no mechanism to feedback what actually happened.

heliosfa commented 3 years ago

resolved in #253

POETSII / Orchestrator

User feedback when calling initialise and run #259