Tristan Watkins on IT Infrastructure

In my post yesterday on User Profile Picture Export Permissions I reviewed the requirements to export the SharePoint PictureURL profile property to the Active Directory thumbnailPhoto user attribute. Where I left off, I had identified a certificate error on our SSL-secured MySite’s wildcard certificate. You may recall that the User Profile synchronisation exported the mobile number property successfully. Given that this mobile number was updated by the end-users though the same MySite host as the User Profile picture, you may wonder why one exported successfully if there were certificate errors that interfered with the other.

Fundamentally, it’s irrelevant that this data was updated by these users in their MySites. The property could have been updated by an administrator in the User Profile Service Application. However, it appears that the User Profile export is not just exporting the URL as a string, it is actually copying the image on export; the User Profile Service Application is browsing to the SSL-secured site to pick up the image and writes it to the user’s thumbnailPhoto attribute. In this post I’ll review the evidence and explain the additional certificate trust configuration required to export an SSL-secured User Profile picture.

Certificate Trusts

While I initially stumbled across this error in the SharePoint ULS logs, it was also logged to the Windows Application event logs as a SharePoint Foundation Topology error (8311), “The root of the certificate chain is not a trusted root authority“. As I hinted at yesterday, I initially disregarded this error because it pertained to our wildcard SSL certificate and I knew that the root certificate (Equifax) would be trusted by Windows by default (this is pretty fundamental to a Public Key Infrastructure). It was only when I noticed that this event occurred as part of the User Profile Synchronisation process that I looked in to it in more detail. These were the ULS logs that first grabbed my attention:

08/31/2010 10:36:12.33    miiserver.exe (0x106C)    0x1A1C    SharePoint Foundation    Topology    e5mc    Medium    WcfSendRequest: RemoteAddress: 'http://<HOSTNAME>:32843/2caef145ca304d148378faec86645981/ProfileDBCacheService.svc' Channel: 'Microsoft.Office.Server.UserProfiles.IProfileDBCacheService' Action: 'http://Microsoft.Office.Server.UserProfiles/GetUserData' MessageId: 'urn:uuid:63e3bc90-878b-4fc4-99b5-38c8ab2a4574'
08/31/2010 10:36:12.34    w3wp.exe (0x0C34)    0x0E14    SharePoint Foundation    Topology    e5mb    Medium    WcfReceiveRequest: LocalAddress: 'http://<FULLY QUALIFIED HOST NAME>:32843/2caef145ca304d148378faec86645981/ProfileDBCacheService.svc' Channel: 'System.ServiceModel.Channels.ServiceChannel' Action: 'http://Microsoft.Office.Server.UserProfiles/GetUserData' MessageId: 'urn:uuid:63e3bc90-878b-4fc4-99b5-38c8ab2a4574'    9c26087b-cb49-40b2-93f5-f8583499eead
08/31/2010 10:36:12.34    w3wp.exe (0x0C34)    0x0E14    SharePoint Foundation    Monitoring    nasq    Medium    Entering monitored scope (ExecuteWcfServerOperation)    9c26087b-cb49-40b2-93f5-f8583499eead
08/31/2010 10:36:12.34    w3wp.exe (0x0C34)    0x0E14    SharePoint Foundation    Monitoring    b4ly    Medium    Leaving Monitored Scope (ExecuteWcfServerOperation). Execution Time=4.61966025838972    9c26087b-cb49-40b2-93f5-f8583499eead
08/31/2010 10:36:12.38    miiserver.exe (0x106C)    0x1A1C    SharePoint Foundation    General    erv2    Medium    Updating X.509 certificate validation policy
08/31/2010 10:36:12.44    miiserver.exe (0x106C)    0x1A1C    SharePoint Foundation    General    erv3    Medium    Adding X.509 certificate thumbprint '<THUMBPRINT 1>' to root authority trust
08/31/2010 10:36:12.44    miiserver.exe (0x106C)    0x1A1C    SharePoint Foundation    Topology    8311    Critical    An operation failed because the following certificate has validation errors:\n\nSubject Name: CN=*.<WILDCARD DOMAIN NAME>, OU=Domain Control Validated - RapidSSL(R), OU=See www.rapidssl.com/resources/cps (c)10, OU=GT12672216, O=*.<WILDCARD DOMAIN NAME>, C=GB, SERIALNUMBER= xxxxxxxxxxxxxxxxxxxxxxxxx-xxxxxx \nIssuer Name: OU=Equifax Secure Certificate Authority, O=Equifax, C=US\nThumbprint: <THUMBPRINT 2>\n\nErrors:\n\n The root of the certificate chain is not a trusted root authority..
08/31/2010 10:36:12.44    miiserver.exe (0x106C)    0x1A1C    SharePoint Foundation    Topology    8311    Critical    An operation failed because the following certificate has validation errors:\n\nSubject Name: CN=*.<WILDCARD DOMAIN NAME>, OU=Domain Control Validated - RapidSSL(R), OU=See www.rapidssl.com/resources/cps (c)10, OU=GT12672216, O=*.<WILDCARD DOMAIN NAME>, C=GB, SERIALNUMBER=xxxxxxxxxxxxxxxxxxxxxxxxx-xxxxxx\nIssuer Name: OU=Equifax Secure Certificate Authority, O=Equifax, C=US\nThumbprint: <THUMBPRINT 2>\n\nErrors:\n\n The root of the certificate chain is not a trusted root authority..

These certificate errors at the bottom interrupted a long series of repeated http://Microsoft.Office.Server.UserProfiles/GetUserData events. The two events at the top of this excerpt are the last in that series, so the certificate errors occurred immediately after the user data had been gathered. This was a pretty strong hint that the certificate errors were interfering with the export. I was initially pretty stumped because I knew Windows trusted this certificate and I could confirm the certificates were fully trusted when I browsed to the MySite from the server, but I didn’t know what requested the certificate and why it wasn’t trusted. So I searched around a bit and found a number of articles about adding root certificates to SharePoint 2010′s Manage Trusts, which I’ve only used for Claims and Cross-Farm Service Applications, but I noticed it also came up for FAST Search, Exchange Web Services and REST – seemingly for any web services that access SSL-secured resources, intra or inter-farm.

What I don’t understand is why SharePoint web services aren’t using the Windows certificate store as a first stop before using SharePoint’s own Manage Trusts. I’m assuming this is something to do with Claims but I’m struggling to uncover anything meaningful that can confirm or disconfirm this. In the absence of guidance, I tested exporting our wildcard certificate and the root CA’s certificate to the local machine’s and the farm account’s certificate stores to see if that would fix the problem, without success. Next I tried to import the wildcard certificate through Manage Trusts, which still did not fix the certificate errors, but when I imported the root CA’s certificate in to Manage Trusts, the next synchronisation succeeded. In an effort to get to grips with these requirements and to understand how the certificate was requested I continued to monitor in ULSViewer and the FIM Client.

Successful Export

Initially, the same two GetUserData actions ran as in the first two events above. In fact, each of the first five ULS entries were identical to the first excert above, followed by the successful addition of three certificates to the root authority trust. This was when I suspected things were working (or that I’d at least cleared the next hurdle).

08/31/2010 12:22:10.65    miiserver.exe (0x07DC)    0x1B1C    SharePoint Foundation    General    erv3    Medium    Adding X.509 certificate thumbprint '<THUMBPRINT 2>' to root authority trust
08/31/2010 12:22:10.67    miiserver.exe (0x07DC)    0x1B1C    SharePoint Foundation    General    erv3    Medium    Adding X.509 certificate thumbprint '<THUMBPRINT 3>' to root authority trust
08/31/2010 12:22:10.72    miiserver.exe (0x07DC)    0x1B1C    SharePoint Foundation    General    erv3    Medium    Adding X.509 certificate thumbprint '<THUMBPRINT 1>' to root authority trust

At this point a number of “Assemblies and Sequences” are registered. Pretty boring stuff, so omitted here. All of these events begin with SPDelegateManager or SPXmlConfigurationManager. This is followed by a few events verifying the upgrade status of the databases, confirming that upgrades are not in progress or necessary. After that there are a couple of handfuls of additional configuration checks. Continuing after all that, we see the expected HTTP GET request for the first user’s updated User Profile picture:

08/31/2010 12:22:14.61    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Monitoring    nasq    Medium    Entering monitored scope (Request (GET:https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg))
08/31/2010 12:22:14.61    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Logging Correlation Data    xmnv    Medium    Name=Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg))    b7ca5cb5-25f0-401d-87e8-fe93bb3c63d5 

This is followed by a few less relevant events, then more log entries about the GET:

08/31/2010 12:22:14.93    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Monitoring    b4ly    Medium    Leaving Monitored Scope (Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg))). Execution Time=325.341137549723    b7ca5cb5-25f0-401d-87e8-fe93bb3c63d5
08/31/2010 12:22:14.93    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Monitoring    nasq    Medium    Entering monitored scope (Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg)))
08/31/2010 12:22:14.93    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Logging Correlation Data    xmnv    Medium    Name=Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg))    dfaaa0df-b2c0-4aab-a461-71e39680ad08
08/31/2010 12:22:14.95    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Monitoring    b4ly    Medium    Leaving Monitored Scope (Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg))). Execution Time=3.98852138030115    dfaaa0df-b2c0-4aab-a461-71e39680ad08
08/31/2010 12:22:14.95    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Monitoring    nasq    Medium    Entering monitored scope (Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg)))
08/31/2010 12:22:14.95    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Logging Correlation Data    xmnv    Medium    Name=Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg))    d3a5dff3-8dad-4c79-abf1-66284748d246 

A few more irrelevant events, then:

08/31/2010 12:22:14.98    w3wp.exe (0x1B08)    0x17EC    SharePoint Foundation    General    af74    Medium    HTTP request URL: /User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg)    d3a5dff3-8dad-4c79-abf1-66284748d246 

More database upgrade checks, then:

08/31/2010 12:22:16.18    w3wp.exe (0x1B08)    0x09EC    SharePoint Foundation    Monitoring    b4ly    Medium    Leaving Monitored Scope (Request (GET: https://<MY SITE HOST>:443/User%20Photos/Profile%20Pictures/<USER 1 PROFILE PICTURE NAME>.jpg)). Execution Time=1240.43874963807    d3a5dff3-8dad-4c79-abf1-66284748d246

These events are then repeated sequentially for other updated users. After these complete, voila! The thumbnailPhoto attribute is exported by FIM, populated in Active Directory and the profile picture appears in the Outlook 2010 Social Connector. I haven’t monitored how quickly this appears, but it works without further intervention.

And the money shot. Who wouldn’t want to see this mug in their Outlook every day. :/

Summary

Following this interrogation, it’s clear to me the certificate errors come from the location of the updated profile picture. The errors can be fixed by importing an export of the root CA’s certificate through SharePoint’s Manage Trusts (possibly the site’s certificate itself as well, although the error was on the root trust). That SharePoint 2010 web services (including the User Profile Service Application) do not appear to use the Windows certificate store feels uncomfortable to me, but I imagine this is probably related to the new SharePoint 2010 STS and I will be looking at this topic in more detail in future.

Thursday, September 2nd, 2010, 6:06 am   |   Security, SharePoint  |  RSS feed |  Respond  |  Trackback