JPPF Issue Tracker
star_faded.png
Please log in to bookmark issues
bug_report_small.png
CLOSED  Bug report JPPF-588  -  Concurrent operations with DefaultFilePersistence job persistence result in exceptions
Posted Apr 20, 2019 - updated Apr 20, 2019
icon_info.png This issue has been closed with status "Closed" and resolution "RESOLVED".
Issue details
  • Type of issue
    Bug report
  • Status
     
    		 Closed
  • Assigned to
    lolo4j
  • Progress
       
  • Type of bug
    Not triaged
  • Likelihood
    Not triaged
  • Effect
    Not triaged
  • Posted by
    lolo4j
  • Owned by
    Not owned by anyone
  • Category
    Persistence
  • Resolution
    RESOLVED
  • Priority
    Normal
  • Reproducability
    Often
  • Severity
    Normal
  • Targetted for
    icon_milestones.png JPPF 6.1.1
Issue description
In a recently failed test of the file-based job persistence, I could find the following pattern in the driver log, where multilpe threads are performing 'store' and 'delete' opeations: 
2019-04-19 08:07:34,852 [DEBUG][JPPF-0007][org.jppf.server.queue.PersistenceHandler.storeResults(116)] persisting 5 results for job ServerJob[id=2, job uuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23, name=testSimplePersistedJob, submissionStatus=EXECUTING, status=EXECUTING, taskCount=0, nbBundles=1, jobExpired=false, pending=false, suspended=false]
...
2019-04-19 08:07:34,852 [DEBUG][JPPF-0007][org.jppf.job.persistence.impl.DefaultFilePersistence.store(97)] storing [PersistenceInfoImpl[type=TASK_RESULT, taskPosition=5, job=testSimplePersistedJob, jobUuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23], PersistenceInfoImpl[type=TASK_RESULT, taskPosition=8, job=testSimplePersistedJob, jobUuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23], PersistenceInfoImpl[type=TASK_RESULT, taskPosition=6, job=testSimplePersistedJob, jobUuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23], PersistenceInfoImpl[type=TASK_RESULT, taskPosition=9, job=testSimplePersistedJob, jobUuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23], PersistenceInfoImpl[type=TASK_RESULT, taskPosition=7, job=testSimplePersistedJob, jobUuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23]]
2019-04-19 08:07:34,852 [DEBUG][JPPF-0005][org.jppf.server.job.JPPFJobManager.jobEnded(195)] jobId 'testSimplePersistedJob' ended
2019-04-19 08:07:34,853 [DEBUG][JPPF-0005][org.jppf.server.queue.PersistenceHandler.deleteJob(141)] removing job 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23 from persistence store
2019-04-19 08:07:34,853 [DEBUG][JPPF-0005][org.jppf.job.persistence.impl.DefaultFilePersistence.deleteJob(168)] deleting job with uuid = 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23
2019-04-19 08:07:34,854 [DEBUG][JPPF-0003][org.jppf.server.queue.PersistenceHandler.deleteJob(141)] removing job 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23 from persistence store
2019-04-19 08:07:34,854 [DEBUG][JPPF-0003][org.jppf.job.persistence.impl.DefaultFilePersistence.deleteJob(168)] deleting job with uuid = 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23
...
2019-04-19 08:07:34,858 [DEBUG][JPPF-0007][org.jppf.server.protocol.ServerJob.lambda$postResultsReceived$0(189)] received results for ServerTaskBundleClient[id=2, pendingTasks=0, cancelled=false, done=true, job=JPPFTaskBundle[name=testSimplePersistedJob, uuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23, initialTaskCount=10, taskCount=10, bundleUuid=null, uuidPath=TraversalList[position=0, list=[4F5DEEB3-FEDE-4A18-A48F-9EE05CF06D94, d1]], nodeBundleId=null]; strategy=NodeResults]
2019-04-19 08:07:34,858 [DEBUG][JPPF-0007][org.jppf.server.protocol.ServerJob.taskCompleted(245)] requeue = false for bundle ServerTaskBundleNode[id=4, name=testSimplePersistedJob, uuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23, initialTaskCount=10, taskCount=5, cancelled=false, requeued=false, channel=AsyncNodeContext[uuid=n2, peer=false, ssl=false, local=false, offline=false, maxJobs=1, jobEntries=0, sendQueue size=0, interestOps=1, executionStatus=EXECUTING]], job = ServerJob[id=2, job uuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23, name=testSimplePersistedJob, submissionStatus=ENDED, status=DONE, taskCount=0, nbBundles=0, jobExpired=false, pending=false, suspended=false]
2019-04-19 08:07:34,859 [DEBUG][JPPF-0007][org.jppf.server.queue.PersistenceHandler.deleteJob(141)] removing job 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23 from persistence store
2019-04-19 08:07:34,859 [DEBUG][JPPF-0007][org.jppf.job.persistence.impl.DefaultFilePersistence.deleteJob(168)] deleting job with uuid = 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23
2019-04-19 08:07:34,860 [WARN ][JPPF-0003][org.jppf.utils.DeleteFileVisitor.visitFile(82)] error trying to delete file 'persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-7.tmp': java.nio.file.NoSuchFileException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-7.tmp
2019-04-19 08:07:34,860 [ERROR][JPPF-0007][org.jppf.server.queue.PersistenceHandler.deleteJob(145)] error deleting persistent job 0282BA15-CE62-4C5D-AF33-5F92CFB2BB23 : org.jppf.job.persistence.JobPersistenceException: java.nio.file.AccessDeniedException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\header.data
  at org.jppf.job.persistence.impl.DefaultFilePersistence.deleteJob(DefaultFilePersistence.java:172)
  at org.jppf.server.queue.PersistenceHandler.deleteJob(PersistenceHandler.java:143)
  at org.jppf.server.queue.PersistenceHandler.deleteJob(PersistenceHandler.java:132)
  at org.jppf.server.queue.RemoveBundleAction.run(RemoveBundleAction.java:63)
  at org.jppf.server.protocol.AbstractServerJob.done(AbstractServerJob.java:333)
  at org.jppf.server.protocol.AbstractServerJob.setSubmissionStatus(AbstractServerJob.java:418)
  at org.jppf.server.protocol.ServerJob.taskCompleted(ServerJob.java:253)
  at org.jppf.server.protocol.ServerJob.postResultsReceived(ServerJob.java:191)
  at org.jppf.server.protocol.ServerJob.resultsReceived(ServerJob.java:142)
  at org.jppf.server.protocol.ServerTaskBundleNode.resultsReceived(ServerTaskBundleNode.java:198)
  at org.jppf.server.nio.nodeserver.async.AsyncNodeMessageHandler.processResults(AsyncNodeMessageHandler.java:337)
  at org.jppf.server.nio.nodeserver.async.AsyncNodeMessageHandler.process(AsyncNodeMessageHandler.java:274)
  at org.jppf.server.nio.nodeserver.async.AsyncNodeMessageHandler.resultsReceived(AsyncNodeMessageHandler.java:183)
  at org.jppf.server.nio.nodeserver.async.AsyncNodeMessageReader.handleMessage(AsyncNodeMessageReader.java:73)
  at org.jppf.nio.NioMessageReader$HandlingTask.run(NioMessageReader.java:134)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)
Caused by: java.nio.file.AccessDeniedException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\header.data
  at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:83)
  at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
  at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102)
  at sun.nio.fs.WindowsFileSystemProvider.implDelete(WindowsFileSystemProvider.java:269)
  at sun.nio.fs.AbstractFileSystemProvider.delete(AbstractFileSystemProvider.java:103)
  at java.nio.file.Files.delete(Files.java:1126)
  at org.jppf.utils.DeleteFileVisitor.visitFile(DeleteFileVisitor.java:78)
  at org.jppf.utils.DeleteFileVisitor.visitFile(DeleteFileVisitor.java:30)
  at java.nio.file.Files.walkFileTree(Files.java:2670)
  at java.nio.file.Files.walkFileTree(Files.java:2742)
  at org.jppf.job.persistence.impl.DefaultFilePersistence.deleteJob(DefaultFilePersistence.java:170)
  ... 17 more
2019-04-19 08:07:34,861 [DEBUG][JPPF-0007][org.jppf.server.protocol.ServerJob.taskCompleted(254)] submissionStatus=ENDED, clientBundles=0 for ServerJob[id=2, job uuid=0282BA15-CE62-4C5D-AF33-5F92CFB2BB23, name=testSimplePersistedJob, submissionStatus=ENDED, status=DONE, taskCount=0, nbBundles=0, jobExpired=false, pending=false, suspended=false]
2019-04-19 08:07:34,861 [DEBUG][JPPF-0007][org.jppf.server.nio.nodeserver.async.AsyncNodeMessageHandler.processResults(338)] updated stats for AsyncNodeContext[uuid=n2, peer=false, ssl=false, local=false, offline=false, maxJobs=1, jobEntries=0, sendQueue size=0, interestOps=1, executionStatus=EXECUTING]
2019-04-19 08:07:34,860 [WARN ][JPPF-0005][org.jppf.utils.DeleteFileVisitor.visitFile(82)] error trying to delete file 'persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\header.data': java.nio.file.NoSuchFileException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\header.data
2019-04-19 08:07:34,862 [WARN ][JPPF-0005][org.jppf.utils.DeleteFileVisitor.visitFile(82)] error trying to delete file 'persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-0.data': java.nio.file.NoSuchFileException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-0.data
2019-04-19 08:07:34,862 [WARN ][JPPF-0005][org.jppf.utils.DeleteFileVisitor.visitFile(82)] error trying to delete file 'persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-1.data': java.nio.file.NoSuchFileException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-1.data
2019-04-19 08:07:34,862 [WARN ][JPPF-0005][org.jppf.utils.DeleteFileVisitor.visitFile(82)] error trying to delete file 'persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-2.data': java.nio.file.NoSuchFileException: persistence\0282BA15-CE62-4C5D-AF33-5F92CFB2BB23\result-2.data
Steps to reproduce this issue
I'm currently working on a JUnit test case that reproduces in a single JVM, without a grid, to ensure the can be reproduced at will before a fix is implemented, and that it cannot be reproduced any more when the fix is done. I will update with a link to the source code of the test when it is commited.

Here's the test code: https://github.com/jppf-grid/JPPF/blob/master/tests/src/tests/test/org/jppf/job/persistence/TestConcurrentFilePersistence.java