Search code examples
pythonloggingsubprocesstraceback

Getting concise error message with python subprocess logging and traceback


I am writing an automatic program which I wish to run through errors and gather information. With my current setup I get the following example logging for one loop instance:

2024-03-21 10:14:44,843 - ERROR - error processing shot '20221201.033':
Traceback (most recent call last):
 File "/home/Desktop/Code/git/populate_database.py", line 76, in <module>
    raise Exception(f"n{stderr.decode()}")
Exception: n
 Fetching parlog information for shot 20221201.033 from archive: 0%|    | 0/5 [00:00<?, ?it/s]
 Fetching parlog information for shot 20221201.033 from archive: 0%|    | 0/5 [00:00<?, ?it/s]

     Mapping rates : 0%|    | 0/10 [00:00<?, ?it/s]
     Mapping rates : 100%|██████████| 10/10 [00:00<00:00, 3360.28it/s]

     Calculating impurity densities : 0%|   | 0/10 [00:00<?, ?it/s]
     Calculating impurity densities : 80%|████████ | 8/10 [00:00<00:00, 73.92it/s]
     Calculating impurity densities : 100%|██████████| 10/10 [00:00<00:00, 73.91it/s]

     Updating profile: 0%|      | 0/10 [00:00<?, ?it/s]
     Updating profile: 20%|██   | 2/10 [00:00<00:00, 8.86it/s]
     Updating profile: 100%|██████████| 10/10 [00:00<00:00, 34.81it/s]
     Updating profile: 100%|██████████| 10/10 [00:00<00:00, 29.59it/s]

         Assessing convergence: 0%|     | 0/10 [00:00<?, ?it/s]
         Assessing convergence: 100%|██████████| 10/10 [00:00<00:00, 84054.19it/s]
Traceback (most recent call last):
 File "/home/Desktop/Code/git/Examples/Program_runfiles/20221201.033.py", line 37, in <module>
    data.run(
 File "/home/Desktop/Code/git/eval.py", line 348, in run
    self.run_post_methods()
 File "/home/Desktop/Code/git/eval.py", line 469, in run_post_methods
    _store_grad_length(
 File "/home/Desktop/Code/git/utilities/write_locally.py", line 103, in _store_grad_length
    dictionary_added["tau_e"] = _get_energy_confinement_time(
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 File "/home/Desktop/Code/git/utilities/fetch_data.py", line 293, in _get_energy_confinement_time
    w_dia_spline = UnivariateSpline(t_w_dia, w_dia, k=4, s=0)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 File "/home/anaconda3/lib/python3.11/site-packages/scipy/interpolate/_fitpack2.py", line 236, in __init__
    data = dfitpack.fpcurf0(x, y, k, w=w, xb=bbox[0],
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
dfitpack.error: (m>k) failed for hidden m: fpcurf0:m=0

Within the full console log above, I am only interested in logging the following part containing the error:

Traceback (most recent call last):
 File "/home/Desktop/Code/git/Examples/Program_runfiles/20221201.033.py", line 37, in <module>
    data.run(
 File "/home/Desktop/Code/git/eval.py", line 348, in run
    self.run_post_methods()
 File "/home/Desktop/Code/git/eval.py", line 469, in run_post_methods
    _store_grad_length(
 File "/home/Desktop/Code/git/utilities/write_locally.py", line 103, in _store_grad_length
    dictionary_added["tau_e"] = _get_energy_confinement_time(
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 File "/home/Desktop/Code/git/utilities/fetch_data.py", line 293, in _get_energy_confinement_time
    w_dia_spline = UnivariateSpline(t_w_dia, w_dia, k=4, s=0)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
 File "/home/anaconda3/lib/python3.11/site-packages/scipy/interpolate/_fitpack2.py", line 236, in __init__
    data = dfitpack.fpcurf0(x, y, k, w=w, xb=bbox[0],
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
dfitpack.error: (m>k) failed for hidden m: fpcurf0:m=0

My current code consists of the following try except method:

from subprocess import Popen, PIPE, STDOUT, DEVNULL

logging.basicConfig(filename='error.log', level=logging.ERROR, format='%(asctime)s - %(levelname)s - %(message)s')

 try:
    # run the file for the shot with error handling
    process = Popen(["python", dest_file], stdout=DEVNULL, stderr=PIPE)

    # wait while file is running
    process.wait()
     
    # get the console error of the subprocess
    stderr = process.communicate()[1]

    # close all figures and clear console
    plt.close()
    os.system('clear')
     
    # if we encountered an error raise it
    if stderr:
    raise Exception(f"n{stderr.decode()}")
 
    # except the raised error and log the error
    except Exception as e:
    # Log the shot name along with the traceback info
    logging.error(f"error processing shot '{shot_name}':", exc_info=True)

How could I filter out the relevant part and log it?


Solution

  • Given it looks like you're only interested in any Python traceback, and presumably that would be the last thing printed, you can use rpartition to split the text at the last instance of the Traceback (most recent call last): header:

    if stderr:
        error = stderr.decode()
        error = error.rpartition("Traceback (most recent call last):\n")[-1]
        raise Exception(error)