Print

[Emin Mamedov]

Hi Laurent,

We are deep in JPPF testing now. At the moment we started LongRun Test. During the test we submit every 2 seconds the same job that consists of 10 tasks on the grid (fixed delay). Mostly everything works fine but sometimes (can be after 1000 iterations, can be after 30000 iterations) we do not receive JOB_END event (but receive all 10 JOB_RETURN events). Below you can see JPPF client debug logs

JPPF: 4.2.5
Java: 1.7.0_45
OS: Win2008
Topology: 1 client, 1 driver, 20 nodes

Logs from client:

Code: [Select]

2015-01-19 04:02:57,833 DEBUG - creating ClientJob #25969 [org.jppf.client.balancer.AbstractClientJob] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:57,833 DEBUG - submission [longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] status changing from 'SUBMITTED' to 'PENDING' [org.jppf.client.JPPFResultCollector] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:57,833 DEBUG - submission [longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] fire status changed event for 'PENDING' [org.jppf.client.JPPFResultCollector] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:57,833 DEBUG - adding bundle with ClientJob[job=JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=0, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538], submissionStatus=PENDING, broadcastUUID=null, executing=false, nbTasks=10] [org.jppf.client.balancer.queue.JPPFPriorityQueue] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:57,833 DEBUG - Maps size information: priorityMap[shallow size=1, total elements=1] - sizeMap[shallow size=1, total elements=1] [org.jppf.client.balancer.queue.JPPFPriorityQueue] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:57,833 DEBUG - 10 channels idle [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - found 10 acceptable channels [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - channel found for bundle: ChannelWrapperRemote[channel=driver1-8[LONGMCFU0177:21510] : ACTIVE] [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - dispatching jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a to channel ChannelWrapperRemote[channel=driver1-8[LONGMCFU0177:21510] : ACTIVE], connectionUuid= [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - requesting bundle with 1000000 tasks, next bundle has 10 tasks [org.jppf.client.balancer.queue.JPPFPriorityQueue] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - removing bundle from queue, jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a [org.jppf.client.balancer.queue.JPPFPriorityQueue] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - Maps size information: priorityMap[shallow size=0, total elements=0] - sizeMap[shallow size=0, total elements=0] [org.jppf.client.balancer.queue.JPPFPriorityQueue] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - connection 'driver1-8 - TasksServer' status changing from ACTIVE to EXECUTING [org.jppf.client.AbstractClientConnectionHandler] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - connection 'driver1-8' status changing from ACTIVE to EXECUTING [org.jppf.client.AbstractJPPFClientConnection] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - firing JOB_START event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=0, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - submission [longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] status changing from 'PENDING' to 'EXECUTING' [org.jppf.client.JPPFResultCollector] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - submission [longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] fire status changed event for 'EXECUTING' [org.jppf.client.JPPFResultCollector] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - firing JOB_DISPATCH event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=0, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [TaskQueueChecker] {}
2015-01-19 04:02:57,833 DEBUG - registered RegisteredClassLoader[classLoader=sun.misc.Launcher$AppClassLoader@fe2509, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] [org.jppf.client.AbstractGenericClient] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,115 DEBUG - creating ClientJob #25970 [org.jppf.client.balancer.AbstractClientJob] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:58,115 DEBUG - submission [longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc] status changing from 'SUBMITTED' to 'PENDING' [org.jppf.client.JPPFResultCollector] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:58,115 DEBUG - submission [longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc] fire status changed event for 'PENDING' [org.jppf.client.JPPFResultCollector] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:58,115 DEBUG - adding bundle with ClientJob[job=JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=0, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b], submissionStatus=PENDING, broadcastUUID=null, executing=false, nbTasks=10] [org.jppf.client.balancer.queue.JPPFPriorityQueue] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:58,115 DEBUG - Maps size information: priorityMap[shallow size=1, total elements=1] - sizeMap[shallow size=1, total elements=1] [org.jppf.client.balancer.queue.JPPFPriorityQueue] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:58,115 DEBUG - 9 channels idle [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - found 9 acceptable channels [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - channel found for bundle: ChannelWrapperRemote[channel=driver1-7[LONGMCFU0177:21510] : ACTIVE] [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - dispatching jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc to channel ChannelWrapperRemote[channel=driver1-7[LONGMCFU0177:21510] : ACTIVE], connectionUuid= [org.jppf.client.balancer.queue.TaskQueueChecker] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - requesting bundle with 1000000 tasks, next bundle has 10 tasks [org.jppf.client.balancer.queue.JPPFPriorityQueue] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - removing bundle from queue, jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc [org.jppf.client.balancer.queue.JPPFPriorityQueue] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - Maps size information: priorityMap[shallow size=0, total elements=0] - sizeMap[shallow size=0, total elements=0] [org.jppf.client.balancer.queue.JPPFPriorityQueue] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - connection 'driver1-7 - TasksServer' status changing from ACTIVE to EXECUTING [org.jppf.client.AbstractClientConnectionHandler] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - connection 'driver1-7' status changing from ACTIVE to EXECUTING [org.jppf.client.AbstractJPPFClientConnection] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - firing JOB_START event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=0, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - submission [longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc] status changing from 'PENDING' to 'EXECUTING' [org.jppf.client.JPPFResultCollector] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - submission [longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc] fire status changed event for 'EXECUTING' [org.jppf.client.JPPFResultCollector] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - firing JOB_DISPATCH event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=0, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [TaskQueueChecker] {}
2015-01-19 04:02:58,115 DEBUG - registered RegisteredClassLoader[classLoader=sun.misc.Launcher$AppClassLoader@fe2509, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc] [org.jppf.client.AbstractGenericClient] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:58,802 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=0 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,802 DEBUG - received 1 tasks from server, first position=0 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - Received results for 1 tasks, pendingCount=9, count=10, jobResults=JobResults[size=1, positions=[0]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=1, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=8 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - received 1 tasks from server, first position=8 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - Received results for 1 tasks, pendingCount=8, count=10, jobResults=JobResults[size=2, positions=[0, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,818 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=2, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,864 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=6 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,864 DEBUG - received 1 tasks from server, first position=6 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,864 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,864 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,864 DEBUG - Received results for 1 tasks, pendingCount=7, count=10, jobResults=JobResults[size=3, positions=[0, 6, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,864 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=3, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,896 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=2 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,896 DEBUG - received 1 tasks from server, first position=2 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,896 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,896 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,896 DEBUG - Received results for 1 tasks, pendingCount=6, count=10, jobResults=JobResults[size=4, positions=[0, 2, 6, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,896 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=4, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,911 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=9 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,911 DEBUG - received 1 tasks from server, first position=9 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,911 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,911 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,911 DEBUG - Received results for 1 tasks, pendingCount=5, count=10, jobResults=JobResults[size=5, positions=[0, 2, 6, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,911 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=5, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,958 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=4 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,958 DEBUG - received 1 tasks from server, first position=4 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,958 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,958 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,958 DEBUG - Received results for 1 tasks, pendingCount=4, count=10, jobResults=JobResults[size=6, positions=[0, 2, 4, 6, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:58,958 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=6, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,130 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=1 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,130 DEBUG - received 1 tasks from server, first position=1 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,130 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,130 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,130 DEBUG - Received results for 1 tasks, pendingCount=3, count=10, jobResults=JobResults[size=7, positions=[0, 1, 2, 4, 6, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,130 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=7, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,270 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f, uuid=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=0 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - received 1 tasks from server, first position=0 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - Received results for 1 tasks, pendingCount=9, count=10, jobResults=JobResults[size=1, positions=[0]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=1, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=6 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - received 1 tasks from server, first position=6 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - Received results for 1 tasks, pendingCount=8, count=10, jobResults=JobResults[size=2, positions=[0, 6]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=2, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=7 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,270 DEBUG - received 1 tasks from server, first position=7 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,270 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,270 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,270 DEBUG - Received results for 1 tasks, pendingCount=2, count=10, jobResults=JobResults[size=8, positions=[0, 1, 2, 4, 6, 7, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,286 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=8, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,317 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=3 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,317 DEBUG - received 1 tasks from server, first position=3 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,317 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,317 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,332 DEBUG - Received results for 1 tasks, pendingCount=1, count=10, jobResults=JobResults[size=9, positions=[0, 1, 2, 3, 4, 6, 7, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,332 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=9, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,364 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=0 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,364 DEBUG - received 1 tasks from server, first position=0 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,364 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,364 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,364 WARN  - position 0 (out of 1) already has a result [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,364 DEBUG - Received results for 1 tasks, pendingCount=8, count=10, jobResults=JobResults[size=2, positions=[0, 6]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,364 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=2, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=2 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 tasks from server, first position=2 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - Received results for 1 tasks, pendingCount=7, count=10, jobResults=JobResults[size=3, positions=[0, 2, 6]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=3, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_8, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=5 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 tasks from server, first position=5 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - Received results for 1 tasks, pendingCount=0, count=10, jobResults=JobResults[size=10, positions=[0, 1, 2, 3, 4, 5, 6, 7, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=10, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - firing JOB_END event for JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=10, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - unregistering RegisteredClassLoader[classLoader=sun.misc.Launcher$AppClassLoader@fe2509, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] [org.jppf.client.AbstractGenericClient] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - bundle=[jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, jobUuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false], exception=null for ClientJob[job=JPPFJob[name=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a, blocking=false, nbTasks=10, nbResults=10, jobSLA=org.jppf.server.protocol.JPPFJobSLA@cf7538], submissionStatus=EXECUTING, broadcastUUID=null, executing=true, nbTasks=0] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - removing bundle from queue, jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a [org.jppf.client.balancer.queue.JPPFPriorityQueue] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - submission [longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] status changing from 'EXECUTING' to 'COMPLETE' [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - submission [longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a] fire status changed event for 'COMPLETE' [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - connection 'driver1-8 - TasksServer' status changing from EXECUTING to ACTIVE [org.jppf.client.AbstractClientConnectionHandler] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - connection 'driver1-8' status changing from EXECUTING to ACTIVE [org.jppf.client.AbstractJPPFClientConnection] [RemoteChannelWrapper-driver1-8-0001] {}
2015-01-19 04:02:59,379 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=4 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 tasks from server, first position=4 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - Received results for 1 tasks, pendingCount=6, count=10, jobResults=JobResults[size=4, positions=[0, 2, 4, 6]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=4, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - request to cancel job with uuid=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a [org.jppf.client.AbstractGenericClient] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:59,379 DEBUG - requesting cancel of jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a [org.jppf.client.balancer.SubmissionManagerClient] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:59,379 DEBUG - requesting cancel of jobId=longruntest#6790@-5128272356269833674_high-piority@629d9dee-e09c-417a-8f60-23683848ca9a [org.jppf.client.balancer.queue.JPPFPriorityQueue] [calculationSessionExecutorPool-1] {}
2015-01-19 04:02:59,379 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=8 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 tasks from server, first position=8 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - Received results for 1 tasks, pendingCount=5, count=10, jobResults=JobResults[size=5, positions=[0, 2, 4, 6, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,379 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=5, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,395 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=1 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,395 DEBUG - received 1 tasks from server, first position=1 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,395 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,395 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,395 DEBUG - Received results for 1 tasks, pendingCount=4, count=10, jobResults=JobResults[size=6, positions=[0, 1, 2, 4, 6, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,395 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=6, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,520 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=7 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,520 DEBUG - received 1 tasks from server, first position=7 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,520 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,520 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,520 DEBUG - Received results for 1 tasks, pendingCount=3, count=10, jobResults=JobResults[size=7, positions=[0, 1, 2, 4, 6, 7, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,520 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=7, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,551 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=3 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,551 DEBUG - received 1 tasks from server, first position=3 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,551 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,551 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,551 DEBUG - Received results for 1 tasks, pendingCount=2, count=10, jobResults=JobResults[size=8, positions=[0, 1, 2, 3, 4, 6, 7, 8]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,551 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=8, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=9 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - received 1 tasks from server, first position=9 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - received 1 results for bundle [jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - Received results for 1 tasks, pendingCount=1, count=10, jobResults=JobResults[size=9, positions=[0, 1, 2, 3, 4, 6, 7, 8, 9]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - firing JOB_RETURN event for JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=9, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b] [org.jppf.client.JPPFJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - unregistering RegisteredClassLoader[classLoader=sun.misc.Launcher$AppClassLoader@fe2509, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc] [org.jppf.client.AbstractGenericClient] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - bundle=[jobId=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, jobUuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false], exception=null for ClientJob[job=JPPFJob[name=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, blocking=false, nbTasks=10, nbResults=9, jobSLA=org.jppf.server.protocol.JPPFJobSLA@3a133b], submissionStatus=EXECUTING, broadcastUUID=null, executing=true, nbTasks=0] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - connection 'driver1-7 - TasksServer' status changing from EXECUTING to ACTIVE [org.jppf.client.AbstractClientConnectionHandler] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,644 DEBUG - connection 'driver1-7' status changing from EXECUTING to ACTIVE [org.jppf.client.AbstractJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:03:12,330 DEBUG - JPPFClientConnectionImpl[connectionUuid=Marina-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=1barrier_heat#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, uuid=1barrier_heat#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Marina-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3
2015-01-19 04:03:12,330 DEBUG - received 1 tasks from server, first position=5 [org.jppf.client.balancer.ChannelWrapperRemote] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:03:12,330 DEBUG - received 1 results for bundle [jobId=1barrier_heat#6793@-6786290744287921289_high-piority@6f09dd71-7982-4956-b49d-ef2e5bda90cc, jobUuid=1barrier_heat#6793@-6786290744287921289_high-piority@6f09dd71-7982-4956-b49d-ef2e5bda90cc, initialTaskCount=10, taskCount=10, requeue=false, cancelled=false] [org.jppf.client.balancer.ClientJob] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:03:12,330 DEBUG - adding 1 results [org.jppf.client.JobResults] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:03:12,330 DEBUG - Received results for 1 tasks, pendingCount=9, count=10, jobResults=JobResults[size=1, positions=[5]] [org.jppf.client.JPPFResultCollector] [RemoteChannelWrapper-driver1-7-0001] {}

Could you please check whats wrong? Do you need anything else for investigation?

UPD: Updated logs. Previously used wrong grep and have provided not all logs.

Thanks,
Emin

[Emin Mamedov]

Hi Laurent,

In provided in previous message logs you can see that at "2015-01-19 04:02:59,270" we receive task result for wrong job (uuid=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f) but connection RemoteChannelWrapper-driver1-7-0001 is used by job with uuid=longruntest#6790@-4759856926223087884_high-piority@6abb5f29-b428-4ff6-a1c9-f9b3a3061afc already. So we 2 times receive results for position 0 for the job.

Emin

[lolo]

Hi Emin,

It looks like there is a subtle bug somewhere in the server, and I'm currently working at reproducing it. Maybe you can help me with that? If you don't mind answering a few questions, if would be very helpful to know:
- what kind of topology you are using, in particular how many client connections and how many concurrent jobs in a typical scenario? (I see that you already mentioned 1 driver and 20 nodes)
- it's my understanding, from the log you provided, that you use a load-balancing algorithm that distributes only one task at a time to each node, could you confirm this? I'm not sure it's really relevant, but better safe than sorry
- what kind of tasks are you executing on the grid, in terms of computational weight? Are they mostly CPU or I/O bound, or a mix? How long do they typically last?
- I've noticed in the logs that there was an attempt to cancel a job via JPPFClient.cancelJob() or JPPFJob.cancel(). This can only come from your client code, and I'm wondering what is the triggering condition?

On my side, I have tried multiple simulations of what I hoped would reproduce the issue, but without success so far. I've tried with various combination of number of jobs (from 1000 up to 100,000 jobs) and various numbers of nodes and client connections. So it's clear I'm still missing something.

Thanks a lot for your help,
-Laurent

[Emin Mamedov]

Hi Laurent,

1. We have just 1 client but with 10 connections to driver (driver1.jppf.pool.size=10)
2. We execute 2 identical jobs in parallel (each job consists of 10 tasks). But they can be started not at the same time. For example, in log from previous post you can see
   

Code: [Select]

    2015-01-19 04:02:57,833 DEBUG - creating ClientJob #25969
    2015-01-19 04:02:58,115 DEBUG - creating ClientJob #25970
    3. You are right. Each node can execute just one task
    Node config:
   

Code: [Select]

    jppf.processing.threads = 1
   
    Driver config:
   

Code: [Select]

    jppf.load.balancing.algorithm = manual
    jppf.load.balancing.profile = manual_profile
    jppf.load.balancing.profile.manual_profile.size = 1
    4. Each task takes up to 1 sec for execution and it is mostly CPU consuming task.
5. We cancel the job even if it was finished successfully to be sure that all resources will be free. Is it ok?

Thanks,
Emin

[Emin Mamedov]

May be it helps also:

Code: [Select]

2015-01-19 04:02:49,954 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f, uuid=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=0 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}
2015-01-19 04:02:59,270 DEBUG - JPPFClientConnectionImpl[connectionUuid=Client-0001_-5174894465750184567_7, status=EXECUTING] : received bundle JPPFTaskBundle[name=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f, uuid=longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f, initialTaskCount=10, taskCount=1, bundleUuid=null, uuidPath=TraversalList[position=0, list=[Client-0001_-5174894465750184567, F1D6D695-76BC-3B81-153F-043965180CA3]]], positions=0 [org.jppf.client.BaseJPPFClientConnection] [RemoteChannelWrapper-driver1-7-0001] {}

Here you can see that we received two identical bundles. First one was expected - we executed longruntest#6788@-7635523889220729194_high-piority@8064603b-3989-4f78-b90b-52dfb6621f9f. This job was successfully finished without any errors. But the second bundle wasn't expected because we were in the middle of another job already ( but used the same driver's connection).

Emin

[Emin Mamedov]

Hi Laurent,

I have changed our implementation and now we do not cancel job if it was finished already. Looks like the issue is not reproducable anymore.

So I can confirm that it is reproducable if in jobEnded callback we call job.cancel(). In this case the last task result could be resent by server later that cause the issue

Thanks,
Emin

[Emin Mamedov]

Hi Laurent,

Sorry, I was wrong. The issue is still reproducable  :(" title="Angry" class="smiley"/>. After one day of long run test execution.

Thanks,
Emin

[Emin Mamedov]

Hi Laurent,

After investigation I can now provide you the steps to reproduce the issue in 100% cases:

JPPF: 4.2.5
Topology:
    - 1 client with 1 connection to the driver
    - 1 driver
    - 10 nodes
Job:
    - Consists of 10 tasks.
    - Each task is executed on node 2 sec (Thread.sleep(2000))
    - MaxTasksResubmits = 1
    - ApplyMaxResubmitsUponNodeError = true
Client: client submits 1 job for execution every 5 seconds

Action to reproduce the issue:
    - Start the client
    - Kill one node as soon as it receives the task

What we have:
    - Exception on driver (java.io.IOException: An existing connection was forcibly closed by the remote host). Driver resubmits the task via RequeueBundleAction
    - When other 9 tasks will be finished driver sends JOB_ENDED event to the client (JPPFPriorityQueue.removeBundle())
    - 2 seconds later driver will send result for task that was resubmited
    - 3 seconds later Client starts next iteration via the same connection. It reads the result for previous job from the stream.
    - Client receives 9 expected results and frees the connection
    - No JOB_ENDED event occurs because there is no thread to read the latest 10th result from the stream

Expected:
    - Driver silently resubmits the task without any client notifications
    - Driver doesn't send JOB_ENDED event if there are tasks that were resubmitted

As a workaround I set MaxTaskResubmit=0 for now.

Thanks,
Emin
   

[lolo]

Hi Emin,

Thank you so much for your investigation! With the steps you described, I am now able to reproduce the same error. Now the bug chase truly begins ...
For tracking purposes, I registered the bug JPPF-361 Driver sends results for wrong job upon task resubmit

Thanks,
-Laurent

[lolo]

Hi Emin,

I have implemented a fix for this issue and made it part of patch 02 for JPPF 4.2.5.
Please let us know if this resolves the problem on your side.

Sincerely,
-Laurent

[Emin Mamedov]

Hi Laurent,

Many thanks for the quick fix. I am testing it already 3 days without any issues. So can confirm now that it works

Thanks,
Emin