1

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!

user3133269
  • 31
  • 1
  • 4
  • Most likely you have more locks than you think. – Peter Lawrey Dec 24 '13 at 19:27
  • @Peter Looks like the same object `ReentrantLock@4462cf1d`. Does a `ReentrantLock` have counters like a `Semaphore`? I don't think so. – Sotirios Delimanolis Dec 24 '13 at 19:31
  • Are you sure you didn't miss some unlocking in the logs. – Sotirios Delimanolis Dec 24 '13 at 19:32
  • 1
    It is possible that depending on how your logging is set up that the lock is actually honored, but the logging is out of order. It seems that only 1/50th of a second passed between the relevant logging messages. – SamYonnou Dec 24 '13 at 19:33
  • Is it possibly you are using an asynchronous logger? – Peter Lawrey Dec 24 '13 at 19:34
  • I'm sure it's the same lock. I even used the 'final' keyword everywhere it's set, and in parameter signatures. I didn't miss any unlocking in the logs, but I do call a condition.await() right after the first lock. I don't think this messes with the locking though.. – user3133269 Dec 24 '13 at 19:38
  • I'm pretty sure it's not the same method call (according to the number of dots in logging messages). It would be better if you provide a detailed code snippet (including logging, and lock sharing among CamTask and MyProcessor) – white Dec 24 '13 at 19:50
  • 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. I didn't find a way to credit you guys for your suggestions in the comments above, but thanks again! – user3133269 Dec 24 '13 at 20:04
  • It's also possible that the lock was acquired multiple times by the same thread; reentrant locks allow that. – David Ehrmann Dec 31 '13 at 20:09

1 Answers1

0

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.

user3133269
  • 31
  • 1
  • 4