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.

https://github.com/ManageIQ/floe/pull/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

• [ ] https://github.com/ManageIQ/floe/pull/223

[miq-bot]

This issue has been automatically marked as stale because it has not been updated for at least 3 months.

If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.