RFR: 8138916: Logging write function does not allow for long enough messages

Wed Nov 4 22:27:59 UTC 2015

Great, thank you, Marcus!
Rachel

On 11/4/2015 2:59 PM, Marcus Larsson wrote:
> Looks good!
>
> Regards,
> Marcus
>
> On 2015-11-04 20:49, Rachel Protacio wrote:
>> Updated webrev with this fgets change: 
>> http://cr.openjdk.java.net/~rprotacio/8139564.04/
>>
>> Passes JPRT tests.
>>
>> Thank you,
>> Rachel
>>
>> On 11/4/2015 4:59 AM, Marcus Larsson wrote:
>>> Hmm, I just noticed that the test doesn't null terminate the string 
>>> it reads from file. Replacing the fgetc loop with a call to fgets 
>>> should fix this.
>>>
>>> Regards,
>>> Marcus
>>>
>>>
>>> On 2015-11-04 10:49, Marcus Larsson wrote:
>>>> Looks good, thank you for fixing this!
>>>>
>>>> Regards,
>>>> Marcus
>>>>
>>>>
>>>> On 2015-11-02 19:03, Rachel Protacio wrote:
>>>>> Thanks for the comments, Marcus. I've undone the "logtest" tag and 
>>>>> instead created an InternalVMTest in log.cpp that writes the 
>>>>> 518-character string to a temporary file and looks for it there. 
>>>>> Using "logging" tag in the "develop" level. Testing succeeds.
>>>>>
>>>>> Webrev: http://cr.openjdk.java.net/~rprotacio/8139564.03/
>>>>>
>>>>> Thank you,
>>>>> Rachel
>>>>>
>>>>> On 10/29/2015 6:35 AM, Marcus Larsson wrote:
>>>>>> Hi,
>>>>>>
>>>>>> On 2015-10-28 21:59, Rachel Protacio wrote:
>>>>>>> Including serviceability-dev. Recap:
>>>>>>>
>>>>>>> Summary: In logging/log.hpp, the logging vwrite function 
>>>>>>> previously asserted that the buffer remains within 512 
>>>>>>> characters, which is
>>>>>>> too short for logging message of non-pre-determined length, e.g. 
>>>>>>> for vtable and itable function names. Now, the function resizes 
>>>>>>> the buffer
>>>>>>> to the appropriate length, asserting only that the resulting 
>>>>>>> buffer is valid. Includes tag "logtest" to test that logging can 
>>>>>>> print an output
>>>>>>> of 518 characters.
>>>>>>>
>>>>>>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8138916.02
>>>>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8138916
>>>>>>
>>>>>> I don't like that the test log message is included in the 
>>>>>> product, or that a completely new tag is introduced for it.
>>>>>>
>>>>>> I think a much better approach would be to do the test logging in 
>>>>>> an internal VM test, reusing the logging tag. This way it won't 
>>>>>> be logged unless we are actually testing stuff, and we don't 
>>>>>> introduce a new tag. Also it would look better if it were logged 
>>>>>> on develop level.
>>>>>>
>>>>>> Thanks,
>>>>>> Marcus
>>>>>>
>>>>>>>
>>>>>>> Includes own acceptance test, and passes JPRT and remote 
>>>>>>> hotspot/test tests.
>>>>>>>
>>>>>>> Thank you,
>>>>>>> Rachel
>>>>>>>
>>>>>>> On 10/28/2015 4:08 PM, Rachel Protacio wrote:
>>>>>>>> Thanks for the review and all the feedback!
>>>>>>>> Rachel
>>>>>>>>
>>>>>>>> On 10/28/2015 4:05 PM, Dmitry Samersoff wrote:
>>>>>>>>> Rachel,
>>>>>>>>>
>>>>>>>>> Looks good for me!
>>>>>>>>>
>>>>>>>>> -Dmitry
>>>>>>>>>
>>>>>>>>> On 2015-10-28 20:50, Rachel Protacio wrote:
>>>>>>>>>> Thank you both. I've removed the re-declaration and added 
>>>>>>>>>> prefix_len to
>>>>>>>>>> newbuf_len. As for line 115, that line is not for the sake of
>>>>>>>>>> recalculating prefix_len, but for writing the prefix to the 
>>>>>>>>>> buffer.
>>>>>>>>>>
>>>>>>>>>> http://cr.openjdk.java.net/~rprotacio/8138916.02/
>>>>>>>>>>
>>>>>>>>>> Thanks,
>>>>>>>>>> Rachel
>>>>>>>>>>
>>>>>>>>>> On 10/28/2015 12:27 PM, Coleen Phillimore wrote:
>>>>>>>>>>> Dmitry, Thank you for reviewing and providing comments.  The 
>>>>>>>>>>> second
>>>>>>>>>>> version is better because of these things that I didn't 
>>>>>>>>>>> notice until
>>>>>>>>>>> you pointed it out.
>>>>>>>>>>>
>>>>>>>>>>> The malloc won't be frequent.  I think it'll be okay and 
>>>>>>>>>>> follows other
>>>>>>>>>>> coding patterns in the jvm.
>>>>>>>>>>>
>>>>>>>>>>> Thanks!
>>>>>>>>>>> Coleen
>>>>>>>>>>>
>>>>>>>>>>> On 10/28/15 12:09 PM, Dmitry Samersoff wrote:
>>>>>>>>>>>> Coleen,
>>>>>>>>>>>>
>>>>>>>>>>>> OK. I'm leaving it in good hands ;)
>>>>>>>>>>>>
>>>>>>>>>>>> -Dmitry
>>>>>>>>>>>>
>>>>>>>>>>>> On 2015-10-28 18:54, Coleen Phillimore wrote:
>>>>>>>>>>>>> Hi, I'm also reviewing this. I think this looks good. I 
>>>>>>>>>>>>> don't think
>>>>>>>>>>>>> the solution to allocate a static buffer is very nice 
>>>>>>>>>>>>> because it still
>>>>>>>>>>>>> has limits and we don't want to allocate something large 
>>>>>>>>>>>>> on the stack.
>>>>>>>>>>>>> The malloc case is the infrequent case. If it becomes 
>>>>>>>>>>>>> frequent we can
>>>>>>>>>>>>> increase LogBufferSize from 512.
>>>>>>>>>>>>>
>>>>>>>>>>>>> I think 111 the assert is good because if the windows code 
>>>>>>>>>>>>> is wrong (or
>>>>>>>>>>>>> the vscprintf does something wrong an unexpected) we can 
>>>>>>>>>>>>> catch the
>>>>>>>>>>>>> error
>>>>>>>>>>>>> with the assert before writing over memory.
>>>>>>>>>>>>>
>>>>>>>>>>>>> I agree 116 shouldn't redeclare 'ret'.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Otherwise, I think it looks really good and I don't need 
>>>>>>>>>>>>> to see another
>>>>>>>>>>>>> revision.
>>>>>>>>>>>>>
>>>>>>>>>>>>> Thanks!
>>>>>>>>>>>>> Coleen
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> On 10/28/15 11:40 AM, Dmitry Samersoff wrote:
>>>>>>>>>>>>>> Rachel,
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> On 2015-10-28 17:48, Rachel Protacio wrote:
>>>>>>>>>>>>>>> Thank you for the comments, both Dmitry and Mikael. 
>>>>>>>>>>>>>>> Replies inline.
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> Modified webrev: 
>>>>>>>>>>>>>>> http://cr.openjdk.java.net/~rprotacio/8138916.01/
>>>>>>>>>>>>>> 111 Assert is never happens on Windows, so it's better to 
>>>>>>>>>>>>>> move it to
>>>>>>>>>>>>>> os_posix
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> 113 newbuf_len doesn't account prefix_len
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> 115 you may consider to use pre-calculated at ll. 108 
>>>>>>>>>>>>>> prefix rather
>>>>>>>>>>>>>> than
>>>>>>>>>>>>>> calculate it again.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> 116 int ret redefined it causes a warning.
>>>>>>>>>>>>>>
>>>>>>>>>>>>>> -Dmitry
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> (Retested and works fine.)
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>> On 10/27/2015 7:52 AM, Dmitry Samersoff wrote:
>>>>>>>>>>>>>>>> Rachel,
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> In worst case (windows, overflow) the code would parse 
>>>>>>>>>>>>>>>> format string
>>>>>>>>>>>>>>>> four times.
>>>>>>>>>>>>>>> You're right. I've added a check. New amount of times 
>>>>>>>>>>>>>>> vnsprintf() is
>>>>>>>>>>>>>>> called:
>>>>>>>>>>>>>>> posix, fits => 1
>>>>>>>>>>>>>>> posix, overflow => 2
>>>>>>>>>>>>>>> windows, fits => 1
>>>>>>>>>>>>>>> windows, overflow => 3 (the best performance we can get)
>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> Also NEW_C_HEAP_ARRAY takes a lock and might become a
>>>>>>>>>>>>>>>> performance bottleneck.
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> POSIX equivalent of _vscprintf(fmt, args) is 
>>>>>>>>>>>>>>>> vsnprintf(NULL, 0, fmt,
>>>>>>>>>>>>>>>> args)
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> So it might be better to create os::log_vcprintf(fmt, 
>>>>>>>>>>>>>>>> args), then
>>>>>>>>>>>>>>>> write
>>>>>>>>>>>>>>>> code at log.hpp as:
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> int buf_len = os::log_vcprintf(fmt, args);
>>>>>>>>>>>>>>>> assert(buf_len < 2*page_size, "Stack overflow in 
>>>>>>>>>>>>>>>> logging");
>>>>>>>>>>>>>>>> char buf[buf_len];
>>>>>>>>>>>>>>>> vsprintf(buf, fmt, args);
>>>>>>>>>>>>>>> I don't think this would work anyway. A char[] needs a 
>>>>>>>>>>>>>>> static size.
>>>>>>>>>>>>>>> Thanks,
>>>>>>>>>>>>>>> Rachel
>>>>>>>>>>>>>>>> -Dmitry
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>> On 2015-10-26 23:58, Rachel Protacio wrote:
>>>>>>>>>>>>>>>>> Hello, all,
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Please review this fix to the faulty write function 
>>>>>>>>>>>>>>>>> from the
>>>>>>>>>>>>>>>>> Unified
>>>>>>>>>>>>>>>>> Logging framework.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Summary: In logging/log.hpp, the logging vwrite 
>>>>>>>>>>>>>>>>> function previously
>>>>>>>>>>>>>>>>> asserted that the buffer remains within 512 
>>>>>>>>>>>>>>>>> characters, which is
>>>>>>>>>>>>>>>>> too
>>>>>>>>>>>>>>>>> short for logging message of non-pre-determined 
>>>>>>>>>>>>>>>>> length, e.g. for
>>>>>>>>>>>>>>>>> vtable
>>>>>>>>>>>>>>>>> and itable function names. Now, the function resizes 
>>>>>>>>>>>>>>>>> the buffer
>>>>>>>>>>>>>>>>> to the
>>>>>>>>>>>>>>>>> appropriate length, asserting only that the resulting 
>>>>>>>>>>>>>>>>> buffer is
>>>>>>>>>>>>>>>>> valid.
>>>>>>>>>>>>>>>>> Includes tag "logtest" to test that logging can print 
>>>>>>>>>>>>>>>>> an output
>>>>>>>>>>>>>>>>> of 518
>>>>>>>>>>>>>>>>> characters.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Open 
>>>>>>>>>>>>>>>>> webrev:http://cr.openjdk.java.net/~rprotacio/8138916/
>>>>>>>>>>>>>>>>> Bug:https://bugs.openjdk.java.net/browse/JDK-8138916
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Includes own acceptance test, and passes JPRT and remote
>>>>>>>>>>>>>>>>> hotspot/test
>>>>>>>>>>>>>>>>> tests.
>>>>>>>>>>>>>>>>>
>>>>>>>>>>>>>>>>> Thank you,
>>>>>>>>>>>>>>>>> Rachel
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>