UI prints error messages twice

[johpiip]

Traceback is printed both with and without "[EXPECTION] tag". Traceback without the [EXCEPTION] tag would suffice. Also, the row before exception is also printed twice even if that is not part of the exception ("[INFO 10:48] Checking base inputdata..." and "[ERROR] {"message": "Checking base inputdata...", "level": "INFO"}"). The JSON-style part is in helmet-model-system log format.

[UI-event] Initializing run of scenarios: alpha
[INFO 10:48] Checking base inputdata...
[EXCEPTION] Traceback (most recent call last):
[EXCEPTION]   File "C:\Users\PiippJo\Home\helmet-model-system\Scripts\helmet_validate_inputfiles.py", line 252, in <module>
[EXCEPTION]     main(args)
[EXCEPTION]   File "C:\Users\PiippJo\Home\helmet-model-system\Scripts\helmet_validate_inputfiles.py", line 75, in main
[EXCEPTION]     import inro.emme.desktop.app as _app
[EXCEPTION] ModuleNotFoundError: No module named 'inro'
[ERROR] {"message": "Checking base inputdata...", "level": "INFO"}
Traceback (most recent call last):
  File "C:\Users\PiippJo\Home\helmet-model-system\Scripts\helmet_validate_inputfiles.py", line 252, in <module>
    main(args)
  File "C:\Users\PiippJo\Home\helmet-model-system\Scripts\helmet_validate_inputfiles.py", line 75, in main
    import inro.emme.desktop.app as _app
ModuleNotFoundError: No module named 'inro'

Can be replicated by trying to run a model run without EMME (or trying to do any other error).

[johpiip]

Might be related to HSLdevcom/helmet-model-system#517 ?

[hsl-petrhaj]

To be solved at the Helmet-Model-Systems side.

[hsl-petrhaj]

Now I think I figured out the reason:

// Relay a loggable event in worker; worker => main => UI
ipcMain.on('loggable-event-from-worker', (event, args) => {
  event_time = args["time"];
  delete(args["time"]);
  // python-shell 3.0.0 breaking change: Every character from
  // stderr is its own value (like {0: 'h', 1: 'e', 2: 'l', 3: 'l', 4: 'o'})
  // so let us join all values into one string ('hello').
  event_string = Object.values(args).join('');
  // Try to read the string as JSON. If it fails, use the whole string
  // as a message. Messages via utils.log are written to stderr as JSON.
  // Warnings from numpy tend to be written as plain-text. 
  try {
    // utils.log
    event_args = JSON.parse(event_string);
    //console.log('Normal event')
  } catch (error) {
    // numpy warnings and other non-log messages
    //return;
    event_args = {
      "level": "EXCEPTION",
      "message": event_string,
    };
    //console.log('Exception event')
  }
  event_args["time"] = event_time;

  mainWindow.webContents.send('loggable-event', event_args);
});

// Log worker-errors (by PythonShell, not stderr) in main console
ipcMain.on('process-error-from-worker', (event, args) => {
  mainWindow.webContents.send('loggable-event', {
    "level": "ERROR",
    "message": (typeof args === "string") ? args : JSON.stringify(args)
  });
});

In the first function, we get the exception rows, in the second function we get the multirow error message. The second message comes the worker itself as it fails.
I propose to remove / comment out the second function, this will mute the second error description while allowing for all stderr messages to appear as [Exception] which should be good enough for the end user.