Print

[CryptoKnight]

Hi all,

I'm trying to cancel a running task and it doesn't seem to be working for me:

Code: [Select]

JPPFClientConnectionImpl clientConnection = (JPPFClientConnectionImpl)_jppfClient.getClientConnection();

JMXDriverConnectionWrapper connection = clientConnection.getJmxConnection();
connection.connect();
connection.cancelJob( job.getJobUuid() );

This code executes without throwing any exceptions, but the job does not cancel. It can be cancelled from the admin panel though. Am I missing a critical step somewhere?


I love JPPF btw, it's exactly what I needed for my project.

[lolo]

Hello,

Thank you very much for your comments on JPPF, it is always a joy to hear.


I belive that in your code, you do not need to call connect(), as the JPPFClientConnectionImpl has already done that. Calling connect() will cause a new connection attempt, which is not immediate, so you might have to wait a little for the connection to be established.

You can try the following code instead:

Code: [Select]

JPPFClientConnectionImpl clientConnection = (JPPFClientConnectionImpl)_jppfClient.getClientConnection();
JMXDriverConnectionWrapper connection = clientConnection.getJmxConnection();
while (!connection.isConnected())
{
  Thread.sleep(1);
}
connection.cancelJob( job.getJobUuid() );

Please let us know if this works for you.

Sincerely,
-Laurent

[CryptoKnight]

Hi,

Unfortunately, the problem still persists after using the modified code.

[lolo]

Hello,

Just one thing that came to my mind: are you submitting the job in blocking mode?

If you are, and you try to cancel the job in the same thread, then it's not going to work as the JPPFClient.submit(JPPFJob) method will block until the job has finished executing.
If this is your usage scenario, then you need to change the way you submit the job and get the results:

Code: [Select]

JPPFClient client = new JPPFClient();
JPPFJob myJob = new JPPFJob();
// add the tasks
myJob.addTask(myTask_1)
...
myJob.addTask(myTask_n)
// set the job in non-blocking (asynchronous) mode and add a results listener.
myJob.setBlocking(false);
JPPFResultCollector collector = new JPPFResultCollector(myJob.getTasks().size());
myJob.setResultListener(collector);
// in non-blocking mode, this method returns immediately
client.submit(myJob);
...
if (some_condition)
{
  // cancel the job
  ...
}
...
List<JPPFTasks> results = collector.waitForResults();

Sincerely,
-Laurent

[CryptoKnight]

The Job is non-blocking and is started in a different thread.

I enabled logging on my client and found this. Can anyone decipher this and determine the cause?

Code: [Select]

javax.management.RuntimeMBeanException: java.lang.NullPointerException
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.rethrow(DefaultMBeanServerInterceptor.java:856)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.rethrowMaybeMBeanException(DefaultMBeanServerInterceptor.java:869)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:838)
at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761)
at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1427)
at javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:72)
at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1265)
at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1360)
at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:788)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
at sun.rmi.transport.Transport$1.run(Transport.java:159)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:255)
at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:233)
at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:142)
at com.sun.jmx.remote.internal.PRef.invoke(Unknown Source)
at javax.management.remote.rmi.RMIConnectionImpl_Stub.invoke(Unknown Source)
at javax.management.remote.rmi.RMIConnector$RemoteMBeanServerConnection.invoke(RMIConnector.java:993)
at org.jppf.management.JMXConnectionWrapper.invoke(JMXConnectionWrapper.java:187)
at org.jppf.management.JMXDriverConnectionWrapper.cancelJob(JMXDriverConnectionWrapper.java:130)
at Cracken.Server.JobManager.cancelJob(JobManager.java:350)
at Cracken.Server.CommandProcessor.cancelJob(CommandProcessor.java:149)
at Cracken.Server.CommandProcessor.processMessage(CommandProcessor.java:40)
at Cracken.Server.CrackenServer$ConnectionHandler.run(Main.java:74)
Caused by: java.lang.NullPointerException
at org.jppf.server.job.management.DriverJobManagement.cancelJob(DriverJobManagement.java:72)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:93)
at com.sun.jmx.mbeanserver.StandardMBeanIntrospector.invokeM2(StandardMBeanIntrospector.java:27)
at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:208)
at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:120)
at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:262)
at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:836)
at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:761)
at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1427)
at javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:72)
at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1265)
at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1360)
at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:788)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:305)
at sun.rmi.transport.Transport$1.run(Transport.java:159)
at java.security.AccessController.doPrivileged(Native Method)
at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)


[lolo]

Hello,

Thanks for posting the log.

In fact, the NPE is caused by unprotected code in the debug statement itself. I have registered a bug for this: NPE in DriverJobManagement when in DEBUG mode
However, it shows that the job is no longer in the server when cancelJob(...) is called, that's why it doesn't seem to be cancelled.
I also posted a patch for the bug, which includes an improvement on the way the job is cancelled: http://www.jppf.org/patch_info.php?patch_id=7

Could you give it a try and let us know if this resolves the problem?

Thanks,
-Laurent

[CryptoKnight]

Hi,

Sorry for the late reply, been really busy over here.

After applying all 2.3 patches, the exception goes away but the job still does not get cancelled.

And you are right, it does say the job does not exist, which is odd because the job is definitely running:

JPPF driver log:

2010-12-20 13:22:26,008 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId '46c757cad022f81c2bc159a0e633da15' : removed node SelectionKeyWrapper[192.168.1.103:55830, readyOps=1, keyOps=0]
2010-12-20 13:22:26,009 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId '46c757cad022f81c2bc159a0e633da15' updated
2010-12-20 13:22:26,010 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId '46c757cad022f81c2bc159a0e633da15' : added node SelectionKeyWrapper[192.168.1.103:55830, readyOps=4, keyOps=0]
2010-12-20 13:22:26,666 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJobInNodes(214)]: Cancelling jobId = '46c757cad022f81c2bc159a0e633da15' in nodes: null
2010-12-20 13:22:26,667 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJob(80)]: Could not find job with uuid = '46c757cad022f81c2bc159a0e633da15'
2010-12-20 13:22:38,415 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId '46c757cad022f81c2bc159a0e633da15' : removed node SelectionKeyWrapper[192.168.1.103:55830, readyOps=1, keyOps=0]
2010-12-20 13:22:38,416 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId '46c757cad022f81c2bc159a0e633da15' updated
2010-12-20 13:22:38,416 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId '46c757cad022f81c2bc159a0e633da15' : added node SelectionKeyWrapper[192.168.1.103:55830, readyOps=4, keyOps=0]
2010-12-20 13:22:50,538 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[192.168.1.103:60079, readyOps=1, keyOps=0] has been disconnected
2010-12-20 13:22:52,848 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId '46c757cad022f81c2bc159a0e633da15' : removed node SelectionKeyWrapper[192.168.1.103:55830, readyOps=1, keyOps=0]
2010-12-20 13:22:52,849 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId '46c757cad022f81c2bc159a0e633da15' updated
2010-12-20 13:22:52,849 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId '46c757cad022f81c2bc159a0e633da15' : added node SelectionKeyWrapper[192.168.1.103:55830, readyOps=1, keyOps=5

[lolo]

Hi,

Do you have a code sample that you can post and that reproduces the problem?

Thanks,
-Laurent

[CryptoKnight]

Hi,

I updated to JPPF 2.4 and task cancellation is working now!

[lolo]

Hello,

That is great news. You might also want to apply this patch, which fixes a bug triggered when suspending/resuming a job.

Sincerely,
-Laurent

[CryptoKnight]

New problem:

When I cancel a job and try to start a new job, the new tasks will not run. Nothing seems to happen on the client. No exceptions thrown on the client side. In fact I don't even see anything about the new job in the logs:


node:

2011-01-05 15:40:19,238 [DEBUG][org.jppf.management.JPPFNodeAdmin.cancelJob(300)]: Request to cancel jobId = '295a2259d41cd43ce259b33e4541903d', requeue = false
2011-01-05 15:40:19,238 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelAllTasks(193)]: cancelling all tasks with: callOnCancel=true, requeue=false
2011-01-05 15:40:19,239 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 16
2011-01-05 15:40:19,239 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@51f21c50, task=null
2011-01-05 15:40:19,239 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 15
2011-01-05 15:40:19,240 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@6e20f237, task=null
2011-01-05 15:40:19,240 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 14
2011-01-05 15:40:19,240 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@34fe315d, task=null
2011-01-05 15:40:19,240 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 13
2011-01-05 15:40:19,241 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@1c5aebd9, task=null
2011-01-05 15:40:19,241 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 12
2011-01-05 15:40:19,241 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@1532021a, task=null
2011-01-05 15:40:19,241 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 11
2011-01-05 15:40:19,241 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@62803d5, task=null
2011-01-05 15:40:19,241 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 10
2011-01-05 15:40:19,242 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@2d13981b, task=null
2011-01-05 15:40:19,242 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 9
2011-01-05 15:40:19,242 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@61672bbb, task=null
2011-01-05 15:40:19,242 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 8
2011-01-05 15:40:19,242 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@3c6833f2, task=null
2011-01-05 15:40:19,243 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 7
2011-01-05 15:40:19,243 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@5d2a73d9, task=null
2011-01-05 15:40:19,243 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 6
2011-01-05 15:40:19,245 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@e1bdb58, task=null
2011-01-05 15:40:19,246 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 5
2011-01-05 15:40:19,246 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@46dd75a4, task=null
2011-01-05 15:40:19,246 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 4
2011-01-05 15:40:19,247 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@75568654, task=null
2011-01-05 15:40:19,247 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 3
2011-01-05 15:40:19,247 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@38d30fb, task=null
2011-01-05 15:40:19,247 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 2
2011-01-05 15:40:19,247 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@2a8ab08f, task=null
2011-01-05 15:40:19,248 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.cancelTask(223)]: cancelling task number = 1
2011-01-05 15:40:19,248 [DEBUG][org.jppf.scheduling.JPPFScheduleHandler.cancelAction(131)]: Node Task Timeout Timer : cancelling action for key=java.util.concurrent.FutureTask@774d921a, task=null
2011-01-05 15:40:19,249 [DEBUG][org.jppf.server.node.NodeExecutionManagerImpl.execute(152)]: total cpu time used: 26988 ms, user time: 26972
2011-01-05 15:40:19,249 [DEBUG][org.jppf.server.node.JPPFNode.processResults(236)]: processing results for job '295a2259d41cd43ce259b33e4541903d'
2011-01-05 15:40:19,251 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1525
2011-01-05 15:40:19,266 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,267 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,267 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,267 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1118
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1119
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1119
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1119
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1119
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1119
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.writeResults(146)]: writing object size = 1119
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.node.JPPFNode.processResults(248)]: tasks executed: 16
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.node.remote.RemoteNodeIO.deserializeObjects(71)]: waiting for next reques

driver:

2011-01-05 15:40:18,991 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJobInNodes(214)]: Cancelling jobId = '295a2259d41cd43ce259b33e4541903d' in nodes: [org.jppf.server.job.ChannelBundlePair@b90db296]
2011-01-05 15:40:18,993 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJob(75)]: Request to cancel jobId = '295a2259d41cd43ce259b33e4541903d'
2011-01-05 15:40:18,993 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJob(76)]: bundleWrapper=org.jppf.server.protocol.BundleWrapper@70c26b16
2011-01-05 15:40:18,994 [DEBUG][org.jppf.server.queue.JPPFPriorityQueue.nextBundle(173)]: requesting bundle with 16 tasks, next bundle has 16 tasks
2011-01-05 15:40:18,994 [DEBUG][org.jppf.server.queue.JPPFPriorityQueue.removeBundle(259)]: removing bundle from queue, jobId=295a2259d41cd43ce259b33e4541903d
2011-01-05 15:40:18,994 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId '295a2259d41cd43ce259b33e4541903d' updated
2011-01-05 15:40:18,994 [DEBUG][org.jppf.server.queue.JPPFPriorityQueue.nextBundle(207)]: Maps size information: priorityMap[shallow size=0, total elements=0] - sizeMap[shallow size=0, total elements=0]
2011-01-05 15:40:18,995 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job 295a2259d41cd43ce259b33e4541903d
2011-01-05 15:40:18,995 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job 295a2259d41cd43ce259b33e4541903d
2011-01-05 15:40:19,068 [DEBUG][org.jppf.server.job.management.CancelJobTask.run(77)]: Request to cancel jobId = '295a2259d41cd43ce259b33e4541903d' on node SelectionKeyWrapper[Ben-LAPTOP:63261, readyOps=4, keyOps=1], requeue = false
2011-01-05 15:40:19,119 [DEBUG][org.jppf.management.JMXConnectionWrapper.run(324)]: Ben-LAPTOP:12001 about to perform RMI connection attempts
2011-01-05 15:40:19,190 [DEBUG][org.jppf.management.JMXConnectionWrapper.performConnection(158)]: Ben-LAPTOP:12001 JMX connection successfully established
2011-01-05 15:40:19,190 [DEBUG][org.jppf.management.JMXConnectionWrapper.run(326)]: Ben-LAPTOP:12001 about to suspend RMI connection attempts
2011-01-05 15:40:19,190 [DEBUG][org.jppf.management.JMXConnectionWrapper.suspend(352)]: Ben-LAPTOP:12001 suspending RMI connection attempts
2011-01-05 15:40:19,190 [DEBUG][org.jppf.management.JMXConnectionWrapper.run(316)]: Ben-LAPTOP:12001 about to go to sleep
2011-01-05 15:40:19,252 [DEBUG][org.jppf.server.nio.StateTransitionManager.submitTransition(79)]: submitting transition for SelectionKeyWrapper[Ben-LAPTOP:63261, readyOps=1, keyOps=1]
2011-01-05 15:40:19,254 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,254 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,254 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1525 bytes from input source, count/size = 1525/1525
2011-01-05 15:40:19,255 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1525, size = 1525
2011-01-05 15:40:19,256 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 0 bytes from input source, count/size = 0/4
2011-01-05 15:40:19,267 [DEBUG][org.jppf.server.nio.StateTransitionManager.submitTransition(79)]: submitting transition for SelectionKeyWrapper[Ben-LAPTOP:63261, readyOps=1, keyOps=1]
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,268 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,269 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,269 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,269 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,269 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,270 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,271 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,272 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,273 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1118 bytes from input source, count/size = 1118/1118
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1118, size = 1118
2011-01-05 15:40:19,274 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1119 bytes from input source, count/size = 1119/1119
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1119, size = 1119
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1119 bytes from input source, count/size = 1119/1119
2011-01-05 15:40:19,275 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1119, size = 1119
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1119 bytes from input source, count/size = 1119/1119
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1119, size = 1119
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,276 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1119 bytes from input source, count/size = 1119/1119
2011-01-05 15:40:19,277 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1119, size = 1119
2011-01-05 15:40:19,277 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,277 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,277 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1119 bytes from input source, count/size = 1119/1119
2011-01-05 15:40:19,277 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1119, size = 1119
2011-01-05 15:40:19,277 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 4 bytes from input source, count/size = 4/4
2011-01-05 15:40:19,278 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 4, size = 4
2011-01-05 15:40:19,278 [DEBUG][org.jppf.server.nio.NioObject.read(103)]: read 1119 bytes from input source, count/size = 1119/1119
2011-01-05 15:40:19,278 [DEBUG][org.jppf.server.nio.NioObject.read(106)]: count = 1119, size = 1119
2011-01-05 15:40:19,278 [DEBUG][org.jppf.server.nio.nodeserver.WaitingResultsState.performTransition(70)]: read bundle[jobId=295a2259d41cd43ce259b33e4541903d, jobUuid=295a2259d41cd43ce259b33e4541903d, initialTaskCount=16, taskCount=16] from node SelectionKeyWrapper[Ben-LAPTOP:63261, readyOps=1, keyOps=0] done
2011-01-05 15:40:19,278 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId '295a2259d41cd43ce259b33e4541903d' : removed node SelectionKeyWrapper[Ben-LAPTOP:63261, readyOps=1, keyOps=0]
2011-01-05 15:40:19,278 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job 295a2259d41cd43ce259b33e4541903d
2011-01-05 15:40:19,279 [DEBUG][org.jppf.server.nio.StateTransitionManager.transitionChannel(125)]: transitionned SelectionKeyWrapper[Ben-LAPTOP:63261, readyOps=1, keyOps=1] from WAITING_RESULTS to IDLE
2011-01-05 15:40:19,279 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job 295a2259d41cd43ce259b33e4541903

[lolo]

Hello,

I was able to reproduce this problem and registered a bug report for it: 3152285 - Job never returns upon cancellation

I built a patch for this issue, that you can download here: http://www.jppf.org/private/patch/jppf-2.4-patch-02.zip
Could you give it a try and let us know if it works for you? Upon your confirmation, I will make it an official patch.

Sincerely,
-Laurent

[CryptoKnight]

This works for me. Thanks!

[codemonkey]

I'm still at a loss with this even after I've applied patches 1 and 2. The job never cancels. I've followed the above code to no avail. Getting some messages in driver log I was wondering if you might be able to help out. I'm not seeing any attempts at cancelling the job in the log either:

Driver log:

Code: [Select]

2011-01-21 15:58:47,336 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#1: Using Auto-Tuned bundle size
2011-01-21 15:58:47,339 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#1: The initial size is 1
2011-01-21 15:58:58,723 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#2: Using Auto-Tuned bundle size
2011-01-21 15:58:58,723 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#2: The initial size is 1
2011-01-21 15:59:08,057 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#3: Using Auto-Tuned bundle size
2011-01-21 15:59:08,057 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#3: The initial size is 1
2011-01-21 15:59:17,998 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#4: Using Auto-Tuned bundle size
2011-01-21 15:59:17,999 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#4: The initial size is 1
2011-01-21 15:59:28,491 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#5: Using Auto-Tuned bundle size
2011-01-21 15:59:28,492 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#5: The initial size is 1
2011-01-21 16:02:07,306 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,308 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,312 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57876, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,313 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57879, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,313 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,314 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,316 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57878, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,317 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57877, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,318 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,319 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,319 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57880, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,320 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57881, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,321 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-21 16:02:07,322 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57882, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:07,322 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57883, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,469 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,470 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57832, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,469 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,471 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57833, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,471 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,471 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57838, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,471 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,472 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,472 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,471 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,471 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57828, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,473 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57829, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,473 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]: Connection reset
2011-01-21 16:02:11,473 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57831, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,474 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57834, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:11,474 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:57830, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:26,872 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: An existing connection was forcibly closed by the remote host
2011-01-21 16:02:26,873 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: node SelectionKeyWrapper[127.0.0.1:57726, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:26,920 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: An existing connection was forcibly closed by the remote host
2011-01-21 16:02:26,929 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: node SelectionKeyWrapper[127.0.0.1:57791, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:26,959 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: An existing connection was forcibly closed by the remote host
2011-01-21 16:02:26,984 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: node SelectionKeyWrapper[127.0.0.1:57762, readyOps=1, keyOps=0] has been disconnected
2011-01-21 16:02:26,984 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: An existing connection was forcibly closed by the remote host
2011-01-21 16:02:26,984 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: node SelectionKeyWrapper[127.0.0.1:57810, readyOps=1, keyOps=0] has been disconnected

Node has no log information pertaining to attempting to cancel the job

Can you possibly provide some suggestions

Thank You!!!!

[lolo]

Hello,

First we will need additional information to try and diagnose the problem.
In the log4j-driver.properties file, could you add the following two lines at the end:

Code: [Select]

log4j.logger.org.jppf.server.job=DEBUG
log4j.logger.org.jppf.server.job.management=DEBUG
This should give us all the log traces regarding job management. Once you have done that, can you restart your driver, perform the test again and post the resulting log?

Also, could you give more details on how you try to cancel the job?
If you are doing it via API, can you post the part of your code that does this? Also, are you submitting a blocking or non-blocking job, and are you canceling it from the same thread?

Thanks for your help,
-Laurent

[codemonkey]

Hi Laurent, thank you for the prompt reply. His is the driver log with debug enabled as you requested:

Code: [Select]

2011-01-22 08:12:38,185 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#1: Using Auto-Tuned bundle size
2011-01-22 08:12:38,187 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#1: The initial size is 1
2011-01-22 08:12:49,324 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#2: Using Auto-Tuned bundle size
2011-01-22 08:12:49,324 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#2: The initial size is 1
2011-01-22 08:12:58,634 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#3: Using Auto-Tuned bundle size
2011-01-22 08:12:58,634 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#3: The initial size is 1
2011-01-22 08:13:08,623 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#4: Using Auto-Tuned bundle size
2011-01-22 08:13:08,623 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#4: The initial size is 1
2011-01-22 08:13:18,665 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(69)]: Bundler#5: Using Auto-Tuned bundle size
2011-01-22 08:13:18,665 [INFO ][org.jppf.server.scheduler.bundle.impl.AbstractAutoTunedBundler.<init>(71)]: Bundler#5: The initial size is 1
2011-01-22 08:14:10,787 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,789 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,789 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53776, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,791 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53777, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,791 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,792 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53775, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,793 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53780, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,794 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,793 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,795 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53781, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,796 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,797 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53779, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,798 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,799 [WARN ][org.jppf.server.app.JPPFConnection.run(101)]:
2011-01-22 08:14:10,799 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53778, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:10,801 [WARN ][org.jppf.server.nio.StateTransitionTask.run(88)]: provider SelectionKeyWrapper[127.0.0.1:53774, readyOps=1, keyOps=0] has been disconnected
2011-01-22 08:14:57,734 [DEBUG][org.jppf.server.job.JPPFJobManager.jobQueued(152)]: jobId 'Analysis Job Dec 07 id[1578]' queued
2011-01-22 08:14:57,738 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_QUEUED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,740 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:14:57,741 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,742 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId 'Analysis Job Dec 07 id[1578]' : added node SelectionKeyWrapper[127.0.0.1:53682, readyOps=1, keyOps=5]
2011-01-22 08:14:57,742 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_DISPATCHED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,760 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:14:57,764 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId 'Analysis Job Dec 07 id[1578]' : added node SelectionKeyWrapper[127.0.0.1:53698, readyOps=1, keyOps=5]
2011-01-22 08:14:57,767 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:14:57,789 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId 'Analysis Job Dec 07 id[1578]' : added node SelectionKeyWrapper[127.0.0.1:53706, readyOps=1, keyOps=5]
2011-01-22 08:14:57,793 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,793 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_DISPATCHED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,794 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,794 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_DISPATCHED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:57,835 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:14:57,867 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:14:58,408 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId 'Analysis Job Dec 07 id[1578]' : added node SelectionKeyWrapper[127.0.0.1:53690, readyOps=4, keyOps=0]
2011-01-22 08:14:58,408 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_DISPATCHED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:19,095 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId 'Analysis Job Dec 07 id[1578]' : removed node SelectionKeyWrapper[127.0.0.1:53690, readyOps=1, keyOps=0]
2011-01-22 08:15:19,095 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:19,095 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:15:19,096 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId 'Analysis Job Dec 07 id[1578]' : added node SelectionKeyWrapper[127.0.0.1:53690, readyOps=1, keyOps=5]
2011-01-22 08:15:19,096 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:19,096 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_DISPATCHED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:20,060 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId 'Analysis Job Dec 07 id[1578]' : removed node SelectionKeyWrapper[127.0.0.1:53682, readyOps=1, keyOps=0]
2011-01-22 08:15:20,060 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:20,060 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:15:20,065 [DEBUG][org.jppf.server.job.JPPFJobManager.jobDispatched(118)]: jobId 'Analysis Job Dec 07 id[1578]' : added node SelectionKeyWrapper[127.0.0.1:53682, readyOps=4, keyOps=0]
2011-01-22 08:15:20,065 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:20,066 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_DISPATCHED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:21,826 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJobInNodes(214)]: Cancelling jobId = 'f8925c6b95cb7ba4cdfdcb2990f5c733' in nodes: [org.jppf.server.job.ChannelBundlePair@4c657ba, org.jppf.server.job.ChannelBundlePair@b482be4d, org.jppf.server.job.ChannelBundlePair@f1626e3e, org.jppf.server.job.ChannelBundlePair@25454f0c]
2011-01-22 08:15:21,828 [DEBUG][org.jppf.server.job.management.CancelJobTask.run(77)]: Request to cancel jobId = 'f8925c6b95cb7ba4cdfdcb2990f5c733' on node SelectionKeyWrapper[127.0.0.1:53698, readyOps=4, keyOps=1], requeue = false
2011-01-22 08:15:21,832 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJob(75)]: Request to cancel jobId = 'Analysis Job Dec 07 id[1578]'
2011-01-22 08:15:21,838 [DEBUG][org.jppf.server.job.management.CancelJobTask.run(77)]: Request to cancel jobId = 'f8925c6b95cb7ba4cdfdcb2990f5c733' on node SelectionKeyWrapper[127.0.0.1:53690, readyOps=4, keyOps=1], requeue = false
2011-01-22 08:15:21,844 [DEBUG][org.jppf.server.job.management.CancelJobTask.run(77)]: Request to cancel jobId = 'f8925c6b95cb7ba4cdfdcb2990f5c733' on node SelectionKeyWrapper[127.0.0.1:53706, readyOps=4, keyOps=1], requeue = false
2011-01-22 08:15:21,844 [DEBUG][org.jppf.server.job.management.CancelJobTask.run(77)]: Request to cancel jobId = 'f8925c6b95cb7ba4cdfdcb2990f5c733' on node SelectionKeyWrapper[127.0.0.1:53682, readyOps=4, keyOps=1], requeue = false
2011-01-22 08:15:21,845 [DEBUG][org.jppf.server.job.management.DriverJobManagement.cancelJob(76)]: bundleWrapper=org.jppf.server.protocol.BundleWrapper@3740b48
2011-01-22 08:15:21,845 [DEBUG][org.jppf.server.job.JPPFJobManager.jobUpdated(179)]: jobId 'Analysis Job Dec 07 id[1578]' updated
2011-01-22 08:15:21,846 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_UPDATED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:22,242 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId 'Analysis Job Dec 07 id[1578]' : removed node SelectionKeyWrapper[127.0.0.1:53690, readyOps=1, keyOps=0]
2011-01-22 08:15:22,248 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:22,251 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId 'Analysis Job Dec 07 id[1578]' : removed node SelectionKeyWrapper[127.0.0.1:53698, readyOps=1, keyOps=0]
2011-01-22 08:15:22,252 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:22,269 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId 'Analysis Job Dec 07 id[1578]' : removed node SelectionKeyWrapper[127.0.0.1:53682, readyOps=1, keyOps=0]
2011-01-22 08:15:22,271 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job Analysis Job Dec 07 id[1578]
2011-01-22 08:15:22,274 [DEBUG][org.jppf.server.job.JPPFJobManager.jobReturned(138)]: jobId 'Analysis Job Dec 07 id[1578]' : removed node SelectionKeyWrapper[127.0.0.1:53706, readyOps=1, keyOps=0]
2011-01-22 08:15:22,278 [DEBUG][org.jppf.server.job.management.DriverJobManagement.sendNotification(297)]: sending event JOB_RETURNED for job Analysis Job Dec 07 id[1578]

Here is the code how I'm canceling the job:

Code: [Select]


JMXDriverConnectionWrapper drvCon = ((JPPFClientConnectionImpl) jppfClientInstance.getClientConnection()).getJmxConnection();

        String host = drvCon.getHost();
     if (drvCon.isConnected(){
            for (int i = 0; i < ids.length; i++) {
                String id = ids[i];
                if (id == null) {
                    continue;
                }
                _log.info("Trying to stop job-> " + id;
                drvCon.cancelJob(id);
                _log.info("job-> " + id + " is stopped");
            }
      }
      else{
         _log.warn("Could not connect to driver: " + host);
     }

All jobs are submitting non-blocking. This is in a web application by where a user makes a request to submit a job, the job is then is submitted and control is returned to the user. The user then has the ability to cancel the job which is a http request to do so. This can be a single job to a number of jobs. The ids are the UUIDS from jobNotification.getJobUuid()

What's interesting is that there is no exceptions thrown and the administration ui does not allow me cancel the task thereafter, just stays there, even after restarting the manager.
Many thanks again for your help

[Xyrus]

One possibility is that your task is not correctly responding to thread interruptions. If you're using multiple threads or spawning other process, you need to make sure that you correctly catch and handle thread interruption exceptions. The driver may cancel the job, but any tasks that are running that don't correctly handle interruptions will continue to run. And depending on how the cancelation logic is implemented in the driver (I haven't looked into this, so it is only an assumption) it may be sitting there waiting for the currently running tasks to complete before marking the job as canceled.

In fact, judging by the log output, that's what appears to be going on as the cancel request is made but then nothing else appears to happen.

~X~

[lolo]

Hello,

I apologize for this late reply.

In fact, what I'm seeing in the log is that the cancel request is processed by the driver (see the "Request to cancel jobId = 'xxx' on node yyy" messages), and the sub-jobs are returned from the nodes shortly thereafter (look for the "JOB_RETURNED" notifications).
However, what I'm not seeing is the final JOB_ENDED notification, that should happen right after all the JOB_RETURNED events are processed.
It's a problem that patch jppf-2.4-patch-02 was supposed to fix, can you confirm that you applied it? Can you do me a favor and apply it again (just this one as it also includes the fixes in the previous patch)?

Thanks,
-Laurent

[codemonkey]

Hi Laurent, thank you for the reply. I double checked that I have the jppf-2.4-patch-02 installed and to no avail I'm still not able to remove the job. Messages in the debug log are the same as from my previous post where the JOB_ENDED status notification should be signaled.

I've ensured that our task runners do in fact intercept thread interruptions, as mentioned by Xyrus. The tasks are release from the nodes but the job still remains on the driver and does not leave until the grid is restarted

What else can I be looking at? This is getting critical for me and appreciate all the help

Thank you very much

[lolo]

Ok, I think I've nailed it down this time.
I have updated patch 02 with a new jar, can you please give it a try again and let us know if it fixes the problem?

Thanks,
-Laurent

[codemonkey]

Success! Working like a charm. Thank You!!! 

I've wanted to ask one more question on regards to cancellation of jobs. I Notice that when I've canceled a job, any of the running tasks that are canceled will have jppfTask.getException() == null and the jppfTask.getResult() == null. Is this correct? Or is there something else I should be looking at.

So many thanks again!