Logging FileHandler: static locks and hardcoded maximum number

[Behrooz Nobakht]

Hi Daniel,

Thanks for the quick reply.

On Thu, Feb 19, 2015 at 1:06 PM, Daniel Fuchs <daniel.fuchs at oracle.com>
wrote:

> Hi Behrooz,
>
> I have made several fixes WRT to lock files used by FileHandler
> recently. Could you please tell us which version of java you
> are using when observing this?
>
> I'll need to analyze your issue a bit deeper - and knowing
> the version (java -version) will help me in not making false
> assumptions :-)
>

The version of Java is irrelevant. We have tested our setup
on Java 7 and Java 8 u25/31. We observe the same exception.


>
> I'm not sure I understand the notion of 'preparing a FileHandler
> for p2' - p1 will need to close that file handler before p2 starts,
> otherwise the file that p1 uses will be locked, and p2 will have
> to create a new file.
>


The p1 JVM behaves like a Java Launcher. In one of its steps,
it creates a redirect thread for the to-be-launched process p2.
The redirect thread uses Java logging and in there, we use an
instance of FileHandler. So, actually, p2 is not aware of such
FileHandler object. FileHandler#close() is called as the result of
the launched p2 process exiting. I hope this clarifies further.
Going back to the above Java relevancy, that's why Java's version
is not relevant. Because FileHandler is initialized the first time
in p1 JVM and since p1 JVM does not exit, so after 100 times
that we try to launch p2 from p1, the maximum exceeds and
we get the exception.

Thanks,
Behrooz




>
> best regards,
>
> -- daniel
>
>
> On 19/02/15 12:44, Behrooz Nobakht wrote:
>
>> Hi,
>>
>> The following describes my situation:
>>
>> 1. I have a long running JVM process (p1).
>> 2. The long running process instantiate another JVM process (p2).
>> 3. On every instantiation of p2, p1 prepares an instance of FileHandler
>> for
>> p2
>>   (used through a redirect thread of logging) as:
>> new FileHandler("/path/to/log/app.stdouterr.%u.%g.log"
>> 4. p2 is short-lived and on its JVM exit, it closes FileHandler
>> 5. p1 can start p2 an arbitrary number of times
>>
>> Our observation started with the following exception:
>>
>> Caused by: java.io.IOException: Couldn't get lock for
>> /path/to/log/app.stdouterr.%u.%g.log
>>          at java.util.logging.FileHandler.openFiles(FileHandler.java:422)
>>          at java.util.logging.FileHandler.<init>(FileHandler.java:318)
>>          (...)
>>
>> Then, I tried to understand why, and I used the following on the running
>> server:
>>
>> $ lsof -uappuser | grep -E "\/path\/to\/log"
>>
>> It's interesting that I see 100 files as ".lck" in generation 0
>> as the following shows (the results are trimmed):
>>
>> ===
>> java    14515 appuser  182wW  REG              252,0        0 109052248
>> /path/to/log/app.stdouterr.0.0.log.lck (deleted)
>> java    14515 appuser  183wW  REG              252,0        0  92274968
>> /path/to/log/app.stdouterr.1.0.log.lck (deleted)
>> java    14515 appuser  184wW  REG              252,0        0 125829396
>> /path/to/log/app.stdouterr.2.0.log.lck (deleted)
>> .
>> .
>> .
>> java    14515 appuser  206wW  REG              252,0        0 109052253
>> /path/to/log/app.stdouterr.98.0.log.lck (deleted)
>> java    14515 appuser  207wW  REG              252,0        0 125829401
>> /path/to/log/app.stdouterr.99.0.log.lck (deleted)
>> java    14515 appuser  168wW  REG              252,0        0   8388893
>> /path/to/log/app.stdouterr.100.0.log.lck
>> java    14515 appuser  176w   REG              252,0      367   8388894
>> /path/to/log/app.stdouterr.100.0.log
>> ===
>>
>> Please note that except the last two, all the *.lck files are marked as
>> (deleted),
>> which means they are not available in the file system (confirmed)
>> but a process has an open handle on the path.
>>
>> Simply, based on (3) and (4), when p1 would reach the 100th time it wants
>> to
>> instantiate p2, we start to observe the exception.
>>
>> As far as I can see the source for FileHandler:
>>
>> - a static field is used to hold the lock files
>> - in our setup, the JVM in p1 initiates the above static field as part of
>> the first time preparing p2
>> - the (deleted) in the above, means that FileHandler#close has been called
>> with success.
>>
>> Questions/Suggestions:
>>
>> (a) The above (deleted) handles would not be released until p1 JVM goes
>> down, correct?
>> (b) If (a) is correct, is there way to ask JVM to do so on FileHandler? If
>> yes, where should I look into?
>> (c) If (b) is no, is there a chance FileHandler could introduce a new API
>> method to be able to perform such clean-up without having to exit p1 JVM?
>>
>> Thanks,
>> Behrooz
>>
>>
>


-- 
-- Behrooz Nobakht