From: "Tomáš Golembiovský" <tgolembi(a)redhat.com&gt; To: devel(a)ovirt.org Sent: Friday, July 1, 2016 4:43:45 PM Subject: [ovirt-devel] execCmd() and storing stdout and stderr in log file

That's why I think having it present in execCmd() ready for everyone's use is the best solution. Unfortunately it seems that the code is a) essential on many places in vdsm and b) not properly covered by tests. Which makes it hard to touch. Also apparently some refactoring is either planned or already underway.

Hi I do work to remove the cpopen usages from execCmd. Using std popen over py3 and subprocess32 over py2 which both implements the same api. The only gap is the output object for async calls that we need to align with the standard implementation and modify our current usages. I don't think that adding more non-standard logics to execCmd is a good idea. we should fit the standard usage in this function or override it separately with specific implementation in commands.py. You may propose such patch On Fri, Jul 1, 2016 at 5:43 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; wrote: > Hi, > > I had a need recently to run a command with execCmd() and store it's > output and error to a log file, while still receiving it in the calling > code. Redirecting the error to output stream to have all in one stream > is also useful feature. > > All this can be done in the calling code: > > a) On the shell level, by modyfing the command. This can be > intentionally dangerous because things like quoting of arguments has to > be considered and also could cause problems when wrappers (sudo, nice, > ...) are used. > > b) By handling the writing to files in a code. This would add > unnecessary code duplication in a long run. (I don't think I'm the only > one who can see a potential in this.) Also for asynchronous process > runs, when storing both stderr & stdout in one file, it requires polling > and some stream magic. It would be better to have this done right and > only once so it can be properly tested. > > That's why I think having it present in execCmd() ready for everyone's > use is the best solution. Unfortunately it seems that the code is a) > essential on many places in vdsm and b) not properly covered by tests. > Which makes it hard to touch. Also apparently some refactoring is either > planned or already underway. > > What is the situation about refactoring that code area? Anyone working > on it? Do we have an estimation of time-frame for it? > > Any suggestions/ideas? > >

> Tomas > > -- > Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > _______________________________________________ > Devel mailing list > Devel(a)ovirt.org > http://lists.ovirt.org/mailman/listinfo/devel -- *Yaniv Bronhaim.*

On Tue, 5 Jul 2016 11:18:58 +0300 Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > On Tue, Jul 5, 2016 at 10:44 AM, Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > > > Hi > > I do work to remove the cpopen usages from execCmd. Using std popen over > > py3 and subprocess32 over py2 which both implements the same api. The only > > gap is the output object for async calls that we need to align with the > > standard implementation and modify our current usages. I don't think that > > adding more non-standard logics to execCmd is a good idea. we should fit > > the standard usage in this function or override it separately with specific > > implementation in commands.py. You may propose such patch Sure, that makes sense. Are there any existing drafts/patches I could look at or help with?

Merging stdout and stderr to one can POpen do for us, I belive. Any

saving stdout and err to log while the process is running is useful only

> [...] > > btw, after examine the area again, isn't watchCmd func is what you > describe? we just need to replace the asyncProc usages there with > something that doesn't use StringIO as we do to support py3 I'm not sure how watchCmd can help with this. Isn't it just a wrapper to get asynchrounous process with a stop condition?

Could you elaborate on why we want to get rid of StringIO in AsyncProc?

If I understand it right, it's purpose is to make sure the executed program doesn't stall on full pipe if VDSM isn't fast enough in processing the output. Or am I missing something? But it could again be implemented as a wrapper around execCmd and not in it. Is that what you mean? -- Tomáš Golembiovský <tgolembi(a)redhat.com&gt; _______________________________________________ Devel mailing list Devel(a)ovirt.org http://lists.ovirt.org/mailman/listinfo/devel

On Wed, 6 Jul 2016 18:37:54 +0300 Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > On Wed, Jul 6, 2016 at 5:07 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > wrote: > > > > > Merging stdout and stderr to one can POpen do for us, I belive. Any > > logging can indeed be done as a wrapper around execCmd. > > saving stdout and err to log while the process is running is useful only > for your purpose currently. using asyncproc as you do now in v2v allows you > to to run a process and monitor it.. can you use overriding of aysncProc > wrapper for your needs instead of changing cpopen or execcmd code? I am not talking about CPOpen. I meant that when calling `subprocess.Popen`, you can pass it `stderr=subprocess.STDOUT` argument and it will handle the FD redirection (stream merging). To me it seems like a proper way of doing this.

> > > [...] > > > > > > btw, after examine the area again, isn't watchCmd func is what you > > > describe? we just need to replace the asyncProc usages there with > > > something that doesn't use StringIO as we do to support py3 > > > > I'm not sure how watchCmd can help with this. Isn't it just a wrapper to > > get asynchrounous process with a stop condition? > > > > it is. thought you need something similar and afterwards log the outputs I can run async process with `execCmd` directly and I don't need any stop condition. Am I missing something that `watchCmd` provides? probably I didn't get you right at first. forget about watchcmd. I thought

-- Tomáš Golembiovský <tgolembi(a)redhat.com&gt; _______________________________________________ Devel mailing list Devel(a)ovirt.org http://lists.ovirt.org/mailman/listinfo/devel

> useful you can add those parameters to execCmd Good news about cpopen! Is it a good idea to add even more parameters to execCmd? Let's discuss this. another approach I could think of is https://gerrit.ovirt.org/#/c/60660/ I'm not that proud of 60660 either, this is why it is a draft :\ So I've been in touch with Tomas, and he kindly tried to rebase his code on top of my 60660, but looks like he was biten by issues fixed in https://gerrit.ovirt.org/#/c/59181/ https://gerrit.ovirt.org/#/c/59095/

I think leveraging cpopen is a good way, it is simple enough and it doesn't hurt our plans to eventually move to subprocess.

On Mon, Jul 11, 2016 at 12:53 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; wrote: > On Wed, 6 Jul 2016 18:37:54 +0300 > Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > >> On Wed, Jul 6, 2016 at 5:07 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; >> wrote: >> >> > >> > Merging stdout and stderr to one can POpen do for us, I belive. Any >> > logging can indeed be done as a wrapper around execCmd. >> >> saving stdout and err to log while the process is running is useful only >> for your purpose currently. using asyncproc as you do now in v2v allows you >> to to run a process and monitor it.. can you use overriding of aysncProc >> wrapper for your needs instead of changing cpopen or execcmd code? > > I am not talking about CPOpen. I meant that when calling > `subprocess.Popen`, you can pass it `stderr=subprocess.STDOUT` argument > and it will handle the FD redirection (stream merging). To me it seems > like a proper way of doing this. This should work with execCmd, since the special subprocess.STDOUT parameter is handled in subprocess.Popen, and cpopen.CPopen inherit this code. However this is not tested with cpopen, so it may be broken. But merging stdout and stderr is likely to break v2v output parser, and vdsm log is not the place for virt-v2v debug logs.

I understand that the issue is keeping virt-v2v debug logs (using --verbose?), and the logs are spread in stdout and stderr. Did you discuss this issue with Richard?

I would use tee to write stdout and stderr to an import log file, without changing the code checking import progress.

Maybe virt-v2v can add a --logfile option appending to given log file? Richard, what do you think? > > >> > > [...] >> > > >> > > btw, after examine the area again, isn't watchCmd func is what you >> > > describe? we just need to replace the asyncProc usages there with >> > > something that doesn't use StringIO as we do to support py3 >> > >> > I'm not sure how watchCmd can help with this. Isn't it just a wrapper to >> > get asynchrounous process with a stop condition? >> > >> >> it is. thought you need something similar and afterwards log the outputs > > I can run async process with `execCmd` directly and I don't need any > stop condition. Am I missing something that `watchCmd` provides? > > -- > Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > _______________________________________________ > Devel mailing list > Devel(a)ovirt.org > http://lists.ovirt.org/mailman/listinfo/devel

On Thu, 14 Jul 2016 15:07:29 +0300 Nir Soffer <nsoffer(a)redhat.com&gt; wrote: > On Mon, Jul 11, 2016 at 12:53 PM, Tomáš Golembiovský > <tgolembi(a)redhat.com&gt; wrote: > > On Wed, 6 Jul 2016 18:37:54 +0300 > > Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > > > >> On Wed, Jul 6, 2016 at 5:07 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > >> wrote: > >> > >> > > >> > Merging stdout and stderr to one can POpen do for us, I belive. Any > >> > logging can indeed be done as a wrapper around execCmd. > >> > >> saving stdout and err to log while the process is running is useful only > >> for your purpose currently. using asyncproc as you do now in v2v allows you > >> to to run a process and monitor it.. can you use overriding of aysncProc > >> wrapper for your needs instead of changing cpopen or execcmd code? > > > > I am not talking about CPOpen. I meant that when calling > > `subprocess.Popen`, you can pass it `stderr=subprocess.STDOUT` argument > > and it will handle the FD redirection (stream merging). To me it seems > > like a proper way of doing this. > > This should work with execCmd, since the special subprocess.STDOUT > parameter is handled in subprocess.Popen, and cpopen.CPopen inherit > this code. However this is not tested with cpopen, so it may be broken. > > But merging stdout and stderr is likely to break v2v output parser, and vdsm > log is not the place for virt-v2v debug logs. This is something that we can deal with. > > I understand that the issue is keeping virt-v2v debug logs (using --verbose?), > and the logs are spread in stdout and stderr. Did you discuss this issue > with Richard? Not yet. > > I would use tee to write stdout and stderr to an import log file, without > changing the code checking import progress. This is something I have tried as first, as you can see here: https://gerrit.ovirt.org/#/c/59834/4/lib/vdsm/v2v.py@404 The problem with this approach is that we don't get proper exit code from virt-v2v because of the pipe. Fixing this in POSIX shell is not trivial and would lead to more complex shell code here. (Would be fairly easy to fix if we could resort to using bash here.)

On Thu, 14 Jul 2016 17:25:28 +0300 Nir Soffer <nsoffer(a)redhat.com&gt; wrote: > After https://gerrit.ovirt.org/#/c/46733/ you should be able to create > the pipeline in python like this: > > v2v = Popen(["virt-v2v", ...], stdout=PIPE, stderr=STDOUT) > tee = Popen(["tee", "-a", logfile], stdin=v2v.stdout, stdout=PIPE, > stderr=PIPE) > > Now we can read output from tee.stdout, and when tee is finished, we can wait > for v2v to get the exit code. > > Since all output would go to tee stdout and stderr may only contain tee usage > errors, we don't need to use AsyncProc, making this code python 3 compatible. Yes, this may actualy work. And do we plan to adopt the cpopen 1.4.1, where this is fixed, in VDSM?

-- Tomáš Golembiovský <tgolembi(a)redhat.com&gt; _______________________________________________ Devel mailing list Devel(a)ovirt.org http://lists.ovirt.org/mailman/listinfo/devel

From: "Nir Soffer" <nsoffer(a)redhat.com&gt; To: "Yaniv Bronheim" <ybronhei(a)redhat.com&gt; Cc: "Shahar Havivi" <shaharh(a)redhat.com&gt;, "Richard Jones" <rjones(a)redhat.com&gt;, "devel" <devel(a)ovirt.org&gt; Sent: Tuesday, July 19, 2016 4:18:31 PM Subject: Re: [ovirt-devel] execCmd() and storing stdout and stderr in log file On Tue, Jul 19, 2016 at 5:07 PM, Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > > On Tue, Jul 19, 2016 at 4:56 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > wrote: >> >> On Thu, 14 Jul 2016 17:25:28 +0300 >> Nir Soffer <nsoffer(a)redhat.com&gt; wrote: >> >> > After https://gerrit.ovirt.org/#/c/46733/ you should be able to create >> > the pipeline in python like this: >> > >> > v2v = Popen(["virt-v2v", ...], stdout=PIPE, stderr=STDOUT) >> > tee = Popen(["tee", "-a", logfile], stdin=v2v.stdout, stdout=PIPE, >> > stderr=PIPE) >> > >> > Now we can read output from tee.stdout, and when tee is finished, we can >> > wait >> > for v2v to get the exit code. >> > >> > Since all output would go to tee stdout and stderr may only contain tee >> > usage >> > errors, we don't need to use AsyncProc, making this code python 3 >> > compatible. >> >> >> Yes, this may actualy work. And do we plan to adopt the cpopen 1.4.1, >> where >> this is fixed, in VDSM? > > > cpopen 1.5.1 - and yes but not in ovirt-4.0 It is included in 1.4.1, released ages ago. $ git log --oneline --decorate 826b5ef (HEAD -> master, origin/master, origin/HEAD) Raise version for 1.5 build a9d2a72 (inherit-fds) Add tests for disabling the close-on-exec flag 7163e79 Do not close inherited fds from parent 1b170fb (gerrit/master) Raising release number and tagging cpopen 1.4.1 69ae841 Sort imports to make it easier to add new imports 1116830 Simplify tests using CPopen.communicate() 58e1b43 Remove unneeded and wrong retry after fork fbf9ff3 Remove wrong and unneeded retry for execv 74ee4a0 Do not retry close() after interrupt 1abde2b Use _exit to terminate child after failure 8709c42 Fix incorrect fd closing $ git show 1b170fb --format=fuller commit 1b170fb8f2d204457ca66e53936fd3a059f4ed4b Author: Yaniv Bronhaim <ybronhei(a)redhat.com&gt; AuthorDate: Wed Oct 14 15:40:07 2015 +0300 Commit: Yaniv Bronhaim <ybronhei(a)redhat.com&gt; CommitDate: Wed Oct 14 09:36:31 2015 -0400 Raising release number and tagging cpopen 1.4.1 Recent patches include only bug fixes. see commit messages Change-Id: Ia1d32dd5bd7f60681b64251cef217c8d1e41b14b Signed-off-by: Yaniv Bronhaim <ybronhei(a)redhat.com&gt;

On Thu, 21 Jul 2016 03:26:44 -0400 (EDT) Francesco Romani <fromani(a)redhat.com&gt; wrote: > ----- Original Message ----- > > From: "Nir Soffer" <nsoffer(a)redhat.com&gt; > > To: "Yaniv Bronheim" <ybronhei(a)redhat.com&gt; > > Cc: "Shahar Havivi" <shaharh(a)redhat.com&gt;, "Richard Jones" <rjones(a)redhat.com&gt;, "devel" <devel(a)ovirt.org&gt; > > Sent: Tuesday, July 19, 2016 4:18:31 PM > > Subject: Re: [ovirt-devel] execCmd() and storing stdout and stderr in log file > > > > On Tue, Jul 19, 2016 at 5:07 PM, Yaniv Bronheim <ybronhei(a)redhat.com&gt; wrote: > > > > > > On Tue, Jul 19, 2016 at 4:56 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > > > wrote: > > >> > > >> On Thu, 14 Jul 2016 17:25:28 +0300 > > >> Nir Soffer <nsoffer(a)redhat.com&gt; wrote: > > >> > > >> > After https://gerrit.ovirt.org/#/c/46733/ you should be able to create > > >> > the pipeline in python like this: > > >> > > > >> > v2v = Popen(["virt-v2v", ...], stdout=PIPE, stderr=STDOUT) > > >> > tee = Popen(["tee", "-a", logfile], stdin=v2v.stdout, stdout=PIPE, > > >> > stderr=PIPE) > > >> > > > >> > Now we can read output from tee.stdout, and when tee is finished, we can > > >> > wait > > >> > for v2v to get the exit code. > > >> > > > >> > Since all output would go to tee stdout and stderr may only contain tee > > >> > usage > > >> > errors, we don't need to use AsyncProc, making this code python 3 > > >> > compatible. > > >> > > >> > > >> Yes, this may actualy work. And do we plan to adopt the cpopen 1.4.1, > > >> where > > >> this is fixed, in VDSM? > > > > > > > > > cpopen 1.5.1 - and yes but not in ovirt-4.0 > > > > It is included in 1.4.1, released ages ago. > > > > $ git log --oneline --decorate > > 826b5ef (HEAD -> master, origin/master, origin/HEAD) Raise version for 1.5 > > build > > a9d2a72 (inherit-fds) Add tests for disabling the close-on-exec flag > > 7163e79 Do not close inherited fds from parent > > 1b170fb (gerrit/master) Raising release number and tagging cpopen 1.4.1 > > 69ae841 Sort imports to make it easier to add new imports > > 1116830 Simplify tests using CPopen.communicate() > > 58e1b43 Remove unneeded and wrong retry after fork > > fbf9ff3 Remove wrong and unneeded retry for execv > > 74ee4a0 Do not retry close() after interrupt > > 1abde2b Use _exit to terminate child after failure > > 8709c42 Fix incorrect fd closing > > > > $ git show 1b170fb --format=fuller > > commit 1b170fb8f2d204457ca66e53936fd3a059f4ed4b > > Author: Yaniv Bronhaim <ybronhei(a)redhat.com&gt; > > AuthorDate: Wed Oct 14 15:40:07 2015 +0300 > > Commit: Yaniv Bronhaim <ybronhei(a)redhat.com&gt; > > CommitDate: Wed Oct 14 09:36:31 2015 -0400 > > > > Raising release number and tagging cpopen 1.4.1 > > > > Recent patches include only bug fixes. see commit messages > > > > Change-Id: Ia1d32dd5bd7f60681b64251cef217c8d1e41b14b > > Signed-off-by: Yaniv Bronhaim <ybronhei(a)redhat.com&gt; > > Thanks to everyone for comments and insights. > > I think is time to wrap up so Tomas can finish his work. > > So, the options on the table are: > 1. Build pipelines in python (Nir's approach above) > - looks like the the fix is in cpopen 1.4.1, available X. One more option that occured to me is: use Nir's approach but use subprocess.Popen directly.

- since Yaniv said updated cpopen won't be available for 4.0

- and since we're aiming for subprocess.Popen in a log run anyway (if my understanding is correct)

- and since the package for python-subprocess32 is available in our 4.0 dependencies repo already

> 2. add options to execCmd to redirect stderr > - make execCmd even bigger, makes everyone grumpy > - could require a couple of simple fixes (talked with > Tomas privately, nothing groundbreaking - like one between stdout > and stderr could be None and we must cope with that)

> 3. DUP execCmd just for v2v and just to avoid making it more complex > - see https://gerrit.ovirt.org/#/c/60660/ > - even worse than extending execCmd? > - still needs the fixes above

> 4. use shell tricks and reuse existing execCmd > - reviewers/future selves needs to wrap their head on that shell magic > - PERHAPS fragile? I don't really know

> 5. something else I forgot? > > > I think the approaches here are ordered by likeness and feasibility, > so I'd actually try in this order (1->2->3->4) > > Please ACK/NACK the above, so Tomas can conclude this patch > for next monday (20160725)

----- Original Message ----- > From: "Nir Soffer" <nsoffer(a)redhat.com&gt; > To: "Tomáš Golembiovský" <tgolembi(a)redhat.com&gt; > Cc: "Francesco Romani" <fromani(a)redhat.com&gt;, "devel" <devel(a)ovirt.org&gt;, "Yaniv Bronheim" <ybronhei(a)redhat.com&gt;, > "Shahar Havivi" <shaharh(a)redhat.com&gt; > Sent: Thursday, July 21, 2016 2:17:19 PM > Subject: Re: [ovirt-devel] execCmd() and storing stdout and stderr in log file > > On Thu, Jul 21, 2016 at 1:51 PM, Tomáš Golembiovský <tgolembi(a)redhat.com&gt; > wrote: > > On Thu, 21 Jul 2016 03:26:44 -0400 (EDT) > > Francesco Romani <fromani(a)redhat.com&gt; wrote: [...] > >> I think is time to wrap up so Tomas can finish his work. > >> > >> So, the options on the table are: > >> 1. Build pipelines in python (Nir's approach above) > >> - looks like the the fix is in cpopen 1.4.1, available > > > > X. One more option that occured to me is: use Nir's approach but use > > subprocess.Popen directly. > > Until we integrate with subprocess32, you should use compat.CPopen. > > When subprocess32 is ready, the correct way would be compat.Popen, > hiding the subprocess32 import on Python 2.7. > > > - since Yaniv said updated cpopen won't be available for 4.0 > > We don't need the update for 4.0, cpopen 1.4.1, available in 4.0 should be > good enough.

> > > - and since we're aiming for subprocess.Popen in a log run anyway (if > > my > > understanding is correct) > > Correct, but we did not integrated with it yet > > > - and since the package for python-subprocess32 is available in our > > 4.0 > > dependencies repo already > > Really? > > I think subprocess32 is not available yet on rhel, so we cannot use it yet. Tomas, could you please check about the availability in RHEL? So, turns out we have only one option (and half? :)) which is good, it simplifies the things.

> >> 2. add options to execCmd to redirect stderr > >> - make execCmd even bigger, makes everyone grumpy > >> - could require a couple of simple fixes (talked with > >> Tomas privately, nothing groundbreaking - like one between stdout > >> and stderr could be None and we must cope with that) > > This is not an option, execCmd is too big and ugly today, we are not going > to add more features to it. > > This helper is the way to use for the common case of running a process, > collecting the data from both stdout and stderr, and returning the results. > > Code that have special needs should not use execCmd.

> > See qemuimg.QemuImgOperation, and storage.check.DirectioChecker for > examles. > > You should use the helpers in cmdutils for consistent logging when starting > and finishing a process. Fine, and thanks for the examples. > > >> 3. DUP execCmd just for v2v and just to avoid making it more complex > >> - see https://gerrit.ovirt.org/#/c/60660/ > >> - even worse than extending execCmd? > >> - still needs the fixes above > > No, one is enough Indeed it is, going to abandon 60660 and bury it very deep as soon as we reach consensus. > > >> 4. use shell tricks and reuse existing execCmd > >> - reviewers/future selves needs to wrap their head on that shell magic > >> - PERHAPS fragile? I don't really know > > I would not use the shell if I don't have to. ok, let's keep this as very last resort. > There are other issues - where do you save the import log > (per-import log file?, v2v.log?) and how the logs are deleted. Indeed they are, but I'm less worried about those since are been already solved in the past and we already have tools to deal with them

> Maybe keep per-import log files, in /var/log/vdsm/v2v, and use logrotate > configuration to rotate them? I think we though about this (me and Tomas) in the past, and that was the plan; Anyway I agree with this, let's make this our plan if it wasn't already :)

This should work with execCmd, since the special subprocess.STDOUT parameter is handled in subprocess.Popen, and cpopen.CPopen inherit this code. However this is not tested with cpopen, so it may be broken. But merging stdout and stderr is likely to break v2v output parser, and vdsm log is not the place for virt-v2v debug logs. I understand that the issue is keeping virt-v2v debug logs (using --verbose?), and the logs are spread in stdout and stderr. Did you discuss this issue with Richard?

I would use tee to write stdout and stderr to an import log file, without changing the code checking import progress. Maybe virt-v2v can add a --logfile option appending to given log file?