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

Wed Nov 4 09:59:44 UTC 2015

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
>>>>>>
>>>>>
>>>>
>>>
>>
>