RFR of JDK-8134599: TEST_BUG: java/rmi/transport/closeServerSocket/CloseServerSocket.java fails intermittently with Address already in use

[Weijun Wang]

> On Oct 16, 2019, at 9:17 AM, Hamlin Li <huaming.li at oracle.com> wrote:
> 
> 
> On 2019/10/15 7:50 PM, Weijun Wang wrote:
>> 
>>> On Oct 15, 2019, at 5:44 PM, Hamlin Li <huaming.li at oracle.com> wrote:
>>> 
>>> 
>>> On 2019/10/15 2:44 PM, Weijun Wang wrote:
>>>> I am OK with the change that makes this test more robust.
>>> Thanks Max.
>>>> However, I am not an expert in RMI and don't know why the port cannot be released. If verifyPortFree(PORT) on line 60 can always succeed right after TestLibrary.getUnusedRandomPort() tries to create a ServerSocket at PORT and close it, this means the OS underneath spends no time in freeing the port.
>>> No, the port is not freed here, it's only freed by unexportObject.
>> I meant the auto close inside getUnusedRandomPort().
> 
> I think you misunderstood the 2 operations: socket.close and unexportObject.
> 
> As I mentioned below, unexportObject is an async operation, here "async" is in the RMI level: unexportObject => async close => socket.close => closed

Before you told me about the async mode, I was wondering maybe on some OS you cannot start listening on a port again *right after* closing a socket using this port. But from what happens in getUnusedRandomPort() this should not be true, and thus I suspected if socket is reliably closed. Now I understand this is because of the async mode.

> 
>> 
>>> But the original code is a little bit faulty at verifyPortInUse, it should be as below, I have also updated the webrev in place: http://cr.openjdk.java.net/~mli/8134599/webrev.01/
>>> 
>>> @@ -101,6 +112,7 @@
>>>      private static void verifyPortInUse(int port) throws IOException {
>>>          try {
>>>              verifyPortFree(port);
>>> +            throw new RuntimeException("port is not in use: " + port);
>>> 
>>>> Is UnicastRemoteObject.unexportObject() also doing something similar? I see that the ServerSocket inside is closed on TCPTransport.java:280. Is it reliably called?
>>> In my understanding, it's not a sync operation, it's async, that means when unexportObject returns, it just triggers the port release, does not mean it already released the port.
>> Ah....
>> 
>>>> Even after this bug is resolved, I'd suggest add some logging and rerun this test unchanged multiple times to see what really happened.
>>> Unfortunately, most of time this kind of issue is not easy to reproduce by running it multiple times. In my point of view, current logging is sufficient for diagnosing.
>> I see some logging calls inside source code. Maybe you can set a logging config file to let it show more?
> 
> I'm not sure I get your point, could you help to clarify?

For example, in src/java.rmi/share/classes/sun/rmi/transport/ObjectTable.java, there is

if (DGCImpl.dgcLog.isLoggable(Log.VERBOSE)) {
    DGCImpl.dgcLog.log(Log.VERBOSE, "remove object " + oe);
}

So it looks it supports logging. Maybe you can provide a logging config file with -Djava.util.logging.config.file and see more info.

Thanks,
Max

> 
> Thank you
> 
> -Hamlin
> 
>> 
>> --Max
>> 
>>> Thank you
>>> 
>>> -Hamlin
>>> 
>>>> --Max
>>>> 
>>>> 
>>>>> On Oct 15, 2019, at 11:04 AM, Hamlin Li <huaming.li at oracle.com> wrote:
>>>>> 
>>>>> Thanks for reviewing, I updated change at: http://cr.openjdk.java.net/~mli/8134599/webrev.01/
>>>>> 
>>>>> it does not increase minimum time time and consider timeout factor at the same time.
>>>>> 
>>>>> Thank you
>>>>> 
>>>>> -Hamlin