BCS is a cool framework to bring external data to Office Applications on the client. But due to various reasons like misconfigured BDC models/ Advanced Code-Based Solutions/ Intermediate Declarative Solutions or External System’s business logic, the expected data might not show up on the client. Most of the troubleshooting can be done by looking at the event logs. If the information in event logs is not enough to troubleshoot the issue, then the next best thing to do is start BCS logging on the client. Client logs provide rich and descriptive information, which is really helpful in debugging complex issues. Check out “Diagnostic logging in Business Connectivity Services overview (SharePoint Server 2010)” for information on how to enable BCS logging on the client.

There are 2 levels of logging from BCS on the client – Events logs and Trace logs. All the logging from BCS can be found in Trace logs. Whereas only a subset of the Trace logs are logged under Event Logs and they comprise of the important BCS actions which will help the user in figuring out the state of the BCS Solutions on the client i.e. information regarding the Solution download, Install & Uninstall, solution activation, Services startup & shutdown, Solution Registration and Errors. Trace Logs are more descriptive than Event logs and contains the exception stack trace of errors if any.

Here are the different Categories under which most of the BCS actions are logged:

  • Deployment - The logs under this category help the user to figure out the important deployment actions that happen when offlining an External list from SharePoint or while doing a standalone install of Declarative/Code-Based solutions. All the actions involved with Solution download, Activation, package verification and Uninstallation get logged under this category.
     
  • Runtime – BCS on the client has both managed and unmanaged assemblies. All the offlining calls from the managed components of BCS like CRUD operations, Subscription Refresh, Picker resolution, Rich List part actions from office applications, etc…fall under this category.
     
  • Wrapped PST – The logs under this category are from the unmanaged BCS Add-in running in outlook.
     
  • Business Data – All the BDC Runtime calls involved in executing against the External System are found under this category. These calls include preparation of the request, invoking of BDC stereotype methods against the External System and runtime processing of the results.
     
    By default the values of Input and Return Parameters are not dumped in the logs due to privacy issues. For debugging purpose, you can add the “LogParameterValues” property at the Method Parameter level in metadata to log the parameter values sent and received from the External System for every call.
     
    <Property Name="LogParameterValues" Type="System.Boolean">true</Property>
     
  • Cross Sync – Actions involving data Sync between Offline Cache (i.e. SQL CE database) and Outlook Wrapped PST are logged under this category.

Here are some sample logs which outline the important actions logged as part of the E2E life cycle of a WCF based External Content Type (ECT) off-lined to outlook:

  • Solution Install/ List Offlining logs:
    • Runtime - BCSSync started with PID: 4020, integrity level: 8192 and command line: ""C:\Program Files (x86)\Microsoft Office\Office14\BCSSync.exe" -Embedding".
    • Runtime - Cache database file not found, creating new database file.
    • Runtime - BCS directory encrypted successfully.
    • Runtime - Service Microsoft.Office.BusinessApplications.Runtime.DiskIOThrottler was started.
    •  Runtime - Service Microsoft.Office.BusinessApplications.Runtime.ProxyRegistrationService was started.
    • Runtime - Service Microsoft.Office.BusinessApplications.Runtime.Deployment.ActivatorService was started.
    • Runtime - Service Microsoft.Office.BusinessApplications.Runtime.Deployment.VerifierService was started.
    • Runtime - Service Microsoft.Office.BusinessData.Offlining.SynchronizationManager was started.
    • Runtime - Service Microsoft.Office.BusinessApplications.Runtime.Deployment.UpdateService was started.
    • Deployment- Url:file:///C:/Users/<UserName>/Desktop/Output/ContosoSalesManager.vsto Solution Name:ContosoSalesManager Solution Id:ContosoSalesManager Solution Version:1.0.0.0 Message:Solution download completed successfully.
    • Runtime - Starting verification process for model C:\Users\<UserName>\AppData\Local\Microsoft\BCS\cont..ager_ae3bf1f59b9d1e0f_0001.0000_0c401f2e52834d92\metadata.xml.
    • Business Data - Generating WCF Proxy Assembly in a parallel App Domain
    • Business Data - Trying to discover service document at 'http://<Server>:8181/webservice.asmx?wsdl'
    • Business Data - Compiling proxy was success, will retrieve the assembly.
    • Runtime - Set to Verification Complete for the solution ContosoSalesManager.
    • Runtime - BCSSync with PID: 4020 was requested to spawn a new instance and shutdown.
    • Runtime - BCSSync started with PID: 4068, integrity level: 8192 and command line: ""C:\Program Files (x86)\Microsoft Office\Office14\BCSSync.exe" /Restart /Activation /RestartApps".
    • Runtime - Starting deployment of subscriptions for solution ContosoSalesManager.
    • Runtime - Verifying subscriptions.
    • Runtime - Generating subscriptions in cache

  • Wrapped PST Data Sync logs:
    • Runtime - Notification is being sent
    • Cross Sync - Receiving Cache Changed (Direct) Event
    • Runtime - 17 direct change notifications processed at 10:42:11.0782575
    • Cross Sync - BCS/PST synchronization: Changing 1 Outlook items with information from item 'e83807ab-4748-4a36-ba32-ab62a9aafd78' IsDeleted=False .
    • Cross Sync - BCS/PST synchronization: Folder 'ContosoCustomerFolderID' is scheduled to be synchronized.
    • Cross Sync - BCS/PST synchronization: Folder state changed to 'vfId=ContosoCustomerFolderID, status=resync, token=8973, exception=null'.
    • Cross Sync - Copied Syncstamp 2010-04-28 17:45:50Z for folder ContosoCustomerFolderID ito XS_FOLDER record
    • Cross Sync - BCS/PST synchronization: Completed synchronization of folders: ContosoCustomerFolderID,
    • Cross Sync - Syncstamp for folder ContosoCustomerFolderID is set to 2010-04-28 17:45:51Z

 

 

 

  • LOB communication logs:
    • Runtime - Data change detected; restarting synchronization loop.
    • Runtime - Refreshing subscription AWWSExampleCustomerSubscription with results of query AWWSExampleCustomerQuery
    • Business Data - Opening connection to SystemInstance: http://<Server>:8080/webservice.asmx?wsdl
    • Business Data - Creating ClientBase object with type : BCSServiceProxy.WebServiceSoapClient
    • Business Data - Using WCF authentication mode : PassThrough
    • Business Data - Executing MethodInstance '2147484216' representing Web Method 'GetCustomers'
    • Business Data - Closing connection to SystemInstance: http://<Server>:8080/webservice.asmx?wsdl
    • Business Data - Exiting out of method to enumerator executor

       

Most of the BCS logs are pretty descriptive and intuitive. Hopefully this blog post can act as a starting point for debugging issues while developing BCS solutions.

- Sreekanth Lingannapeta