Join 34,000+ subscribers and receive articles from our
blog about software quality, testing, QA and security.

Viewing all log entries and understanding them


#1

Hi,

one screenshot, a bit of code and two questions :wink:

  1. I can extend the rightmost column that shows the time. With the title-column, I saw that I drag the divider to the right of the control and it would add that width, but for the time-column this doesn’t work.

The next question is about VB.net-logging (and sequence of execution and logging).
below is the code which was logged in the screenshot above:

SiAuto.Main.LogString("defval893 VOR Aufruf GFCR",defval893.Value) defval893.Value = GetFromCurrentRecord("id_stammvpm","DropDownList","TplDropDownList893") SiAuto.Main.LogString("defval893 NACH Aufruf GFCR",defval893.Value) if MultiView1.ActiveViewIndex = 0 Then SiAuto.Main.LogObject("GridView1",GridView1) SiAuto.Main.LogObject("GridView1.FooterRow","GridView1.FooterRow") if GridView1.FooterRow is Nothing Then SiAuto.Main.LogMessage("Footer undefiniert!") else ctl = GridView1.FooterRow.FindControl("FooterTplDropDownList893") ctl.SelectedValue=defval893.Value SiAuto.Main.LogString("defval893",defval893.Value) SiAuto.Main.LogString("selval",ctl.SelectedValue) end if end if SqlDataSource1.InsertParameters("id_stammvpm").DefaultValue=defval893.Value

Now, in that code we can basically see the sub “GetFromCurrentRecord” is only called in the 2nd line, thereafter we see a lot of different logs and no calls of other subs. Yet, if you look at the log, you see that it has logged several calls of GetRowFromCurrentRecord, while there are no calls of subroutines in my code.
Two possible explanations I could think of:

  1. the log doesn’t show the entries in exact order of time. Unfortunately I couldn’t verify that idea, as I couldn’t make the time-column wide enough. (see #1).
  2. ASP.NET was executing in multiple threads and called GetRowFromCurrentRecord as part of execution of some <%-code.

Or could there be another reason? Are there perhaps additional features in SI that I could use to find out more about the ‘calling environment’?


#2

Hello Michael,

That’s a known limitation of the underlying tree view control. We are looking into ways how to improve this. What usually helps in this situation is, if the tree is growing to the right because of unmatched Enter/Leave pairs, to insert a ‘Reset Call Stack’ log entry (Edit | Reset Call Stack) to reset the tree.

I also guess that these log statements come indeed from different threads. To verify this, you can apply a so-called AutoView rule which lets you, among other things, create a new view for each thread in the current log.

Several simple rules are already built-in and can be found under ‘Edit | Apply Built-in AutoView Rules’. Custom rules can be added with the AutoView rules dialog (Edit | AutoView Rules). So, if you apply the built-in ‘Thread Rule’, the Console will open a new view for each thread in your log and you can easily see your log statements independently from other threads. This should help you to find out if your method is really called from multiple threads.


#3

Thanks Tobias, that’ s helpful.[quote]That’s a known limitation of the underlying tree view control. We are looking into ways how to improve this.[/quote]Maybe inserting a dummy-column with 0width would help? I guess it’s not possible, but what would like is to have the time as leftmost col, not scrolling. :slight_smile:

And yes, the call-stack was a bit out of balance, because I had inserted EnterMethod as first statement of subs and LeaveMethod as last statement - even after “Return”!


#4

I guess fixing this scrolling problem won’t be so easy (if possible at all). However, I will look into it.