Uploaded image for project: 'OpenDJ'
  1. OpenDJ
  2. OPENDJ-1071

Tasks sometimes fail with error message "There are no tasks defined with ID ..."

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 2.6.0, 2.4.4
    • Fix Version/s: None
    • Component/s: tools
    • Labels:
    • Support Ticket IDs:
    • Sprint:
      DJ Sustaining Sprint 15, DJ Sustaining Sprint 16, DJ Sustaining Sprint 17, DJ Sustaining Sprint 18, DJ Sustaining Sprint 25

      Description

      Sometimes tasks scheduled by running a tool (import, backup, ...) in online mode fail with error message "There are no tasks defined with ID ..."

      1. Configure the instance

      $ /var/tmp/opendj/setup --cli -h localhost -p 7389 --adminConnectorPort 7444 -D "cn=myself" -w "password" -b dc=com -d 20 -n
      

      2. Run a loop doing a import of 161 entries

      $ /var/tmp/opendj/bin/import-ldif -h localhost -p 7444 -X -D "cn=myself" -w "password" -l /var/tmp/Example.ldif -n userRoot -R /var/tmp/import_tasks_rejects.txt
      Import task 20130711143431780 scheduled to start immediately
      There are no tasks defined with ID '20130711143431780'
      $ echo $?
      1
      

      3. In the errors log, we can see that the task has been executed and finished

      $ cat /var/tmp/opendj/logs/errors
      ...
      [11/Jul/2013:14:34:31 +0200] category=BACKEND severity=NOTICE msgID=9896349 msg=Import task 20130711143431780 started execution
      [11/Jul/2013:14:34:31 +0200] category=BACKEND severity=NOTICE msgID=9896306 msg=The backend userRoot is now taken offline
      [11/Jul/2013:14:34:31 +0200] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381717 msg=Installation Directory:  /var/tmp/opendj
      [11/Jul/2013:14:34:31 +0200] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381719 msg=Instance Directory:      /var/tmp/opendj
      [11/Jul/2013:14:34:31 +0200] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381713 msg=JVM Information: 1.7.0_25-b15 by Oracle Corporation, 64-bit architecture, 1847394304 bytes heap size
      [11/Jul/2013:14:34:31 +0200] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381714 msg=JVM Host: localhost, running Linux 3.5.0-34-generic amd64, 8311570432 bytes physical memory size, number of processors available 4
      [11/Jul/2013:14:34:31 +0200] category=RUNTIME_INFORMATION severity=NOTICE msgID=20381715 msg=JVM Arguments: "-Dorg.opends.server.scriptName=start-ds"
      [11/Jul/2013:14:34:31 +0200] category=JEB severity=NOTICE msgID=8847546 msg=The amount of free memory available to the import task is 624924878 bytes. The number of phase one buffers required is 320 buffers
      [11/Jul/2013:14:34:31 +0200] category=JEB severity=NOTICE msgID=8847568 msg=The amount memory available to the temporary DN cache environment is 412342285 bytes
      [11/Jul/2013:14:34:31 +0200] category=JEB severity=NOTICE msgID=8847545 msg=Setting DB cache size to 8388608 bytes and phase one buffer size to to 510075 bytes
      [11/Jul/2013:14:34:31 +0200] category=JEB severity=NOTICE msgID=8847533 msg=OpenDJ 2.7.0 starting import (build 20130711122042Z, R9215)
      [11/Jul/2013:14:34:31 +0200] category=JEB severity=NOTICE msgID=8847449 msg=Import Thread Count: 8 threads
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847556 msg=The available memory for phase two processing is 624924878 bytes. The read ahead cache size is 510075 bytes calculated using 29 buffers
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index dn.dn phase two started processing 8 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index givenName.substring phase two started processing 4 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index cn.substring phase two started processing 3 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index cn.equality phase two started processing 4 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index cn.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index telephoneNumber.substring phase two started processing 4 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index givenName.substring phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847538 msg=DN phase two processing completed. Processed 161 DNs
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index objectClass.equality phase two started processing 4 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index sn.substring phase two started processing 7 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index objectClass.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index sn.equality phase two started processing 7 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index sn.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index uid.equality phase two started processing 5 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index sn.substring phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index uniqueMember.equality phase two started processing 3 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index uid.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index uniqueMember.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index mail.equality phase two started processing 6 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index cn.substring phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index givenName.equality phase two started processing 7 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index entryUUID.equality phase two started processing 7 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index telephoneNumber.substring phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index mail.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index telephoneNumber.equality phase two started processing 5 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index givenName.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847571 msg=Index mail.substring phase two started processing 4 buffers in 1 batches
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index entryUUID.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index telephoneNumber.equality phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847539 msg=Index mail.substring phase two processing completed
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847569 msg=Total import time was 0 seconds. Phase one processing completed in 0 seconds, phase two processing completed in 0 seconds
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847454 msg=Processed 161 entries, imported 161, skipped 0, rejected 0 and migrated 0 in 0 seconds (average rate 2205.5/sec)
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847536 msg=Import LDIF environment close took 0 seconds
      [11/Jul/2013:14:34:32 +0200] category=JEB severity=NOTICE msgID=8847402 msg=The database backend userRoot containing 161 entries has started
      [11/Jul/2013:14:34:32 +0200] category=BACKEND severity=NOTICE msgID=9896350 msg=Import task 20130711143431780 finished execution
      

      4. If we search for this task under "cn=Tasks" backend, we can see that the state of the task is "COMPLETED_SUCCESSFULLY"

      $ cat /var/tmp/opendj/bin/ldapsearch -p 7389 -D cn=myself -w password -b cn=Tasks ds-task-id=20130711143431780
      dn: ds-task-id=20130711143431780,cn=Scheduled Tasks,cn=Tasks
      ds-task-import-backend-id: userRoot
      objectClass: ds-task-import
      objectClass: ds-task
      objectClass: top
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=0 m
       sgID=9896349 message="Import task 20130711143431780 started execution"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="INFORMATION" msgCoun
       t=1 msgID=9437595 message="Local DB backend userRoot does not specify the numbe
       r of lock tables: defaulting to 97"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="INFORMATION" msgCoun
       t=2 msgID=9437594 message="Local DB backend userRoot does not specify the numbe
       r of cleaner threads: defaulting to 24 threads"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=3 m
       sgID=9896306 message="The backend userRoot is now taken offline"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=4 m
       sgID=20381717 message="Installation Directory:  /var/tmp/opendj"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=5 m
       sgID=20381719 message="Instance Directory:      /var/tmp/opendj"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=6 m
       sgID=20381713 message="JVM Information: 1.7.0_25-b15 by Oracle Corporation, 64-
       bit architecture, 1847394304 bytes heap size"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=7 m
       sgID=20381714 message="JVM Host: localhost, running Linux 3.5.0-34-generic amd
       64, 8311570432 bytes physical memory size, number of processors available 4"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=8 m
       sgID=20381715 message="JVM Arguments: "-Dorg.opends.server.scriptName=start-ds"
       "
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=9 m
       sgID=8847546 message="The amount of free memory available to the import task is
        624924878 bytes. The number of phase one buffers required is 320 buffers"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=10 
       msgID=8847568 message="The amount memory available to the temporary DN cache en
       vironment is 412342285 bytes"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=11 
       msgID=8847545 message="Setting DB cache size to 8388608 bytes and phase one buf
       fer size to to 510075 bytes"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=12 
       msgID=8847533 message="OpenDJ 2.7.0 starting import (build 20130711122042Z, R92
       15)"
      ds-task-log-message: [11/Jul/2013:14:34:31 +0200] severity="NOTICE" msgCount=13 
       msgID=8847449 message="Import Thread Count: 8 threads"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="NOTICE" msgCount=14 
       msgID=8847556 message="The available memory for phase two processing is 6249248
       78 bytes. The read ahead cache size is 510075 bytes calculated using 29 buffers
       "
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="NOTICE" msgCount=15 
       msgID=8847569 message="Total import time was 0 seconds. Phase one processing co
       mpleted in 0 seconds, phase two processing completed in 0 seconds"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="NOTICE" msgCount=16 
       msgID=8847454 message="Processed 161 entries, imported 161, skipped 0, rejected
        0 and migrated 0 in 0 seconds (average rate 2205.5/sec)"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="NOTICE" msgCount=17 
       msgID=8847536 message="Import LDIF environment close took 0 seconds"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="INFORMATION" msgCoun
       t=18 msgID=9437595 message="Local DB backend userRoot does not specify the numb
       er of lock tables: defaulting to 97"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="INFORMATION" msgCoun
       t=19 msgID=9437594 message="Local DB backend userRoot does not specify the numb
       er of cleaner threads: defaulting to 24 threads"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="NOTICE" msgCount=20 
       msgID=8847402 message="The database backend userRoot containing 161 entries has
        started"
      ds-task-log-message: [11/Jul/2013:14:34:32 +0200] severity="NOTICE" msgCount=21 
       msgID=9896350 message="Import task 20130711143431780 finished execution"
      ds-task-import-thread-count: 0
      ds-task-id: 20130711143431780
      ds-task-actual-start-time: 20130711123431Z
      ds-task-import-reject-file: /var/tmp/import_tasks_025-rejects.txt
      ds-task-import-random-seed: 0
      ds-task-completion-time: 20130711123432Z
      ds-task-state: COMPLETED_SUCCESSFULLY
      ds-task-class-name: org.opends.server.tasks.ImportTask
      ds-task-import-ldif-file: /var/tmp/Example.ldif
      

      5. But in the access log, we can see that at one point the tasks was no more present under "cn=Tasks" backend

      $ cat /var/tmp/opendj/logs/access
      ...
      [11/Jul/2013:14:34:31 +0200] CONNECT conn=63 from=127.0.0.1:33990 to=127.0.1.1:7444 protocol=LDAPS
      [11/Jul/2013:14:34:31 +0200] BIND REQ conn=63 op=0 msgID=1 version=3 type=SIMPLE dn="cn=myself"
      [11/Jul/2013:14:34:31 +0200] BIND RES conn=63 op=0 msgID=1 result=0 authDN="cn=Directory Manager,cn=Root DNs,cn=config" etime=0
      [11/Jul/2013:14:34:31 +0200] ADD REQ conn=63 op=1 msgID=0 dn="ds-task-id=20130711143431780,cn=Scheduled Tasks,cn=Tasks"
      [11/Jul/2013:14:34:31 +0200] ADD RES conn=63 op=1 msgID=0 result=0 etime=7
      [11/Jul/2013:14:34:31 +0200] SEARCH REQ conn=63 op=2 msgID=1 base="cn=Tasks" scope=wholeSubtree filter="(ds-task-id=20130711143431780)" attrs="ALL"
      [11/Jul/2013:14:34:31 +0200] SEARCH RES conn=63 op=2 msgID=1 result=0 nentries=1 etime=2
      [11/Jul/2013:14:34:31 +0200] SEARCH REQ conn=63 op=3 msgID=2 base="cn=Tasks" scope=wholeSubtree filter="(ds-task-id=20130711143431780)" attrs="ALL"
      [11/Jul/2013:14:34:31 +0200] SEARCH RES conn=63 op=3 msgID=2 result=32 message="The entry cn=Tasks specified as the search base does not exist in the Directory Server" nentries=0 etime=0
      [11/Jul/2013:14:34:31 +0200] DISCONNECT conn=63 reason="Client Disconnect"
      

        Attachments

          Activity

            People

            • Assignee:
              patrickdiligent patrick diligent
              Reporter:
              csovant Christophe Sovant
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: