Title: Showers of stack dumps from netty finalization
Type: crash Severity: normal
Components: Versions: Jython 2.7
Status: open Resolution: accepted
Dependencies: Superseder:
Assigned To: jeff.allen Nosy List: amak, jeff.allen, zyasoft
Priority: high Keywords: test failure causes

Created on 2016-08-31.06:51:17 by jeff.allen, last changed 2017-03-18.15:07:24 by jeff.allen.

msg10924 (view) Author: Jeff Allen (jeff.allen) Date: 2016-08-31.06:51:15
Observed on Windows regrtest, I get a lot of these (below) after test_socket_jy. It's not actually a test failure, but seems to indicate we have something wrong.

    [exec] Aug 31, 2016 7:27:46 AM io.netty.util.concurrent.DefaultPromise safeExecute
     [exec] SEVERE: Failed to submit a listener notification task. Event loop shut down?
     [exec] java.util.concurrent.RejectedExecutionException: event executor terminated
     [exec]     at io.netty.util.concurrent.SingleThreadEventExecutor.reject(
     [exec]     at io.netty.util.concurrent.SingleThreadEventExecutor.offerTask(
     [exec]     at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(
     [exec]     at io.netty.util.concurrent.SingleThreadEventExecutor.execute(
     [exec]     at io.netty.util.concurrent.DefaultPromise.safeExecute(
     [exec]     at io.netty.util.concurrent.DefaultPromise.notifyListeners(
     [exec]     at io.netty.util.concurrent.DefaultPromise.addListener(
     [exec]     at
     [exec]     at
     [exec]     at sun.reflect.GeneratedMethodAccessor332.invoke(Unknown Source)
     [exec]     at sun.reflect.DelegatingMethodAccessorImpl.invoke(
     [exec]     at java.lang.reflect.Method.invoke(
     [exec]     at org.python.core.PyReflectedFunction.__call__(
     [exec]     at org.python.core.PyReflectedFunction.__call__(
     [exec]     at org.python.core.PyObject.__call__(
     [exec]     at org.python.core.PyObject.__call__(
     [exec]     at org.python.core.PyMethod.__call__(
     [exec]     at _socket$py.close$89(C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\
     [exec]     at _socket$py.call_function(C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\
     [exec]     at
     [exec]     at
     [exec]     at org.python.core.PyFunction.__call__(
     [exec]     at org.python.core.PyMethod.__call__(
     [exec]     at _socket$py.close$127(C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\
     [exec]     at _socket$py.call_function(C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\
     [exec]     at
     [exec]     at
     [exec]     at org.python.core.PyFunction.__call__(
     [exec]     at org.python.core.PyMethod.__call__(
     [exec]     at _socket$py.__del__$129(C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\
     [exec]     at _socket$py.call_function(C:\Users\Jeff\Documents\Eclipse\jython-trunk\dist\Lib\
     [exec]     at
     [exec]     at
     [exec]     at org.python.core.PyFunction.__call__(
     [exec]     at org.python.core.PyMethod.__call__(
     [exec]     at org.python.core.PyMethod.__call__(
     [exec]     at org.python.core.PyObjectDerived.__del_derived__(
     [exec]     at org.python.core.finalization.FinalizeTrigger.runFinalizer(
     [exec]     at org.python.core.finalization.FinalizeTrigger.performFinalization(
     [exec]     at org.python.core.finalization.FinalizeTrigger.finalize(
     [exec]     at java.lang.System$2.invokeFinalize(
     [exec]     at java.lang.ref.Finalizer.runFinalizer(
     [exec]     at java.lang.ref.Finalizer.access$100(
     [exec]     at java.lang.ref.Finalizer$
msg10926 (view) Author: Jim Baker (zyasoft) Date: 2016-09-02.18:25:18
This is a side effect of our upgrade to Netty 4.1 - before Netty dropped these notifications.

We just need to setup the appropriate listener to quiet. To be researched what that is, but we should get this done for the RC - random stuff to stderr has impact on usage.
msg10928 (view) Author: Jim Baker (zyasoft) Date: 2016-09-02.20:24:46
The relevant Netty change is, which happened in 4.0.16; but most likely 4.1 made this more prominent. My recollection is that I don't believe it's possible to have Python socket closing semantics without attempting to close the pool as soon as possible - as it is, we wait up to 100ms. See the _realsocket._finish_closing method in Lib/ for more on what is being done to close the socket.

Therefore we need to take advantage of the rejected logger, which is under the name io.netty.util.concurrent.DefaultPromise.rejectedExecution; see

Assuming SL4J + Logback is still being used, this advice on StackOverflow should be relevant: In particular we can put a suitably configured logback.xml in jython.jar or jython-dev.jar to remove this logging:
msg10941 (view) Author: Jim Baker (zyasoft) Date: 2016-09-06.05:21:57
I verified by looking at the source of Netty that logback is used. Now it's just a question of implementing the appropriate silencing.
msg11230 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-15.09:09:36
I'll take a look at this. Following Jim's advice (silence the messages) as a pragmatic answer, but also on the lookout for a root cause. It seems to be that we are giving work to a worker we already retired, but quite why I can't see.
msg11240 (view) Author: Jeff Allen (jeff.allen) Date: 2017-03-18.15:07:23
Not logback (which seems an excellent library BTW) but plain ol' java.util.logging. Netty adapts to what's available .

I'm going to quiet the stack dumps I observe in test_socket only, treating them for now as a side effect of the way we keep making and tearing things up when testing. There are two loggers: one producing at SEVERE, the other at WARNING, which I'll set to OFF and SEVERE respectively.

I suspect there are real causes here we could fix, along with the hang I regularly experience, but I'd need to know more about Netty and sockets -- which I'd like to.
Date User Action Args
2017-03-18 15:07:24jeff.allensetmessages: + msg11240
2017-03-15 09:09:36jeff.allensetassignee: jeff.allen
messages: + msg11230
2017-02-27 04:45:33zyasoftsetpriority: urgent -> high
assignee: zyasoft -> (no value)
2016-09-06 05:21:58zyasoftsetmessages: + msg10941
2016-09-02 20:24:47zyasoftsetmessages: + msg10928
2016-09-02 18:25:18zyasoftsetpriority: normal -> urgent
assignee: zyasoft
resolution: accepted
messages: + msg10926
nosy: + zyasoft
2016-09-02 16:11:31amaksetnosy: + amak
2016-08-31 06:51:17jeff.allencreate