Print output in plans are not getting into logs

[DominicOram]

Often for quick debugging at a beamline staff/users will inject temporary print statements into plans. When doing this under plans run by BlueAPI the output are not appearing in the logs, either in graylog or in k8s.

Acceptance Criteria

• Print statement output gets into logs
• There is a system test for this

[Relm-Arrowny]

Can I pick this up, I want this too and I am dived around the log for the other issue anyway.

[DominicOram]

It's not a massive priority for MX so we won't pick it up any time soon. If you have a fix then I'd be happy to review

[Relm-Arrowny]

would #675 be a reasonable solution? Any advice on how to write system test for the log, I never done it before and system test is currently failing on my local run...

[callumforrester]

@Relm-Arrowny A good read for your testing, I actually also think a unit test or integration test is fine here.

https://docs.pytest.org/en/stable/how-to/logging.html#caplog-fixture

I'd need to look at your solution more closely, but will it work for actual print(...) statements or just logging.info(...) statements?

[Relm-Arrowny]

Thanks :)

I'd need to look at your solution more closely, but will it work for actual print(...) statements or just logging.info(...) statements?

It much dumber than that, all it does is redirect the stdout to LOGGER and you can set the level.

[callumforrester]

Do we understand why the originally reported bug is happening? I feel like it's important that we least get our heads around it before deciding on the appropriate solution

[Relm-Arrowny]

Dive a little deeper, I think the worker logger is working as expected, bluesky log is logged correctly, for example you can add this to the plan and it will log:

from bluesky.log import logger
logger.info("This will log")

I have a quick run around the bluesky.run_engine I am 75% sure it does not automatically send stdout to its logger?

So I think the simplest way to get what we want is to use logger.debug rather than print(). Or we can redirect the stdout to the logger but that will have side effect, it will capture everything bluesky send to the stdout.

[callumforrester]

I think the worry here is a scientist, who doesn't know about logger.debug, sticks a print statement in their plan and then can't figure out why it doesn't show up in the logs

[joeshannon]

Out of interest, does the print statement inside a plan output appear in blueapi's stdout? If so I thought you would expect it in Graylog since doesn't k8s log all stdout/stderr there, or is that not accurate?

[Relm-Arrowny]

Out of interest, does the print statement inside a plan output appear in blueapi's stdout? If so I thought you would expect it in Graylog since doesn't k8s log all stdout/stderr there, or is that not accurate?

It does appear in blueapi's stdout, I am not sure about Graylong.

[callumforrester]

Hmm, strange, that means you can't replicate the original bug...

@DominicOram can you reproduce it locally or just on the beamline?