Client request is processed twice

[Olivier Matrot]

Hello,
I have a problem with an ASP.NET 2.0 Application.
A client request is processed in parrallel by two threads.
This ends with the following exception :

<Source>System</Source>
<StackTrace> at System.Collections.Specialized.ListDictionary.Add(Object
key, Object value)
at System.Web.UI.ClientScriptManager.RegisterScriptBlock(ScriptKey key,
String script, ListDictionary&amp; scriptBlocks, ArrayList&amp; scriptList,
Boolean needsScriptTags, Boolean&amp; inScriptBlock)
at System.Web.UI.ClientScriptManager.RegisterScriptBlock(ScriptKey key,
String script, ClientAPIRegisterType type)
at System.Web.UI.ClientScriptManager.RegisterClientScriptInclude(Type
type, String key, String url)
at
System.Web.UI.ScriptRegistrationManager.RegisterClientScriptInclude(Control
control, Type type, String key, String url)
at
System.Web.UI.ScriptManager.RegisterClientScriptIncludeInternal(Control
control, Type type, String key, String url)
at System.Web.UI.ScriptManager.RegisterScripts()
at System.Web.UI.ScriptManager.OnPagePreRenderComplete(Object sender,
EventArgs e)
at System.EventHandler.Invoke(Object sender, EventArgs e)
at System.Web.UI.Page.OnPreRenderComplete(EventArgs e)
at System.Web.UI.Page.ProcessRequestMain(Boolean
includeStagesBeforeAsyncPoint, Boolean
includeStagesAfterAsyncPoint)</StackTrace>
<Message>An entry with the same key already exists.</Message>

Any idea ?
Thanks in advance.

 

[Olivier Matrot]

More information :
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.

 

[Patrice]

IMO you'll have to explain a bit what you meant or how you do :
- A client request is processed in parrallel by two threads
- There is 2 disctinct session for the request
or what it your overall goal.

The standard situation is that an HTTP request is processed by a single
thread and is binded to a single session so it would seems you try something
special. My first thought would be that you try to add the same key twice in
distinct threads when you have a single request coming and that the
clientscriptmanager is likely not designed to handle such an unusual
situation

It's likely that your best bet is first to explain what you are trying to do
so that we can better grasp the context (you have build in capabilites for
async processing in .NET 2.0 that you could perhaps use ?)...

 

[Olivier Matrot]

My goal is not to have a client request processed twice.
This is a weird behavior I have on my web site.
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>|

 

[Patrice]

Humm... Never seen this.

My first thought would be having the ASPX page handler registered twice ?
But as you don't have this yourself perhaps those users are behind a network
equipement such as a proxy. But then the IIS log show anyway a single
request so it would be something server side ?

Really weird...

Good luck.
--
Patrice

My goal is not to have a client request processed twice.
This is a weird behavior I have on my web site.
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>|