geodesymiami / rsmas_insar

RSMAS InSAR code
https://rsmas-insar.readthedocs.io/
GNU General Public License v3.0
62 stars 23 forks source link

Subprocess call in PYSAR scrambles output #99

Closed falkamelung closed 5 years ago

falkamelung commented 5 years ago

A problem in PYSAR is that the output from pysarApp.py gets scrambled, which makes debugging very difficult. Check out the functions below. If you run ./test_print_order.py in interactive mode (used by Yunjun for development) you get an output as desired:

First command
Second command as simple subprocess
Third command
output:
b'Fourth command as subprocess capturing STDOUT and STDERR\n'
Fifth command

But if you run as a job, bsub < test_print_order.job you get the output scrambled:

///login4/nethome/famelung/test_python[1052] cat z_output_1970785
Second command as simple subprocess
First command
Third command
output:
b'Fourth command as subprocess capturing STDOUT and STDERR\n'
Fifth command

That makes debugging very difficult. For now we just need some advice on how to do the subprocess.Popen submission in pysarApp.py. I see 4 options:

  1. Does subprocess has options to pipe output to the correct place?
  2. Shall we have a function that does different subprocess calls depending on whether we are in interactive mode or operations mode?
  3. Convince Yunjun to get away from interactive mode .
  4. Convince Yunjun to use logging in PySAR (how to deal with the progress bar?)

Content: of `/nethome/famelung/test_python/test_print_order.py ' :


#! /usr/bin/env python3

import os
import sys
import subprocess

def main():

    print('First command')

    command = ['ls', 'aa'] 
    command = 'echo Second command as simple subprocess\n' 

    status = subprocess.Popen(command, shell=True).wait()
    if status is not 0:
        raise Exception('ERROR executing second command')

    print('Third command')

    command = ['echo', 'Fourth command as subprocess capturing STDOUT and STDERR'] 
    proc = subprocess.Popen(command,  stderr=subprocess.PIPE, stdout=subprocess.PIPE)

    output, error = proc.communicate()
    if proc.returncode is not 0:
        print('errors:')
        print(error)
        raise Exception('ERROR executing first command')

    print('output:')
    print(output)

    print('Fifth command')

###########################################################################################
if __name__ == '__main__':
    main()

Content: of `/nethome/famelung/test_python/test_print_order.job ' :

#! /bin/tcsh
#BSUB -J test_print_order
#BSUB -n 1
#BSUB -o z_output_%J.o
#BSUB -e z_output_%J.e
#BSUB -R span[hosts=1]
#BSUB -P insarlab
cd /nethome/famelung/test_python
echo "HELLO FALK"
./test_print_order.py 
sleep 10;
gravelcycles commented 5 years ago

Really interesting point. This would actually be a great reason to move away from subprocess.Popen(command).wait(). The main thing to understand here is buffers. Do some searching on your own to understand them and read this article: https://www.quora.com/What-is-output-buffering-in-Python

What is happening is the following (it's a bit low-level):

  1. When print("First command") is executed, it doesn't actually put the characters on the screen automatically, since doing so takes a lot of time. The letters are added to a buffer and then all written at once to the screen when enough characters are added to the buffer or something forces the buffer to be flushed.

  2. Next, the subprocess.Popen(command).wait() finishes and flushes its buffer (writes the words onto the screen) when it terminates (program termination forces the buffer to be flushed). The important thing is that when a subprocess is opened, it uses a different buffer since it's in a different process.

  3. After that, either print("Third command") is executed or something else, but we are back to using the original process.

  4. The last subprocess call doesn't write to the screen, it writes to subprocess.PIPE and then is printed within the original command.

WARNING: DON'T USE THIS IN THE CODEBASE UNLESS ABSOLUTELY NECESSARY. THERE ARE ALMOST ALWAYS WORK AROUNDS: Adding sys.stdout.flush() after print("First command") will force the buffer to be flushed.

Instead, I would suggest to abandoning the subprocess.Popen(command).wait() pattern and move to the subprocess.Popen(command, stderr=subprocess.PIPE, stdout=subprocess.PIPE) pattern. Besides solving this problem, we also capture stderr output that we can now use in error messages, etc.

Note: The best I can do to explain the discrepancy between running it on your machine or on the LSF cluster is that they handle buffers differently. I'm unsure exactly what the setting is that leads to the difference. However, the above solution will work for both environments.

yunjunz commented 5 years ago

If we use subprocess.PIPE in command line or interactive mode, is it possible to print out the message during the call, in order to see the internal progress? The current example Falk showed seems like to print out everything after it's finished.

gravelcycles commented 5 years ago

@yunjunz Check out subprocess.poll()

falkamelung commented 5 years ago

I am glad that the refactor worked, but, unfortunately, the original problem is not solved. The output is still scambled with (most of) the function output showing up where they belong but the function call is detached and at the end, see below process_rsmas_19776774.o . This could be solved by something like a print(cmd) at the beginning of each function? For some reason the only function for which the output and command call is not scambled is save_hdfeos5.py.@Yunjunz, is there anything that we could apply to all other functions?

cat /projects/scratch/insarlab/famelung/unittestGalapagosSenDT128/out_pysar.o
cat /projects/scratch/insarlab/famelung/unittestGalapagosSenDT128/process_rsmas_19776774.o
gravelcycles commented 5 years ago

Those .o files are pretty big. Could you point me to the specific lines that are scrambled and the code they come from?

falkamelung commented 5 years ago

As an example, the following is what is supposed to be together (I think): Function call:

******************** step - correct_troposphere ********************
Atmospheric correction using Weather Re-analysis dataset (PyAPS, Jolivet et al., 2011)
Weather Re-analysis dataset: ECMWF
tropo_pyaps.py -f timeseries.h5 --model ECMWF -g /projects/scratch/insarlab/famelung/unittestGalapagosSenDT128/PYSAR/INPUTS/geometryRadar.h5 -w /nethome/dwg11/insarlab/WEATH

******************** step - deramp ********************
No phase ramp removal.

And function output:

weather model: ECMWF
output tropospheric delay file: INPUTS/ECMWF.h5
weather data directory: /nethome/dwg11/insarlab/WEATHER
time of cloest available product: 12:00 UTC
read date list from timeseries file: timeseries.h5
reference pixel: [456, 842]
geocoded: False
converting DEM/incAngle for PyAPS to read
writing pyapsDem.hgt
write pyapsDem.hgt.rsc
writing pyapsIncAngle.flt
write pyapsIncAngle.flt.rsc
converting lat for PyAPS to read
writing pyapsLat.flt
write pyapsLat.flt.rsc
converting lon for PyAPS to read
writing pyapsLon.flt
write pyapsLon.flt.rsc

------------------------------------------------------------------------------
downloading weather model data using PyAPS ...
common file size: 29109972 bytes
number of grib files existed    : 7
number of grib files to download: 0
------------------------------------------------------------------------------

Falk Amelung Professor Department of Marine Geosciences Rosenstiel School of Marine and Atmospheric Sciences University of Miami 4600 Rickenbacker Causeway Miami, FL 33149 USA Tel: 305 421 4949 E-mail: famelung@rsmas.miami.edumailto:famelung@rsmas.miami.edu Web: http://insar.rsmas.miami.edu InSAR data: http://insarmaps.miami.edu

On Mar 18, 2019, at 1:21 AM, David W Grossman notifications@github.com<mailto:notifications@github.com> wrote:

Those .o files are pretty big. Could you point me to the specific lines that are scrambled and the code they come from?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fgeodesymiami%2Frsmas_isce%2Fissues%2F99%23issuecomment-473773695&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7C6134feb6e90e47e2aa1108d6ab619dbe%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636884833077525894&sdata=zz%2FSdfTw2EPaaTS3foGE%2BUvPmOFKaUdtkM5iFpNzokU%3D&reserved=0, or mute the threadhttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAKpT3IqXc_q-OnqJdatFJwj1gKHEd_TEks5vXyJpgaJpZM4b2jKU&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7C6134feb6e90e47e2aa1108d6ab619dbe%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636884833077525894&sdata=GO91yM2aQWX%2BaSlY8LKx3MT9yYtMcV5VYTGi6Zwn95I%3D&reserved=0.

yunjunz commented 5 years ago

@falkamelung I don't see anything special codewise for save_hdfeos5.py.

falkamelung commented 5 years ago

Hold on. I think I will take this back. I may have used a wrong version and it may be working as expected??

Falk Amelung Professor Department of Marine Geosciences Rosenstiel School of Marine and Atmospheric Sciences University of Miami 4600 Rickenbacker Causeway Miami, FL 33149 USA Tel: 305 421 4949 E-mail: famelung@rsmas.miami.edumailto:famelung@rsmas.miami.edu Web: http://insar.rsmas.miami.edu InSAR data: http://insarmaps.miami.edu

On Mar 18, 2019, at 2:13 PM, Zhang Yunjun notifications@github.com<mailto:notifications@github.com> wrote:

@falkamelunghttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Ffalkamelung&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7Cd7d1581c94a849288a7a08d6abd5c831%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885332022047762&sdata=zsod%2BfpwoFMGJH%2FGqYTUBbbrxDqdmLNT4OoPMhTgRMk%3D&reserved=0 I don't see anything special codewise for save_hdfeos5.py.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHubhttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fgeodesymiami%2Frsmas_isce%2Fissues%2F99%23issuecomment-474061234&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7Cd7d1581c94a849288a7a08d6abd5c831%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885332022057766&sdata=MeU1rUeQwHLCrCb18fAyQ0G%2B4GPItenT9cI7kgssCa0%3D&reserved=0, or mute the threadhttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAKpT3Cbqbc43_yFGhPaqEfte3AruPfPKks5vX-VOgaJpZM4b2jKU&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7Cd7d1581c94a849288a7a08d6abd5c831%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885332022057766&sdata=ZMIKU1vIyd3VP1sevFdAU%2F5Yh9DqEJzJmNHuhgWnin8%3D&reserved=0.

falkamelung commented 5 years ago

Yes. It works perfectly! This is great process. Thank you!

Falk Amelung Professor Department of Marine Geosciences Rosenstiel School of Marine and Atmospheric Sciences University of Miami 4600 Rickenbacker Causeway Miami, FL 33149 USA Tel: 305 421 4949 E-mail: famelung@rsmas.miami.edumailto:famelung@rsmas.miami.edu Web: http://insar.rsmas.miami.edu InSAR data: http://insarmaps.miami.edu

On Mar 18, 2019, at 5:24 PM, Amelung, Falk C famelung@rsmas.miami.edu<mailto:famelung@rsmas.miami.edu> wrote:

Hold on. I think I will take this back. I may have used a wrong version and it may be working as expected??

Falk Amelung Professor Department of Marine Geosciences Rosenstiel School of Marine and Atmospheric Sciences University of Miami 4600 Rickenbacker Causeway Miami, FL 33149 USA Tel: 305 421 4949 E-mail: famelung@rsmas.miami.edumailto:famelung@rsmas.miami.edu Web: http://insar.rsmas.miami.edu InSAR data: http://insarmaps.miami.eduhttps://nam01.safelinks.protection.outlook.com/?url=http%3A%2F%2Finsarmaps.miami.edu&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7C569c28c496a546cb6a7c08d6abf08d11%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885446974698949&sdata=6OeSmu0w4Gbazr%2B1%2Fla%2F38iRAfEG%2F4F5HgbFxGkscm0%3D&reserved=0

On Mar 18, 2019, at 2:13 PM, Zhang Yunjun notifications@github.com<mailto:notifications@github.com> wrote:

@falkamelunghttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Ffalkamelung&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7C569c28c496a546cb6a7c08d6abf08d11%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885446974698949&sdata=%2F5PlOAcvl%2B6lEM%2BFtY4IH86cHfJP78ni2NMVh6LqyIw%3D&reserved=0 I don't see anything special codewise for save_hdfeos5.py.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHubhttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fgeodesymiami%2Frsmas_isce%2Fissues%2F99%23issuecomment-474061234&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7C569c28c496a546cb6a7c08d6abf08d11%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885446974708958&sdata=zJLYMRIHFmLlNVi0xuYr%2F8mUXp%2BA0GzF9h7fl17TpYc%3D&reserved=0, or mute the threadhttps://nam01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FAKpT3Cbqbc43_yFGhPaqEfte3AruPfPKks5vX-VOgaJpZM4b2jKU&data=02%7C01%7Cfamelung%40rsmas.miami.edu%7C569c28c496a546cb6a7c08d6abf08d11%7C2a144b72f23942d48c0e6f0f17c48e33%7C0%7C0%7C636885446974708958&sdata=mMrpRrE0juyLAiH7o1MwLWVeEE6MWzYuNAROwbtqDVU%3D&reserved=0.

yunjunz commented 5 years ago

That's good to hear, well-done @2gotgrossman. Close this issue if you think it's ready please @falkamelung.

falkamelung commented 5 years ago

It works very nicely. Thank you all!