Eventing Service timing out

Scrum for Team System - v1.x Discusions

Eventing Service timing out

PeterBauwens 08-13-2007, 10:40

In our TFS setup the Scrum Eventing Service often times out while updating work items. I've been reviewing the messages in the Event Viewer and tracked back on several of the workitem id's i found in there. There seems to be no obviuous reason why it would time out. At first I thought it might be caused by PBI's having a lot of SBI's but it also happens with PBI's having only 2 or 3 linked SBI's.

Any idea why updating a PBI with 2 SBI's would take longer than 2 minutes? When updating the PBI's and SBI's using the ScrumConsistencyCheck tool it never occurs...

Thx in advance,

Peter

Re: Eventing Service timing out

Stuart Preston 08-22-2007, 8:02
Please enable tracing by setting the TracingEnabled key to True in C:\Inetpub\wwwroot\Scrum.Eventing.Service\web.config

<add key="TracingEnabled" Value="False"/>

Then please can you make a change to an SBI that will cause the issue, and export the Eventlog, emailing it to scrumforteamsystem@conchango.com

Please could you also confirm which version of Scrum for Team System you are using.

In a previous post (http://scrumforteamsystem.com/cs/forums/989/ShowPost.aspx), you mentioned that you unsubscribed and resubscribed the event when you moved server - do you have the steps used for this as the out-of-the-box-installation limits the event to only fire to a limited set of actions?

Re: Eventing Service timing out

PeterBauwens 08-24-2007, 9:29

Stuart,

Let me give you an update:

at first we were using Version 1.1
- sometimes workitems were not updated
- the apppool of TFS (ScrumEventingService running in it) regularly consumed way too much CPU and memory, bringing TFS to a halt
- we contacted microsoft
- sent them a couple of dumps of the W3WP process of the TFS apppool
- got feedback that one of the components generating the load was the ScrumEventingService
- I posted a message on this forum to ask if we could run SEC in a seperate apppool, got feedback that this should be OK and moved it to a seperate apppool
- After this TFS ran just fine, TFS logged a lot of events stating the SEC timed out whenever it got notified of a change
we installed Version 1.2
- SEC could no longer run in a seperate apppool, error we got was 'cannot share handle accross multiple appdomains'
- we moved the SEC back to the TFS app pool
- everything seemed to be OK at first
- But started failing again, had to recycle the TFS app pool this morning
- i unsibscribed the eventing service because we cannot go on like this

Some statistics:

We've currently got about

25 Team Projects
60 People using TFS (developers, project leads, ...)
10 Continuous integration builds generating about 100 builds a day
5 Overnight full builds

I cannot send you the complete eventlog but i included some screenshots in the rtf in attachment...

The event was correctly registered, i've put the filter in the rtf document as well.

Thx in advance

Re: Eventing Service timing out

PeterBauwens 08-24-2007, 9:32

Uploading the RTF failed so here goes....

Scrum Version

1.2

Event Subscription

"CoreFields/StringFields/Field[ReferenceName = 'System.WorkItemType']/NewValue" = "Sprint Backlog Item" AND (("ChangedFields/IntegerFields/Field[ReferenceName='Conchango.VSTS.Scrum.WorkRemaining']/OldValue" <> "ChangedFields/IntegerFields/Field[ReferenceName='Conchango.VSTS.Scrum.WorkRemaining']/NewValue") OR (("ChangedFields/StringFields/Field[ReferenceName='System.State']/OldValue" <> "Deleted" AND "ChangedFields/StringFields/Field[ReferenceName='System.State']/NewValue" = "Deleted") OR ("ChangedFields/StringFields/Field[ReferenceName='System.State']/OldValue" = "Deleted" AND "ChangedFields/StringFields/Field[ReferenceName='System.State']/NewValue" <> "Deleted")))

Event captured by Eventing Service

Event Type: Information
Event Source: Scrum for Team System
Event Category: None
Event ID: 0
Date:  24/08/2007
Time:  4:05:33
User:  N/A
Computer: S2001330
Description:
SprintBacklogItemChanged.Notify
eventXml: <?xml version="1.0" encoding="utf-16"?><WorkItemChangedEvent xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema"><PortfolioProject>KBC.MisKBC2</PortfolioProject><ProjectNodeId>f94d61c7-9d49-4539-aaa6-a2810bf676c6</ProjectNodeId><AreaPath>\KBC.MisKBC2\Web Application\Tactical</AreaPath><Title>KBC.MisKBC2 Work Item Changed: Sprint Backlog Item 11863 - Mass Prolongation tactical SI Link</Title><WorkItemTitle>Mass Prolongation tactical SI Link</WorkItemTitle><Subscriber>ONT001\TFSSERVICE</Subscriber><ChangerSid>S-1-5-21-911899778-770800173-925700815-7358</ChangerSid><DisplayUrl>http://s2001330:8080/WorkItemTracking/WorkItem.aspx?artifactMoniker=11863</DisplayUrl><TimeZone>W. Europe Daylight Time</TimeZone><TimeZoneOffset>+02:00:00</TimeZoneOffset><ChangeType>Change</ChangeType><CoreFields><IntegerFields><Field><Name>ID</Name><ReferenceName>System.Id</ReferenceName><OldValue>11863</OldValue><NewValue>11863</NewValue></Field><Field><Name>Rev</Name><ReferenceName>System.Rev</ReferenceName><OldValue>13</OldValue><NewValue>14</NewValue></Field><Field><Name>AreaID</Name><ReferenceName>System.AreaId</ReferenceName><OldValue>520</OldValue><NewValue>520</NewValue></Field></IntegerFields><StringFields><Field><Name>Work Item Type</Name><ReferenceName>System.WorkItemType</ReferenceName><OldValue>Sprint Backlog Item</OldValue><NewValue>Sprint Backlog Item</NewValue></Field><Field><Name>Title</Name><ReferenceName>System.Title</ReferenceName><OldValue>Mass Prolongation tactical SI Link</OldValue><NewValue>Mass Prolongation tactical SI Link</NewValue></Field><Field><Name>Area Path</Name><ReferenceName>System.AreaPath</ReferenceName><OldValue>\KBC.MisKBC2\Web Application\Tactical</OldValue><NewValue>\KBC.MisKBC2\Web Application\Tactical</NewValue></Field><Field><Name>State</Name><ReferenceName>System.State</ReferenceName><OldValue>In Progress</OldValue><NewValue>In Progress</NewValue></Field><Field><Name>Reason</Name><ReferenceName>System.Reason</ReferenceName><OldValue>Work has commenced</OldValue><NewValue>Work has commenced</NewValue></Field><Field><Name>Assigned To</Name><ReferenceName>System.AssignedTo</ReferenceName><OldValue>U92575A</OldValue><NewValue>U92575A</NewValue></Field><Field><Name>Changed By</Name><ReferenceName>System.ChangedBy</ReferenceName><OldValue>U92575A</OldValue><NewValue>U92575A</NewValue></Field><Field><Name>Created By</Name><ReferenceName>System.CreatedBy</ReferenceName><OldValue>U94871A</OldValue><NewValue>U94871A</NewValue></Field><Field><Name>Changed Date</Name><ReferenceName>System.ChangedDate</ReferenceName><OldValue>23/08/2007 18:06:13</OldValue><NewValue>23/08/2007 18:06:25</NewValue></Field><Field><Name>Created Date</Name><ReferenceName>System.CreatedDate</ReferenceName><OldValue>1/08/2007 10:24:24</OldValue><NewValue>1/08/2007 10:24:24</NewValue></Field><Field><Name>Authorized As</Name><ReferenceName>System.AuthorizedAs</ReferenceName><OldValue>U92575A</OldValue><NewValue>U92575A</NewValue></Field><Field><Name>Iteration Path</Name><ReferenceName>System.IterationPath</ReferenceName><OldValue>\KBC.MisKBC2</OldValue><NewValue>\KBC.MisKBC2</NewValue></Field></StringFields></CoreFields><ChangedFields><IntegerFields><Field><Name>Work Remaining</Name><ReferenceName>Conchango.VSTS.Scrum.WorkRemaining</ReferenceName><OldValue>13</OldValue><NewValue>12</NewValue></Field></IntegerFields><StringFields /></ChangedFields></WorkItemChangedEvent>
tfsIdentityXml: <TeamFoundationServer url="http://S2001330:8080" />

Event Type: Information
Event Source: Scrum for Team System
Event Category: None
Event ID: 0
Date:  24/08/2007
Time:  4:05:33
User:  N/A
Computer: S2001330
Description:
SprintBacklogItemChanged.ParseSprintBacklogItemChangedEvent
eventWorkItemType: Sprint Backlog Item
projectName: KBC.MisKBC2
sprintBacklogItemId: 11863
serverName: http://S2001330:8080
isEventForCorrectWorkItemType: True

Messages in Event Log showing MakeTFSConnection 1 thru 7

Event Type: Error
Event Source: Scrum for Team System
Event Category: None
Event ID: 0
Date:  24/08/2007
Time:  4:05:43
User:  N/A
Computer: S2001330
Description:
MakeTfsConnection
point 7

Messages in Event Log showing construction of Projects Collection
Messages in Event Log showing UpdateWorkRemaining

Event Type: Error
Event Source: Scrum for Team System
Event Category: None
Event ID: 0
Date:  24/08/2007
Time:  4:05:52
User:  N/A
Computer: S2001330
Description:
SprintBacklogItemChanged.UpdateWorkRemaining
point 0

Events of Scrum4TS looping over all Scrum Projects

This is the last event before TFS Signals timeout after almost 4 minutes

Event Type: Warning
Event Source: TFS Services
Event Category: None
Event ID: 3051
Date:  24/08/2007
Time:  4:10:30
User:  N/A
Computer: S2001330
Description:
TF53010: An unexpected condition has occurred in a Team Foundation component. The information contained here should be made available to your site administrative staff.
Technical Information (for the administrative staff):
Date (UTC): 24/08/2007 2:10:30
Machine: S2001330
Application Domain: /LM/W3SVC/3/Root/services-2-128323227031074520
Assembly: Microsoft.TeamFoundation.Server, Version=8.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a; v2.0.50727
Process Details:
Process Name: w3wp
Process Id: 3624
Thread Id: 2960
Account name: ONT001\TFSSERVICE

Detailed Message: TF50280: Could not connect to the service at: 'http://s2001330/Scrum.Eventing.Service/SprintBacklogItemChanged.asmx'. Check the service configuration.
Full Exception:
The operation has timed out
Exception Message: The operation has timed out (type WebException)

Exception Stack Trace:    at System.Web.Services.Protocols.WebClientProtocol.GetWebResponse(WebRequest request)
   at System.Web.Services.Protocols.HttpWebClientProtocol.GetWebResponse(WebRequest request)
   at Microsoft.TeamFoundation.Client.TeamFoundationSoapProxy.GetWebResponse(WebRequest request)
   at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)
   at Microsoft.TeamFoundation.Server.NotificationClient.Notify(String eventXml, String tfsIdentityXml, SubscriptionInfo SubscriptionInfo)

For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

Re: Eventing Service timing out

jzrawlins 11-01-2007, 11:55
I'm having a similar issue. Any updates on this?

Re: Eventing Service timing out

berni 12-29-2007, 1:28

I am also having a very similar issue. Our problem began about 3 weeks ago and we have been using Scrum for Team System for 5 months. When Scurm.Eventing.Service begins to fail other applications begin to as well. Currently Scrum.Eventing.Service is running in the TFS AppPool with other critical TFS items. To help with the situation I have set the application pool to recycle every 2 hours. I am currently pondering the possibility of moving Scrum.Eventing.Service into its own AppPool so it does not affect other applications. Does any one have solution for this issue?

Event Type: Warning
Event Source: TFS Services
Event Category: None
Event ID: 3051
Date:  12/28/2007
Time:  10:10:18 AM
User:  N/A
Computer: ****TFS1
Description:
TF53010: An unexpected condition has occurred in a Team Foundation component. The information contained here should be made available to your site administrative staff.
Technical Information (for the administrative staff):
Date (UTC): 12/28/2007 6:10:18 PM
Machine: ****TFS1
Application Domain: /LM/W3SVC/3/Root/services-2-128433353912659016
Assembly: Microsoft.TeamFoundation.Server, Version=8.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a; v2.0.50727
Process Details:
Process Name: w3wp
Process Id: 2068
Thread Id: 1552
Account name: *****\svc_tfs

Detailed Message: TF50280: Could not connect to the service at: 'http://****tfs1/Scrum.Eventing.Service/SprintBacklogItemChanged.asmx'. Check the service configuration.
Full Exception:
The operation has timed out
Exception Message: The operation has timed out (type WebException)

Event Type: Error
Event Source: Scrum for Team System
Event Category: None
Event ID: 0
Date:  12/28/2007
Time:  10:17:07 AM
User:  N/A
Computer: ****TFS1
Description:
Error in Server constructor
Message = External component has thrown an exception., Stack Trace =    at new[](UInt32 )
   at CPslArray<unsigned __int64>.FAlloc(CPslArray<unsigned __int64>* , UInt32 n)
   at CPslArray<unsigned __int64>.FAppend(CPslArray<unsigned __int64>* , UInt64* t)
   at CCurrNodeRules.HrSetRule(CCurrNodeRules* , UInt64 cookie, PsRuleMetadataRecord* pRule)
   at CPsBusinessRuleEngine.HrBuildAccessToken(CPsBusinessRuleEngine* , Int32 fUseSidSecurity, Char* pszNamePart, Char* pszSid, IUnknown** ppUnkToken)
   at CCacheManager.HrSetIdentity(CCacheManager* , Char* bstrUserAccountName, Char* bstrUserFriendlyName, Char* bstrUserSid, PsUserDisplayModeEnum displayMode, Boolean fUseSidSecurity)
   at CProdStudioDataStore.HrRefreshCache(CProdStudioDataStore* , Boolean fResynchOnly, Boolean bInit, Boolean fNoFire, Boolean fByPassFireOnThis, Int32 hCredentials, Char* bstrUserAccountName, Char* bstrUserFriendlyName, Char* bstrUserSid)
   at CProdStudioDataStore.ConnectEx(CProdStudioDataStore* , Char* bstrUrl, Int32 hCredentials, Char* bstrDefaultCachePath, Char* bstrInstanceId, Char* bstrUserAccountName, Char* bstrUserFriendlyName, Char* bstrUserSid)
   at Microsoft.TeamFoundation.WorkItemTracking.Client.DataStore.DatastoreClass.ConnectEx(String connectionString, Int32 hCredentials, String defaultCachePath, String instanceId, String userSamName, String userFriendlyName, String userSid)
   at Microsoft.TeamFoundation.WorkItemTracking.Client.WorkItemStore.InitializeInternal()
   at Microsoft.TeamFoundation.WorkItemTracking.Client.WorkItemStore.Microsoft.TeamFoundation.Client.ITeamFoundationServerObject.Initialize(TeamFoundationServer teamFoundationServer)
   at Microsoft.TeamFoundation.Client.TeamFoundationServer.CreateITFSObjectInstance(Type serviceType)
   at Microsoft.TeamFoundation.Client.TeamFoundationServer.GetService(Type serviceType)
   at Conchango.TeamSystem.Scrum.Common.Server.MakeTfsConnection(String serverName)
   at Conchango.TeamSystem.Scrum.Common.Server..ctor(String serverName)

Re: Eventing Service timing out

jzrawlins 01-16-2008, 7:29
Anyone? Anyone? Buler?

Re: Eventing Service timing out

Stuart Preston 01-17-2008, 9:04
For all those who find this thread and by way of an update on this issue:

Background:

Each "Sprint Backlog Item" update will cause a new request to our webservice initiated by TFS. The webservice itself connects to TFS, using the context of the saved work item (passed in by TFS) to evaluate the linked items. If a Product Backlog Item is found, all the links of that Product Backlog Item are evaluated to see if there are any tasks with Work Remaining - if so, the totals are added up and the "parent" Product Backlog Item is updated.

Technical overview:

The call to create a new instance of the Server object is rather expensive, and as has been reported a couple of times with larger installations (e.g. corporations running multiple concurrent projects) - a resource limit can be reached prior to the IIS Application Pool being recycled naturally causing exceptions that are surfaced from within TFS.

Workaround:

For those people who experience this issue, we recommend disabling the existing subscription with the following command:

"C:\Program Files\Conchango\Scrum for Team System\tools\EventSubscriber.exe" "/U" "/TFSName" "http://[TFSServerName]:8080"

We then recommend to schedule the Work Remaining Consistency Checker tool (see http://scrumforteamsystem.com/cs/forums/1108/ShowPost.aspx) to ensure that Work Remaining is synced occasionally (e.g. every 15 minutes). This can be scheduled for individual projects and offers a better performance profile overall for larger projects.

We have rewritten this service for Scrum for Team System v2.0 and a decision has been made not to back port it for earlier versions. Whilst we have tested and seen dramatic improvements overall, we would be grateful for any feedback from the community on the performance of the new version.

The beta version of Scrum for Team System v2.0 can be downloaded from our forum at http://scrumforteamsystem.com/cs/forums/default.aspx?ForumGroupID=2