provide more information in output
- useful for reading log files
Merge request reports
Activity
@akarnad - I'd like to use these changes to debug / understand what is going on in other places. Could you review this?
requested review from @akarnad
Resolved by Hans FangohrI feel the function name
runis quite generic and could be easily misunderstood. can we call it something likerun_cmdorlogg_and_run(cant think of something concise at the moment do you have any suggestion)?- Last reply by Hans Fangohr
83 CompletedProcess(args=['date', '+%Y-%m-%d'], returncode=0) 84 85 >>> run(['date +%Y-%m-%d'], shell=True) 86 ##-04 Starting subprocess.run(['date +%Y-%m-%d']) with options shell=True 87 ##-04 getcwd=/Users/fangohr/git/mpsd-software-environments 88 ##-04 COMMAND=date +%Y-%m-%d 89 2023-05-30 90 ##-04 Completed in 0.0069s. 91 ##-04 92 CompletedProcess(args=['date +%Y-%m-%d'], returncode=0) 93 """ 94 # token is printed in front of every meta-data line - useful for 95 # searching the logs. Starts with "##-00", then "##-01", ... 96 token = f"##-{counter[0]:02d}" 97 98 counter[0] += 1 # increase counter -
Since
counteris not set in any of the calls to this function (for eg incheckout_result = run(["git", "checkout", mpsd_release])) I dont see how this counter is being incremented. I am assuming you are interested in counting the number of timessubprocess.runor its equivalent is called, please correct me if im wrong. I am also not convinced that we need this counter feature, especially as we are not logging this anywhere at the moment but only printing to stdout -
- the counter does increase. Just run the program, perhaps with the tests. Here is part of the output:
tests.py::test_prepare_environment ##-00 Starting subprocess.run(['git', 'clone', 'https://gitlab.gwdg.de/mpsd-cs/spack-environments.git']) with options ##-00 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/dev-23a ##-00 COMMAND=git clone https://gitlab.gwdg.de/mpsd-cs/spack-environments.git Cloning into 'spack-environments'... remote: Enumerating objects: 1682, done. remote: Counting objects: 100% (263/263), done. remote: Compressing objects: 100% (263/263), done. remote: Total 1682 (delta 181), reused 0 (delta 0), pack-reused 1419 Receiving objects: 100% (1682/1682), 205.92 KiB | 546.00 KiB/s, done. Resolving deltas: 100% (945/945), done. ##-00 Completed in 1.5548s. ##-00 ##-01 Starting subprocess.run(['git', 'fetch', '--all']) with options ##-01 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/dev-23a/spack-environments ##-01 COMMAND=git fetch --all ##-01 Completed in 0.3124s. ##-01 ##-02 Starting subprocess.run(['git', 'checkout', 'dev-23a']) with options ##-02 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/dev-23a/spack-environments ##-02 COMMAND=git checkout dev-23a branch 'dev-23a' set up to track 'origin/dev-23a'. Switched to a new branch 'dev-23a' ##-02 Completed in 0.0131s. ##-02 ##-03 Starting subprocess.run(['git', 'pull']) with options ##-03 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/dev-23a/spack-environments ##-03 COMMAND=git pull Already up to date. ##-03 Completed in 0.3535s. ##-03 ##-04 Starting subprocess.run(['git', 'rev-parse', 'HEAD']) with options stdout=-1 ##-04 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/dev-23a/spack-environments ##-04 COMMAND=git rev-parse HEAD ##-04 Completed in 0.0065s. ##-04 ##-05 Starting subprocess.run(['git', 'rev-parse', '--abbrev-ref', 'HEAD']) with options stdout=-1 ##-05 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/dev-23a/spack-environments ##-05 COMMAND=git rev-parse --abbrev-ref HEAD ##-05 Completed in 0.0064s. ##-05 ##-06 Starting subprocess.run(['git', 'rev-parse', '--abbrev-ref', 'HEAD']) with options stdout=-1 ##-06 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env ##-06 COMMAND=git rev-parse --abbrev-ref HEAD fatal: not a git repository (or any of the parent directories): .git ##-06 Completed in 0.0084s. ##-06 ##-07 Starting subprocess.run(['git', 'rev-parse', '--short', 'HEAD']) with options stdout=-1 ##-07 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env ##-07 COMMAND=git rev-parse --short HEAD fatal: not a git repository (or any of the parent directories): .git ##-07 Completed in 0.0061s. ##-07 ##-08 Starting subprocess.run(['git', 'clone', 'https://gitlab.gwdg.de/mpsd-cs/spack-environments.git']) with options ##-08 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/wrong-mpsd-release ##-08 COMMAND=git clone https://gitlab.gwdg.de/mpsd-cs/spack-environments.git Cloning into 'spack-environments'... remote: Enumerating objects: 1682, done. remote: Counting objects: 100% (263/263), done. remote: Compressing objects: 100% (263/263), done. remote: Total 1682 (delta 181), reused 0 (delta 0), pack-reused 1419 Receiving objects: 100% (1682/1682), 205.96 KiB | 661.00 KiB/s, done. Resolving deltas: 100% (945/945), done. ##-08 Completed in 1.1895s. ##-08 ##-09 Starting subprocess.run(['git', 'fetch', '--all']) with options ##-09 getcwd=/private/var/folders/wc/d1lyft3x2jn29b6yffrzh4vw0000gq/T/pytest-of-fangohr/pytest-15/test_prepare_environment0/test_prepare_env/wrong-mpsd-release/spack-environments ##-09 COMMAND=git fetch --all -
Do we need this? I see multiple use cases:
- easy to navigate long output
- having the token prefix helps to connect the execution time and end of the command with the beginning
- for discussions with users (octopus developers for example) we can use this refer exactly to a particular execution
- if you know the number for the command, you can find the associated execution time easily, even if the output in between is long.
I expect we will write this to file / email somehow; certainly the CI does this, and we and users have to do the same should we ever need to debug something.
[Perhaps will switch to using the logging framework instead of printing, or ask users to redirect output to a file (with
tee) if something goes wrong, etc.]
109 elif isinstance(arg, list): 110 command = " ".join(arg) 111 else: 112 # we do not expect this to happen 113 raise NotImplementedError(f"{arg=}, {args=}") 114 115 # make options (such as `shell=True`) nicely readable 116 options = ", ".join([f"{key}={value}" for key, value in kwargs.items()]) 117 118 # provide information about upcoming subprocess.run call 119 print(f"{token} Starting subprocess.run({arg}) with options {options}") 120 print(f"{token} getcwd={os.getcwd()}") 121 print(f"{token} COMMAND={command}") 122 123 time_start = time.time() 124 process = subprocess.run(*args, **kwargs) -
I would leave this to the caller of the
runmethod.There you can say
run(...., check=True)(as we do already in another merge request. But that fails in ways that are hard (for me) to understand, and thus I want this extended output here to better understand. Perhaps there is a good reason not to use it at some point?
-
I guess, we can merge this for now, so that it would allow you to explore other problems, but im still not quite convinced of why we would need this step. I am not sure what problem you are trying to address. Perhaps its a matter of taste, I find the output too verbose ( in an already verbose set of output) perhaps you like the output because of that. Maybe this is better discussed in person tomorrow, but we can merge this for now.
Edited by Ashwin Kumar Karnad -
Thanks.
I am trying to understand what the script does, initially for the tests (without looking at the source and trying to work it out from there; partly to make that process easier). This will happen when other people use the script, and they face the same issue if something doesn't work. I understand that the importance of that is not visible to you: to you it is clear what happens as you have written the code that is executed.
I agree with the verbosity: if everything works, we want less output. Let's address that later; either with a verbose=True mode or through the logging module.
mentioned in commit b5402380