progress reporting / logging

[falkamelung]

As mintpy uses print() statements to display progress to the screen (STDOUT), this information gets scrambled on clusters. For example under LSF bpeek command does not properly relay where mintpy is in the processing. I see two ways to resolve this.

1. Proper logging using the python logging modules
2. adding sys.stdout.flush() at the end of each print statement.

Obviously, (2) is much easier than (1). I will this unless somebody yells. I unlikely will do the entire code but only those scripts that occasionally give trouble. I could look for a student to do the entire code. Having a student adding proper logging may not be a good idea as this may need too much oversight.

[yunjunz]

@falkamelung I have not seen (2) in other projects, could you give some references?

We should apply proper logging. I would recommend you to find a permanent solution with proper documentation so that other developers could easily follow it.

[falkamelung]

This remains an issue

[yunjunz]

Since this issue still remains, let's keep it open for future reference.

[jlmaurer]

A related/perhaps the same issue is relevant error reporting. I've run into issues where mintpy crashes and it turns out to be simple file naming conventions; e.g. underscores vs dashes in a name. Usually the crash point happens well after the actual issue code, so some sort of verbose log file could be helpful when sorting this out.

[yunjunz]

@jlmaurer Could you post an example so that we could be more aware of the scenario? That would help shape the future logging style.

[pbrotoisworo]

Would it be useful to capture all print commands and then write it to a log file? I do that in my software. Here is the template I use for my own projects. I use 2 functions where 1 function is used to run the CLI and capture output, the 2nd function writes it to a log file.

I am sharing my CLI tool I use which I got from Whitebox Tools with some revisions for logging.

    def _run_command(self, cmd: str, cwd: Union[str, None]) -> int:
        """
        Run command and log to file
        :param cmd: Command to execute
        :param cwd: Current working directory
        :return: Return code 0 is success. 1 is failure
        """

        # Create file to capture output
        if not os.path.exists(self.log_file):
            with open(self.log_file, 'w', newline='') as f:
                f.write('DINSAR LOG FILE\n')
                f.write(f'TIMESTAMP: {self.timestamp}\n')
                f.write('======================================\n')

        proc = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE,
                                stderr=subprocess.STDOUT, bufsize=0, universal_newlines=True,
                                cwd=cwd)
        return_code = 0
        while proc is not None:
            try:
                line = proc.stdout.readline()
            except UnicodeDecodeError:
                sys.stdout.flush()
                continue
            sys.stdout.flush()
            if line != '':
                print_line = line.replace('\n', '')
                print(print_line)
                with open(self.log_file, 'a', newline='') as f:
                    f.write(line)
                # Catch errors using string matching
                if 'Error:' in line:
                    msg = f'WARNING: Possible CLI failure'
                    self._print_to_log(msg)
                    return_code = 1
            else:
                break

        return return_code

    def _print_to_log(self, input_var, print_to_terminal=True) -> None:
        """
        Object print command that will also print to the log file
        :return:
        """
        input_var = str(input_var)
        if print_to_terminal:
            print(input_var)
        path = self.log_file
        file_exists = os.path.exists(path)
        with open(path, 'a', newline='') as f:
            if not file_exists:
                f.write('MINTPY LOG FILE\n')
                f.write(f'TIMESTAMP: {self.timestamp}\n')
                f.write('======================================\n')
            if not input_var.endswith('\n'):
                input_var += '\n'
            f.write(input_var)

Here is a sample log file from my own analyses:

Using the functions as an example, you will have to replace every print() statement with _print_to_log(). E.g., _print_to_log('Hello world').

If you just want to write it to the log file and not print on the terminal then set print_to_terminal=False.