I see nothing wrong.
I also see why you 're confused

Let me explain the process:
Before the actual build process starts (i.e. the compiler/linker commands start executing), a preprocessing step runs which generates all needed command-lines. This step is necessary because it also caches much information making subsequent builds faster.
The build scripts run in this preprocessing step. And if you think about it, that's how it should be. Because build scripts alter project/target options which are then added to the command line (in this step).
So, you 're seeing your script log messages first because C::B runs the preprocessing step. When this is done, then it starts to actually execute build commands (including pre/post-build steps).
Does it make sense now, or did I confuse you even more?
