Engine Log weirdness

Questions & Suggestions
1

I looked at the engine log out of curiosity and I'm worried by what I see there.

This part for instance:

2017-12-20 07:43:21 Engine Starting 8.0.4
2017-12-20 07:43:21 Old engine details remains a running process Running Engine Details/370
2017-12-20 07:43:22 Running application query took a while (3788 us)
2017-12-20 07:43:22 Invalid Plug In Action with Name Wrap Text

and the fact that there are hundreds of lines with Invalid Plug In Action with Name Wrap Text populating that log.

Does anyone know if/what I should do about that?

Tom answered:
Why haven’t you opened a new topic?

I have now

That means that at least one of your macros has an action that is based on a custom plugin “Wrap Text”, and that plugin is either missing or it is not compatible with KM8.

The plugins are located here:

~/Library/Application Support/Keyboard Maestro/Keyboard Maestro Actions
If the plugin is there, then update it or remove it. If you remove it then you should also remove the corresponding action(s) from your macros.

If it is not there, then install it or remove the orphaned action(s) from your macros.

Re:
07:43:21 Old engine details remains a running process Running Engine Details

I don’t know if this related to the plugin issue. There is a very similar thread here1, also about missing plugins, and this message is also mentioned. So, quite possible that it is related. Fix the plugin issue and then see if the “old engine” message still appears.

I've searched for Wrap Text and it found markdown macros. While I could not find any reference to a 'Wrap Text' action in any of them, I deleted the whole macro group and the invalid plugin message stopped in the engine log.

This part still persist after a reboot though:

2017-12-20 09:21:48 Engine Starting 8.0.4
2017-12-20 09:21:48 Old engine details remains a running process Running Engine Details/370
2017-12-20 09:21:49 Daemon launched by login window. Initiating login actions.
2017-12-20 09:21:49 Running application query took a while (3058 us)
2

Here is the link to my original reply. @JMichaelTX or another moderator, could you please move it into the new thread?

Fine. Just to keep things tidy, have you also looked in the plugins directory, if there is an outdated/dysfunctional plugin?

3

No, there is nothing in the plugins directory.

4

I just looked at my log file (could have done this earlier :slight_smile:) and I also have the “old engine” message. It appears exclusively after the “Engine Starting 8.0.4” message, that is, it appears only after engine (re)start.

So, I think, this is nothing to worry about. But maybe @peternlewis can shed some light on this.

5

Do you also have the running application query took a while log entry?

6

Yes, several times each day. This is from today (filtered with “took”):

2017-12-20 04:43:07 Running application query took a while (5213 us)
2017-12-20 04:43:07 Running application query took a while (6662 us)
2017-12-20 04:43:09 Running application query took a while (23951 us)
2017-12-20 04:43:09 Running application query took a while (14839 us)
2017-12-20 04:43:09 Running application query took a while (5890 us)
2017-12-20 04:43:09 Running application query took a while (5918 us)
2017-12-20 04:43:09 Running application query took a while (6938 us)
2017-12-20 04:43:09 Running application query took a while (3477 us)
2017-12-20 04:43:09 Running application query took a while (4057 us)
2017-12-20 09:52:44 Running application query took a while (9581 us)
2017-12-20 09:52:44 Running application query took a while (19748 us)
2017-12-20 09:52:44 Running application query took a while (8158 us)
2017-12-20 09:52:44 Running application query took a while (6591 us)
2017-12-20 09:52:44 Running application query took a while (70648 us)
2017-12-20 09:52:44 Running application query took a while (20874 us)
2017-12-20 09:52:44 Running application runningApplicationWithProcessIdentifier (<NSRunningApplication: 0x60800010e850 (com.apple.systemuiserver - 370)>) took a while (1174 us)
2017-12-20 09:52:44 Running application query took a while (3620 us)

PS/edit:

I noticed that in the above sample it looks like it was tied to a system sleep/wake (reflecting my usual sleep/wake hour :slight_smile:). But this is not typical. Here a sample from yesterday, which doesn’t show that pattern:

2017-12-19 01:47:59 Running application query took a while (3828 us)
2017-12-19 01:58:21 Running application query took a while (5510 us)
2017-12-19 01:58:21 Running application query took a while (3268 us)
2017-12-19 02:19:31 Running application query took a while (5440 us)
2017-12-19 02:19:31 Running application query took a while (3209 us)
2017-12-19 02:21:07 Running application query took a while (3961 us)
2017-12-19 05:34:38 Running application query took a while (5718 us)
2017-12-19 05:34:38 Running application query took a while (5231 us)
2017-12-19 11:53:59 Running application query took a while (4820 us)
2017-12-19 13:53:58 Running application query took a while (3193 us)
2017-12-19 14:15:35 Running application query took a while (4763 us)
2017-12-19 17:01:10 Running application query took a while (161655 us)
2017-12-19 17:01:10 Running application query took a while (217087 us)
2017-12-19 17:01:10 Running application query took a while (99574 us)
2017-12-19 17:01:10 Running application query took a while (70839 us)
2017-12-19 17:01:10 Running application query took a while (128431 us)
2017-12-19 17:01:11 Running application query took a while (91466 us)
2017-12-19 17:01:11 Running application query took a while (89203 us)
2017-12-19 17:01:11 Running application query took a while (75931 us)
2017-12-19 17:18:28 Running application query took a while (3082 us)
2017-12-19 17:18:39 Running application query took a while (3353 us)
2017-12-19 17:26:52 Running application query took a while (3079 us)
7

That just means there is a running process with PID 370.

In the Terminal, run the command:

ps auxw | grep 370

and see what it is.

Yes, as I have lamented many times, the Apple RunningApplications API is severely broken. Unfortunately, Apple has deprecated all previous APIs, so I have little choice but to use it. It has many failings, such as reporting an application as the frontmost application, but not listing it as a running application. And it also has a tendency to take a ridiculously long time (in the example shown, 3ms) to answer trivial queries (and in some of the cases @Tom showed, as much as 70ms). For a query that should take a few microseconds, this is an insanely long time. Keyboard Maestro complains about these because they are worthy of complaining about, but for the most part it just works around the issues.

8

Peter, may I ask what is the point, the value, of making the log entry if nothing can be done about it?

I find that these useless log entries clutter the log file and make it hard to see/find other real logs.

Can the logging of this event be removed?

Thanks.

1 Like
9

Because otherwise people complain that stuff to do with applications is slow, in certain cases, especially in loops, and this way there is evidence of the cause.

10

You could make a hidden preference that allows us to make the log less verbose:

DebugLog -bool NO
2 Likes