ReentrantLock shared by threads not seeming to honor lock

Question

I have a single ReentrantLock object that I share among threads, but I'm able to lock the same object by different threads. This doesn't seem right as they are different threads. Here is the truncated/simplified output:

11:04:47,136 [http-bio-8080-exec-9] INFO  CamTask  - ABOUT TO LOCK..... java.util.concurrent.locks.ReentrantLock@4462cf1d[Unlocked] -- 0
11:04:47,136 [http-bio-8080-exec-9] INFO  CamTask  - GOT LOCK java.util.concurrent.locks.ReentrantLock@4462cf1d[Locked by thread http-bio-8080-exec-9] -- 1
// ...     //
11:04:48,244 [Camel thread #1] INFO  MyProcessor  - ABOUT TO LOCK... java.util.concurrent.locks.ReentrantLock@4462cf1d[Unlocked] -- 0
11:04:48,245 [Camel thread #1] INFO  MyProcessor  - GOT LOCK java.util.concurrent.locks.ReentrantLock@4462cf1d[Locked by thread Camel thread #1] -- 1
// ...     //
11:04:48,280 [Camel thread #1] INFO  MyProcessor  - ABOUT TO UNLOCK.. java.util.concurrent.locks.ReentrantLock@4462cf1d[Locked by thread Camel thread #1] -- 1
11:04:48,280 [Camel thread #1] INFO  MyProcessor  - UNLOCKED. java.util.concurrent.locks.ReentrantLock@4462cf1d[Unlocked] -- 0
// ...     //
11:04:48,284 [http-bio-8080-exec-9] INFO  CamTask  - ABOUT TO UNLOCK..... java.util.concurrent.locks.ReentrantLock@4462cf1d[Locked by thread http-bio-8080-exec-9] -- 1
11:04:48,284 [http-bio-8080-exec-9] INFO  CamTask  - UNLOCKED. java.util.concurrent.locks.ReentrantLock@4462cf1d[Unlocked] -- 0

My logging is structured like this:

log.info("ABOUT TO LOCK.. "+lock+" -- "+lock.getHoldCount());
lock.lock();
log.info("GOT LOCK "+lock+" -- "+lock.getHoldCount());

As you can see:

1. [http-bio-8080-exec-9] locks (hold count is 0 then 1 after lock as expected)
2. [Camel thread #1] locks (WHY IS THIS POSSIBLE SINCE [http-bio-8080-exec-9] HASN'T UNLOCKED YET?)

MyProcessor gets called as the result of a message arriving on the queue. The lock object is passed to MyProcessor in its constructor. When I print out the lock object in the logs above, you can see it's the same object (has same reference ID).

Any ideas?

Thanks!

Answer 1

Thanks all for the comments. As per the suggestions of asynchronous logging, and logging ordering, I added some sleeps to find out. After adding the sleeps, the locking waits as expected, so I think the logging was just out of order.