The Log Window displays things in the wrong order

Bome Products
1

This has always bugged me. Why does BMTP log the result of an outgoing action before the actual outgoing action?. See picture.

Capture

2

I believe Florian will need to provide the definitive answer however I can speculate.

I believe there are different messages types and each one has it’s own thread.

  1. Incoming and Outgoing Message types
  2. MIDI IN and MIDI Out message types
  3. Internal Bome Informational message types
  4. Log message types

I think you are running up against the different between Type1 and type3. Type 3 messages might include things like discovering and opening MIDI ports etc and of course preset changes. Of course, there has to be a decision in which order they are displayed as you cannot display both together or it would look like a jumbled mess. My guess is that informational message types like "Activated preset 1: New (2) Preset " always occur before In and out message types. Maybe they also occur before MIDI IN and MIDI OUT message types as well.

Again this is just my speculation and we can see how Florian answers.

Steve Caldwell
Bome Customer Care

Also available for paid consulting services: bome@sniz.biz
4

Steve is right that sometimes there are so-called race conditions for actions trying to log something at the same time.

In this case (and for most translation actions), the logic is:

  1. execute the respective function (e.g. activate the preset) as fast as possible
  2. if successful, log that the function has been executed successfully (otherwise, report an error)

In some cases, step 1) will also issue a log message what it did (again, after executing the respective function).

Internally, there are different modules for the translation actions and for the actual function modules (Preset Manager / translation engine). E.g., The Outgoing Action tells the Translation Engine to activate a certain preset.

So in general, the IN / OUT log messages can be read as ‘executed successfully’. The log text, however, is always in present tense, because it’s the general description of the action.

I hope that explains.

5

I appreciate the in depth explanation. But maybe in a future iteration of BMTP this could be changed?.
Working in BMTP often requires sequencing things in a particular order. So viewing those things/events in the correct order in the Log Window is somewhat important. Sometimes the “Activated Preset xx” log entry is 20+ log entries before the “OUT activate preset xx” log entry.

6

Maybe there should be an option to filter out these internal informational message that are happening within the MT Engine. For troubleshooting, most of the time they should probably be ignored anyway?

Steve Caldwell
Bome Customer Care

Also available for paid consulting services: bome@sniz.biz
8

Some more in-depth info:
This is a multi-threaded realtime system. So it is impossible to log a message at exactly the time the function happens. The log will either be before execution or after. As explained, logging before execution would be a bad idea (for performance). And due to the multi-threadedness, even though the ‘OUT activate preset xx’ message is logged immediately after execution, 100 other translation threads could theoretically run at the same time and log their actions at the same time. The log module enqueues all messages in the order of reception and then (asynchronously) displays the messages, again, in order.

The Log Window definitely outputs all messages in correct order…

Now, just as a thought experiment, imagine we’d output the action log message before execution: from reading the log, you would think that it’s already executed at that time, but there might be 20 or more actions happening at the same time (and being logged afterwards), so the log will show 20+ messages before the engine has really activated the preset. IMHO, that would lead to more confusion than logging a little later than expected, but definitely AFTER the fact.

So please correct me if that’s not what you’re seeing, but if there are 20+ log entries between ‘Activated Preset xx’ and ‘OUT activate preset xx’, they’ve all happened at pretty much the same time, right? Could you post an example?

And one last information: some Outgoing Actions might be executed asynchronously. For example, 3 Translators in one preset:

Translator 1: Incoming: MIDI Note 60
  Outgoing: MIDI Note 70

Translator 2: Incoming: MIDI Note 60
  Outgoing: Activate Preset 10

Translator 3: Incoming: MIDI Note 60
  Outgoing: MIDI Note 80

Now on MIDI Note 60, all three Outgoing Actions are triggered. However, the translation engine does not guarantee that Preset 10 will be activated before sending MIDI Note 80. The engine only guarantees execution in order for the same type. So it is guaranteed that Note 70 will be sent before Note 80. And if another Preset Activation is triggered further down, it is guaranteed to happen after the Preset change in Translator 2. But the MIDI execution is on its own thread and can happen in parallel, or faster, or (hopefully not!) slower.

For logging just before execution of the Outgoing Action, you can add a line like this into the Rules of the respective Translator:

Log "Just before Preset Activation xx"

You’ll probably see that Preset Activation is executed asynchronously.

9

@FlorianBome

Fascinating, I’ll read that post about ten more times and then I’ll get back to you. LOL

Absolutely.

10

@SteveC
I emailed you regarding a quote for converting an LaunchPad Mini Mk 2 project to a LP Mini Mk 3 project. Did you receive it?. Here is a project file. I stated in the email that this project works better with the “Manipulate bits” Translator disabled.
Example of existing project.bmtp (45.5 KB)

11

Yes, I replied this morning as I try to to work on Sundays. Sorry for the delay!

Steve Caldwell
Bome Customer Care

Also available for paid consulting services: bome@sniz.biz