Tracing an E-Spot Request

Tracing logs is difficult as WebSphere is a multi-threaded environment. There could be dozens of active requests, all logging unrelated tasks. These other log entries are difficult to read the trace. Troubleshooting marketing-related issues is a challenging task. This document helps to simplify the troubleshooting information provided to understand the e-spot request and extract the e-spot-specific trace snippet for further analysis. The examples of REST and BOD-based marketing calls from the storefront are explained in this document.

The traces captured with Marketing MustGather are used for explanation. If you have not captured it, follow the instructions below to configure your environment for the required diagnostic information:
  1. Update the size of the trace files to 100MB and the number of historical trace files retained to 20.
  2. Enable the following trace strings:
    com.ibm.websphere.commerce.WC_MARKETING=all:
com.ibm.commerce.marketing.*=all:
com.ibm.commerce.foundation.logging.ServiceLogger=finest:
com.ibm.commerce.content.*=all:com.ibm.commerce.rest.marketing.handler.*=all:com.ibm.websphere.commerce.WC_USER=all:com.ibm.commerce.foundation.rest.*=all
  3. Browse the storefront page containing the e-marketing spot to trace the scenario.
  4. Call REST API directly in Postman or the browser.

E-Marketing spot request flow

The following image shows the flow of an e-spot request from start to finish.

To understand the request: GET (http://localhost/webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1)

E-marketing Spot is always a part of the storefront page, such as CategoryDispalay, ProductDisplay, and HomePage. In this scenario MyE-MarketingSpot is a part of the Computer Accessories; CategoryDisplay page. Search for parentId=0 or ServiceLogger > in the trace logs to find the start of the request. In this example, the following entry is requested for entry and exit:
  • Using parentId zero
    • 00000122 ServletReques 2   PerfLog <entry operation="Runtime Servlet : Request : /webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1" parameters="fetchFacets=[true]" id="6507127426286355781" parentId="0" startTime="3978755713792675" method="GET" queryString="fetchFacets=true" user="-1002" />
    • After the entry trace, search for 6507127426286355781 to find the exit. 6507127426286355781 is the identifier value of the request as highlighted in blue.
      Note: Performance Measurement Logger introduces the concept of id/parentId. Here, id is the unique identifier of the current operation, and parentId is the caller's identifier.
      00000122 ServletReques 2   PerfLog <entry operation="Runtime Servlet : Request : /webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1" parameters="fetchFacets=[true]" id="6507127426286355781" parentId="0" startTime="3978755713792675" method="GET" queryString="fetchFacets=true" user="-1002" />
[4/17/17 15:13:02:423 EDT] 00000122 ServletReques 1   PerfLog <exit operation="Runtime Servlet : Request : http://localhost/webapp/wcs/stores/servlet/CategoryDisplay" parameters="fetchFacets=[true] seoUrl=http://localhost/webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1" id="6507127426286355781" parentId="0" startTime="3978755713792675" stopTime="3978760255249759" duration="4541457084" durationMs="4541" resultSize="1000" cacheHit="false" cacheEnabled="false" successful="true" />
  • Using ServiceLogger
    • 00000122 ServiceLogger >   Web <http://localhost/webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1> <user:-1002> <method:GET> <fetchFacets=true>  ENTRY
    • After the entry trace, use threadId as part of the search keyword 00000122 ServiceLogger 1 Web to determine the exit.
      00000122 ServiceLogger >   Web <http://localhost/webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1> <user:-1002> <method:GET> <fetchFacets=true>  ENTRY
00000122 ServiceLogger 1   Web <request: http://localhost/webapp/wcs/stores/servlet/en/auroraesite/electronics/accessories-10028--1> <translated-to: http://localhost/webapp/wcs/stores/servlet/CategoryDisplay> <user:-1002> <elapsed:4546ms>  RETURN
    • Note the entry, exit, and the threadId. Use this filter parameter to extract the request. In the above example, 00000122 is the threadId. Use grep or Notepad++ tools to mark and extract lines with the threadId. For more details, refer to Troubleshooting 101: Extracting Error Requests from Trace.
    • After tracing the snippet containing the e-spot call, extract the actual e-spot internal/sub request. This is important for third-party integration. E-spot call is made by invoking rest call REST GET: /store/{storeId}/espot/{name} or the BOD: GetMarketingSpotDataTypeImpl web service directly. However, as shown in the flow diagram, you can extract the BOD request by looking at the storefront request, as the Rest request is around the BOD request.

Extracting E-Marketing spot REST requests and verifying response

If the request comes from a source other than storefront pages, you can use parentId=0 or ServiceLogger > to find the request.
  • Using parentId zero
    • 00000114 RestServerLog 2   PerfLog <entry operation="RESTCacheFilter : " parameters="DM_ReqCmd=[CategoryDisplay] categoryId=[10028]" id="6507127426286363631" parentId="0" startTime="4070527931052690" method="GET" queryString="categoryId=10028&amp;DM_ReqCmd=CategoryDisplay" user="-1002" />

00000114 RestServerLog 2   PerfLog <entry operation="REST : GET : com.ibm.commerce.rest.marketing.handler.ESpotDataHandler.findByName(String,String,String)" parameters="name=MyE-MarketingSpot storeId=10201 DM_ReqCmd=CategoryDisplay categoryId=10028" id="6507127426286363632" parentId="6507127426286363631" startTime="4070527936789452" />
[4/18/17 16:42:30:314 EDT] 00000114 RestServerLog 1   PerfLog <exit operation="REST : GET : com.ibm.commerce.rest.marketing.handler.ESpotDataHandler.findByName(String,String,String)" parameters="name=MyE-MarketingSpot storeId=10201 DM_ReqCmd=CategoryDisplay categoryId=10028" id="6507127426286363632" parentId="6507127426286363631" startTime="4070527936789452" stopTime="4070528155038420" duration="218248968" durationMs="218" resultSize="427" cacheHit="false" cacheEnabled="false" successful="true" />

00000114 RestServerLog 1   PerfLog <exit operation="REST : BOD Mapping" parameters="dataMap=-226097492" id="6507127426286363649" parentId="6507127426286363631" startTime="4070528156332160" stopTime="4070528275842879" duration="119510719" durationMs="119" resultSize="1000" cacheHit="false" cacheEnabled="false" successful="true" />
[4/18/17 16:42:30:439 EDT] 00000114 RestServerLog 1   PerfLog <exit operation="RESTCacheFilter : " parameters="DM_ReqCmd=[CategoryDisplay] categoryId=[10028]" id="6507127426286363631" parentId="0" startTime="4070527931052690" stopTime="4070528281856772" duration="350804082" durationMs="350" resultSize="1000" cacheHit="false" cacheEnabled="false" successful="true" />

    • 00000114 ServiceLogger >   REST <http://localhost/wcs/resources/store/10201/espot/MyE-MarketingSpot> <user:-1002> <method:GET> <categoryId=10028&DM_ReqCmd=CategoryDisplay>  ENTRY
00000114 ServiceLogger 1   REST <http://localhost/wcs/resources/store/10201/espot/MyE-MarketingSpot> <user:-1002> <elapsed:344ms>  RETURN
    • Search for com.ibm.commerce.foundation.rest.providers.AbstractEntityProvider formatResponseUsingBODToMapConfig(Map) RETURN to find the response.
      00000114 AbstractEntit < com.ibm.commerce.foundation.rest.providers.AbstractEntityProvider formatResponseUsingBODToMapConfig(Map) RETURN {resourceId=http://localhost:80/wcs/resources/store/10201/espot/MyE-MarketingSpot?categoryId=10028&DM_ReqCmd=CategoryDisplay, MarketingSpotData=[{marketingSpotIdentifier=11501, previewReport=[SpotFound|11501|10201|MARKETING|MyE-MarketingSpot|true, ScheduledActivity|10802|10201|0| | |RecommendContentForMen's, ScheduledActivity|10801|10201|0| | |MyCDPActivity, EvaluateActivitiesBegin, EvaluateActivity|10802|10201|0| | |RecommendContentForMen's, Target|currentCustomerBehaviorCategoryBrowsing|11408|11408, TargetUserBehavior|10002|0|false, TargetFalse, EvaluateActivityEnd, EvaluateActivity|10801|10201|0| | |MyCDPActivity, NotEnoughContent, Target|currentCustomerBehaviorCategoryBrowsing|11404|11404, TargetUserBehavior|10028|1|true, TargetTrue, Action|displayContent|11403|11403, DataReturnedFromElement|MarketingContent|10207|ContentForAccessoriesPage|1, EvaluateActivityEnd, EvaluateActivitiesEnd, ReturnRecommendation|MarketingContent|10207|10801|ContentForAccessoriesPage|ContentForAccessoriesPage|1, StaticMarketingSpotBehavior], eSpotName=MyE-MarketingSpot, behavior=0, nextTimeLimit=-1, baseMarketingSpotActivityData=[{activityIdentifierID=10801, contentFormatId=1, contentMimeType=image, attachementStoreId=10101, baseMarketingSpotDataType=MarketingContent, AttachmentDescription=[{}], contentId=10207, attachementId=1610, contentFormatName=File, attachmentReferenceDescription=[{attachmentShortDescription=Save on Printers, attachmentName=Save on Printers, attachmentLanguage=-1}], attachmentImage=images/attachments/usages/unassign_icon.jpg, attachmentDisplaySequence=0.0, activityFormat=web, MarketingContentDescription=[{}], attachmentAsset=[{attachmentAssetStoreId=10101, attachmentAssetLanguage=[-1], attachmentAssetPath=images/advertisements/en_US/0709B_EES_Printers_001.jpg, attachmentAssetId=2147, attachmentAssetDirectoryPath=images/advertisements/en_US, attachmentAssetRootDirectory=AuroraStorefrontAssetStore, attachmentLocalAsset=true, attachmentAssetMimeType=image/jpeg}], attachmentReferenceId=1610, marketingContentDescription=[{marketingText=Save on Printers, language=-1}], baseMarketingSpotActivityID=10207, attachmentDescription=[{attachmentShortDescription=Save on Printers 50% off with any desktop purchase, attachmentName=Save on Printers, attachmentLanguage=-1}], attachementExternalId=Desktops_Atct_2, properties=[{baseMarketingValue=Recommend content to a customer that satisfies the chosen target conditions., baseMarketingKey=mktActivityDescription}], attachmentUsageName=NOUSAGE, contentName=ContentForAccessoriesPage, AttachmentReferenceDescription=[{}], activityIdentifierName=MyCDPActivity, activityPriority=0, contentStoreId=10101, baseMarketingSpotActivityName=ContentForAccessoriesPage, contentClickAction=None}]}], resourceName=espot}

Extracting E-Marketing Spot BOD requests and verifying response

To find the BOD request entry point, search for <_mkt:GetMarketingSpotData and locate the your_epot_name highlighted in blue.
  • Following is the sample BOD request: 
    00000122 BusinessObjec > com.ibm.commerce.foundation.server.command.bod.BusinessObjectDocumentProcessor processBusinessObjectDocument(BusinessObjectDocumentType, String) ENTRY <?xml version="1.0" encoding="UTF-8"?>
<_mkt:GetMarketingSpotData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:_mkt="http://www.ibm.com/xmlns/prod/commerce/9/marketing" xmlns:_wcf="http://www.ibm.com/xmlns/prod/commerce/9/foundation" xmlns:oa="http://www.openapplications.org/oagis/9" releaseID="9.0" versionID="7.0.0.8">
  <oa:ApplicationArea xsi:type="_wcf:ApplicationAreaType">
    <oa:CreationDateTime>2017-04-17T19:13:01.923Z</oa:CreationDateTime>
    <oa:BODID>e00f5ee0-23a1-11e7-aec1-824958f5022a</oa:BODID>
    <_wcf:BusinessContext>
      <_wcf:ContextData name="locale">en_US</_wcf:ContextData>
      <_wcf:ContextData name="catalogId">10052</_wcf:ContextData>
      <_wcf:ContextData name="langId">-1</_wcf:ContextData>
      <_wcf:ContextData name="storeId">10201</_wcf:ContextData>
      <_wcf:ContextData name="currency">USD</_wcf:ContextData>
      <_wcf:ContextData name="contentPersonalizationId">1447870211984-1</_wcf:ContextData>
    </_wcf:BusinessContext>
  </oa:ApplicationArea>
  <_mkt:DataArea>
    <oa:Get>
      <oa:Expression expressionLanguage="_wcf:XPath">{_wcf.ap=IBM_Store_All...}/MarketingSpotData[MarketingSpotIdentifier[ExternalIdentifier[(Name=&quot;MyE-MarketingSpot&quot;)]]]</oa:Expression>
    </oa:Get>
  </_mkt:DataArea>
</_mkt:GetMarketingSpotData> com.ibm.commerce.marketing
  • You have the threadId available to pull this thread from the original trace file.
  • Using the BOD ID from the request, search for the response. e00f5ee0-23a1-11e7-aec1-824958f5022a is the BOD ID in this case. If you cannot locate the BOD ID, search for mkt:ShowMarketingSpotData. Following is the sample BOD response: 
    00000122 BusinessObjec < com.ibm.commerce.foundation.server.command.bod.BusinessObjectDocumentProcessor processBusinessObjectDocument(BusinessObjectDocumentType, String) RETURN <?xml version="1.0" encoding="UTF-8"?>
<_mkt:ShowMarketingSpotData xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:_mkt="http://www.ibm.com/xmlns/prod/commerce/9/marketing" xmlns:_wcf="http://www.ibm.com/xmlns/prod/commerce/9/foundation" xmlns:oa="http://www.openapplications.org/oagis/9" releaseID="9.0">
  <oa:ApplicationArea xsi:type="_wcf:ApplicationAreaType">
    <oa:CreationDateTime>2017-04-17T19:13:02.142Z</oa:CreationDateTime>
    <oa:BODID>e030c990-23a1-11e7-aec1-824958f5022a</oa:BODID>
  </oa:ApplicationArea>
  <_mkt:DataArea>
    <oa:Show>
      <oa:OriginalApplicationArea>
        <oa:CreationDateTime>2017-04-17T19:13:01.923Z</oa:CreationDateTime>
        <oa:BODID>e00f5ee0-23a1-11e7-aec1-824958f5022a</oa:BODID>
      </oa:OriginalApplicationArea>
    </oa:Show>
    <_mkt:MarketingSpotData>
      <_mkt:MarketingSpotIdentifier>
        <_wcf:UniqueID>11501</_wcf:UniqueID>
        <_wcf:ExternalIdentifier>
          <_wcf:Name>MyE-MarketingSpot</_wcf:Name>
        </_wcf:ExternalIdentifier>
      </_mkt:MarketingSpotIdentifier>
      <_mkt:BaseMarketingSpotActivityData xsi:type="_mkt:MarketingSpotActivityMarketingContentDataType">
        <_mkt:Name>ContentForAccessoriesPage</_mkt:Name>
        <_mkt:DataType>MarketingContent</_mkt:DataType>
        <_mkt:UniqueID>10207</_mkt:UniqueID>
        <_mkt:ActivityIdentifier>
          <_wcf:UniqueID>10801</_wcf:UniqueID>
          <_wcf:ExternalIdentifier>
            <_wcf:Name>MyCDPActivity</_wcf:Name>
          </_wcf:ExternalIdentifier>
        </_mkt:ActivityIdentifier>
        <_mkt:ActivityFormat>web</_mkt:ActivityFormat>
        <_mkt:ActivityPriority>0</_mkt:ActivityPriority>
        <_mkt:Properties name="mktActivityDescription">Recommend content to a customer that satisfies the chosen target conditions.</_mkt:Properties>
        <_mkt:MarketingContent>
          <_mkt:MarketingContentIdentifier>
            <_wcf:UniqueID>10207</_wcf:UniqueID>
            <_wcf:ExternalIdentifier>
              <_wcf:Name>ContentForAccessoriesPage</_wcf:Name>
              <_wcf:StoreIdentifier>
                <_wcf:UniqueID>10101</_wcf:UniqueID>
              </_wcf:StoreIdentifier>
            </_wcf:ExternalIdentifier>
          </_mkt:MarketingContentIdentifier>
          <_mkt:MarketingContentDescription language="-1">
            <_mkt:MarketingText>Save on Printers</_mkt:MarketingText>
            <_wcf:UserData/>
          </_mkt:MarketingContentDescription>
          <_mkt:MarketingContentFormat>
            <_mkt:UniqueID>1</_mkt:UniqueID>
            <_mkt:Name>File</_mkt:Name>
          </_mkt:MarketingContentFormat>
          <_mkt:ClickAction>None</_mkt:ClickAction>
          <_mkt:MimeType>image</_mkt:MimeType>
          <_mkt:Attachment>
            <_wcf:AttachmentReferenceIdentifier>
              <_wcf:UniqueID>1610</_wcf:UniqueID>
            </_wcf:AttachmentReferenceIdentifier>
            <_wcf:AttachmentIdentifier>
              <_wcf:UniqueID>1610</_wcf:UniqueID>
              <_wcf:ExternalIdentifier>
                <_wcf:Identifier>Desktops_Atct_2</_wcf:Identifier>
                <_wcf:StoreIdentifier>
                  <_wcf:UniqueID>10101</_wcf:UniqueID>
                </_wcf:StoreIdentifier>
              </_wcf:ExternalIdentifier>
            </_wcf:AttachmentIdentifier>
            <_wcf:AttachmentAsset localAsset="true">
              <_wcf:AttachmentAssetIdentifier>
                <_wcf:UniqueID>2147</_wcf:UniqueID>
              </_wcf:AttachmentAssetIdentifier>
              <_wcf:StoreIdentifier>
                <_wcf:UniqueID>10101</_wcf:UniqueID>
              </_wcf:StoreIdentifier>
              <_wcf:AttachmentAssetPath>images/advertisements/en_US/0709B_EES_Printers_001.jpg</_wcf:AttachmentAssetPath>
              <_wcf:RootDirectory>AuroraStorefrontAssetStore</_wcf:RootDirectory>
              <_wcf:DirectoryPath>images/advertisements/en_US</_wcf:DirectoryPath>
              <_wcf:MimeType>image/jpeg</_wcf:MimeType>
              <_wcf:language>-1</_wcf:language>
            </_wcf:AttachmentAsset>
            <_wcf:AttachmentUsage>
              <_wcf:UsageName>NOUSAGE</_wcf:UsageName>
              <_wcf:Image>images/attachments/usages/unassign_icon.jpg</_wcf:Image>
            </_wcf:AttachmentUsage>
            <_wcf:DisplaySequence>0.0</_wcf:DisplaySequence>
            <_wcf:AttachmentDescription language="-1">
              <_wcf:Name>Save on Printers</_wcf:Name>
              <_wcf:ShortDescription>Save on Printers 50% off with any desktop purchase</_wcf:ShortDescription>
            </_wcf:AttachmentDescription>
            <_wcf:AttachmentReferenceDescription language="-1">
              <_wcf:Name>Save on Printers</_wcf:Name>
              <_wcf:ShortDescription>Save on Printers</_wcf:ShortDescription>
            </_wcf:AttachmentReferenceDescription>
            <_wcf:UserData/>
          </_mkt:Attachment>
          <_mkt:MarketingSpotBehavior>0</_mkt:MarketingSpotBehavior>
          <_mkt:UIDisplayable>1</_mkt:UIDisplayable>
          <_mkt:ManagingTool>0</_mkt:ManagingTool>
          <_mkt:OvrMktLimit>1</_mkt:OvrMktLimit>
          <_wcf:UserData/>
        </_mkt:MarketingContent>
      </_mkt:BaseMarketingSpotActivityData>
      <_mkt:PreviewReport>...</_mkt:PreviewReport>
      <_mkt:Behavior>0</_mkt:Behavior>
      <_mkt:NextTimeLimit>-1</_mkt:NextTimeLimit>
    </_mkt:MarketingSpotData>
  </_mkt:DataArea>
</_mkt:ShowMarketingSpotData>

BOD response shows the actual Marketing content scheduled to display in the e-spot.