New Posts New Posts RSS Feed: WCF Failure
  FAQ FAQ  Forum Search   Calendar   Register Register  Login Login

WCF Failure
 Post Reply Post Reply
Author
  Share Topic Share Topic  Topic Search Topic Search  Topic Options Topic Options
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Topic: WCF Failure
    Posted: 17-Sep-2009 at 6:47pm
In both 5.1 and 5.2 I am experiencing this strange behavior. Somehow, the WCF service (EntityService.svc) is creating a malformed message that is killing the conversation and totally farking up the client.

I turned on the Web Service Tracing to see what was going on and was able to discover this. There doesn't seem to be anything in the data that could cause this. Any ideas? Thanks!

Here is the message:


The trace record is not correct and cannot be loaded. This might be caused by one of the following reasons:
     1. The source file has been changed, which affected the location of the loading trace.
     2. There is no valid ending tag in the trace record.
     3. The trace file goes wrong.

Trace record file offset:     768109
Error trace record:

<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
<System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
<EventID>0</EventID>
<Type>3</Type>
<SubType Name="Information">0</SubType>
<Level>8</Level>
<TimeCreated SystemTime="2009-09-18T01:12:17.7155770Z" />
<Source Name="System.ServiceModel.MessageLogging" />
<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
<Execution ProcessName="WebDev.WebServer" ProcessID="6956" ThreadID="6" />
<Channel />
<Computer>JDJQXF1-WXP</Computer>
</System>
<ApplicationData>
<TraceData>
<DataItem>
<MessageLogTraceRecord Time="2009-09-17T21:12:17.7155770-04:00" Source="TransportSend" Type="System.ServiceModel.Dispatcher.OperationFormatter+OperationFormatterMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">
<s:Envelope xmlns:s="http://www.w3.org/2003/05/soap-envelope" xmlns:a="http://www.w3.org/2005/08/addressing">
<s:Header>
<a:Action s:mustUnderstand="1">http://ideablade.com/EntityModel/EntityServer/FetchResponse</a:Action>
<a:RelatesTo>urn:uuid:3f319951-26ad-42e2-a275-86e0c0345f48</a:RelatesTo>
</s:Header>
<s:Body>
<FetchResponse xmlns="http://ideablade.com/EntityModel">
<FetchResult z:Id="1" xmlns:b="http://schemas.datacontract.org/2004/07/IdeaBlade.EntityModel" xmlns:i="http://www.w3.org/2001/XMLSchema-instance" xmlns:z="http://schemas.microsoft.com/2003/10/Serialization/">
<b:QueryInfo z:Id="2">
<b:QueryClassification>Mergeable QueryCacheable Ghostable</b:QueryClassification>
</b:QueryInfo>
<b:Results z:Id="3" z:Size="2">
<b:DataQueryResult z:Id="4">
<b:DataBlock z:Id="5" i:type="b:EntitiesDataBlock">
<b:DeconstructedEntities z:Id="6" z:Size="12">
<b:DeconstructedEntity z:Id="7">
<b:DataArray z:Id="8" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="9" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
<c:anyType z:Id="10" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">IF FOM</c:anyType>
<c:anyType z:Id="11" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">INSIDE FERC FIRST OF THE MONTH</c:anyType>
<c:anyType z:Id="12" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">M</c:anyType>
<c:anyType z:Id="13" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="14" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">JESSEJA</c:anyType>
<c:anyType z:Id="15" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2001-10-15T11:37:55</c:anyType>
<c:anyType z:Id="16" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="17">
<b:DataArray z:Id="18" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="19" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">2</c:anyType>
<c:anyType z:Id="20" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NGW-MNTH</c:anyType>
<c:anyType z:Id="21" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NATURAL GAS WEEK - MONTHLY</c:anyType>
<c:anyType z:Id="22" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">M</c:anyType>
<c:anyType z:Id="23" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="24" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">HAMMOSA</c:anyType>
<c:anyType z:Id="25" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2001-10-16T15:02:32</c:anyType>
<c:anyType z:Id="26" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="27">
<b:DataArray z:Id="28" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="29" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">3</c:anyType>
<c:anyType z:Id="30" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DAILY</c:anyType>
<c:anyType z:Id="31" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">GAS DAILY AVERAGE PRICE</c:anyType>
<c:anyType z:Id="32" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">D</c:anyType>
<c:anyType z:Id="33" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="34" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">HAMMOSA</c:anyType>
<c:anyType z:Id="35" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2001-10-16T15:02:04</c:anyType>
<c:anyType z:Id="36" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="37">
<b:DataArray z:Id="38" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="39" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">4</c:anyType>
<c:anyType z:Id="40" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NGW-WEEK</c:anyType>
<c:anyType z:Id="41" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NATURAL GAS WEEK - WEEKLY</c:anyType>
<c:anyType z:Id="42" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">W</c:anyType>
<c:anyType z:Id="43" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="44" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">HAMMOSA</c:anyType>
<c:anyType z:Id="45" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2001-10-16T15:02:48</c:anyType>
<c:anyType z:Id="46" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="47">
<b:DataArray z:Id="48" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="49" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">6</c:anyType>
<c:anyType z:Id="50" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DLYAVGZ1</c:anyType>
<c:anyType z:Id="51" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DAILY AVERAGE PRICE 500/800 LEG</c:anyType>
<c:anyType z:Id="52" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">D</c:anyType>
<c:anyType z:Id="53" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="54" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">MOINILE</c:anyType>
<c:anyType z:Id="55" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2002-02-08T14:08:00</c:anyType>
<c:anyType z:Id="56" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="57">
<b:DataArray z:Id="58" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="59" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">7</c:anyType>
<c:anyType z:Id="60" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DLYLOWZ1</c:anyType>
<c:anyType z:Id="61" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DAILY LOWEST PRICE 500/800 LEG</c:anyType>
<c:anyType z:Id="62" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">D</c:anyType>
<c:anyType z:Id="63" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="64" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">MOINILE</c:anyType>
<c:anyType z:Id="65" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2002-02-08T14:08:00</c:anyType>
<c:anyType z:Id="66" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="67">
<b:DataArray z:Id="68" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="69" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">8</c:anyType>
<c:anyType z:Id="70" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DLYHIZ1</c:anyType>
<c:anyType z:Id="71" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DAILY HIGHEST PRICE 500/800 LEG</c:anyType>
<c:anyType z:Id="72" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">D</c:anyType>
<c:anyType z:Id="73" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="74" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">MOINILE</c:anyType>
<c:anyType z:Id="75" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2002-02-08T14:08:00</c:anyType>
<c:anyType z:Id="76" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="77">
<b:DataArray z:Id="78" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="79" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">9</c:anyType>
<c:anyType z:Id="80" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NYMEX</c:anyType>
<c:anyType z:Id="81" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DAILY NYMEX SETTLEMENT</c:anyType>
<c:anyType z:Id="82" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">D</c:anyType>
<c:anyType z:Id="83" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="84" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">SEARCSC</c:anyType>
<c:anyType z:Id="85" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2004-03-31T13:28:04</c:anyType>
<c:anyType z:Id="86" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="87">
<b:DataArray z:Id="88" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="89" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">10</c:anyType>
<c:anyType z:Id="90" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">LDS</c:anyType>
<c:anyType z:Id="91" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">MONTHLY NYMEX SETTLEMENT</c:anyType>
<c:anyType z:Id="92" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">M</c:anyType>
<c:anyType z:Id="93" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="94" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">SEARCSC</c:anyType>
<c:anyType z:Id="95" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2004-03-31T13:35:50</c:anyType>
<c:anyType z:Id="96" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="97">
<b:DataArray z:Id="98" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="99" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">11</c:anyType>
<c:anyType z:Id="100" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">DLVDGDA</c:anyType>
<c:anyType z:Id="101" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">GDA DELIVERED PRICE</c:anyType>
<c:anyType z:Id="102" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">D</c:anyType>
<c:anyType z:Id="103" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="104" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">SEARCSC</c:anyType>
<c:anyType z:Id="105" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2004-11-19T13:21:55</c:anyType>
<c:anyType z:Id="106" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="107">
<b:DataArray z:Id="108" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="109" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">61</c:anyType>
<c:anyType z:Id="110" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">GDPG</c:anyType>
<c:anyType z:Id="111" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">GAS DAILY PRICE GUIDE</c:anyType>
<c:anyType z:Id="112" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">M</c:anyType>
<c:anyType z:Id="113" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="114" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">SEARCSC</c:anyType>
<c:anyType z:Id="115" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2006-08-09T16:41:25</c:anyType>
<c:anyType z:Id="116" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
<b:DeconstructedEntity z:Id="117">
<b:DataArray z:Id="118" z:Size="8" xmlns:c="http://schemas.microsoft.com/2003/10/Serialization/Arrays">
<c:anyType z:Id="119" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">81</c:anyType>
<c:anyType z:Id="120" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NGI FOM</c:anyType>
<c:anyType z:Id="121" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">NAT GAS INTELLIGENCE - MONTHLY</c:anyType>
<c:anyType z:Id="122" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">M</c:anyType>
<c:anyType z:Id="123" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">Y</c:anyType>
<c:anyType z:Id="124" i:type="d:string" xmlns:d="http://www.w3.org/2001/XMLSchema">SEARCSC</c:anyType>
<c:anyType z:Id="125" i:type="d:dateTime" xmlns:d="http://www.w3.org/2001/XMLSchema">2006-10-31T16:36:45</c:anyType>
<c:anyType z:Id="126" i:type="d:long" xmlns:d="http://www.w3.org/2001/XMLSchema">1</c:anyType>
</b:DataArray>
<b:RelatedLinkages i:nil="true"></b:RelatedLinkages>
</b:DeconstructedEntity>
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 18-Sep-2009 at 8:16am
Those FetchResponses are ugly, aren't they? 
 
My best guess is that it's choking on the data during serialization.  Do you have the query which resulted in the failure, and the expected resuts?  If you can send me your EDMX and the query I can take a look, although I might need your DB too if nothing stands out.  Send to kimj@ ...
Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 18-Sep-2009 at 10:29am
It doesn't seem to matter which query. I've removed the one that this fetched and it is still failing. Might it be message size somewhere?
The failure happens inside a set of tasks in an AsyncParallelTask.

I'm trying to put something together that I can send you.

Is it possible that one of the queries in the set is causing the service to fail but the error shows up in a message for a different query?


Edited by skingaby - 18-Sep-2009 at 10:50am
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 18-Sep-2009 at 10:52am
What is the error received on the client?  And is an error written to the server's debug log?  How many concurrent parallel actions does your task contain? 
 
The default message size used by DevForce is actually 2G, the maximum allowed, unless you've modified the bindings in either the web.config or added a ServiceReferences.ClientConfig.  There's also the
   <httpRuntime maxRequestLength="sizeinKB"/>
element you can set in the web.config if you are sending large amounts of data. 
 
Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 18-Sep-2009 at 1:57pm
No error on the client. The UI seems fine until the very next Async action and then it goes off into limbo and never returns.
The debug.log does not show anything either.
There are 10 queries in the AsyncParallelTask.
I have removed the ServiceReferences.ClientConfig to eliminate that as a possibility.
The web.config is showing the Service Binding as:
      <customBinding>
        <binding name="customBinaryBinding" receiveTimeout="00:20:00" sendTimeout="00:20:00" openTimeout="00:20:00" closeTimeout="00:20:00">
          <binaryMessageEncoding>
            <readerQuotas maxDepth="2147483647" maxStringContentLength="2147483647" maxArrayLength="2147483647" />
          </binaryMessageEncoding>
          <httpTransport maxReceivedMessageSize="2147483647" maxBufferSize="2147483647" maxBufferPoolSize="2147483647" />
        </binding>
      </customBinding>

I am not (to my knowledge) pulling tons of data. Most of the queries are 10-200 rows. One has 2000 rows.
Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 18-Sep-2009 at 2:00pm
I have configured the new Client side logging with a TraceViewer window and with an InvokeServerMethodAsync to post the client-side messages to the server log. (That is a VERY NICE addition in this version! Thanks to all concerned!) I am hoping I can spam my code with DebugFns.WriteLine and see where something is breaking.
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 21-Sep-2009 at 11:49am

The number of queries in the parallel task - 10 - is an interesting number.   The default throttle for MaxConcurrentSessions is 10, but DevForce always injects a ServiceThrottlingBehavior, if not already present, with the max values set to 1000.   If you're using a custom throttle, maybe check this.

When using the AsyncParallelTask DevForce will fire off a new thread, and a new service request, for each action in the task.  So with 10 actions you potentially have 10 threads, and 10 requests outstanding to the service at one time.  DevForce also opens a new database connection to serve each request, so you also may have 10 open database connections too.  My new guess is that something - WCF, the firewall, the database - is complaining about a possible DoS attack.
 
A few things to look at in your code -
  - Make sure that you've called LoginAsync (or ConnectAsync and LoginAsync) prior to executing the AsyncParallelTask.  If you haven't, every action in the task will first try to connect/login before running the query, so there may be more service activity than expected. 
 - If you don't already have one, add an exception handler to the AsyncParallelTask to try to trap errors.
 - Maybe add an EntityServerError handler on the client.  This event should always fire for any errors and may help if the error is otherwise being handled somewhere else.
Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 22-Sep-2009 at 9:56am
Please, stop the ride I want to get off. My head is spinning and I am thoroughly befuddled now because the timing of all these async calls is anything but sequential. :)

Nevertheless, I have implemented logging so the DebugFns and TraceFns are displayed in a Silverlight popup window over top of my page and are also being sent (via InvokeServerMethodAsync) to the server to be logged there too.
I've also added event handlers for all of the query events in Ward's post. So, I am watching the send/receive chat between client and server. I also have web service diagnostics turned on in web.config.
The symptoms that I am seeing are:
1) The client side log window shows a lot of activity and everything appears to be fine.
2) The server side log shows a lot of back and forth, logging both server and client activity properly and then just stops.
3) The EntityService.svclog is truncated in the middle of a message and is no longer valid XML. The exact position of the truncation varies so I cannot see a pattern in what/why/when this failure happens.
4) After the page has loaded, the grid is populated and the loads are completed, the next request to the server hangs and never returns. I am not sure what is happening at this point because the logging has already stopped keeping track of things (See Symptom 2 above).

In response to your comments:
- I have a single PersistenceService (modelled after the Prism MEV Explorer example from 2 versions ago). I am instantiating the Server side EntityManager in global.asax and the client side EntityManager in the module's PersistenceService.Startup. I then Initialize the EntityManager, which includes logging it in. This is all done long before the AsyncParallelTask.
I've added an ExceptionHandler to the AsyncParallelTask, and it is never called.
The EntityServerError handler is never called.

Is there something timing out? Is there something that would stop the server side service from responding. Is there a risk that all this logging is breaking something? (I doubt it because the problem pre-exists the logging -- that is why I started logging everything I could.)

Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 22-Sep-2009 at 10:02am
This is interesting. The UI guy added a loop that adds a PropertyChanged event handler to each and every object in the object graph. Commenting out the line that enters that loop had this effect:
1) The grid loads, and the loading processing all happens, and finishes.
2) About a minute or two later, seemingly spontaneously, a ton of timeout messages are logged on the client, and then a bunch of queries are fired off. I have NO idea what triggers this second round of events, but they are logged in the Silverlight side. (I am emailing you the log.xml)
3) A couple of times, we have seen the ViewModel.Start method called more than once. Hunh? Does the ViewModel go out of scope somewhere?

I know these are advanced questions kimj, but I have been trying to crack this nut for a week now and I sure do appreciate your help.

Edited by skingaby - 22-Sep-2009 at 10:03am
Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 22-Sep-2009 at 11:14am
Another interesting tidbit. We have two kinds of Deals, Buy and Sell. Sell deals have a Cost, Buy deals do not. But we have one Entity: Deal, for both types. When populating the grid, we load EntityManager.Deals.Include("DealCost"). This is a 1 to 0..1 relationship. However, the bound grid was causing all the Buy deals to fire an Async request to get the DealCost. I added this interceptor:
        [BeforeGet(Deal.EntityPropertyNames.DealCost)]
        public void BeforeGetDealCost(IPropertyInterceptorArgs args)
        {
            if (this.DealType == null || this.DealType.Key == DealTypeEnum.Buy)
            {
               args.Cancel = true;
               args.Value = this.EntityManager.GetNullEntity<DealCost>();
            }
        }
Now, the async calls initiated by the grid to get the DealCost for Buy deals are NOT happening. Yay! And, the timeout errors are not happening. Double-Yay? I am still doing further testing to see what else has been "fixed".
So, my question is: If the grid was doing something that was firing the async queries to fill in the "missing" DealCost entities, and I am now preventing that be intercepting that call and returning the null DealCost entity, why did the query timeout instead of returning the null entity itself?

Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 22-Sep-2009 at 11:31am
Further testing is showing that fixing/intercepting the DealCost bogus calls has fixed the other problems we were having too. Including the one that started this thread.
So: A) How was it timing out and not breaking in any of the error handlers? B) How did the time out cause the service to hang up and stop responding to incoming messages? C) Why did the 1 to 0..1 relation cause not return the null entity when the record was missing (correctly) in the Database.
Thanks,
Simon
Back to Top
kimj View Drop Down
IdeaBlade
IdeaBlade
Avatar

Joined: 09-May-2007
Posts: 1391 		Post Options Post Options   Quote kimj Quote  Post ReplyReply Direct Link To This Post Posted: 22-Sep-2009 at 11:44am
The debuglog made my head spin too. 
 
The grid, just by calling the getter on the DealCost property, was causing the async navigation logic to kick in for this related entity, resulting in another async query to the server for each row.  We likely have some bug in not correctly identifying when a related entity has resolved to the NullEntity vs. when it still needs retrieval, so I will look into that.  (In answer to question C.)
 
As for why these would cause timeouts, I have no idea. :)  The async navigation logic works a bit differently than the usual async queries and async tasks so I'll need to look into this too.  It's possible that one side (and I'm really not sure which) was just too busy processing all those individual queries of DealCost for each deal ID.   Also, when a timeout exception is received the client will retry once before throwing the exception to the caller.  So if your handler never saw the timeout exception then the retry succeeded (question A).
 
Question B) - it's not clear that the server was hung up, at least based on the log.  The server does start responding to queries again after those timeout messages.  If it was hung up, then maybe it did run into a problem of too many outstanding requests ... and what that magic number is I don't know.
 
 
 
Back to Top
skingaby View Drop Down
DevForce MVP
DevForce MVP
Avatar

Joined: 23-Apr-2008
Location: United States
Posts: 146 		Post Options Post Options   Quote skingaby Quote  Post ReplyReply Direct Link To This Post Posted: 22-Sep-2009 at 1:04pm
Thanks for the quick response. I think I've done all I can with this particular error and it seems to be resolved. Now I am going to get back to sorting out the atrocious performance issues we are experiencing loading these entities into the cache and the grid. There are a couple of places where there are 10-15 second gaps in the log and I am not sure at all how to figure out which query is causing it, short of chaining them all and dumping the AsyncParallelQuery.

Let me know if there is anything I can do to help you identify/debug the items in A and C. Thanks for your help.
Back to Top
 Post Reply Post Reply

Forum Jump Forum Permissions View Drop Down