Re: Servlet Threads Changing Instance Data

2018-08-15 Thread Christopher Schultz
-BEGIN PGP SIGNED MESSAGE-
Hash: SHA256

Jerry,

On 8/15/18 4:00 PM, Jerry Malcolm wrote:
> On 8/15/2018 1:50 PM, Olaf Kock wrote:
>> Jerry,
>> 
>> 
>> On 15.08.2018 18:14, Jerry Malcolm wrote:
>>> I have a mobile app that issues several http web service calls
>>> to initialize.  I was making them sequentially with no issues.
>>> I then changed to give them all separate threads so they could
>>> load asynchronously.  Then the bottom fell out.  I started
>>> getting empty responses and some responses with results of
>>> three or four of the calls concatenated.  I traced the problem
>>> from the app back through apache through mod_jk and found the
>>> culprit to be Tomcat.
>>> 
>>> I'm a seasoned Tomcat developer for over 15 years.  I've never
>>> seen anything like this.  But it's really scary.  What I found
>>> is that sometime during the execution of one servlet call, it's
>>> thread data is swapped to thread data of another servlet call.
>>> I know this sounds like Twilight Zone.  But here is a log
>>> output. At the beginning of doGet(), I generated a random text
>>> string just to keep track of the thread data/:/
>>> 
>>> Thread: ajp-nio-8009-exec-24 uid: rclebgb --> Thread:
>>> ajp-nio-8009-exec-29 uid: ceycfqd --> Thread:
>>> ajp-nio-8009-exec-29 uid: ceycfqd <-- Thread:
>>> ajp-nio-8009-exec-24 uid: ceycfqd <--
>>> 
>>> Note that when thread 24 starts I store the "rcl..." uid.
>>> Another call comes in and starts thread 29.  By the time thread
>>> 24's servlet code is done, it now has thread 29's data.  (The
>>> uid is just a quick variable for reference.  The request
>>> object, response object, EVERYTHING is now thread 29's data).
>>> 
>>> This explains why I'm getting empty responses and other
>>> response with the data for multiple requests concatenated
>>> together.  The "rcl..." instance data has totally disappeared,
>>> and all of the server calls are now using the "cey..." instance
>>> data (i.e. response object).
>>> 
>>> I figure this is some sort of timing/race condition that only
>>> occurs with a second call coming in while the first call is
>>> still in progress. I can go back to sending the mobile app
>>> calls serially and probably work around this.  But this is a
>>> huge problem.
>>> 
>>> Any ideas?  (BTW... Tomcat 9.0.7)
>>> 
>> 
>> As we don't know which code generates this log output, it's hard
>> to judge what actually causes your problem. You say "thread data"
>> is being swapped, and the very first aspect that comes to my mind
>> is: Servlets are inherently multithreaded, and a common pattern
>> of bugs is if a servlet has a member variable that is used for
>> request processing: There typically is only one Servlet object
>> ever, thus they all share the same state, if the state is stored
>> in a member variable. This might be directly in the servlet or in
>> some other component or singleton somewhere.
>> 
>> Any state and request processing must be done on the
>> request/response pair, and properly threadsafe in every other
>> part of your code.
>> 
>> And most likely this is an issue that luckily shows up when
>> you're issuing a lot of parallel threads due to parallelizing one
>> client. It'd be a lot harder to reproduce if it were individual
>> users, who (very) occasionally see the wrong data. Consider
>> yourself lucky to have such a nice and reproducible issue.
>> 
>> Olaf
> 
> Olaf,
> 
> I'm having a bit of trouble feeling "lucky" that I have a problem
> that is catastrophically blocking my development progress toward a
> deadline.

Uh  hmm.

> I'm not sure what you mean by typically there is only one servlet 
> object.  There's one class.  But a new instance is created on each 
> request, right?  And all instance variables should be scoped to
> that instance alone, right?

Nope. I think that's where everything you're observing is coming from,
then.

> It's fundamental to Java that a private local variable can't
> arbitrarily change to another value in the middle of executing a
> method other than by the local code changing it itself, right?

Since servlet instances are shared, so are all those private variable
references.

> Yet uid (and all the other variables including request and 
> response) changed.. somewhere between the beginning and ending of 
> doGet().   !! I'm not doing any singleton stuff.  Simply 
> request-->Servlet-->response.

So, that's a scary thing or me to hear: "and all the other variables
including request and response". Are you asking about the parameters
to the e.g. doGet() method, or are you saying that you also have
"private HttpServletRequest request" defined in your servlet and you
are somewhere doing this:

public void doGet(HttpServletRequest request, HttpServletResponse
response) {

  this.request = request;
  this.response = response;

  ... other stuff
}

?

> My servlet code is very basic.  It is not multithreaded.
> 
> public class MyServlet() { private String uid;// <
> PRIVATE access!!

Yes, 

Re: Servlet Threads Changing Instance Data

2018-08-15 Thread Michael Osipov

Am 2018-08-15 um 22:00 schrieb Jerry Malcolm:

On 8/15/2018 1:50 PM, Olaf Kock wrote:

Jerry,


On 15.08.2018 18:14, Jerry Malcolm wrote:
I have a mobile app that issues several http web service calls to 
initialize.  I was making them sequentially with no issues.  I then 
changed to give them all separate threads so they could load 
asynchronously.  Then the bottom fell out.  I started getting empty 
responses and some responses with results of three or four of the 
calls concatenated.  I traced the problem from the app back through 
apache through mod_jk and found the culprit to be Tomcat.


I'm a seasoned Tomcat developer for over 15 years.  I've never seen 
anything like this.  But it's really scary.  What I found is that 
sometime during the execution of one servlet call, it's thread data 
is swapped to thread data of another servlet call. I know this sounds 
like Twilight Zone.  But here is a log output. At the beginning of 
doGet(), I generated a random text string just to keep track of the 
thread data/:/


Thread: ajp-nio-8009-exec-24 uid: rclebgb -->
Thread: ajp-nio-8009-exec-29 uid: ceycfqd -->
Thread: ajp-nio-8009-exec-29 uid: ceycfqd <--
Thread: ajp-nio-8009-exec-24 uid: ceycfqd <--

Note that when thread 24 starts I store the "rcl..." uid. Another 
call comes in and starts thread 29.  By the time thread 24's servlet 
code is done, it now has thread 29's data.  (The uid is just a quick 
variable for reference.  The request object, response object, 
EVERYTHING is now thread 29's data).


This explains why I'm getting empty responses and other response with 
the data for multiple requests concatenated together.  The "rcl..." 
instance data has totally disappeared, and all of the server calls 
are now using the "cey..." instance data (i.e. response object).


I figure this is some sort of timing/race condition that only occurs 
with a second call coming in while the first call is still in 
progress. I can go back to sending the mobile app calls serially and 
probably work around this.  But this is a huge problem.


Any ideas?  (BTW... Tomcat 9.0.7)



As we don't know which code generates this log output, it's hard to 
judge what actually causes your problem. You say "thread data" is 
being swapped, and the very first aspect that comes to my mind is: 
Servlets are inherently multithreaded, and a common pattern of bugs is 
if a servlet has a member variable that is used for request 
processing: There typically is only one Servlet object ever, thus they 
all share the same state, if the state is stored in a member variable. 
This might be directly in the servlet or in some other component or 
singleton somewhere.


Any state and request processing must be done on the request/response 
pair, and properly threadsafe in every other part of your code.


And most likely this is an issue that luckily shows up when you're 
issuing a lot of parallel threads due to parallelizing one client. 
It'd be a lot harder to reproduce if it were individual users, who 
(very) occasionally see the wrong data. Consider yourself lucky to 
have such a nice and reproducible issue.


Olaf


Olaf,

I'm having a bit of trouble feeling "lucky" that I have a problem that 
is catastrophically blocking my development progress toward a deadline.


I'm not sure what you mean by typically there is only one servlet 
object.  There's one class.  But a new instance is created on each 
request, right?  And all instance variables should be scoped to that 
instance alone, right?  It's fundamental to Java that a private local 
variable can't arbitrarily change to another value in the middle of 
executing a method other than by the local code changing it itself, 
right?  Yet uid (and all the other variables including request and 
response) changed.. somewhere between the beginning and ending of 
doGet().   !! I'm not doing any singleton stuff.  Simply 
request-->Servlet-->response.


My servlet code is very basic.  It is not multithreaded.

public class MyServlet() {
private String uid;    // < PRIVATE access!!


Oh hell, this is so wrong. The servlet instance exists only once in the 
webapp classloader. No one is creating a new instace on each an every 
request. You *cannot* share a variable like that, it is not threadsafe.


This is your problem. You have to fix that. You also *must* review the 
rest of your code. Here is your exact problem: 
https://stackoverflow.com/a/2184147/696632. Trust Bauke Scholz!


Michael


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org



RE: Servlet Threads Changing Instance Data

2018-08-15 Thread Caldarale, Charles R
> From: Jerry Malcolm [mailto:techst...@malcolms.com] 
> Subject: Re: Servlet Threads Changing Instance Data

> I'm not sure what you mean by typically there is only one servlet 
> object.  There's one class.  But a new instance is created on each 
> request, right?

No - there's only one instance of each defined servlet.  All requests for a
particular servlet share that instance.

  - Chuck


THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY
MATERIAL and is thus for use only by the intended recipient. If you received
this in error, please contact the sender and delete the e-mail and its
attachments from all computers.



smime.p7s
Description: S/MIME cryptographic signature


Re: Servlet Threads Changing Instance Data

2018-08-15 Thread Jerry Malcolm

On 8/15/2018 1:50 PM, Olaf Kock wrote:

Jerry,


On 15.08.2018 18:14, Jerry Malcolm wrote:
I have a mobile app that issues several http web service calls to 
initialize.  I was making them sequentially with no issues.  I then 
changed to give them all separate threads so they could load 
asynchronously.  Then the bottom fell out.  I started getting empty 
responses and some responses with results of three or four of the 
calls concatenated.  I traced the problem from the app back through 
apache through mod_jk and found the culprit to be Tomcat.


I'm a seasoned Tomcat developer for over 15 years.  I've never seen 
anything like this.  But it's really scary.  What I found is that 
sometime during the execution of one servlet call, it's thread data 
is swapped to thread data of another servlet call. I know this sounds 
like Twilight Zone.  But here is a log output. At the beginning of 
doGet(), I generated a random text string just to keep track of the 
thread data/:/


Thread: ajp-nio-8009-exec-24 uid: rclebgb -->
Thread: ajp-nio-8009-exec-29 uid: ceycfqd -->
Thread: ajp-nio-8009-exec-29 uid: ceycfqd <--
Thread: ajp-nio-8009-exec-24 uid: ceycfqd <--

Note that when thread 24 starts I store the "rcl..." uid. Another 
call comes in and starts thread 29.  By the time thread 24's servlet 
code is done, it now has thread 29's data.  (The uid is just a quick 
variable for reference.  The request object, response object, 
EVERYTHING is now thread 29's data).


This explains why I'm getting empty responses and other response with 
the data for multiple requests concatenated together.  The "rcl..." 
instance data has totally disappeared, and all of the server calls 
are now using the "cey..." instance data (i.e. response object).


I figure this is some sort of timing/race condition that only occurs 
with a second call coming in while the first call is still in 
progress. I can go back to sending the mobile app calls serially and 
probably work around this.  But this is a huge problem.


Any ideas?  (BTW... Tomcat 9.0.7)



As we don't know which code generates this log output, it's hard to 
judge what actually causes your problem. You say "thread data" is 
being swapped, and the very first aspect that comes to my mind is: 
Servlets are inherently multithreaded, and a common pattern of bugs is 
if a servlet has a member variable that is used for request 
processing: There typically is only one Servlet object ever, thus they 
all share the same state, if the state is stored in a member variable. 
This might be directly in the servlet or in some other component or 
singleton somewhere.


Any state and request processing must be done on the request/response 
pair, and properly threadsafe in every other part of your code.


And most likely this is an issue that luckily shows up when you're 
issuing a lot of parallel threads due to parallelizing one client. 
It'd be a lot harder to reproduce if it were individual users, who 
(very) occasionally see the wrong data. Consider yourself lucky to 
have such a nice and reproducible issue.


Olaf


Olaf,

I'm having a bit of trouble feeling "lucky" that I have a problem that 
is catastrophically blocking my development progress toward a deadline.


I'm not sure what you mean by typically there is only one servlet 
object.  There's one class.  But a new instance is created on each 
request, right?  And all instance variables should be scoped to that 
instance alone, right?  It's fundamental to Java that a private local 
variable can't arbitrarily change to another value in the middle of 
executing a method other than by the local code changing it itself, 
right?  Yet uid (and all the other variables including request and 
response) changed.. somewhere between the beginning and ending of 
doGet().   !! I'm not doing any singleton stuff.  Simply 
request-->Servlet-->response.


My servlet code is very basic.  It is not multithreaded.

public class MyServlet() {
private String uid;    // < PRIVATE access!!

doGet() {
   uid = createUID();
   System.out.println( "Thread: " + Thread.currentThread().getName() + 
" uid: " + uid + " -->");


    (no new threads, totally synchronous, simply get 
a couple of vars from a JDBC call)


   System.out.println( "Thread: " + Thread.currentThread().getName() + 
" uid: " + uid + " <--");

}

That's it.  I can think of nothing I could be doing that would cause the 
PRIVATE uid varible to be different on the 2nd println from the 1st 
println.  And furthermore, the 2nd println has a uid from a DIFFERENT 
request.


What could I possibly be doing in this code above that could cause this?

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org



Re: Servlet Threads Changing Instance Data

2018-08-15 Thread Christopher Schultz
-BEGIN PGP SIGNED MESSAGE-
Hash: SHA256

Jerry,

On 8/15/18 12:14 PM, Jerry Malcolm wrote:
> I have a mobile app that issues several http web service calls to 
> initialize.  I was making them sequentially with no issues.  I
> then changed to give them all separate threads so they could load 
> asynchronously.  Then the bottom fell out.  I started getting
> empty responses and some responses with results of three or four of
> the calls concatenated.  I traced the problem from the app back
> through apache through mod_jk and found the culprit to be Tomcat.
> 
> I'm a seasoned Tomcat developer for over 15 years.  I've never
> seen anything like this.  But it's really scary.  What I found is
> that sometime during the execution of one servlet call, it's thread
> data is swapped to thread data of another servlet call.  I know
> this sounds like Twilight Zone.  But here is a log output. At the
> beginning of doGet(), I generated a random text string just to keep
> track of the thread data/:/
> 
> Thread: ajp-nio-8009-exec-24 uid: rclebgb --> Thread:
> ajp-nio-8009-exec-29 uid: ceycfqd --> Thread: ajp-nio-8009-exec-29
> uid: ceycfqd <-- Thread: ajp-nio-8009-exec-24 uid: ceycfqd <--
> 
> Note that when thread 24 starts I store the "rcl..." uid. Another
> call comes in and starts thread 29.  By the time thread 24's
> servlet code is done, it now has thread 29's data.  (The uid is
> just a quick variable for reference.  The request object, response
> object, EVERYTHING is now thread 29's data).
> 
> This explains why I'm getting empty responses and other response
> with the data for multiple requests concatenated together.  The
> "rcl..." instance data has totally disappeared, and all of the
> server calls are now using the "cey..." instance data (i.e.
> response object).
> 
> I figure this is some sort of timing/race condition that only
> occurs with a second call coming in while the first call is still
> in progress. I can go back to sending the mobile app calls serially
> and probably work around this.  But this is a huge problem.
> 
> Any ideas?  (BTW... Tomcat 9.0.7)

Some more specific questions thatn what Olaf has already asked:

1. Where is your "uid" being stored?
2. What does your code look like? Can you just post some of it? We
really don't care what your application is doing, of course. Just the
parts that generate+log the "uids" you are showing to us.

- -chris
-BEGIN PGP SIGNATURE-
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/

iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAlt0g7gACgkQHPApP6U8
pFjxcQ/9GdFR302AfkCzCW2WDLqOYlcV/WqGHv2qIq3G5Eyv6b8fRHlqncg6QGbv
JZOMT1DHvfWYnMZ/XOcVbF1AdRfpCx4TUPuuaw4YoeS4kqghGKM3L545+Uavm5Qi
8I1GR5NL87fpFExifWrjqVgDIWGXmsHHG0TPwyWq16ALJ8IQ0jStbGdft82AEZeF
jUkbt2/+aDvKsGJhqROQ/Z+QnA+F9u6NW2vZTP2zhb2S9Max1L/MHySx3WLZv4aN
72sS592+KquSMOw1068Wj+BdsIN6ag6HOaNc/o3WCRivcLd/bQbZ4+v8UoegruRW
DK57voXd28lMBZI0SOU4sCLJpRctdprA8+zIsEiHKx4ln6UD+SHg3C9MGHhED5vp
zRI6dFTcuzoQ3f6/LTp3zNXqBsxTWPyF7C82CphRP0BOfQT526a4D0GkAO4BpdAU
Xm9tEpy1jQEyLplOWRctrSdy/e1uaqlJ3F+3/dkZEn+zfV9hpnMQ76BS8Mrei+Ke
aH8K5f6Ahak4iaey69nUKe8vVhGHex3uq8oo94Ud+mMVlSeWNFvcY8Kb7ByjAcUb
z3SsqTsGRHcmdJGg3Ku3FNpLEi9HkdZaAhGxENBg1lOd0oKHOEE/fsvnB83tartc
Aqjan2IdjHtil5vYRiQQqqmZ372KLIpxTfle1cj0PoJgd/P52DI=
=tZjO
-END PGP SIGNATURE-

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org



Re: Servlet Threads Changing Instance Data

2018-08-15 Thread Olaf Kock

Jerry,


On 15.08.2018 18:14, Jerry Malcolm wrote:
I have a mobile app that issues several http web service calls to 
initialize.  I was making them sequentially with no issues.  I then 
changed to give them all separate threads so they could load 
asynchronously.  Then the bottom fell out.  I started getting empty 
responses and some responses with results of three or four of the 
calls concatenated.  I traced the problem from the app back through 
apache through mod_jk and found the culprit to be Tomcat.


I'm a seasoned Tomcat developer for over 15 years.  I've never seen 
anything like this.  But it's really scary.  What I found is that 
sometime during the execution of one servlet call, it's thread data is 
swapped to thread data of another servlet call.  I know this sounds 
like Twilight Zone.  But here is a log output. At the beginning of 
doGet(), I generated a random text string just to keep track of the 
thread data/:/


Thread: ajp-nio-8009-exec-24 uid: rclebgb -->
Thread: ajp-nio-8009-exec-29 uid: ceycfqd -->
Thread: ajp-nio-8009-exec-29 uid: ceycfqd <--
Thread: ajp-nio-8009-exec-24 uid: ceycfqd <--

Note that when thread 24 starts I store the "rcl..." uid. Another call 
comes in and starts thread 29.  By the time thread 24's servlet code 
is done, it now has thread 29's data.  (The uid is just a quick 
variable for reference.  The request object, response object, 
EVERYTHING is now thread 29's data).


This explains why I'm getting empty responses and other response with 
the data for multiple requests concatenated together.  The "rcl..." 
instance data has totally disappeared, and all of the server calls are 
now using the "cey..." instance data (i.e. response object).


I figure this is some sort of timing/race condition that only occurs 
with a second call coming in while the first call is still in 
progress. I can go back to sending the mobile app calls serially and 
probably work around this.  But this is a huge problem.


Any ideas?  (BTW... Tomcat 9.0.7)



As we don't know which code generates this log output, it's hard to 
judge what actually causes your problem. You say "thread data" is being 
swapped, and the very first aspect that comes to my mind is: Servlets 
are inherently multithreaded, and a common pattern of bugs is if a 
servlet has a member variable that is used for request processing: There 
typically is only one Servlet object ever, thus they all share the same 
state, if the state is stored in a member variable. This might be 
directly in the servlet or in some other component or singleton somewhere.


Any state and request processing must be done on the request/response 
pair, and properly threadsafe in every other part of your code.


And most likely this is an issue that luckily shows up when you're 
issuing a lot of parallel threads due to parallelizing one client. It'd 
be a lot harder to reproduce if it were individual users, who (very) 
occasionally see the wrong data. Consider yourself lucky to have such a 
nice and reproducible issue.


Olaf



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org