Problem : Client request is processed simultaneously by two threads !

  • Thread starter Thread starter Olivier Matrot
  • Start date Start date
O

Olivier Matrot

I have a problem with an ASP.NET 2.0 Application.
A client request is processed in parrallel by two threads.
After further analysis, it appears that :
- There is 2 disctinct session for the request (Session_Start in
global.asax)
- One of the session ends (Session_End in global.asax).
- The ramining session is used for subsequent requests, and everything works
fine.
- This is happening primarily when the application is started for the first
time, but sometimes it is on a simple page request. No page in particular is
concerned, and I can't reproduce it myself.
My application generates a log file, and the facts exposed here are clearly
visible in that file.
The IIS log file shows that only one request is comming from the client.
Take a look at the following :

Line |Thread Id| Date| Hour|Delta|
Category|Text

------------------------------------------------------------------------------------------

28387| 00000007|05/09/2007|13:35:33.611| + |
Hit|Session starting from [196.201.XX.XXX]...|

28388| 00000007|05/09/2007|13:35:33.611| 0|
Browsers|Browser is : [IE] Version [6.0] on [WinXP]|

28393| 00000001|05/09/2007|13:35:33.611| 0|
Hit|Session starting from [196.201.XX.XXX]...|

28394| 00000001|05/09/2007|13:35:33.611| 0|
Browsers|Browser is : [IE] Version [6.0] on [WinXP]|

28396| 00000007|05/09/2007|13:35:33.783| 172|Client Language
Preferences|Prefered Language is [fr] LCID -> 12|

28397| 00000001|05/09/2007|13:35:33.783| 0|Client Language
Preferences|Prefered Language is [fr] LCID -> 12|

28398| 00000001|05/09/2007|13:35:33.798| 15|
|AcquireRequestState|

28399| 00000001|05/09/2007|13:35:33.798| 0| |No
Cookie with prefered language. Browser languages will be analysed (english
is default) !|

28400| 00000001|05/09/2007|13:35:33.798| 0|
|Selected runtime culture is [fr]|

28401| 00000001|05/09/2007|13:35:33.798| 0| ||

28402| 00000007|05/09/2007|13:35:33.798| 0|
|AcquireRequestState|

28406| 00000001|05/09/2007|13:35:34.533| 735|
StartEndFunction|Page [/members/Web/SendFax.aspx] is requested for the first
time.|

28407| 00000007|05/09/2007|13:35:34.533| 0|
StartEndFunction|Page [/members/Web/SendFax.aspx] is requested for the first
time.|

28408| 00000001|05/09/2007|13:35:34.564| 31|
StartEndFunction|Entering InitSessionUserId()|

28409| 00000001|05/09/2007|13:35:34.564| 0|
|Time zone offset (GMT) cookie value is [0]|

28410| 00000007|05/09/2007|13:35:34.564| 0|
StartEndFunction|Entering InitSessionUserId()|

28411| 00000007|05/09/2007|13:35:34.564| 0|
|Time zone offset (GMT) cookie value is [0]|

28412| 00000001|05/09/2007|13:35:35.189| 625|
|********* TEMP : GetRoles() : User is
[[email protected]] *********|

28413| 00000007|05/09/2007|13:35:35.204| 15|
|********* TEMP : GetRoles() : User is
[[email protected]] *********|

28414| 00000007|05/09/2007|13:35:35.251| 47|
RTEFBLDAPUser|Finding existing user [[email protected]] in []...|

28415| 00000001|05/09/2007|13:35:35.251| 0|
RTEFBLDAPUser|Finding existing user [[email protected]] in []...|

28416| 00000001|05/09/2007|13:35:35.267| 16|
DirectoryHelper|DetectDirectory [LDAP://rcs.private]|

28417| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|DetectDirectory [LDAP://rcs.private]|

28418| 00000001|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Directory is detected as [ActiveDirectory]|

28419| 00000001|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Naming context from RootDSE is [DC=rcs,DC=private]|

28420| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Directory is detected as [ActiveDirectory]|

28421| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Naming context from RootDSE is [DC=rcs,DC=private]|

28422| 00000001|05/09/2007|13:35:35.267| 0|
DirectoryHelper|GetDefaultContainer
[LDAP://rcs.private/ou=XXXXXXXXXXXXXXX,OU=XXXXXXXXXX,DC=rcs,DC=private] with
user [RCS\rw.gofaxbox] and AuthenticationTypes [Secure] |

28423| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|GetDefaultContainer
[LDAP://rcs.private/ou=XXXXXXXXXXXXXXX,OU=XXXXXXXXXX,DC=rcs,DC=private] with
user [RCS\rw.gofaxbox] and AuthenticationTypes [Secure] |

28424| 00000001|05/09/2007|13:35:35.267| 0|
RTEFBLDAPUser|DirectorySearcher Filter is
[(&((objectClass=user)([email protected])))] Scope is [Subtree]|

28425| 00000007|05/09/2007|13:35:35.267| 0|
RTEFBLDAPUser|DirectorySearcher Filter is
[(&((objectClass=user)([email protected])))] Scope is [Subtree]|

28427| 00000001|05/09/2007|13:35:35.314| 47|
|Find all user's email...|

28428| 00000007|05/09/2007|13:35:35.314| 0|
|Find all user's email...|

28429| 00000001|05/09/2007|13:35:35.329| 15|
StartEndFunction|Leaving InitSessionUserId()|

28430| 00000007|05/09/2007|13:35:35.329| 0|
StartEndFunction|Leaving InitSessionUserId()|

28431| 00000007|05/09/2007|13:35:35.329| 0|
StartEndFunction|End PageLoad|

28432| 00000001|05/09/2007|13:35:35.329| 0|
StartEndFunction|End PageLoad|

28433| 00000001|05/09/2007|13:35:36.142| 813| Application Error|An
entry with the same key already exists.<?xml version="1.0"
encoding="utf-8"?>[0D][0A]<RTELogClientExceptionContainer
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:xsd="http://www.w3.org/2001/XMLSchema">[0D][0A]
<Source>System</Source>[0D][0A] <StackTrace> at
System.Collections.Specialized.ListDictionary.Add(Object key, Object
value)[0D][0A] at
System.Web.UI.ClientScriptManager.RegisterScriptBlock(ScriptKey key, String
script, ListDictionary&amp; scriptBlocks, ArrayList&amp; scriptList, Boolean
needsScriptTags, Boolean&amp; inScriptBlock)[0D][0A] at
System.Web.UI.ClientScriptManager.RegisterScriptBlock(ScriptKey key, String
script, ClientAPIRegisterType type)[0D][0A] at
System.Web.UI.ClientScriptManager.RegisterClientScriptInclude(Type type,
String key, String url)[0D][0A] at
System.Web.UI.ScriptRegistrationManager.RegisterClientScriptInclude(Control
control, Type type, String key, String url)[0D][0A] at
System.Web.UI.ScriptManager.RegisterClientScriptIncludeInternal(Control
control, Type type, String key, String url)[0D][0A] at
System.Web.UI.ScriptManager.RegisterScripts()[0D][0A] at
System.Web.UI.ScriptManager.OnPagePreRenderComplete(Object sender, EventArgs
e)[0D][0A] at System.EventHandler.Invoke(Object sender, EventArgs
e)[0D][0A] at System.Web.UI.Page.OnPreRenderComplete(EventArgs e)[0D][0A]
at System.Web.UI.Page.ProcessRequestMain(Boolean
includeStagesBeforeAsyncPoint, Boolean
includeStagesAfterAsyncPoint)</StackTrace>[0D][0A] <Message>An entry with
the same key already
exists.</Message>[0D][0A]</RTELogClientExceptionContainer>|


Any help appreciated.
 
a common cause is a src="" in the page. this will cause the browser to
do a second request. if you are using firefox, check the media tab to
see if the page is referenced again. if you are using IE, get the dev
toolbar.


-- bruce (sqlwork.com)

Olivier said:
I have a problem with an ASP.NET 2.0 Application.
A client request is processed in parrallel by two threads.
After further analysis, it appears that :
- There is 2 disctinct session for the request (Session_Start in
global.asax)
- One of the session ends (Session_End in global.asax).
- The ramining session is used for subsequent requests, and everything works
fine.
- This is happening primarily when the application is started for the first
time, but sometimes it is on a simple page request. No page in particular is
concerned, and I can't reproduce it myself.
My application generates a log file, and the facts exposed here are clearly
visible in that file.
The IIS log file shows that only one request is comming from the client.
Take a look at the following :

Line |Thread Id| Date| Hour|Delta|
Category|Text

------------------------------------------------------------------------------------------

28387| 00000007|05/09/2007|13:35:33.611| + |
Hit|Session starting from [196.201.XX.XXX]...|

28388| 00000007|05/09/2007|13:35:33.611| 0|
Browsers|Browser is : [IE] Version [6.0] on [WinXP]|

28393| 00000001|05/09/2007|13:35:33.611| 0|
Hit|Session starting from [196.201.XX.XXX]...|

28394| 00000001|05/09/2007|13:35:33.611| 0|
Browsers|Browser is : [IE] Version [6.0] on [WinXP]|

28396| 00000007|05/09/2007|13:35:33.783| 172|Client Language
Preferences|Prefered Language is [fr] LCID -> 12|

28397| 00000001|05/09/2007|13:35:33.783| 0|Client Language
Preferences|Prefered Language is [fr] LCID -> 12|

28398| 00000001|05/09/2007|13:35:33.798| 15|
|AcquireRequestState|

28399| 00000001|05/09/2007|13:35:33.798| 0| |No
Cookie with prefered language. Browser languages will be analysed (english
is default) !|

28400| 00000001|05/09/2007|13:35:33.798| 0|
|Selected runtime culture is [fr]|

28401| 00000001|05/09/2007|13:35:33.798| 0| ||

28402| 00000007|05/09/2007|13:35:33.798| 0|
|AcquireRequestState|

28406| 00000001|05/09/2007|13:35:34.533| 735|
StartEndFunction|Page [/members/Web/SendFax.aspx] is requested for the first
time.|

28407| 00000007|05/09/2007|13:35:34.533| 0|
StartEndFunction|Page [/members/Web/SendFax.aspx] is requested for the first
time.|

28408| 00000001|05/09/2007|13:35:34.564| 31|
StartEndFunction|Entering InitSessionUserId()|

28409| 00000001|05/09/2007|13:35:34.564| 0|
|Time zone offset (GMT) cookie value is [0]|

28410| 00000007|05/09/2007|13:35:34.564| 0|
StartEndFunction|Entering InitSessionUserId()|

28411| 00000007|05/09/2007|13:35:34.564| 0|
|Time zone offset (GMT) cookie value is [0]|

28412| 00000001|05/09/2007|13:35:35.189| 625|
|********* TEMP : GetRoles() : User is
[[email protected]] *********|

28413| 00000007|05/09/2007|13:35:35.204| 15|
|********* TEMP : GetRoles() : User is
[[email protected]] *********|

28414| 00000007|05/09/2007|13:35:35.251| 47|
RTEFBLDAPUser|Finding existing user [[email protected]] in []...|

28415| 00000001|05/09/2007|13:35:35.251| 0|
RTEFBLDAPUser|Finding existing user [[email protected]] in []...|

28416| 00000001|05/09/2007|13:35:35.267| 16|
DirectoryHelper|DetectDirectory [LDAP://rcs.private]|

28417| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|DetectDirectory [LDAP://rcs.private]|

28418| 00000001|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Directory is detected as [ActiveDirectory]|

28419| 00000001|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Naming context from RootDSE is [DC=rcs,DC=private]|

28420| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Directory is detected as [ActiveDirectory]|

28421| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|Naming context from RootDSE is [DC=rcs,DC=private]|

28422| 00000001|05/09/2007|13:35:35.267| 0|
DirectoryHelper|GetDefaultContainer
[LDAP://rcs.private/ou=XXXXXXXXXXXXXXX,OU=XXXXXXXXXX,DC=rcs,DC=private] with
user [RCS\rw.gofaxbox] and AuthenticationTypes [Secure] |

28423| 00000007|05/09/2007|13:35:35.267| 0|
DirectoryHelper|GetDefaultContainer
[LDAP://rcs.private/ou=XXXXXXXXXXXXXXX,OU=XXXXXXXXXX,DC=rcs,DC=private] with
user [RCS\rw.gofaxbox] and AuthenticationTypes [Secure] |

28424| 00000001|05/09/2007|13:35:35.267| 0|
RTEFBLDAPUser|DirectorySearcher Filter is
[(&((objectClass=user)([email protected])))] Scope is [Subtree]|

28425| 00000007|05/09/2007|13:35:35.267| 0|
RTEFBLDAPUser|DirectorySearcher Filter is
[(&((objectClass=user)([email protected])))] Scope is [Subtree]|

28427| 00000001|05/09/2007|13:35:35.314| 47|
|Find all user's email...|

28428| 00000007|05/09/2007|13:35:35.314| 0|
|Find all user's email...|

28429| 00000001|05/09/2007|13:35:35.329| 15|
StartEndFunction|Leaving InitSessionUserId()|

28430| 00000007|05/09/2007|13:35:35.329| 0|
StartEndFunction|Leaving InitSessionUserId()|

28431| 00000007|05/09/2007|13:35:35.329| 0|
StartEndFunction|End PageLoad|

28432| 00000001|05/09/2007|13:35:35.329| 0|
StartEndFunction|End PageLoad|

28433| 00000001|05/09/2007|13:35:36.142| 813| Application Error|An
entry with the same key already exists.<?xml version="1.0"
encoding="utf-8"?>[0D][0A]<RTELogClientExceptionContainer
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:xsd="http://www.w3.org/2001/XMLSchema">[0D][0A]
<Source>System</Source>[0D][0A] <StackTrace> at
System.Collections.Specialized.ListDictionary.Add(Object key, Object
value)[0D][0A] at
System.Web.UI.ClientScriptManager.RegisterScriptBlock(ScriptKey key, String
script, ListDictionary&amp; scriptBlocks, ArrayList&amp; scriptList, Boolean
needsScriptTags, Boolean&amp; inScriptBlock)[0D][0A] at
System.Web.UI.ClientScriptManager.RegisterScriptBlock(ScriptKey key, String
script, ClientAPIRegisterType type)[0D][0A] at
System.Web.UI.ClientScriptManager.RegisterClientScriptInclude(Type type,
String key, String url)[0D][0A] at
System.Web.UI.ScriptRegistrationManager.RegisterClientScriptInclude(Control
control, Type type, String key, String url)[0D][0A] at
System.Web.UI.ScriptManager.RegisterClientScriptIncludeInternal(Control
control, Type type, String key, String url)[0D][0A] at
System.Web.UI.ScriptManager.RegisterScripts()[0D][0A] at
System.Web.UI.ScriptManager.OnPagePreRenderComplete(Object sender, EventArgs
e)[0D][0A] at System.EventHandler.Invoke(Object sender, EventArgs
e)[0D][0A] at System.Web.UI.Page.OnPreRenderComplete(EventArgs e)[0D][0A]
at System.Web.UI.Page.ProcessRequestMain(Boolean
includeStagesBeforeAsyncPoint, Boolean
includeStagesAfterAsyncPoint)</StackTrace>[0D][0A] <Message>An entry with
the same key already
exists.</Message>[0D][0A]</RTELogClientExceptionContainer>|


Any help appreciated.
Click to expand...
 
Back
Top