New extended log file for SAP connector in On-Premises Data Gateway coming in September

I recently checked in the master branch for the next release of the On-Premises Data Gateway (should be coming in September) a new extended log file generator for the Logic Apps SAP connector. This generator will redirect previously difficult to access ETW events in a more approachable way to rotating log files added into the zipped Gateway log files. Let's unpack this mouthful...

First the underlying ETW events

You can try this with the existing August release of the On-Premises Data Gateway. To capture the events -assuming you are not writing a program to do it-, you should download PerfView so you may capture and view ETW traces (.etl files).

You will need elevated privileges to capture the trace. Do refrain from other activities but the OPDG once you have started the capture.

In PerfView (or PerfView64), start a capture this way:

You need to specify the additional provider for SAP explicitly, the string is

*Microsoft-LobAdapter

It is critical that you provide this otherwise the captured trace will only have general ETW events and not the SAP adapter events you are looking for. And this is where to provide the string in the UX:

Leave the other default settings except maybe changing the name or location of the Data File, and click “Start Collection”:

Once you have reproduced the issue or have collected sufficient data to analyze, click “Stop Collection”:

If you are working with someone else like Azure support engineers, at this point you can compress the .etl file to an archive and share it for analysis.

You may also if you would like view the content of the trace by clicking on Events under the new file entry in PerfView:

You then get to the view:

Multi-select the relevant Event Types and click “Update”:

Here is how to filter to just these events and the gateway process once the trace is captured:

Note that the LegacyTrace* events are rather verbose at the moment. Your feedback on which events are more and less useful will help us refine these events over time.

The new SAP log file

This extended logging is somewhat spurious and could affect performance negatively if always enabled. To turn it ON when you want to analyze an issue in depth, you need to update the Microsoft.PowerBI.DataMovement.Pipeline.GatewayCore.dll.config file which by default is in the C:\Program Files\On-premises data gateway folder. With the September release of the gateway these two new settings will appear in the file:

     <setting name="SapExtendedTracing" serializeAs="String">
      <value>False</value>
    </setting>
    <setting name="SapTracingLevel" serializeAs="String">
      <value>Informational</value>
    </setting>

Change False to True. You may also change the tracing level for SAP from its default of Informational to Error or Warning for fewer events, or even Verbose for a lot of events.
Save the file and restart the gateway service under the Service Settings, from the gateway configurator.

Reproduce your issue then export the gateway logs:

The generated file will include SAP logs organized by day and if one log file is full it will generate additional files with increasing number:

Here is a sample of what the log would contain:

 8/13/2018 10:44:18 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=Broker shortMessage=Received SendToLob Request.
8/13/2018 10:44:20 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=Broker shortMessage=Message action is https://Microsoft.LobServices.Sap/2007/03/Rfc/BAPI_BANK_GETDETAIL.
8/13/2018 10:44:20 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=WcfRuntime shortMessage=Entering CreateChannelFactory.
8/13/2018 10:44:20 AM EventName=ConnectionPoolNewPools Level=Informational ProcessID=14068 ThreadID=7956 connectionPoolsHash=46068471 connectionId=z9UnCXseDVmfmr+Fglxn3nzWAV2o3GmY2LrX2CNFd21Y0HnZNg23N6EQ89UKqmmq1nA56ZeN0rbPh6rBAUxcqw==
8/13/2018 10:44:20 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=https://Microsoft.Adapters.Sap/SapConnection/06954cbd-b6ec-4ffe-a7d2-5c336adef14d/ shortMessage=Calling LibRFCConnection::Open.
8/13/2018 10:44:21 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=https://Microsoft.Adapters.Sap/OutboundCall/TransmitWorkId/4aacf227-379a-476a-a0de-fdcd5ab727d2/ shortMessage=IOutboundHandler:Execute. Action=https://Microsoft.LobServices.Sap/2007/03/Rfc/BAPI_BANK_GETDETAIL
8/13/2018 10:44:21 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=https://Microsoft.Adapters.Sap/OperationMetadata/ shortMessage=https://Microsoft.LobServices.Sap/2007/03/Rfc/BAPI_BANK_GETDETAIL
8/13/2018 10:44:21 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=https://Microsoft.Adapters.Sap/OperationMetadata/ shortMessage=ResolveOperationMetadataUsingSdk. FuncName=BAPI_BANK_GETDETAIL
8/13/2018 10:44:21 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=https://Microsoft.Adapters.Sap/OperationMetadata/ shortMessage=INT_RFC/BAPI_BANK_GETDETAIL
8/13/2018 10:44:22 AM EventName=LegacyTraceInformational Level=Informational ProcessID=14068 ThreadID=7956 correlationCode=https://Microsoft.Adapters.Sap/TypeMetadata/ shortMessage=ResolveTypeMetadata : typeId=SAPTABLE/BAPI1011_ADDRESS

Remember to change the extended tracing back to false in the gateway core assembly configuration file, then restart the gateway service process again to ensure you don't negatively affect the performance of your gateway after the capture.