avocado-framework / aexpect

Python library used to control interactive programs
GNU General Public License v2.0
8 stars 32 forks source link

Provide the session prefix when logging sent commands #107

Closed pevogam closed 2 years ago

pevogam commented 2 years ago

In cases where one works with multiple (and many) remote hosts and sessions at the same time it is really useful to be able to see what remote host the command executed on.

Signed-off-by: Plamen Dimitrov plamen.dimitrov@intra2net.com

pevogam commented 2 years ago

Hello Plamen, I do find this feature useful, but I don't think pure ShellSession should log those, especially it should not depend on the output_prefix variable which is already used for a different purpose.

I wasn't aware of the other purpose and thought this is it. Do you mind elaborating with details?

I'm trying to think how to solve it in the RemoteSession only, but I don't really see any sensible solution, but if you see one, please let me know.

Another suitable solution could be to add a generic API into ShellSession to support such prefixes and set it to on {host} for RemoteSession. Note this API should cover cmd_output as well as cmd_output_safe. Anyway I'd really love to see something outside the ShellSession so if you have an idea on how to elegantly implement that...

Maybe we can refactor the logic of ShellSession to make this optional but I guess I have to understand the original use of the output_prefix you are referring to first.

ldoktor commented 2 years ago

The output_prefix together with output_func can be used to allow to add hooks to consume session outputs. I vaguely remember it was used in virttest to distinguish between different guests/sessions, in tp-qemu I found load_session.set_output_prefix("(guest load %d) " % i) and in runperf I am using it to log the outputs into my debugging streams with a certain prefix.

In most cases I think it should not break anything, but as the output_prefix can mean anything and can contain whatever characters (still it will always be a string) the message Sending command on ... might be misleading.

It's a tough call, I'm not sure many people are using this feature. I'm tempted to allow something like:

if self.output_prefix:
    LOG.debug("Sending command (%s): %s", self.output_prefix, cmd)
else:
    LOG.debug("Sending command: %s", cmd)

rather than adding yet another argument, on the other hand it might look ugly in some cases like in the tp-qemu:

Sending command ((guest load 1): true

So if you see another clean solution, that would be appreciated. Otherwise we'd have to invite tp-qemu and perhaps others to ensure we will not brake their workflows.

pevogam commented 2 years ago

In most cases I think it should not break anything, but as the output_prefix can mean anything and can contain whatever characters (still it will always be a string) the message Sending command on ... might be misleading.

Indeed, now I understand what you mean and it makes a lot of sense.

It's a tough call, I'm not sure many people are using this feature. I'm tempted to allow something like:

if self.output_prefix:
    LOG.debug("Sending command (%s): %s", self.output_prefix, cmd)
else:
    LOG.debug("Sending command: %s", cmd)

rather than adding yet another argument,

This is what I would have suggested next, so I still get the meaning of the argument more or less right.

on the other hand it might look ugly in some cases like in the tp-qemu:

Sending command ((guest load 1): true

So if you see another clean solution, that would be appreciated. Otherwise we'd have to invite tp-qemu and perhaps others to ensure we will not brake their workflows.

How about indicating it as a "tag" via something like:

Sending command [guest load 1]: true

or better yet

[guest load 1]: Sending command: true

with the tag in square brackets potentially not being displayed if the value is empty (no-tag handling)?

The generic use case of seeing where a command is run (optionally, all via tagging) remains valid and very similar to the original purpose of conceiving the prefix argument above. I initially applied it in the same way like you but then realized there are plenty more cases where I cannot see which session the logs are talking about. How about adding this tag when nonempty string to all valid logging messages? Do you think there are more locations than cmd_output and cmd_output_safe that would help consider the session tag in as widely applicable and generic sense as possible?

ldoktor commented 2 years ago

How about indicating it as a "tag" via something like:

Sending command [guest load 1]: true

or better yet

[guest load 1]: Sending command: true

with the tag in square brackets potentially not being displayed if the value is empty (no-tag handling)?

Either way is fine by me

The generic use case of seeing where a command is run (optionally, all via tagging) remains valid and very similar to the original purpose of conceiving the prefix argument above. I initially applied it in the same way like you but then realized there are plenty more cases where I cannot see which session the logs are talking about. How about adding this tag when nonempty string to all valid logging messages? Do you think there are more locations than cmd_output and cmd_output_safe that would help consider the session tag in as widely applicable and generic sense as possible?

In the core aexpect I only see the cmd_output and cmd_output_safe logging usage, but sure, feel free to add it everywhere it makes sense (and is associable) in the remote* and ops.

pevogam commented 2 years ago

The generic use case of seeing where a command is run (optionally, all via tagging) remains valid and very similar to the original purpose of conceiving the prefix argument above. I initially applied it in the same way like you but then realized there are plenty more cases where I cannot see which session the logs are talking about. How about adding this tag when nonempty string to all valid logging messages? Do you think there are more locations than cmd_output and cmd_output_safe that would help consider the session tag in as widely applicable and generic sense as possible?

In the core aexpect I only see the cmd_output and cmd_output_safe logging usage, but sure, feel free to add it everywhere it makes sense (and is associable) in the remote* and ops.

Alright, if there are no obvious points where we are missing out I will simply push version with these two updates and keep the commit messages as is, i.e. "Provide the session prefix when logging sent commands" and not any other locations. We will see after some future use if there are obvious other places that would directly benefit from the tag as right now most session use would need executing commands of some sorts.

ldoktor commented 2 years ago

@avocado-framework/vt-maintainers this change might slightly change the log output in case you use output_prefix in your sessions (I had seen some usage in tp-qemu). For humans it should not make a big deal but in case you post-process the output automatically, please ensure it keeps working well and let us know should it break something for you. The difference is:

DEBUG:aexpect.client:[WHATEVER IS IN YOUR OUTPUT_PREFIX] Sending command: asdf

vs.

DEBUG:aexpect.client:Sending command: asdf

There is no change in case output_prefix is not set.