DiagnosticsService - odd behavior

Apr 8, 2010 at 3:18 AM

Test Case:

Using Microsoft.Practices.SharePoint.Common  ->   DiagnosticsService   I have no issues registering this (using DiagnosticsService.Local)  I then use the code in the pdf/chm for registering areas/categories.  

At this point I can go into _admin/metrics.aspx and see my areas/categories all ready to be configured.  So I know that the .Common example works.


My Case:

That said, I then proceed to pull the DiagnosticsService out and place it into my own project.  I pulled over all of the things it seemed to need.

Testing the areas/categories code everything ends up in the farm.properties as it should.  So all is good there.

 

However,  I registered my DiagnosticsService (which is an exact copy of the one in Microsoft.Practices.SharePoint.Common except with a different [Guid( ... )]) using .Local
I am doing this in a Farm level feature in the Active event.

No exceptions are thrown.  However, when I go to the _admin/metrics.aspx page I now get an "Object reference not set to an instance of an object."
If I deactivate my feature (and thus UnRegister() my DiagnosticsService) said error goes away.

I have added tracing to every function in the DiagnosticsService to see what is going on. 
On Registering it (.Local)  no exceptions are thrown and nothing seems to be out of the ordinary.
Hitting the _admin/metrics.aspx the only tracing that fires is the ProvideAreas() method which returns areas and doesn't seem to have any issues. (No exceptions and it returns a list of areas as it should)


Questions:

1) What parts of the SharePoint Foundation should I set to "Verbose" in _admin/metrics.aspx to better trouble shoot this?  (as I currently see nothing relevant in the SP trace logs in the 14 hive)

2) What process/service needs to be restarted to unlock my DLL? IISReset doesn't seem to cut it after I register the DiagnosticsService (I would use Process Explorer for this but it seems to be Blue Screening my HyperV box)

3) Other then ProvideAreas() what parts of my code would be firing?

 

Any assistance/suggestions on this would be most welcome and very much appreciated.

Apr 8, 2010 at 4:59 PM

Observation

This appears to be an issue that occurs when you want your DiagnosticsService to only define one category.


The DiagnosticsService has the concept of the "Default Area" which has a "Default Category".
The DiagnosticsService seems to assume that you will have this default AND your configured areas.

You can see this in the DiagnosticsService.ProvideAreas().

It pulls down your configured areas, adds them to the spAreas list.

After that, it adds the default area.

In my case my defaults are set to "MyArea" with "MyCategory".

When I define the areas I want to have configurable the only area I want is "MyArea".
Thus I configured "MyArea" with "MyOtherCategory".

This causes "ProvideAreas" to try and add "MyArea" twice.
You end up with:
MyArea with MyCategory
and an odd area that has null values that contains MyOtherCategory.

This happens because ProvideAreas doesn't check to see if your default area is in your configured areas. (Which may be a valid assumption base on the design, see questions below)

Questions

I am getting around this by having ProvideAreas not add the default to the list it returns.  I am also having my configureation manager auto add the default area to my configuration.

1) Am I using the Areas/Categories in an incorrect way base on their design?

2) What is the expected use? Is using the default area as your only area not a correct path?

3) Does the DiagnosticsService require you to have a minimum of 2 areas? (the default always being a separate area?)

4) Did I completely miss a section in the pdf/chm on this?

Thanks!

Coordinator
Apr 8, 2010 at 6:41 PM

Hi,

I'd consider one bug on our side, but I don't think this is the issue you are hitting.  We require the default area/category for our behavior, and we don't want you removing it, but we also should not allow you to add it through configuration.  We expect it to always be there in its own category.  We do enforce no duplicate configured areas or categories, but unfortunately missed this case for the one we are adding programmatically.

You can customize the implementation we provide to override the default category that we provide, but if you do that, it must be a different area.  You could also modify the code in provide areas to not add the default category, or alternatively add the default category in provide areas before the area is provided - and merge it into an existing area if the default area already exists.  This situation was beyond the scope of the current design.  We had considered the situation of overriding the default category in the future, we just didn't have time to get it in. 

We'll open a bug on the first issue.

Chris

 

Apr 8, 2010 at 8:16 PM

I thank you greatly for the response.

Honestly, I just wanted to make sure I hadn't missed the intended use of the class.

Thanks for the clarification on the intended design, and for providing this awesome tool set.

Keep up the "awesome".

 

Apr 15, 2010 at 4:58 PM

I have run into another interesting bit of behavior.
I am still on SharePoint 2010 Database Version: 14.0.4730.1010 (if that helps any)

Behavior:

I register my area/category (AreaOne/CategoryOne) and then call DiagnosticsService.Local to register it.
I log some stuff (in a sharepoint feature) and it seems to log just fine. (tracing as well)

The oddness happends when I change the areas configured levels in _admin/metrics.aspx.

Traces work just fine.
Events seem to follow the level I have configured for Trace.

If I set Trace as Verbose and Event as None (in _admin/metrics.aspx) my events will log as if they were set to Verbose. 

If I set Trace as None and Events as Verbose my events no longer log.


Also, I am noticing that the EventSeverity enum doesn't seem to come through into the Logs as I am expecting.

With the TraceSeverity (Unexpected, Monitorable, High, Medium, Verbose) they come into the log with the given severity. (This works as expected)

When I log using EventSeverity the enum seems to map odd  (CriticalError, Error, Warning, Information, Verbose) seem to map to (CriticalError, CriticalError, Warning, Information, Information).  Everything logs, just shows up with the wrong Severity.

 

My first thought was "I must have converted something wrong" so I pulled down the SharePoint2010Drop8, setup a new HyperV and deployed it.
This new box running only the Practices code experiences the same behavior.

 

 

Questions:

1) Is this expected? (I didn't see it in the documentation)

2) Is this a known issue? (Didn't see it in the documentation or in your discussions)

3) Have you guys run into this behavior before?

Coordinator
Apr 21, 2010 at 12:27 PM

Sorry for the late reply, but did you find the problem?

The logger out of the box works fine with the metrics page on my local installation and in our testing, including the configuration.

Can you provide more details about your setup?

Chris

Apr 21, 2010 at 5:19 PM
I am in the process of setting up a new environment for this to make sure that isn't the issue. (As this is very odd behavior) I will get you more detailed information after I verify that it isn't just my environment. Thanks.
Apr 22, 2010 at 3:12 PM

Ok,  I setup a new SharePoint 2010 box and I am still seeing the same behavior.  I am seeing this with the Microsoft.Practices. 

I haven't even looked at my custom code yet as I want to get an environment where the MS.Practices.SharePoint runs fine.

Behavior:
Events follow the logging level set for my traces in central admin.

Events will log with any of the Severity levels, but all events have their severity set to either Critical, Warning, or Information when they actually hit the logs.

Setup:
I am running SharePoint 2010 Database Version: 14.0.4730.1010 on Windows Server 2008 SP2 Enterprise edition. (This is a Hyper V environment)

SQL Server 2008 with a named instance.

I did the "farm" install for SharePoint but everything (SQL included) is on the same box.

Because this is a dev box I don't have the usual multi accounts.  Everything is running as the same domain admin.


I am running tests through a "big button" webpart that simply kicks off a list of Events and Traces when the "big button" is pressed.

Other then that everything is running with whatever defaults were set when sharepoint was installed.

Is there any other information I could provide that might be helpful?

Thanks

Coordinator
Apr 23, 2010 at 3:32 PM

Thanks for the detail.  We will re-examine this area one more time on our side to see if we can replicate the behavior.

Apr 23, 2010 at 4:18 PM
I have pulled down and am installing the SharePoint 2010 release. I am currently building a box to check this behavior in the new release.
Apr 27, 2010 at 3:56 PM

Hi Souls512,

we have tried to repro, but we are unable to repro issue as reported by you. if possible share your sources to us so that we can try same with our environment and get back to you.

 

thanks

Appaji

v-appave@microsoft.com

Apr 27, 2010 at 8:52 PM

I will whip up a full test harness that reproduces the behavior.

It will probably be sometime tomorrow.

 

I was able to reproduce this with MS.Practices.SharePoint in the RTM.

Thanks a million for looking at this for me guys!

Apr 28, 2010 at 6:51 PM

I have whipped up a full Test harness using the MS.Practices Drop9 code.  It reproduces the issue.

How do you want me to get you this?  Email? (Was unsure if the email was part of your signature or included for this purpose)

 

May 4, 2010 at 6:50 PM

Appaji,

Were you all able to see the behavior I described?

Thanks,
Souls512

May 12, 2010 at 6:59 PM
Edited May 12, 2010 at 7:12 PM

Updating the discussion for Posterity

Emailed the Practices team a test harness that used the Microsoft.Practices.SharePoint.Common.dll and reproduced my behavior.

My odd behavior was confirmed by the practices team (Durga)

**From the email with Durga**

Since event severity is set to warning, event viewer shows event with warning and error.(expected behavior)

Trace severity is set to High, but event with medium,unexpected,monitorable and information are also shown in ULS viewer. (Unexpected behavior) could be SharePoint Bug

 

Navigated to configure diagnostics logging(_admin\metrics.aspx) page.

Changed the event level to error and trace level to high. Following are observation made. Since event severity is set to Error, event viewer shows event with Error.(expected behavior)

Trace severity is set to High, but event with medium,unexpected,monitorable and information are also shown in ULS viewer.(Unexpected behavior)

 

More Observations: Critical and Error will appear in the logs as Critical – we are able to repro, we will look into this and get back if any code changes required from our end. Information appears as Information -- true Verbose comes in as Information – we will look into this and get back if any code changes required from our end.

**end email**

 I am now waiting to hear if this is a SharePoint bug (expected) or a Practices bug.

Thanks for looking into this guys and I hope to hear what your findings are.

Coordinator
May 12, 2010 at 7:34 PM

-> Critical and Error will appear as error because there is only one level to map to in the event log event types (Error) that makes sense.  Same is true with Verbose mapping to Information.

-> We are still looking at this.  We made some updates related to storing logger settings that I did not think should impact this area.  I cannot reproduce the behavior.  It seems to be logging and tracing correctly with filters applied and custom categories.  We will continue testing to see if we can repro again, or if the issue is gone.

May 13, 2010 at 11:04 PM

Interesting.

I sent Appaji a test harness that reproduced this with Drop 9. 
Did you get that test harness?

I will test with Drop10, didn't see that you guys had made another.

If I reproduce it would you like a copy of the code I used to reproduce it?

Thanks,
Souls512

May 13, 2010 at 11:05 PM

"-> Critical and Error will appear as error because there is only one level to map to in the event log event types (Error) that makes sense.  Same is true with Verbose mapping to Information."

Is this also true for the SharePoint trace logs found in the 14 hive? because this is where I am seeing the mapping of Critical and Error both to Critical.

Coordinator
May 14, 2010 at 1:01 PM

I'll take a look in the ULS logs for the traces.

Durga cannot reproduce with the latest code base.  There is one change that may be impacting this that hasn't been released which is unregister and re-register of the logger when categories are updated.  I added this so that categories show up without an issreset.  This issue was introduced when we moved from using SPFarm.Properties to our own SPPersistedObject that is a child of farm to store farm level config.  We did this because SPFarm.Local.Update causes SharePoint to dump and reload all cached information (which is why before we didn't have the problem with categories showing up).

Coordinator
May 14, 2010 at 2:01 PM

I did find the behavior you describe in the ULS logs as well.  I'm looking into if it is expected behavior, but it is something that I'm pretty certain the patterns and practices code has no control over. 

May 21, 2010 at 5:04 PM

I tested Drop10:

Behavior 1:   (Last i heard we were waiting to hear if htis was expected)

Events log to the ULS Trace logs show up in  

CriticalError and Error = Critical

Warning = Warning

Information and Verbose = Information

 

Behavior 2:  (This may be expected, but it would be nice to get verification on this)

Setting Events to Verbose and Traces to None

Events writes to the Event Log per what you have Events configure as.  However, it writes to the ULS Trace logs per what you have Traces configured as.  (I haven't found any documentation saying this is expected but I could see how it would be)

Traces, Works as expected.