Logging showing too much ... how do I limit?

[Dave_Novak]

First, I want to be clear that I am well-aware of the "Disable logging of action output" on the General tab, and in many cases I do have that option selected. I also am making use of the following logging options:
• Application logging option “Log build rule when a step is skipped or repeated” is unchecked
• Application logging option "Enable file logging" is unchecked
• Project-level file logging turned on

That said, when I start a build (either Console or GUI based), my project log file is filled with information from steps where I explicitly stated "Disable logging of action output". What I’d prefer to see in my log file is just those steps where I have logging enabled. Am I missing something?

I’m running the latest version of VBP (6.1). Sample log file attached. When reviewing the log file, please note that I have logging specifically disabled for all subroutine calls (which is most of what I do).

[kinook]

The 'Disable logging of action output' only prevents logging of the action's output, not logging of whether an action was processed (and possibly skipped).

If you put the conditional steps in a subroutine and the rule on the Subroutine Call step, if that step is skipped, none of the subroutine steps will be processed (or logged). Also, subroutine steps can call other subroutines for the same effect.

Alternatively, you could completely disable file logging for skipped sections of the build script and re-enable later on. See the attached sample.

[Dave_Novak]

Even in your example, I get the following output in my log file:

5/12/2006 9:50:48 AM: --------------------Starting Build: 'C:\Documents and Settings\Dave Novak\Local Settings\Temporary Internet Files\Content.IE5\ZIJKLVNX\disablelogging[1].bld'--------------------
5/12/2006 9:50:48 AM: Building project step 'Project steps'...
5/12/2006 9:50:48 AM: Building project step 'Conditional'...
5/12/2006 9:50:48 AM: Building project step 'Skipped #1'...
test
5/12/2006 9:50:48 AM: Building project step 'Skipped #2'...
test2
5/12/2006 9:50:48 AM: Building project step 'More'...
5/12/2006 9:50:48 AM: Build successfully completed.


The logging just seems to be way too verbose. I don't understand the purpose of having a "Log Message" step that is written to the log file as both "Building project step..." and then my output. Is there no concept of "Log Level" whereby I can turn off the step tracing? Is there any way for me to disable step tracing?

I would prefer my output to look like the following:

5/12/2006 9:50:48 AM: --------------------Starting Build: 'C:\Documents and Settings\Dave Novak\Local Settings\Temporary Internet Files\Content.IE5\ZIJKLVNX\disablelogging[1].bld'--------------------
test
test2

[kinook]

Originally posted by Dave_Novak
Even in your example, I get the following output in my log file:
Are you referring to the Output pane or the log file? In my tests, the log file has:

5/12/2006 8:40:22 AM: --------------------Starting Build: 'C:\disablelogging.bld'--------------------
5/12/2006 8:40:22 AM: Building project step 'Project steps'...
5/12/2006 8:40:22 AM: Building project step 'Conditional'...
Step 'Conditional' build rule evaluates false: %BLAH% is defined
5/12/2006 8:40:22 AM: Step skipped
5/12/2006 8:40:22 AM: Building project step 'More'...
5/12/2006 8:40:22 AM: Build successfully completed.

The Output pane currently displays all logging events; we'll consider providing a way to filter/limit the ouptut in this view in a future release.

The logging just seems to be way too verbose. I don't understand the purpose of having a "Log Message" step that is written to the log file as both "Building project step..." and then my output. Is there no concept of "Log Level" whereby I can turn off the step tracing? Is there any way for me to disable step tracing?

Not with the built-in text logger (we'll consider adding such a capability). A couple of options:
1) Use XML logging, then the Transform XML log action to generate an HTML log report. You can customize the contents of the report via the action properties and/or using a custom XSLT stylesheet.
http://www.visualbuild.com/Manual/transformlogaction.htm

2) Create your own custom logging component that only writes the output you're interested in seeing.
http://www.visualbuild.com/Manual/vbploggersample.htm

[Dave_Novak]

I am looking at the log file rather than the output pane.

Just to be clear, I do see the value in tracing all of the output steps, especially if you need do some build debugging (post build). That said, I also see great value in having a log that shows only the build output (for succinctness). I do hope that you will consider adding logging level to help alleviate this noise when it is unwanted.

In the meantime, I'll start looking at your alternative suggesitons.

[kinook]

Originally posted by Dave_Novak
I am looking at the log file rather than the output pane.
Are you doing a Rebuild Selected rather than a Build or Rebuild (according to your log output, none of the conditional steps were skipped)?
http://www.visualbuild.com/Manual/methodsofbuilding.htm

[Dave_Novak]

I actually did a rebuild. HOWEVER, I changed the conditional step to make it UNconditional.

Going back to the original version, my output is:

Settings\Temporary Internet Files\Content.IE5\ZIJKLVNX\disablelogging[1].bld'--------------------
5/12/2006 11:47:50 AM: Building project step 'Project steps'...
5/12/2006 11:47:50 AM: Building project step 'Conditional'...
5/12/2006 11:47:57 AM: Step skipped
5/12/2006 11:47:57 AM: Building project step 'More'...
5/12/2006 11:47:57 AM: Build successfully completed.


So, indeed logging is disabled temporarily for those skipped steps in your example. I'm going to see what I can do to mimic this as it appears to be a faster solution. My apologies for the confusion I introduced.

BTW -- How can I programmatically check the "Disable logging of action output" setting for the current Step? I could use this as my flag for disabling / re-enabling logging.

[kinook]

Originally posted by Dave_Novak
BTW -- How can I programmatically check the "Disable logging of action output" setting for the current Step? I could use this as my flag for disabling / re-enabling logging.
If Step.NoLogging Then

http://www.visualbuild.com/Manual/nologgingproperty.htm

[Dave_Novak]

Well, I'm getting closer. I was able to turn off a fair amount of looging with the following code:

Sub vbld_StepStartingProject()
' turn off logging for any step that checked "Disable logging of action output"
If Step.NoLogging Then
vbld_TempMacros().Add "LOGFILE", ""
Else
' ensure that the logfile is re-enabled (it may have been disabled previously)
vbld_TempMacros().Remove "LOGFILE"
End If
End Sub

Sub vbld_StepDoneProject()
If Step.NoLogging Or Step.BuildStatus = vbldStepStatSkipped Then
vbld_TempMacros().Add "LOGFILE", ""
End If
End Sub


That said, is there any way to turn off output for steps that are skipped? I've been able to supress the "Step skipped" message in the log, but I can't figure out how to stop it from writing the "Building xxxxx" to the log. Is there an easy way to tell if a step is going to be skipped?

[kinook]

No. But you could remove those lines from the log file at the end of the build (see attached sample).

[Dave_Novak]

I have added a thread for "Logging improvements sorely needed" to the Suggestions area -- http://www.kinook.com/Forum/showthread.php?s=&threadid=1813