Gentlemen,

I am working at the start of a fairly large project.  I have some questions
related to the general health of Apex...need to get a warm and fuzzy
feeling that the project is not going to die on the vine as it were.

I am seeing the volume of commits and contributor activity dropped off
significantly since early 2016 and there has been a drop again after
Datatorrent folded...What is your sense of the project?  I really like the
framework and definitely would prefer to use it as well as contribute
back...just want to make sure I am not going to have work on it solo or
worse, end up having to switch to something else later...

Your thoughts?

Aaron

On Wed, Jun 20, 2018 at 12:10 PM Pramod Immaneni <pramod.imman...@gmail.com>
wrote:

> There are hadoop IPC calls are failing possibly because of its reliance on
> kryo for serializing the payload and there is some incompatibility with the
> new version. I will dig in more to see what is going on.
>
> On Tue, Jun 19, 2018 at 6:54 PM Aaron Bossert <aa...@punchcyber.com>
> wrote:
>
> > Pramod,
> >
> > Thanks for taking the time to help!
> >
> > Here is the output (just failed parts) when running full install (clean
> > install -X) on the Master branch:
> >
> > Running com.datatorrent.stram.StramRecoveryTest
> > 2018-06-19 21:34:28,137 [main] INFO  stram.StramRecoveryTest
> > testRpcFailover - Mock server listening at macbook-pro-6.lan/
> > 192.168.87.125:62154
> > 2018-06-19 21:34:28,678 [main] ERROR stram.RecoverableRpcProxy invoke -
> > Giving up RPC connection recovery after 507 ms
> > java.net.SocketTimeoutException: Call From macbook-pro-6.lan/
> > 192.168.87.125
> > to macbook-pro-6.lan:62154 failed on socket timeout exception:
> > java.net.SocketTimeoutException: 500 millis timeout while waiting for
> > channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62155
> > remote=macbook-pro-6.lan/192.168.87.125:62154]; For more details see:
> > http://wiki.apache.org/hadoop/SocketTimeout
> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> > at
> >
> >
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> > at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791)
> > at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:750)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1472)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1399)
> > at
> >
> >
> org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:244)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> com.datatorrent.stram.RecoverableRpcProxy.invoke(RecoverableRpcProxy.java:157)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testRpcFailover(StramRecoveryTest.java:561)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> > at
> >
> >
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> > at
> >
> >
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> > at
> >
> >
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> > at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> > at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.junit.runners.Suite.runChild(Suite.java:127)
> > at org.junit.runners.Suite.runChild(Suite.java:26)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> > at
> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
> > Caused by: java.net.SocketTimeoutException: 500 millis timeout while
> > waiting for channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62155
> > remote=macbook-pro-6.lan/192.168.87.125:62154]
> > at
> > org.apache.hadoop.net
> > .SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:161)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:131)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:513)
> > at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1071)
> > at org.apache.hadoop.ipc.Client$Connection.run(Client.java:966)
> > 2018-06-19 21:34:29,178 [IPC Server handler 0 on 62154] WARN  ipc.Server
> > processResponse - IPC Server handler 0 on 62154, call log(containerId,
> > timeout), rpc version=2, client version=201208081755,
> > methodsFingerPrint=-1300451462 from 192.168.87.125:62155 Call#136
> Retry#0:
> > output error
> > 2018-06-19 21:34:29,198 [main] WARN  stram.RecoverableRpcProxy invoke -
> RPC
> > failure, will retry after 100 ms (remaining 994 ms)
> > java.net.SocketTimeoutException: Call From macbook-pro-6.lan/
> > 192.168.87.125
> > to macbook-pro-6.lan:62154 failed on socket timeout exception:
> > java.net.SocketTimeoutException: 500 millis timeout while waiting for
> > channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62156
> > remote=macbook-pro-6.lan/192.168.87.125:62154]; For more details see:
> > http://wiki.apache.org/hadoop/SocketTimeout
> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> > at
> >
> >
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> > at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791)
> > at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:750)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1472)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1399)
> > at
> >
> >
> org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:244)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> com.datatorrent.stram.RecoverableRpcProxy.invoke(RecoverableRpcProxy.java:157)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testRpcFailover(StramRecoveryTest.java:575)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> > at
> >
> >
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> > at
> >
> >
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> > at
> >
> >
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> > at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> > at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.junit.runners.Suite.runChild(Suite.java:127)
> > at org.junit.runners.Suite.runChild(Suite.java:26)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> > at
> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
> > Caused by: java.net.SocketTimeoutException: 500 millis timeout while
> > waiting for channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62156
> > remote=macbook-pro-6.lan/192.168.87.125:62154]
> > at
> > org.apache.hadoop.net
> > .SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:161)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:131)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:513)
> > at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1071)
> > at org.apache.hadoop.ipc.Client$Connection.run(Client.java:966)
> > 2018-06-19 21:34:29,806 [main] WARN  stram.RecoverableRpcProxy invoke -
> RPC
> > failure, will retry after 100 ms (remaining 386 ms)
> > java.net.SocketTimeoutException: Call From macbook-pro-6.lan/
> > 192.168.87.125
> > to macbook-pro-6.lan:62154 failed on socket timeout exception:
> > java.net.SocketTimeoutException: 500 millis timeout while waiting for
> > channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62157
> > remote=macbook-pro-6.lan/192.168.87.125:62154]; For more details see:
> > http://wiki.apache.org/hadoop/SocketTimeout
> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> > at
> >
> >
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> > at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791)
> > at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:750)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1472)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1399)
> > at
> >
> >
> org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:244)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> com.datatorrent.stram.RecoverableRpcProxy.invoke(RecoverableRpcProxy.java:157)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testRpcFailover(StramRecoveryTest.java:575)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> > at
> >
> >
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> > at
> >
> >
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> > at
> >
> >
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> > at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> > at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.junit.runners.Suite.runChild(Suite.java:127)
> > at org.junit.runners.Suite.runChild(Suite.java:26)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> > at
> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
> > Caused by: java.net.SocketTimeoutException: 500 millis timeout while
> > waiting for channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62157
> > remote=macbook-pro-6.lan/192.168.87.125:62154]
> > at
> > org.apache.hadoop.net
> > .SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:161)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:131)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:513)
> > at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1071)
> > at org.apache.hadoop.ipc.Client$Connection.run(Client.java:966)
> > 2018-06-19 21:34:30,180 [IPC Server handler 0 on 62154] WARN  ipc.Server
> > processResponse - IPC Server handler 0 on 62154, call log(containerId,
> > timeout), rpc version=2, client version=201208081755,
> > methodsFingerPrint=-1300451462 from 192.168.87.125:62156 Call#137
> Retry#0:
> > output error
> > 2018-06-19 21:34:30,808 [main] ERROR stram.RecoverableRpcProxy invoke -
> > Giving up RPC connection recovery after 506 ms
> > java.net.SocketTimeoutException: Call From macbook-pro-6.lan/
> > 192.168.87.125
> > to macbook-pro-6.lan:62154 failed on socket timeout exception:
> > java.net.SocketTimeoutException: 500 millis timeout while waiting for
> > channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62159
> > remote=macbook-pro-6.lan/192.168.87.125:62154]; For more details see:
> > http://wiki.apache.org/hadoop/SocketTimeout
> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> > at
> >
> >
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> > at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791)
> > at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:750)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1472)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1399)
> > at
> >
> >
> org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:244)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> com.datatorrent.stram.RecoverableRpcProxy.invoke(RecoverableRpcProxy.java:157)
> > at com.sun.proxy.$Proxy138.log(Unknown Source)
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testRpcFailover(StramRecoveryTest.java:596)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> > at
> >
> >
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> > at
> >
> >
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> > at
> >
> >
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> > at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> > at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.junit.runners.Suite.runChild(Suite.java:127)
> > at org.junit.runners.Suite.runChild(Suite.java:26)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> > at
> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
> > Caused by: java.net.SocketTimeoutException: 500 millis timeout while
> > waiting for channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62159
> > remote=macbook-pro-6.lan/192.168.87.125:62154]
> > at
> > org.apache.hadoop.net
> > .SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:161)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:131)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:513)
> > at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1071)
> > at org.apache.hadoop.ipc.Client$Connection.run(Client.java:966)
> > 2018-06-19 21:34:31,307 [IPC Server handler 0 on 62154] WARN  ipc.Server
> > processResponse - IPC Server handler 0 on 62154, call log(containerId,
> > timeout), rpc version=2, client version=201208081755,
> > methodsFingerPrint=-1300451462 from 192.168.87.125:62159 Call#141
> Retry#0:
> > output error
> > 2018-06-19 21:34:31,327 [main] WARN  stram.RecoverableRpcProxy invoke -
> RPC
> > failure, will retry after 100 ms (remaining 995 ms)
> > java.net.SocketTimeoutException: Call From macbook-pro-6.lan/
> > 192.168.87.125
> > to macbook-pro-6.lan:62154 failed on socket timeout exception:
> > java.net.SocketTimeoutException: 500 millis timeout while waiting for
> > channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62160
> > remote=macbook-pro-6.lan/192.168.87.125:62154]; For more details see:
> > http://wiki.apache.org/hadoop/SocketTimeout
> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> > at
> >
> >
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> > at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791)
> > at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:750)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1472)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1399)
> > at
> >
> >
> org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:244)
> > at com.sun.proxy.$Proxy138.reportError(Unknown Source)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> com.datatorrent.stram.RecoverableRpcProxy.invoke(RecoverableRpcProxy.java:157)
> > at com.sun.proxy.$Proxy138.reportError(Unknown Source)
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testRpcFailover(StramRecoveryTest.java:610)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> > at
> >
> >
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> > at
> >
> >
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> > at
> >
> >
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> > at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> > at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.junit.runners.Suite.runChild(Suite.java:127)
> > at org.junit.runners.Suite.runChild(Suite.java:26)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> > at
> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
> > Caused by: java.net.SocketTimeoutException: 500 millis timeout while
> > waiting for channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62160
> > remote=macbook-pro-6.lan/192.168.87.125:62154]
> > at
> > org.apache.hadoop.net
> > .SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:161)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:131)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:513)
> > at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1071)
> > at org.apache.hadoop.ipc.Client$Connection.run(Client.java:966)
> > 2018-06-19 21:34:31,931 [main] WARN  stram.RecoverableRpcProxy invoke -
> RPC
> > failure, will retry after 100 ms (remaining 391 ms)
> > java.net.SocketTimeoutException: Call From macbook-pro-6.lan/
> > 192.168.87.125
> > to macbook-pro-6.lan:62154 failed on socket timeout exception:
> > java.net.SocketTimeoutException: 500 millis timeout while waiting for
> > channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62161
> > remote=macbook-pro-6.lan/192.168.87.125:62154]; For more details see:
> > http://wiki.apache.org/hadoop/SocketTimeout
> > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> > at
> >
> >
> sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
> > at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:791)
> > at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:750)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1472)
> > at org.apache.hadoop.ipc.Client.call(Client.java:1399)
> > at
> >
> >
> org.apache.hadoop.ipc.WritableRpcEngine$Invoker.invoke(WritableRpcEngine.java:244)
> > at com.sun.proxy.$Proxy138.reportError(Unknown Source)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> com.datatorrent.stram.RecoverableRpcProxy.invoke(RecoverableRpcProxy.java:157)
> > at com.sun.proxy.$Proxy138.reportError(Unknown Source)
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testRpcFailover(StramRecoveryTest.java:610)
> > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> > at
> >
> >
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> > at
> >
> >
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> > at java.lang.reflect.Method.invoke(Method.java:498)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> > at
> >
> >
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> > at
> >
> >
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> > at
> >
> >
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> > at
> >
> >
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> > at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> > at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> > at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> > at
> >
> >
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.junit.runners.Suite.runChild(Suite.java:127)
> > at org.junit.runners.Suite.runChild(Suite.java:26)
> > at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> > at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> > at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> > at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> > at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> > at org.junit.runners.ParentRunner.run(ParentRunner.java:309)
> > at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> > at
> >
> >
> org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:161)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:290)
> > at
> >
> >
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:242)
> > at
> > org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:121)
> > Caused by: java.net.SocketTimeoutException: 500 millis timeout while
> > waiting for channel to be ready for read. ch :
> > java.nio.channels.SocketChannel[connected local=/192.168.87.125:62161
> > remote=macbook-pro-6.lan/192.168.87.125:62154]
> > at
> > org.apache.hadoop.net
> > .SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:161)
> > at org.apache.hadoop.net
> > .SocketInputStream.read(SocketInputStream.java:131)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at java.io.FilterInputStream.read(FilterInputStream.java:133)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:513)
> > at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
> > at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> >
> >
> org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1071)
> > at org.apache.hadoop.ipc.Client$Connection.run(Client.java:966)
> > 2018-06-19 21:34:32,310 [IPC Server handler 0 on 62154] WARN  ipc.Server
> > processResponse - IPC Server handler 0 on 62154, call
> > reportError(containerId, null, timeout, null), rpc version=2, client
> > version=201208081755, methodsFingerPrint=-1300451462 from
> > 192.168.87.125:62160 Call#142 Retry#0: output error
> > 2018-06-19 21:34:32,512 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithSyncAgent/app1/recovery/log
> > 2018-06-19 21:34:32,628 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithSyncAgent/app1/recovery/log
> > 2018-06-19 21:34:32,696 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithSyncAgent/app2/recovery/log
> > 2018-06-19 21:34:32,698 [main] INFO  stram.StramClient copyInitialState -
> > Copying initial state took 32 ms
> > 2018-06-19 21:34:32,799 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithSyncAgent/app2/recovery/log
> > 2018-06-19 21:34:32,850 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithSyncAgent/app3/recovery/log
> > 2018-06-19 21:34:32,851 [main] INFO  stram.StramClient copyInitialState -
> > Copying initial state took 28 ms
> > 2018-06-19 21:34:32,955 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithSyncAgent/app3/recovery/log
> > 2018-06-19 21:34:32,976 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=3,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:32,977 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=4,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:32,977 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=5,name=o3,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,166 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=3,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,166 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=4,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,166 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=5,name=o3,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,338 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp2603930902590449397
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:33,436 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithAsyncAgent/app1/recovery/log
> > 2018-06-19 21:34:33,505 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithAsyncAgent/app1/recovery/log
> > 2018-06-19 21:34:33,553 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithAsyncAgent/app2/recovery/log
> > 2018-06-19 21:34:33,554 [main] INFO  stram.StramClient copyInitialState -
> > Copying initial state took 22 ms
> > 2018-06-19 21:34:33,642 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithAsyncAgent/app2/recovery/log
> > 2018-06-19 21:34:33,690 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithAsyncAgent/app3/recovery/log
> > 2018-06-19 21:34:33,691 [main] INFO  stram.StramClient copyInitialState -
> > Copying initial state took 29 ms
> > 2018-06-19 21:34:33,805 [main] INFO  stram.FSRecoveryHandler rotateLog -
> > Creating
> >
> >
> target/com.datatorrent.stram.StramRecoveryTest/testRestartAppWithAsyncAgent/app3/recovery/log
> > 2018-06-19 21:34:33,830 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=3,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,830 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=4,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,831 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=5,name=o3,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:33,831 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp1878353095301008843
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:34,077 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=3,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:34,077 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=4,name=o2,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:34,077 [main] WARN  physical.PhysicalPlan <init> -
> > Operator PTOperator[id=5,name=o3,state=INACTIVE] shares container without
> > locality contraint due to insufficient resources.
> > 2018-06-19 21:34:34,077 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp7337975615972280003
> as
> > the basepath for checkpointing.
> > Tests run: 8, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 6.143 sec
> > <<< FAILURE! - in com.datatorrent.stram.StramRecoveryTest
> > testWriteAheadLog(com.datatorrent.stram.StramRecoveryTest)  Time elapsed:
> > 0.111 sec  <<< FAILURE!
> > java.lang.AssertionError: flush count expected:<1> but was:<2>
> > at
> >
> >
> com.datatorrent.stram.StramRecoveryTest.testWriteAheadLog(StramRecoveryTest.java:326)
> >
> >
> > Running com.datatorrent.stram.CustomControlTupleTest
> > 2018-06-19 21:34:49,308 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp1213673348429546877
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:49,451 [main] INFO  storage.DiskStorage <init> - using
> > /Users/mbossert/testIdea/apex-core/engine/target as the basepath for
> > spooling.
> > 2018-06-19 21:34:49,451 [ProcessWideEventLoop] INFO  server.Server
> > registered - Server started listening at /0:0:0:0:0:0:0:0:62181
> > 2018-06-19 21:34:49,451 [main] INFO  stram.StramLocalCluster run - Buffer
> > server started: localhost:62181
> > 2018-06-19 21:34:49,452 [container-0] INFO  stram.StramLocalCluster run -
> > Started container container-0
> > 2018-06-19 21:34:49,452 [container-1] INFO  stram.StramLocalCluster run -
> > Started container container-1
> > 2018-06-19 21:34:49,452 [container-2] INFO  stram.StramLocalCluster run -
> > Started container container-2
> > 2018-06-19 21:34:49,452 [container-1] INFO  stram.StramLocalCluster log -
> > container-1 msg: [container-1] Entering heartbeat loop..
> > 2018-06-19 21:34:49,452 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Entering heartbeat loop..
> > 2018-06-19 21:34:49,452 [container-2] INFO  stram.StramLocalCluster log -
> > container-2 msg: [container-2] Entering heartbeat loop..
> > 2018-06-19 21:34:50,460 [container-2] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=3,name=receiver,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=ProcessorToReceiver,sourceNodeId=2,sourcePortName=output,locality=<null>,partitionMask=0,partitionKeys=<null>]],outputs=[]]]
> > 2018-06-19 21:34:50,460 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=1,name=randomGenerator,type=INPUT,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=out,streamId=genToProcessor,bufferServer=localhost]]]]
> > 2018-06-19 21:34:50,460 [container-1] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=2,name=process,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=<null>,partitionMask=0,partitionKeys=<null>]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=localhost]]]]
> > 2018-06-19 21:34:50,463 [container-0] INFO  engine.WindowGenerator
> activate
> > - Catching up from 1529458489500 to 1529458490463
> > 2018-06-19 21:34:50,465 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62181/2.output.1, windowId=ffffffffffffffff,
> > type=ProcessorToReceiver/3.input, upstreamIdentifier=2.output.1, mask=0,
> > partitions=null, bufferSize=1024}
> > 2018-06-19 21:34:50,466 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=1.out.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:34:50,466 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=2.output.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:34:50,466 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62181/1.out.1, windowId=ffffffffffffffff,
> > type=genToProcessor/2.input, upstreamIdentifier=1.out.1, mask=0,
> > partitions=null, bufferSize=1024}
> > 2018-06-19 21:34:51,458 [main] INFO  stram.StramLocalCluster run -
> Stopping
> > on exit condition
> > 2018-06-19 21:34:51,458 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:51,458 [container-1] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:51,458 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Exiting heartbeat loop..
> > 2018-06-19 21:34:51,458 [container-2] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:51,458 [container-2] INFO  stram.StramLocalCluster log -
> > container-2 msg: [container-2] Exiting heartbeat loop..
> > 2018-06-19 21:34:51,458 [container-1] INFO  stram.StramLocalCluster log -
> > container-1 msg: [container-1] Exiting heartbeat loop..
> > 2018-06-19 21:34:51,461 [container-2] INFO  stram.StramLocalCluster run -
> > Container container-2 terminating.
> > 2018-06-19 21:34:51,467 [container-1] INFO  stram.StramLocalCluster run -
> > Container container-1 terminating.
> > 2018-06-19 21:34:51,467 [container-0] INFO  stram.StramLocalCluster run -
> > Container container-0 terminating.
> > 2018-06-19 21:34:51,467 [ServerHelper-86-1] INFO  server.Server run -
> > Removing ln LogicalNode@7d88b4a4identifier
> > =tcp://localhost:62181/2.output.1,
> > upstream=2.output.1, group=ProcessorToReceiver/3.input, partitions=[],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@35d66f18
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@d43c092
> > {identifier=2.output.1,
> > data=1048576, readingOffset=0, writingOffset=481,
> > starting_window=5b29af3900000001, ending_window=5b29af3900000005,
> > refCount=2, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@4dca4fb0[identifier=2.output.1]
> > 2018-06-19 21:34:51,468 [ServerHelper-86-1] INFO  server.Server run -
> > Removing ln LogicalNode@3cb5be9fidentifier
> =tcp://localhost:62181/1.out.1,
> > upstream=1.out.1, group=genToProcessor/2.input, partitions=[],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@5c9a41d0
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@5a324bf4
> > {identifier=1.out.1,
> > data=1048576, readingOffset=0, writingOffset=481,
> > starting_window=5b29af3900000001, ending_window=5b29af3900000005,
> > refCount=2, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@49665770[identifier=1.out.1]
> > 2018-06-19 21:34:51,469 [ProcessWideEventLoop] INFO  server.Server run -
> > Server stopped listening at /0:0:0:0:0:0:0:0:62181
> > 2018-06-19 21:34:51,469 [main] INFO  stram.StramLocalCluster run -
> > Application finished.
> > 2018-06-19 21:34:51,469 [main] INFO  stram.CustomControlTupleTest
> testApp -
> > Control Tuples received 3 expected 3
> > 2018-06-19 21:34:51,492 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp5496551078484285394
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:51,623 [main] INFO  storage.DiskStorage <init> - using
> > /Users/mbossert/testIdea/apex-core/engine/target as the basepath for
> > spooling.
> > 2018-06-19 21:34:51,624 [ProcessWideEventLoop] INFO  server.Server
> > registered - Server started listening at /0:0:0:0:0:0:0:0:62186
> > 2018-06-19 21:34:51,624 [main] INFO  stram.StramLocalCluster run - Buffer
> > server started: localhost:62186
> > 2018-06-19 21:34:51,624 [container-0] INFO  stram.StramLocalCluster run -
> > Started container container-0
> > 2018-06-19 21:34:51,624 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Entering heartbeat loop..
> > 2018-06-19 21:34:52,628 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=1,name=randomGenerator,type=INPUT,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=out,streamId=genToProcessor,bufferServer=<null>]]],
> >
> OperatorDeployInfo[id=2,name=process,type=OIO,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=THREAD_LOCAL,partitionMask=0,partitionKeys=<null>]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=<null>]]],
> >
> >
> OperatorDeployInfo[id=3,name=receiver,type=OIO,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=ProcessorToReceiver,sourceNodeId=2,sourcePortName=output,locality=THREAD_LOCAL,partitionMask=0,partitionKeys=<null>]],outputs=[]]]
> > 2018-06-19 21:34:52,630 [container-0] INFO  engine.WindowGenerator
> activate
> > - Catching up from 1529458491500 to 1529458492630
> > 2018-06-19 21:34:53,628 [main] INFO  stram.StramLocalCluster run -
> Stopping
> > on exit condition
> > 2018-06-19 21:34:53,629 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:53,630 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Exiting heartbeat loop..
> > 2018-06-19 21:34:53,640 [container-0] INFO  stram.StramLocalCluster run -
> > Container container-0 terminating.
> > 2018-06-19 21:34:53,641 [ProcessWideEventLoop] INFO  server.Server run -
> > Server stopped listening at /0:0:0:0:0:0:0:0:62186
> > 2018-06-19 21:34:53,642 [main] INFO  stram.StramLocalCluster run -
> > Application finished.
> > 2018-06-19 21:34:53,642 [main] INFO  stram.CustomControlTupleTest
> testApp -
> > Control Tuples received 3 expected 3
> > 2018-06-19 21:34:53,659 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp2212795894390935125
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:53,844 [main] INFO  storage.DiskStorage <init> - using
> > /Users/mbossert/testIdea/apex-core/engine/target as the basepath for
> > spooling.
> > 2018-06-19 21:34:53,844 [ProcessWideEventLoop] INFO  server.Server
> > registered - Server started listening at /0:0:0:0:0:0:0:0:62187
> > 2018-06-19 21:34:53,844 [main] INFO  stram.StramLocalCluster run - Buffer
> > server started: localhost:62187
> > 2018-06-19 21:34:53,845 [container-0] INFO  stram.StramLocalCluster run -
> > Started container container-0
> > 2018-06-19 21:34:53,845 [container-1] INFO  stram.StramLocalCluster run -
> > Started container container-1
> > 2018-06-19 21:34:53,845 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Entering heartbeat loop..
> > 2018-06-19 21:34:53,845 [container-2] INFO  stram.StramLocalCluster run -
> > Started container container-2
> > 2018-06-19 21:34:53,845 [container-1] INFO  stram.StramLocalCluster log -
> > container-1 msg: [container-1] Entering heartbeat loop..
> > 2018-06-19 21:34:53,845 [container-3] INFO  stram.StramLocalCluster run -
> > Started container container-3
> > 2018-06-19 21:34:53,845 [container-2] INFO  stram.StramLocalCluster log -
> > container-2 msg: [container-2] Entering heartbeat loop..
> > 2018-06-19 21:34:53,845 [container-3] INFO  stram.StramLocalCluster log -
> > container-3 msg: [container-3] Entering heartbeat loop..
> > 2018-06-19 21:34:54,850 [container-3] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=1,name=randomGenerator,type=INPUT,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=out,streamId=genToProcessor,bufferServer=localhost]]]]
> > 2018-06-19 21:34:54,850 [container-1] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=3,name=process,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=<null>,partitionMask=1,partitionKeys=[1]]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=localhost]]]]
> > 2018-06-19 21:34:54,850 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=4,name=receiver,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=ProcessorToReceiver,sourceNodeId=5,sourcePortName=outputPort,locality=CONTAINER_LOCAL,partitionMask=0,partitionKeys=<null>]],outputs=[]],
> >
> >
> OperatorDeployInfo.UnifierDeployInfo[id=5,name=process.output#unifier,type=UNIFIER,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=<merge#output>,streamId=ProcessorToReceiver,sourceNodeId=2,sourcePortName=output,locality=<null>,partitionMask=0,partitionKeys=<null>],
> >
> >
> OperatorDeployInfo.InputDeployInfo[portName=<merge#output>,streamId=ProcessorToReceiver,sourceNodeId=3,sourcePortName=output,locality=<null>,partitionMask=0,partitionKeys=<null>]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=outputPort,streamId=ProcessorToReceiver,bufferServer=<null>]]]]
> > 2018-06-19 21:34:54,850 [container-2] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=2,name=process,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=<null>,partitionMask=1,partitionKeys=[0]]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=localhost]]]]
> > 2018-06-19 21:34:54,852 [container-3] INFO  engine.WindowGenerator
> activate
> > - Catching up from 1529458493500 to 1529458494852
> > 2018-06-19 21:34:54,855 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=1.out.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:34:54,857 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=2.output.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:34:54,858 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=3.output.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:34:54,858 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62187/1.out.1, windowId=ffffffffffffffff,
> > type=genToProcessor/3.input, upstreamIdentifier=1.out.1, mask=1,
> > partitions=[1], bufferSize=1024}
> > 2018-06-19 21:34:54,858 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62187/1.out.1, windowId=ffffffffffffffff,
> > type=genToProcessor/2.input, upstreamIdentifier=1.out.1, mask=1,
> > partitions=[0], bufferSize=1024}
> > 2018-06-19 21:34:54,858 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62187/3.output.1, windowId=ffffffffffffffff,
> > type=ProcessorToReceiver/5.<merge#output>(3.output),
> > upstreamIdentifier=3.output.1, mask=0, partitions=null, bufferSize=1024}
> > 2018-06-19 21:34:54,859 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62187/2.output.1, windowId=ffffffffffffffff,
> > type=ProcessorToReceiver/5.<merge#output>(2.output),
> > upstreamIdentifier=2.output.1, mask=0, partitions=null, bufferSize=1024}
> > 2018-06-19 21:34:55,851 [main] INFO  stram.StramLocalCluster run -
> Stopping
> > on exit condition
> > 2018-06-19 21:34:55,852 [container-2] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:55,852 [container-3] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:55,852 [container-3] INFO  stram.StramLocalCluster log -
> > container-3 msg: [container-3] Exiting heartbeat loop..
> > 2018-06-19 21:34:55,852 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:55,852 [container-2] INFO  stram.StramLocalCluster log -
> > container-2 msg: [container-2] Exiting heartbeat loop..
> > 2018-06-19 21:34:55,852 [container-1] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:55,852 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Exiting heartbeat loop..
> > 2018-06-19 21:34:55,852 [container-1] INFO  stram.StramLocalCluster log -
> > container-1 msg: [container-1] Exiting heartbeat loop..
> > 2018-06-19 21:34:55,857 [container-1] INFO  stram.StramLocalCluster run -
> > Container container-1 terminating.
> > 2018-06-19 21:34:55,858 [container-3] INFO  stram.StramLocalCluster run -
> > Container container-3 terminating.
> > 2018-06-19 21:34:55,858 [ServerHelper-92-1] INFO  server.Server run -
> > Removing ln LogicalNode@5dbf681cidentifier
> > =tcp://localhost:62187/3.output.1,
> > upstream=3.output.1,
> group=ProcessorToReceiver/5.<merge#output>(3.output),
> > partitions=[],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@6244ac9
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@60e28815
> > {identifier=3.output.1,
> > data=1048576, readingOffset=0, writingOffset=487,
> > starting_window=5b29af3d00000001, ending_window=5b29af3d00000006,
> > refCount=2, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@46bbe39d[identifier=3.output.1]
> > 2018-06-19 21:34:55,858 [ServerHelper-92-1] INFO  server.Server run -
> > Removing ln LogicalNode@7fb3226aidentifier
> =tcp://localhost:62187/1.out.1,
> > upstream=1.out.1, group=genToProcessor/2.input,
> > partitions=[BitVector{mask=1, bits=0}],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@2ad6890f
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@e00fc9e
> > {identifier=1.out.1,
> > data=1048576, readingOffset=0, writingOffset=487,
> > starting_window=5b29af3d00000001, ending_window=5b29af3d00000006,
> > refCount=3, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@7a566f6b[identifier=1.out.1]
> > 2018-06-19 21:34:55,858 [ServerHelper-92-1] INFO  server.Server run -
> > Removing ln LogicalNode@2551b8a4identifier
> =tcp://localhost:62187/1.out.1,
> > upstream=1.out.1, group=genToProcessor/3.input,
> > partitions=[BitVector{mask=1, bits=1}],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@6368ccb7
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@e00fc9e
> > {identifier=1.out.1,
> > data=1048576, readingOffset=0, writingOffset=487,
> > starting_window=5b29af3d00000001, ending_window=5b29af3d00000006,
> > refCount=2, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@7a566f6b[identifier=1.out.1]
> > 2018-06-19 21:34:55,862 [container-2] INFO  stram.StramLocalCluster run -
> > Container container-2 terminating.
> > 2018-06-19 21:34:55,862 [ServerHelper-92-1] INFO  server.Server run -
> > Removing ln LogicalNode@2e985326identifier
> > =tcp://localhost:62187/2.output.1,
> > upstream=2.output.1,
> group=ProcessorToReceiver/5.<merge#output>(2.output),
> > partitions=[],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@7d68bf24
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@7405581b
> > {identifier=2.output.1,
> > data=1048576, readingOffset=0, writingOffset=487,
> > starting_window=5b29af3d00000001, ending_window=5b29af3d00000006,
> > refCount=2, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@3de15cc7[identifier=2.output.1]
> > 2018-06-19 21:34:55,862 [container-0] INFO  stram.StramLocalCluster run -
> > Container container-0 terminating.
> > 2018-06-19 21:34:55,864 [ProcessWideEventLoop] INFO  server.Server run -
> > Server stopped listening at /0:0:0:0:0:0:0:0:62187
> > 2018-06-19 21:34:55,864 [main] INFO  stram.StramLocalCluster run -
> > Application finished.
> > 2018-06-19 21:34:55,864 [main] INFO  stram.CustomControlTupleTest
> testApp -
> > Control Tuples received 3 expected 3
> > 2018-06-19 21:34:55,883 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp8804999206923662400
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:56,032 [main] INFO  storage.DiskStorage <init> - using
> > /Users/mbossert/testIdea/apex-core/engine/target as the basepath for
> > spooling.
> > 2018-06-19 21:34:56,032 [ProcessWideEventLoop] INFO  server.Server
> > registered - Server started listening at /0:0:0:0:0:0:0:0:62195
> > 2018-06-19 21:34:56,032 [main] INFO  stram.StramLocalCluster run - Buffer
> > server started: localhost:62195
> > 2018-06-19 21:34:56,033 [container-0] INFO  stram.StramLocalCluster run -
> > Started container container-0
> > 2018-06-19 21:34:56,033 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Entering heartbeat loop..
> > 2018-06-19 21:34:57,038 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=2,name=process,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=CONTAINER_LOCAL,partitionMask=0,partitionKeys=<null>]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=<null>]]],
> >
> >
> OperatorDeployInfo[id=3,name=receiver,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=ProcessorToReceiver,sourceNodeId=2,sourcePortName=output,locality=CONTAINER_LOCAL,partitionMask=0,partitionKeys=<null>]],outputs=[]],
> >
> >
> OperatorDeployInfo[id=1,name=randomGenerator,type=INPUT,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=out,streamId=genToProcessor,bufferServer=<null>]]]]
> > 2018-06-19 21:34:57,040 [container-0] INFO  engine.WindowGenerator
> activate
> > - Catching up from 1529458495500 to 1529458497040
> > 2018-06-19 21:34:58,042 [main] INFO  stram.StramLocalCluster run -
> Stopping
> > on exit condition
> > 2018-06-19 21:34:59,045 [main] WARN  stram.StramLocalCluster run -
> > Container thread container-0 is still alive
> > 2018-06-19 21:34:59,047 [ProcessWideEventLoop] INFO  server.Server run -
> > Server stopped listening at /0:0:0:0:0:0:0:0:62195
> > 2018-06-19 21:34:59,047 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:34:59,047 [main] INFO  stram.StramLocalCluster run -
> > Application finished.
> > 2018-06-19 21:34:59,047 [main] INFO  stram.CustomControlTupleTest
> testApp -
> > Control Tuples received 4 expected 4
> > 2018-06-19 21:34:59,047 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Exiting heartbeat loop..
> > 2018-06-19 21:34:59,057 [container-0] INFO  stram.StramLocalCluster run -
> > Container container-0 terminating.
> > 2018-06-19 21:34:59,064 [main] INFO  util.AsyncFSStorageAgent save -
> using
> > /Users/mbossert/testIdea/apex-core/engine/target/chkp4046668014410536641
> as
> > the basepath for checkpointing.
> > 2018-06-19 21:34:59,264 [main] INFO  storage.DiskStorage <init> - using
> > /Users/mbossert/testIdea/apex-core/engine/target as the basepath for
> > spooling.
> > 2018-06-19 21:34:59,264 [ProcessWideEventLoop] INFO  server.Server
> > registered - Server started listening at /0:0:0:0:0:0:0:0:62196
> > 2018-06-19 21:34:59,265 [main] INFO  stram.StramLocalCluster run - Buffer
> > server started: localhost:62196
> > 2018-06-19 21:34:59,265 [container-0] INFO  stram.StramLocalCluster run -
> > Started container container-0
> > 2018-06-19 21:34:59,265 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Entering heartbeat loop..
> > 2018-06-19 21:34:59,265 [container-1] INFO  stram.StramLocalCluster run -
> > Started container container-1
> > 2018-06-19 21:34:59,265 [container-2] INFO  stram.StramLocalCluster run -
> > Started container container-2
> > 2018-06-19 21:34:59,266 [container-1] INFO  stram.StramLocalCluster log -
> > container-1 msg: [container-1] Entering heartbeat loop..
> > 2018-06-19 21:34:59,266 [container-3] INFO  stram.StramLocalCluster run -
> > Started container container-3
> > 2018-06-19 21:34:59,266 [container-2] INFO  stram.StramLocalCluster log -
> > container-2 msg: [container-2] Entering heartbeat loop..
> > 2018-06-19 21:34:59,266 [container-3] INFO  stram.StramLocalCluster log -
> > container-3 msg: [container-3] Entering heartbeat loop..
> > 2018-06-19 21:35:00,270 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=1,name=randomGenerator,type=INPUT,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=out,streamId=genToProcessor,bufferServer=localhost]]]]
> > 2018-06-19 21:35:00,270 [container-2] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=2,name=process,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=<null>,partitionMask=1,partitionKeys=[0]]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=localhost]]]]
> > 2018-06-19 21:35:00,271 [container-1] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=4,name=receiver,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=ProcessorToReceiver,sourceNodeId=5,sourcePortName=outputPort,locality=CONTAINER_LOCAL,partitionMask=0,partitionKeys=<null>]],outputs=[]],
> >
> >
> OperatorDeployInfo.UnifierDeployInfo[id=5,name=process.output#unifier,type=UNIFIER,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=<merge#output>,streamId=ProcessorToReceiver,sourceNodeId=2,sourcePortName=output,locality=<null>,partitionMask=0,partitionKeys=<null>],
> >
> >
> OperatorDeployInfo.InputDeployInfo[portName=<merge#output>,streamId=ProcessorToReceiver,sourceNodeId=3,sourcePortName=output,locality=<null>,partitionMask=0,partitionKeys=<null>]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=outputPort,streamId=ProcessorToReceiver,bufferServer=<null>]]]]
> > 2018-06-19 21:35:00,270 [container-3] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Deploy request:
> >
> >
> [OperatorDeployInfo[id=3,name=process,type=GENERIC,checkpoint={ffffffffffffffff,
> > 0,
> >
> >
> 0},inputs=[OperatorDeployInfo.InputDeployInfo[portName=input,streamId=genToProcessor,sourceNodeId=1,sourcePortName=out,locality=<null>,partitionMask=1,partitionKeys=[1]]],outputs=[OperatorDeployInfo.OutputDeployInfo[portName=output,streamId=ProcessorToReceiver,bufferServer=localhost]]]]
> > 2018-06-19 21:35:00,273 [container-0] INFO  engine.WindowGenerator
> activate
> > - Catching up from 1529458499500 to 1529458500273
> > 2018-06-19 21:35:00,274 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=1.out.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:35:00,276 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=3.output.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:35:00,277 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62196/1.out.1, windowId=ffffffffffffffff,
> > type=genToProcessor/2.input, upstreamIdentifier=1.out.1, mask=1,
> > partitions=[0], bufferSize=1024}
> > 2018-06-19 21:35:00,278 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received publisher request: PublishRequestTuple{version=1.0,
> > identifier=2.output.1, windowId=ffffffffffffffff}
> > 2018-06-19 21:35:00,278 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62196/1.out.1, windowId=ffffffffffffffff,
> > type=genToProcessor/3.input, upstreamIdentifier=1.out.1, mask=1,
> > partitions=[1], bufferSize=1024}
> > 2018-06-19 21:35:00,278 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62196/3.output.1, windowId=ffffffffffffffff,
> > type=ProcessorToReceiver/5.<merge#output>(3.output),
> > upstreamIdentifier=3.output.1, mask=0, partitions=null, bufferSize=1024}
> > 2018-06-19 21:35:00,278 [ProcessWideEventLoop] INFO  server.Server
> > onMessage - Received subscriber request:
> SubscribeRequestTuple{version=1.0,
> > identifier=tcp://localhost:62196/2.output.1, windowId=ffffffffffffffff,
> > type=ProcessorToReceiver/5.<merge#output>(2.output),
> > upstreamIdentifier=2.output.1, mask=0, partitions=null, bufferSize=1024}
> > 2018-06-19 21:35:01,273 [main] INFO  stram.StramLocalCluster run -
> Stopping
> > on exit condition
> > 2018-06-19 21:35:01,273 [container-3] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:35:01,273 [container-2] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:35:01,273 [container-2] INFO  stram.StramLocalCluster log -
> > container-2 msg: [container-2] Exiting heartbeat loop..
> > 2018-06-19 21:35:01,273 [container-0] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:35:01,274 [container-0] INFO  stram.StramLocalCluster log -
> > container-0 msg: [container-0] Exiting heartbeat loop..
> > 2018-06-19 21:35:01,273 [container-3] INFO  stram.StramLocalCluster log -
> > container-3 msg: [container-3] Exiting heartbeat loop..
> > 2018-06-19 21:35:01,273 [container-1] INFO  engine.StreamingContainer
> > processHeartbeatResponse - Received shutdown request type ABORT
> > 2018-06-19 21:35:01,274 [container-1] INFO  stram.StramLocalCluster log -
> > container-1 msg: [container-1] Exiting heartbeat loop..
> > 2018-06-19 21:35:01,279 [container-3] INFO  stram.StramLocalCluster run -
> > Container container-3 terminating.
> > 2018-06-19 21:35:01,279 [ServerHelper-98-1] INFO  server.Server run -
> > Removing ln LogicalNode@d80a435identifier
> > =tcp://localhost:62196/3.output.1,
> > upstream=3.output.1,
> group=ProcessorToReceiver/5.<merge#output>(3.output),
> > partitions=[],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@2f53b5e7
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@1e2d4212
> > {identifier=3.output.1,
> > data=1048576, readingOffset=0, writingOffset=36,
> > starting_window=5b29af4300000001, ending_window=5b29af4300000005,
> > refCount=2, uniqueIdentifier=0, next=null, future=null}}} from dl
> > DataList@1684ecee[identifier=3.output.1]
> > 2018-06-19 21:35:01,285 [container-2] INFO  stram.StramLocalCluster run -
> > Container container-2 terminating.
> > 2018-06-19 21:35:01,285 [container-1] INFO  stram.StramLocalCluster run -
> > Container container-1 terminating.
> > 2018-06-19 21:35:01,286 [container-0] INFO  stram.StramLocalCluster run -
> > Container container-0 terminating.
> > 2018-06-19 21:35:01,286 [ServerHelper-98-1] INFO  server.Server run -
> > Removing ln LogicalNode@75d245a1identifier
> > =tcp://localhost:62196/2.output.1,
> > upstream=2.output.1,
> group=ProcessorToReceiver/5.<merge#output>(2.output),
> > partitions=[],
> >
> >
> iterator=com.datatorrent.bufferserver.internal.DataList$DataListIterator@719c5cd2
> > {da=com.datatorrent.bufferserver.internal.DataList$Block@43d2338b
> > {identifier=2.output.1,
> > data=1048576, readingOffset=0, w



-- 

M. Aaron Bossert
(571) 242-4021
Punch Cyber Analytics Group

Reply via email to