Multiple simultaneous workflows are hard to tell apart in the logs

[Fryguy]

See example below.

I think we can fix this by ensuring that log lines are prefixed with a GUID or a run identifier or some sorr

---

$ exe/floe examples/workflow.asl examples/workflow.asl --input '{"foo":1}'
I, [2024-06-18T16:16:16.300309 #72612]  INFO -- : checking 2 workflows...
I, [2024-06-18T16:16:16.300409 #72612]  INFO -- : Running state: [Task:FirstState] with input [{"foo"=>1}]...
D, [2024-06-18T16:16:16.302993 #72612] DEBUG -- : Running docker run --detach -e foo\=1 -e _CREDENTIALS\=/run/secrets -v /var/folders/47/l4t878ld45d2h11b45x88sr80000gn/T/20240618-72612-ulwuk9:/run/secrets:z --name floe-hello-world-c197ca50 docker.io/agrare/hello-world:latest
I, [2024-06-18T16:16:19.503519 #72612]  INFO -- : Running state: [Task:FirstState] with input [{"foo"=>1}]...Complete - next state [ChoiceState] output: [{"foo"=>1}]
I, [2024-06-18T16:16:19.573398 #72612]  INFO -- : Running state: [Choice:ChoiceState] with input [{"foo"=>1}]...
I, [2024-06-18T16:16:19.574053 #72612]  INFO -- : Running state: [Choice:ChoiceState] with input [{"foo"=>1}]...Complete - next state [FirstMatchState] output: [{"foo"=>1}]
I, [2024-06-18T16:16:19.574151 #72612]  INFO -- : Running state: [Task:FirstMatchState] with input [{"foo"=>1}]...
D, [2024-06-18T16:16:19.574398 #72612] DEBUG -- : Running docker run --detach -e foo\=1 --name floe-hello-world-26ef3e94 docker.io/agrare/hello-world:latest
I, [2024-06-18T16:16:22.204991 #72612]  INFO -- : Running state: [Task:FirstMatchState] with input [{"foo"=>1}]...Complete - next state [PassState] output: [{"foo"=>1}]
I, [2024-06-18T16:16:22.275456 #72612]  INFO -- : Running state: [Pass:PassState] with input [{"foo"=>1}]...
I, [2024-06-18T16:16:22.275980 #72612]  INFO -- : Running state: [Pass:PassState] with input [{"foo"=>1}]...Complete - next state [WaitState] output: [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]
I, [2024-06-18T16:16:22.276249 #72612]  INFO -- : Running state: [Wait:WaitState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...
I, [2024-06-18T16:16:22.276519 #72612]  INFO -- : Running state: [Task:FirstState] with input [{"foo"=>1}]...
D, [2024-06-18T16:16:22.277897 #72612] DEBUG -- : Running docker run --detach -e foo\=1 -e _CREDENTIALS\=/run/secrets -v /var/folders/47/l4t878ld45d2h11b45x88sr80000gn/T/20240618-72612-zoekht:/run/secrets:z --name floe-hello-world-16ef454b docker.io/agrare/hello-world:latest
I, [2024-06-18T16:16:24.815303 #72612]  INFO -- : Running state: [Task:FirstState] with input [{"foo"=>1}]...Complete - next state [ChoiceState] output: [{"foo"=>1}]
I, [2024-06-18T16:16:24.882831 #72612]  INFO -- : Running state: [Choice:ChoiceState] with input [{"foo"=>1}]...
I, [2024-06-18T16:16:24.883143 #72612]  INFO -- : Running state: [Choice:ChoiceState] with input [{"foo"=>1}]...Complete - next state [FirstMatchState] output: [{"foo"=>1}]
I, [2024-06-18T16:16:24.883193 #72612]  INFO -- : Running state: [Task:FirstMatchState] with input [{"foo"=>1}]...
D, [2024-06-18T16:16:24.883419 #72612] DEBUG -- : Running docker run --detach -e foo\=1 --name floe-hello-world-855e78ba docker.io/agrare/hello-world:latest
I, [2024-06-18T16:16:27.473651 #72612]  INFO -- : Running state: [Task:FirstMatchState] with input [{"foo"=>1}]...Complete - next state [PassState] output: [{"foo"=>1}]
I, [2024-06-18T16:16:27.532827 #72612]  INFO -- : Running state: [Pass:PassState] with input [{"foo"=>1}]...
I, [2024-06-18T16:16:27.533346 #72612]  INFO -- : Running state: [Pass:PassState] with input [{"foo"=>1}]...Complete - next state [WaitState] output: [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]
I, [2024-06-18T16:16:27.533613 #72612]  INFO -- : Running state: [Wait:WaitState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...
I, [2024-06-18T16:16:27.534566 #72612]  INFO -- : Running state: [Wait:WaitState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...Complete - next state [NextState] output: [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]
I, [2024-06-18T16:16:27.534702 #72612]  INFO -- : Running state: [Task:NextState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...
D, [2024-06-18T16:16:27.535376 #72612] DEBUG -- : Running docker run --detach -e foo\=1 -e result\=\{\"foo\"\=\>\"bar\",\ \"bar\"\=\>\"baz\"\} --name floe-hello-world-14091cb0 docker.io/agrare/hello-world:latest
I, [2024-06-18T16:16:29.987189 #72612]  INFO -- : Running state: [Task:NextState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...Complete workflow - output: [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]
I, [2024-06-18T16:16:30.224314 #72612]  INFO -- : Running state: [Wait:WaitState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...Complete - next state [NextState] output: [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]
I, [2024-06-18T16:16:30.224452 #72612]  INFO -- : Running state: [Task:NextState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...
D, [2024-06-18T16:16:30.224674 #72612] DEBUG -- : Running docker run --detach -e foo\=1 -e result\=\{\"foo\"\=\>\"bar\",\ \"bar\"\=\>\"baz\"\} --name floe-hello-world-e69b61f4 docker.io/agrare/hello-world:latest
I, [2024-06-18T16:16:33.476195 #72612]  INFO -- : Running state: [Task:NextState] with input [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]...Complete workflow - output: [{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}]
I, [2024-06-18T16:16:33.565456 #72612]  INFO -- : checking 2 workflows...Complete - 2 ready

workflow
===
{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}

workflow
===
{"foo"=>1, "result"=>{"foo"=>"bar", "bar"=>"baz"}}

[kbrock]

We had this issue with automate.
I don't think developers should need to access a single large logfile all.
It feels like a security issue, especially in the multi-tenant environment.

We currently have a mechanism that displays automae logs per job.
Lets leverage that and collect worker logs for each workflow job.

#223

[Fryguy]

@kbrock Partially agree. On the ManageIQ side, yes, we should absolutely put the logs into a different consumable format. However, for floe, I still think we need a differentiator in the raw logs, such as a guid.

[agrare]

Yeah so an idea I had was to use the context["Execution"]["Id"] which would be unique for each workflow execution to use as a log_header in the per-workflow logger that @kbrock put in that should make it simple to see which workflow execution each log line was from

[kbrock]

I would also like logging in automate so the rest of the system can follow workflow and automate processes

• Separate workflow/context with different loggers #223