Hello support team,
I have a problem which has been bothering me for weeks and I can't figure if the problem is in my application or on the Dukascopy side.
I get disconnected from time to time and I try to connect again automatically as shown in the wiki.
Unfortunately, quite often (but not all the time), the Client listener invocation thread seems to be BLOCKED.
The logs I get from Dukascopy are:
2015-03-11 07:56:00,846| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:01,888| INFO | ient.ClientConnector | Primary connect successfull, primarySession is [MinaIoSessionWrapper [session=(SOCKET, R: d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443, L: /10.0.0.10:52540, S: d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443)]], address is [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:02,245| ERROR | ient.ClientConnector | Exception caught (Mina-thread - 5)
java.io.IOException: Connection reset by peer
at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
at sun.nio.ch.IOUtil.read(IOUtil.java:197)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(SocketIoProcessor.java:218)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(SocketIoProcessor.java:198)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$400(SocketIoProcessor.java:45)
at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:485)
at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at java.lang.Thread.run(Thread.java:745)
2015-03-11 07:56:02,293| INFO | lientProtocolHandler | Disconnect task in queue, reason [EXCEPTION_CAUGHT], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:03,326| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:03,427| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:04,456| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:04,557| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:05,586| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:05,687| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:06,722| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:06,823| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:07,856| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:07,958| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:08,986| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:09,087| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:10,120| INFO | ient.ClientConnector | Primary connect call failed, address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443] (ClientConnector)
2015-03-11 07:56:10,222| INFO | lientProtocolHandler | Disconnect task in queue, reason [CONNECTION_PROBLEM], server address [d-ja-gva-91-142.dukascopy.com/194.8.15.142:10443], transport name [null] (ClientConnector)
2015-03-11 07:56:21,843| INFO | .AuthorizationClient | Selecting the best server... (invocation thread - 1)
2015-03-11 07:56:22,378| INFO | .AuthorizationClient | retry count = 1, properties request time = 2015-03-11 07:56:22 (invocation thread - 1)
2015-03-11 07:56:27,897| INFO | .AuthorizationClient | retry count = 1, properties response time = 2015-03-11 07:56:27 (invocation thread - 1)
2015-03-11 07:56:27,979| INFO | ient.ClientConnector | Primary connect successfull, primarySession is [MinaIoSessionWrapper [session=(SOCKET, R: d-ja-gva-101-133-167.dukascopy.com/194.8.15.167:10443, L: /10.0.0.10:43172, S: d-ja-gva-101-133-167.dukascopy.com/194.8.15.167:10443)]], address is [d-ja-gva-101-133-167.dukascopy.com/194.8.15.167:10443] (ClientConnector)
2015-03-11 07:56:28,595| INFO | uthorizationProvider | !!!:Thread[ClientConnector,5,main] (Mina-thread - 6)
2015-03-11 07:56:29,714| INFO | ient.ClientConnector | Child session opened for [d-ja-gva-101-133-167.dukascopy.com/194.8.15.167:10443] (ClientConnector)
2015-03-11 07:56:53,936| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3009, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:53,948| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3021, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:53,960| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3033, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:53,972| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3045, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:53,984| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3057, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:53,996| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3069, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,008| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3081, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,020| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3093, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,032| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3105, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,044| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3117, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,056| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3129, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,068| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3141, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,080| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3153, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,092| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3165, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,104| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3177, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,116| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3189, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,128| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3201, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,140| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3213, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,152| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3225, possible application problem or deadLock (Mina-thread - 2)
2015-03-11 07:56:54,164| ERROR | lientProtocolHandler | fireFeedbackMessageReceived: TO LARGE EXECUTION WAIT TIME: 3237, possible application problem or deadLock (Mina-thread - 2)
etc....
My app won't reconnect and I have to kill it to be able to connect again. The logs mention a possible application problem or deadlock, which seems to be the case when looking a the related threads:
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 0 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 1 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 2 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 3 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 4 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 5 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 6 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 7 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 8 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 9 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 10 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 11 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = Mina-thread - 12 : WAITING
2015-03-11 08:09:31,754 - DEBUG - Thread = (27864225) Client listeners invocation thread - 1 : RUNNABLE
2015-03-11 08:09:31,755 - DEBUG - Thread = Mina-thread - 13 : WAITING
2015-03-11 08:09:31,755 - DEBUG - Thread = Mina-thread - 14 : WAITING
2015-03-11 08:09:31,755 - DEBUG - Thread = FeedDataProvider_ActionsThread_2 : WAITING
2015-03-11 08:09:31,755 - DEBUG - Thread = Mina-thread - 15 : WAITING
2015-03-11 08:09:31,755 - DEBUG - Thread = OrderedThreadPoolExecutor CleanUp : TIMED_WAITING
2015-03-11 08:09:31,755 - DEBUG - Thread = (27864225) Client listeners invocation thread - 2 : BLOCKED
But I don't understand why this happens when my code seems very similar to the code you proposed on the wiki page.
My connect method is
public static void connect(final String url, final String u, final String p) {
try {
final IClient instance = ClientFactory.getDefaultInstance();
log.warn("Connecting to Dukascopy ...");
instance.connect(url, u, p);
int i = Consts.SEC_ALLOWED_TO_CONNECT;
while (i > 0 && !instance.isConnected()) {
log.debug("Not connected yet {}", i);
Thread.sleep(Consts.THREAD_SLEEPING_TIME_ONE_SEC);
i--;
}
} catch (JFException | NoRouteToHostException | UnknownHostException | ConnectException e) {
try {
Thread.sleep(60 * 1000);
} catch (InterruptedException ignored) {
}
} catch (MalformedURLException e) {
log.error("MalformedURLException with URL {}", url, e);
} catch (InterruptedException ignored) {
} catch (Exception e) {
log.error("connect: {}", e.toString(), e);
}
}
My System Listener (set at program startup) is:
public static void setSystemListener(final String url, final String u, final String pw) {
try {
final IClient instance = ClientFactory.getDefaultInstance();
instance.setSystemListener(new ISystemListener() {
private int lightReconnects = Consts.NB_RECONNECTS;
/**
* ! It seems this method is not executed when starting the strategy !
*/
@Override
public void onStart(final long processId) {
}
@Override
public void onStop(final long processId) {
}
@Override
public void onConnect() {
log.info("Connected to Dukascopy servers");
lightReconnects = Consts.NB_RECONNECTS;
}
@Override
public void onDisconnect() {
log.warn("Disconnected from Dukascopy servers");
if (lightReconnects > 0) {
log.warn("Trying to light reconnect, {} tries left: ", lightReconnects);
instance.reconnect();
--lightReconnects;
return;
}
try {
DateTime start = DateTime.now();
while (!instance.isConnected()
&& DateTime.now().compareTo(start.plusHours(Consts.HRS_TRYING_CONNECT)) < 0) {
//sleep for 10 seconds before attempting to reconnect
Thread.sleep(10000);
DukaTools.connect(url, u, pw);
}
if (!instance.isConnected()) {
log.error("Failed to connect to Dukascopy after {} hours.", Consts.HRS_TRYING_CONNECT);
}
} catch (InterruptedException ignored) {
} catch (Exception e) {
log.error("onDisconnect: {} ", e.toString(), e);
}
}
});
} catch (ClassNotFoundException | IllegalAccessException | InstantiationException e) {
log.error(e.toString(), e);
}
Finally, at program startup I connect using:
instance = ClientFactory.getDefaultInstance();
DukaTools.setSystemListener(url, u, pw);
DukaTools.connect(url, u, pw);
So all this seems pretty straightforward. I don't see what could be wrong or where there could be a deadlock in my code...
Am I the only one having this issue? I have no more idea about this problem and where it comes from...
Thanks for any help!