Bug Report: Malformed Error Log When Script Error

[JMichaelTX]

Running Keyboard Maestro 9.0.5 on macOS 10.14.6 (Mojave).

@peternlewis, it appears to me that the KM Engine Log entries when there is an AppleScript error are malformed and incomplete.

Example KM Engine Log

2020-05-25 20:40:33 Execute macro “TEST Macro Error Handling of Script Error @TEST” from trigger Duplicate Macro Palette
2020-05-25 20:40:33 text-script:939:952: execution error: [Script ERROR] Can’t divide 5.0 by zero.  SCRIPT: “Create Script Error” 1.1 (-2700)

2020-05-25 20:40:33 text-script:939:952: execution error: [Script ERROR] Can’t divide 5.0 by zero.  SCRIPT: “Create Script Error” 1.1 (-2700)
 Macro “TEST Macro Error Handling of Script Error @TEST” cancelled (while executing SCRIPT:  Cause a Script Error (AS)).

Issues

1. There is a blank line in the middle of the error logs
2. The line reporting the Macro cancellation does NOT have a time stamp:

 Macro “TEST Macro Error Handling of Script Error @TEST” cancelled (while executing SCRIPT:  Cause a Script Error (AS)).

The format/layout of the log for an Execute Script Action is quite different than other Actions, which generally look like this:

2020-05-25 20:57:19 Execute macro “TEST for Proper Logging of Search Action with Regex @TEST” from trigger Duplicate Macro Palette
2020-05-25 20:57:19 Search Regular Expression failed to match (.+) NotFound (.+)
2020-05-25 20:57:19 Search Regular Expression failed to match (.+) NotFound (.+) Macro “TEST for Proper Logging of Search Action with Regex @TEST” cancelled (while executing RegEx: Example Regex that fails -- Notify and Terminate ON).

It would be very helpful, for both manual and automated, analysis of KM Error logs if the format/layout of the failure of an Action was consistent for all Actions.

At a bare minimum, I would request that you add the time stamp, and removed the blank line.

But something like this would be great!

~~~ If the script was a script text: ~~~
2020-05-25 20:40:33 Execute AppleScript failed with “[Script ERROR] Can’t divide 5.0 by zero.” in text-script. Macro “TEST Macro Error Handling of Script Error @TEST” cancelled (while executing SCRIPT:  Cause a Script Error (AS)).

~~~ If the script was a script file: ~~~
2020-05-25 20:40:33 Execute AppleScript failed with “[Script ERROR] Can’t divide 5.0 by zero.” in /path/to/script/Create Script Error.scpt. Macro “TEST Macro Error Handling of Script Error @TEST” cancelled (while executing SCRIPT:  Cause a Script Error (AS)).

Just to be clear, and maybe a bit helpful, this is the format:

<Date/Time> <Action Type> failed with “<Error Msg>” in <Source>. Macro “<Macro Name>” cancelled (while executing “<Action Name>”)

I added a few fancy quotes that you have not been using, which helps make the variable info clear.

Thanks.

[peternlewis]

The log includes the error output of the script. I will trim it so it is less likely to include blank lines, but the error out put could include line breaks in the middle in which case there will be other lines that contain errors.

It will look something like:

2020-05-26 14:54:30 Execute an AppleScript failed with script error: text-script:21:25: execution error: The variable asda is not defined. (-2753)
2020-05-26 14:54:30 Execute an AppleScript failed with script error: text-script:21:25: execution error: The variable asda is not defined. (-2753). Macro “00)🚧 Testing A” cancelled (while executing Execute AppleScript).

I don't have any plans to try to make the log file parsable in general.

[jonathonl]

Whilst this does NOT address errors or formatting reported within the KM Engine log , I am just about to release a set of macros [UserLog] where the errors or progress of a macro can be reported in a separate UserLog file.It is highly customisable including error code format. Sample output.

I do not know how KM reports errors back to the user when in Applescript or shell etc , but assuming there is some parameter, then that could be passed as parameter to the UserLog macrol

The UserLog macro call would look like (showing the CHRON and an example call)

[JMichaelTX]

@jonathonl

The UserLog macro call would look like (showing the CHRON and an example call)

I don't think your system will help me, but I'm not sure how it actually works.
See my reply in your Macro topic.. Let's continue the discussion there.

[JMichaelTX]

@peternlewis

I don't have any plans to try to make the log file parsable in general.

Since the only notification KM provides to the user when a Macro terminates is the macOS Notification system, we need a much better notification, which includes all of the error msg. As I'm sure you know, the tiny notification displayed in the Notification Center cuts off most of the text most of the time.

So, just a little help from you in consistently formatting the KM Engine Logs when a macro terminates would be of GREAT assistance to ALL end users. I have a working Macro that shows something like this:

If the user runs this macro shortly after receiving notification of a macro error, he/she will get this helpful report, that will help in identifying and debugging the issues.

Clicking on the "Edit Macro" button will even open the KM Editor to the macro, and try to highlight the Action where the error occurred.

So please, help me help your users.

[peternlewis]

@JMichaelTX

Since the only notification KM provides to the user when a Macro terminates is the macOS Notification system, we need a much better notification, which includes all of the error msg.

If the objective is to report on the failure causes of past macros, parsing the log file is not the right answer.

An altogether different solution would be appropriate, something that tracks and displays specifically those errors.

I have no solution for this issue at this time, but a structured parsable log would not be how I will solve this issue.

The log contains endless possibilities of unstructured data, and turning it in to some structured format would be a massive task, almost certainly much harder that resolving this issue in some other way.

[JMichaelTX]

@peternlewis

If the objective is to report on the failure causes of past macros, parsing the log file is not the right answer.

First of all, Peter, you of all people should know there is no such thing as a “right“ or “wrong“ answer, as long as the results are correct. There are only solutions, some of which are better than others. And the worst solution, is better than no solution at all .

Yet I would be the first to agree that parsing the log is not the best solution. The best solution would be for you to provide us with a direct error report when a macro error occurs that gives us all of the details that I show in my error report.

However, in spite of repeated request, you have declined to do so.

Therefore, I as a KM user, have only one alternative: parse the error log.

Actually, parsing the error log is working quite well and quite fast with a few exceptions.

So, I am asking you for something I believe is fairly small. I am not asking you to rewrite the entire system for logging errors. I am simply asking you to fix a couple of areas where you could make the log entry more consistent when a macro error occurs.

For example, fixing the formatting of the log entry for when a script error occurs. Surely this is not a huge task.

The current system for reporting KM errors is very poor. The Mac OS Notification Center provides a very poor output device. And the KM log entry is hard to get to and hard to read especially with the multitude of other log entries which are mostly irrelevant.

So I would again ask you to please help me help all KLM users.