SuccessConsole Output

Skipping 2,796 KB.. Full Log
b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:2, nbD:2]
[DEBUG] 2019-11-12 05:07:48,961 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,961 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,961 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:1, nbD:1]
[DEBUG] 2019-11-12 05:07:48,961 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:1, nbD:1]
[DEBUG] 2019-11-12 05:07:48,961 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:5]
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:5]
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:4]
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:4]
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:8]
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:8]
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,962 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:7]
[DEBUG] 2019-11-12 05:07:48,963 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:7]
[DEBUG] 2019-11-12 05:07:48,963 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,963 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050745.730000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050748.840000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050748.820000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (JdbmTable:remove:686) ---> Remove 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.820000Z#000000#000#000000, 601b118d-7343-466a-9c10-4ecea8507f9e
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050745.730000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050748.840000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050748.820000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050745.730000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (CsnComparator:compare:64) comparing CSN objects '20191112050748.840000Z#000000#000#000000' with '20191112050748.820000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,963 (JdbmTable:remove:744) <--- Remove AVL 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.820000Z#000000#000#000000, 601b118d-7343-466a-9c10-4ecea8507f9e
[DEBUG] 2019-11-12 05:07:48,963 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<9082b452-d901-4c02-8e24-86d9f1b35baf, 'd1NodeServiceId=CNReplication-v1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,964 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<9082b452-d901-4c02-8e24-86d9f1b35baf, 'd1NodeServiceId=CNReplication-v1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,964 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 601b118d-7343-466a-9c10-4ecea8507f9e
[DEBUG] 2019-11-12 05:07:48,964 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 601b118d-7343-466a-9c10-4ecea8507f9e
IndexEntry[ ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:7], 0734da6c-75f8-497f-b1be-0e04a057935c ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=cilogon'>[nbC:0, nbD:0], 91d42a7e-2b33-4870-8c60-7918fac56448 ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:4], e5ee9b06-6833-4a19-847b-d716d848c4a9 ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=admin'>[nbC:0, nbD:0], 24ca1543-cf91-4994-8af9-37303df661ea ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=TestOne'>[nbC:0, nbD:0], 636dbec7-029d-4dc7-9b8e-f5d03b285efa ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:1, nbD:1], 9082b452-d901-4c02-8e24-86d9f1b35baf ]
      IndexEntry[ ParentIdAndRdn<9082b452-d901-4c02-8e24-86d9f1b35baf, 'd1NodeServiceId=CNRegister-v1'>[nbC:0, nbD:0], 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'cn=orgAuthorizationRequirementsACISubentry'>[nbC:0, nbD:0], 122892d5-0447-49ef-b000-84bd013be835 ]
-----------------------------
[DEBUG] 2019-11-12 05:07:48,964 (JdbmTable:remove:799) ---> Remove master = 601b118d-7343-466a-9c10-4ecea8507f9e
[DEBUG] 2019-11-12 05:07:48,964 (JdbmTable:remove:825) <--- Remove ONE master = 601b118d-7343-466a-9c10-4ecea8507f9e
[DEBUG] 2019-11-12 05:07:48,970 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'collectiveattributesubentry'
[DEBUG] 2019-11-12 05:07:48,970 (AdministrativePointInterceptor:delete:1251) Exit from Administrative Interceptor
[DEBUG] 2019-11-12 05:07:48,970 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'accesscontrolsubentry'
[DEBUG] 2019-11-12 05:07:48,970 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:48,970 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 89
[DEBUG] 2019-11-12 05:07:48,970 (DeleteResponseHandler:handle:40) Message sent : MessageType : DEL_RESPONSE
Message ID : 2
    Delete Response
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[ INFO] 2019-11-12 05:07:48,970 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2019-11-12 05:07:48,970 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 89
[DEBUG] 2019-11-12 05:07:48,970 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:48,970 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:48,970 (StoreMessageId:action:100) Ldap Message Id has been decoded : 3
[DEBUG] 2019-11-12 05:07:48,970 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <UNBIND_REQUEST_STATE>, tag <0x42>, action : Unbind Request initialization
[DEBUG] 2019-11-12 05:07:48,970 (AbstractGrammar:executeAction:130) Transition from state <UNBIND_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:48,970 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:48,971 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 90
[DEBUG] 2019-11-12 05:07:48,971 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:48,971 (StoreMessageId:action:100) Ldap Message Id has been decoded : 1
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <BIND_REQUEST_STATE>, tag <0x60>, action : Init BindRequest
[DEBUG] 2019-11-12 05:07:48,971 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 89
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <BIND_REQUEST_STATE> to state <VERSION_STATE>, tag <0x02>, action : Store BindRequest Version
[DEBUG] 2019-11-12 05:07:48,971 (StoreVersion:action:84) Ldap version 
[DEBUG] 2019-11-12 05:07:48,971 (LdapProtocolHandler:cleanUpSession:130) Cleaning the LdapSession : <2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org,/127.0.0.1:55138> session
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <VERSION_STATE> to state <NAME_STATE>, tag <0x04>, action : Store BindRequest Name value
[ INFO] 2019-11-12 05:07:48,971 (LdapRequestHandler:handleMessage:131) ignoring the message MessageType : UNBIND_REQUEST
Message ID : 3
    UnBind Requestorg.apache.directory.api.ldap.model.message.UnbindRequestImpl@98de3166    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'
 received from null session
[DEBUG] 2019-11-12 05:07:48,971 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 89
[DEBUG] 2019-11-12 05:07:48,971 (StoreName:action:108)  The Bind name is cn=admin,dc=dataone,dc=org
[DEBUG] 2019-11-12 05:07:48,971 (AbstractGrammar:executeAction:130) Transition from state <NAME_STATE> to state <SIMPLE_STATE>, tag <0x80>, action : Store BindRequest Simple Authentication
[DEBUG] 2019-11-12 05:07:48,972 (StoreSimpleAuth:action:94) The simple authentication is : 0x70 0x61 0x73 0x73 0x77 0x6F 0x72 0x64 
[DEBUG] 2019-11-12 05:07:48,972 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 90
[DEBUG] 2019-11-12 05:07:48,972 (BindRequestHandler:handle:620) Received: MessageType : BIND_REQUEST
Message ID : 1
    BindRequest
        Version : '3'
        Name : 'cn=admin,dc=dataone,dc=org'
        Simple authentication : '(omitted-for-safety)'

[DEBUG] 2019-11-12 05:07:48,972 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'admin'
[DEBUG] 2019-11-12 05:07:48,972 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'dataone'
[DEBUG] 2019-11-12 05:07:48,972 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:48,972 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=admin,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,972 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:48,972 (BindRequestHandler:sendBindSuccess:476) Returned SUCCESS message: MessageType : BIND_RESPONSE
Message ID : 1
    BindResponse
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'
.
[DEBUG] 2019-11-12 05:07:48,972 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:21389/dc=org'
[DEBUG] 2019-11-12 05:07:48,972 (BindResponseHandler:handle:40) Message Sent : MessageType : BIND_RESPONSE
Message ID : 1
    BindResponse
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[DEBUG] 2019-11-12 05:07:48,972 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 90
[DEBUG] 2019-11-12 05:07:48,973 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 90
[DEBUG] 2019-11-12 05:07:48,973 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:48,973 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:48,973 (StoreMessageId:action:100) Ldap Message Id has been decoded : 2
[DEBUG] 2019-11-12 05:07:48,973 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <DEL_REQUEST_STATE>, tag <0x4A>, action : Delete Request initialization
[DEBUG] 2019-11-12 05:07:48,973 (InitDelRequest:action:122) Deleting Dn d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone,dc=org
[DEBUG] 2019-11-12 05:07:48,973 (AbstractGrammar:executeAction:130) Transition from state <DEL_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:48,973 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:48,973 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:48,973 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:48,973 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:48,973 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 90
[DEBUG] 2019-11-12 05:07:48,973 (DeleteRequestHandler:handle:48) Handling request: MessageType : DEL_REQUEST
Message ID : 2
    Del request
        Entry : 'd1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone,dc=org'
org.apache.directory.api.ldap.model.message.DeleteRequestImpl@c314fc24    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'

[DEBUG] 2019-11-12 05:07:48,973 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'CNRegister-v1'
[DEBUG] 2019-11-12 05:07:48,973 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'urn:node:sqrm1'
[DEBUG] 2019-11-12 05:07:48,973 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'dataone'
[DEBUG] 2019-11-12 05:07:48,973 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:48,974 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'd1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,974 (DefaultDnFactory:create:123) Dn 2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org found in the cache
[DEBUG] 2019-11-12 05:07:48,974 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,974 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,974 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=admin,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,974 (MaxImmSubFilter:filter:81) Filtering MaxImmSub...
[DEBUG] 2019-11-12 05:07:48,974 (HighestPrecedenceFilter:filter:42) Filtering HighestPrecedence...
[DEBUG] 2019-11-12 05:07:48,974 (HighestPrecedenceFilter:filter:46) HighestPrecedence : nothing to do
[DEBUG] 2019-11-12 05:07:48,974 (AdministrativePointInterceptor:delete:1239) >>> Entering into the Administrative Interceptor, delRequest
[DEBUG] 2019-11-12 05:07:48,974 (CsnSyntaxChecker:isValidSyntax:78) Syntax valid for '20191112050748.974000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,974 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,974 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'd1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,975 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,975 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'd1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,975 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'alias'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1node' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1nodeservice' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1nodeservice' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = d1nodeservice, 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,975 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1node' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1nodeservice' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1nodeservice' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1node' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1nodeservice' with 'd1nodeservice'
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = d1nodeservice, 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:1, nbD:1]
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:1, nbD:1]
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,976 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:4]
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:4]
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:3]
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:3]
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:7]
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:7]
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,977 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:6]
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:6]
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,978 (CsnComparator:compare:64) comparing CSN objects '20191112050745.730000Z#000000#000#000000' with '20191112050748.840000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,978 (CsnComparator:compare:64) comparing CSN objects '20191112050748.840000Z#000000#000#000000' with '20191112050748.840000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:remove:686) ---> Remove 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.840000Z#000000#000#000000, 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,978 (CsnComparator:compare:64) comparing CSN objects '20191112050745.730000Z#000000#000#000000' with '20191112050748.840000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,978 (CsnComparator:compare:64) comparing CSN objects '20191112050748.840000Z#000000#000#000000' with '20191112050748.840000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,978 (CsnComparator:compare:64) comparing CSN objects '20191112050745.730000Z#000000#000#000000' with '20191112050748.840000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:remove:744) <--- Remove AVL 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.840000Z#000000#000#000000, 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<9082b452-d901-4c02-8e24-86d9f1b35baf, 'd1NodeServiceId=CNRegister-v1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<9082b452-d901-4c02-8e24-86d9f1b35baf, 'd1NodeServiceId=CNRegister-v1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,978 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
IndexEntry[ ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:6], 0734da6c-75f8-497f-b1be-0e04a057935c ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=cilogon'>[nbC:0, nbD:0], 91d42a7e-2b33-4870-8c60-7918fac56448 ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:3], e5ee9b06-6833-4a19-847b-d716d848c4a9 ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=admin'>[nbC:0, nbD:0], 24ca1543-cf91-4994-8af9-37303df661ea ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=TestOne'>[nbC:0, nbD:0], 636dbec7-029d-4dc7-9b8e-f5d03b285efa ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:0, nbD:0], 9082b452-d901-4c02-8e24-86d9f1b35baf ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'cn=orgAuthorizationRequirementsACISubentry'>[nbC:0, nbD:0], 122892d5-0447-49ef-b000-84bd013be835 ]
-----------------------------
[DEBUG] 2019-11-12 05:07:48,979 (JdbmTable:remove:799) ---> Remove master = 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,979 (JdbmTable:remove:825) <--- Remove ONE master = 0f9a366f-33fd-4a83-aea9-e2e2a0aac3df
[DEBUG] 2019-11-12 05:07:48,985 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'collectiveattributesubentry'
[DEBUG] 2019-11-12 05:07:48,985 (AdministrativePointInterceptor:delete:1251) Exit from Administrative Interceptor
[DEBUG] 2019-11-12 05:07:48,985 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'accesscontrolsubentry'
[DEBUG] 2019-11-12 05:07:48,985 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:48,985 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 90
[DEBUG] 2019-11-12 05:07:48,985 (DeleteResponseHandler:handle:40) Message sent : MessageType : DEL_RESPONSE
Message ID : 2
    Delete Response
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[DEBUG] 2019-11-12 05:07:48,985 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 90
[ INFO] 2019-11-12 05:07:48,985 (NodeLdapPopulation:deleteNode:131) deleting : cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2019-11-12 05:07:48,985 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:48,986 (StoreMessageId:action:100) Ldap Message Id has been decoded : 3
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <UNBIND_REQUEST_STATE>, tag <0x42>, action : Unbind Request initialization
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <UNBIND_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:48,986 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:48,986 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:48,986 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 91
[DEBUG] 2019-11-12 05:07:48,986 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 90
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:48,986 (LdapProtocolHandler:cleanUpSession:130) Cleaning the LdapSession : <2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org,/127.0.0.1:55140> session
[DEBUG] 2019-11-12 05:07:48,986 (StoreMessageId:action:100) Ldap Message Id has been decoded : 1
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <BIND_REQUEST_STATE>, tag <0x60>, action : Init BindRequest
[ INFO] 2019-11-12 05:07:48,986 (LdapRequestHandler:handleMessage:131) ignoring the message MessageType : UNBIND_REQUEST
Message ID : 3
    UnBind Requestorg.apache.directory.api.ldap.model.message.UnbindRequestImpl@98de3166    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'
 received from null session
[DEBUG] 2019-11-12 05:07:48,986 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 90
[DEBUG] 2019-11-12 05:07:48,986 (AbstractGrammar:executeAction:130) Transition from state <BIND_REQUEST_STATE> to state <VERSION_STATE>, tag <0x02>, action : Store BindRequest Version
[DEBUG] 2019-11-12 05:07:48,987 (StoreVersion:action:84) Ldap version 
[DEBUG] 2019-11-12 05:07:48,987 (AbstractGrammar:executeAction:130) Transition from state <VERSION_STATE> to state <NAME_STATE>, tag <0x04>, action : Store BindRequest Name value
[DEBUG] 2019-11-12 05:07:48,987 (StoreName:action:108)  The Bind name is cn=admin,dc=dataone,dc=org
[DEBUG] 2019-11-12 05:07:48,987 (AbstractGrammar:executeAction:130) Transition from state <NAME_STATE> to state <SIMPLE_STATE>, tag <0x80>, action : Store BindRequest Simple Authentication
[DEBUG] 2019-11-12 05:07:48,987 (StoreSimpleAuth:action:94) The simple authentication is : 0x70 0x61 0x73 0x73 0x77 0x6F 0x72 0x64 
[DEBUG] 2019-11-12 05:07:48,987 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 91
[DEBUG] 2019-11-12 05:07:48,987 (BindRequestHandler:handle:620) Received: MessageType : BIND_REQUEST
Message ID : 1
    BindRequest
        Version : '3'
        Name : 'cn=admin,dc=dataone,dc=org'
        Simple authentication : '(omitted-for-safety)'

[DEBUG] 2019-11-12 05:07:48,987 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'admin'
[DEBUG] 2019-11-12 05:07:48,987 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'dataone'
[DEBUG] 2019-11-12 05:07:48,987 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:48,987 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=admin,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,987 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:48,988 (BindRequestHandler:sendBindSuccess:476) Returned SUCCESS message: MessageType : BIND_RESPONSE
Message ID : 1
    BindResponse
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'
.
[DEBUG] 2019-11-12 05:07:48,988 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 91
[DEBUG] 2019-11-12 05:07:48,988 (BindResponseHandler:handle:40) Message Sent : MessageType : BIND_RESPONSE
Message ID : 1
    BindResponse
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[DEBUG] 2019-11-12 05:07:48,988 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:21389/dc=org'
[DEBUG] 2019-11-12 05:07:48,988 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 91
[DEBUG] 2019-11-12 05:07:48,988 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:48,988 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:48,988 (StoreMessageId:action:100) Ldap Message Id has been decoded : 2
[DEBUG] 2019-11-12 05:07:48,988 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <DEL_REQUEST_STATE>, tag <0x4A>, action : Delete Request initialization
[DEBUG] 2019-11-12 05:07:48,988 (InitDelRequest:action:122) Deleting Dn cn=urn:node:sqrm1,dc=dataone,dc=org
[DEBUG] 2019-11-12 05:07:48,988 (AbstractGrammar:executeAction:130) Transition from state <DEL_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:48,988 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:48,988 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:48,988 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:48,988 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:48,989 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 91
[DEBUG] 2019-11-12 05:07:48,989 (DeleteRequestHandler:handle:48) Handling request: MessageType : DEL_REQUEST
Message ID : 2
    Del request
        Entry : 'cn=urn:node:sqrm1,dc=dataone,dc=org'
org.apache.directory.api.ldap.model.message.DeleteRequestImpl@c844002f    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'

[DEBUG] 2019-11-12 05:07:48,989 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'urn:node:sqrm1'
[DEBUG] 2019-11-12 05:07:48,989 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'dataone'
[DEBUG] 2019-11-12 05:07:48,989 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:48,989 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=urn:node:sqrm1,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,989 (DefaultDnFactory:create:123) Dn 2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org found in the cache
[DEBUG] 2019-11-12 05:07:48,989 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,989 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,989 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=admin,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,989 (MaxImmSubFilter:filter:81) Filtering MaxImmSub...
[DEBUG] 2019-11-12 05:07:48,990 (HighestPrecedenceFilter:filter:42) Filtering HighestPrecedence...
[DEBUG] 2019-11-12 05:07:48,990 (HighestPrecedenceFilter:filter:46) HighestPrecedence : nothing to do
[DEBUG] 2019-11-12 05:07:48,990 (AdministrativePointInterceptor:delete:1239) >>> Entering into the Administrative Interceptor, delRequest
[DEBUG] 2019-11-12 05:07:48,990 (CsnSyntaxChecker:isValidSyntax:78) Syntax valid for '20191112050748.990000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,990 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,990 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=urn:node:sqrm1,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,990 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:48,990 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=urn:node:sqrm1,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:48,990 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'alias'
[DEBUG] 2019-11-12 05:07:48,990 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,990 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,990 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1node' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,990 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = d1node, 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1node' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1node'
[DEBUG] 2019-11-12 05:07:48,991 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = d1node, 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'device' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = device, 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'device'
[DEBUG] 2019-11-12 05:07:48,991 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'device' with 'device'
[DEBUG] 2019-11-12 05:07:48,992 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'device'
[DEBUG] 2019-11-12 05:07:48,992 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'device'
[DEBUG] 2019-11-12 05:07:48,992 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'device'
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = device, 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:3]
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:3, nbD:3]
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:2, nbD:2]
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:2, nbD:2]
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:6]
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:6]
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,992 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:5]
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:5]
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:48,993 (CsnComparator:compare:64) comparing CSN objects '20191112050745.705000Z#000000#000#000000' with '20191112050748.702000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,993 (CsnComparator:compare:64) comparing CSN objects '20191112050748.702000Z#000000#000#000000' with '20191112050748.702000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:remove:686) ---> Remove 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.702000Z#000000#000#000000, 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,993 (CsnComparator:compare:64) comparing CSN objects '20191112050745.705000Z#000000#000#000000' with '20191112050748.702000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,993 (CsnComparator:compare:64) comparing CSN objects '20191112050748.702000Z#000000#000#000000' with '20191112050748.702000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,993 (CsnComparator:compare:64) comparing CSN objects '20191112050745.705000Z#000000#000#000000' with '20191112050748.702000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:remove:744) <--- Remove AVL 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.702000Z#000000#000#000000, 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=urn:node:sqrm1'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,993 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 9082b452-d901-4c02-8e24-86d9f1b35baf
IndexEntry[ ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:5], 0734da6c-75f8-497f-b1be-0e04a057935c ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=cilogon'>[nbC:0, nbD:0], 91d42a7e-2b33-4870-8c60-7918fac56448 ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:2, nbD:2], e5ee9b06-6833-4a19-847b-d716d848c4a9 ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=admin'>[nbC:0, nbD:0], 24ca1543-cf91-4994-8af9-37303df661ea ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=TestOne'>[nbC:0, nbD:0], 636dbec7-029d-4dc7-9b8e-f5d03b285efa ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'cn=orgAuthorizationRequirementsACISubentry'>[nbC:0, nbD:0], 122892d5-0447-49ef-b000-84bd013be835 ]
-----------------------------
[DEBUG] 2019-11-12 05:07:48,994 (JdbmTable:remove:799) ---> Remove master = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,994 (JdbmTable:remove:825) <--- Remove ONE master = 9082b452-d901-4c02-8e24-86d9f1b35baf
[DEBUG] 2019-11-12 05:07:48,999 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'collectiveattributesubentry'
[DEBUG] 2019-11-12 05:07:48,999 (AdministrativePointInterceptor:delete:1251) Exit from Administrative Interceptor
[DEBUG] 2019-11-12 05:07:48,999 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'accesscontrolsubentry'
[DEBUG] 2019-11-12 05:07:49,000 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:49,000 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 91
[DEBUG] 2019-11-12 05:07:49,000 (DeleteResponseHandler:handle:40) Message sent : MessageType : DEL_RESPONSE
Message ID : 2
    Delete Response
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[DEBUG] 2019-11-12 05:07:49,000 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 91
[DEBUG] 2019-11-12 05:07:49,000 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:49,000 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:49,000 (StoreMessageId:action:100) Ldap Message Id has been decoded : 3
[DEBUG] 2019-11-12 05:07:49,000 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <UNBIND_REQUEST_STATE>, tag <0x42>, action : Unbind Request initialization
[DEBUG] 2019-11-12 05:07:49,000 (AbstractGrammar:executeAction:130) Transition from state <UNBIND_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:49,000 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:49,000 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:49,000 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:49,000 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:49,000 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 92
[DEBUG] 2019-11-12 05:07:49,000 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 91
[DEBUG] 2019-11-12 05:07:49,001 (LdapProtocolHandler:cleanUpSession:130) Cleaning the LdapSession : <2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org,/127.0.0.1:55142> session
[DEBUG] 2019-11-12 05:07:49,001 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:49,001 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[ INFO] 2019-11-12 05:07:49,001 (LdapRequestHandler:handleMessage:131) ignoring the message MessageType : UNBIND_REQUEST
Message ID : 3
    UnBind Requestorg.apache.directory.api.ldap.model.message.UnbindRequestImpl@98de3166    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'
 received from null session
[DEBUG] 2019-11-12 05:07:49,001 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 91
[DEBUG] 2019-11-12 05:07:49,001 (StoreMessageId:action:100) Ldap Message Id has been decoded : 1
[DEBUG] 2019-11-12 05:07:49,001 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <BIND_REQUEST_STATE>, tag <0x60>, action : Init BindRequest
[DEBUG] 2019-11-12 05:07:49,001 (AbstractGrammar:executeAction:130) Transition from state <BIND_REQUEST_STATE> to state <VERSION_STATE>, tag <0x02>, action : Store BindRequest Version
[DEBUG] 2019-11-12 05:07:49,001 (StoreVersion:action:84) Ldap version 
[DEBUG] 2019-11-12 05:07:49,001 (AbstractGrammar:executeAction:130) Transition from state <VERSION_STATE> to state <NAME_STATE>, tag <0x04>, action : Store BindRequest Name value
[DEBUG] 2019-11-12 05:07:49,001 (StoreName:action:108)  The Bind name is cn=admin,dc=dataone,dc=org
[DEBUG] 2019-11-12 05:07:49,001 (AbstractGrammar:executeAction:130) Transition from state <NAME_STATE> to state <SIMPLE_STATE>, tag <0x80>, action : Store BindRequest Simple Authentication
[DEBUG] 2019-11-12 05:07:49,001 (StoreSimpleAuth:action:94) The simple authentication is : 0x70 0x61 0x73 0x73 0x77 0x6F 0x72 0x64 
[DEBUG] 2019-11-12 05:07:49,001 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 92
[DEBUG] 2019-11-12 05:07:49,001 (BindRequestHandler:handle:620) Received: MessageType : BIND_REQUEST
Message ID : 1
    BindRequest
        Version : '3'
        Name : 'cn=admin,dc=dataone,dc=org'
        Simple authentication : '(omitted-for-safety)'

[DEBUG] 2019-11-12 05:07:49,001 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'admin'
[DEBUG] 2019-11-12 05:07:49,001 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'dataone'
[DEBUG] 2019-11-12 05:07:49,002 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:49,002 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=admin,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:49,002 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:49,002 (BindRequestHandler:sendBindSuccess:476) Returned SUCCESS message: MessageType : BIND_RESPONSE
Message ID : 1
    BindResponse
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'
.
[DEBUG] 2019-11-12 05:07:49,002 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 92
[DEBUG] 2019-11-12 05:07:49,002 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:21389/dc=org'
[DEBUG] 2019-11-12 05:07:49,002 (BindResponseHandler:handle:40) Message Sent : MessageType : BIND_RESPONSE
Message ID : 1
    BindResponse
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[DEBUG] 2019-11-12 05:07:49,002 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 92
[DEBUG] 2019-11-12 05:07:49,002 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:49,002 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:49,002 (StoreMessageId:action:100) Ldap Message Id has been decoded : 2
[DEBUG] 2019-11-12 05:07:49,002 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <DEL_REQUEST_STATE>, tag <0x4A>, action : Delete Request initialization
[DEBUG] 2019-11-12 05:07:49,002 (InitDelRequest:action:122) Deleting Dn cn=TestOne,dc=dataone,dc=org
[DEBUG] 2019-11-12 05:07:49,002 (AbstractGrammar:executeAction:130) Transition from state <DEL_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:49,002 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:49,002 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:49,003 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:49,003 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:49,003 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 92
[DEBUG] 2019-11-12 05:07:49,003 (DeleteRequestHandler:handle:48) Handling request: MessageType : DEL_REQUEST
Message ID : 2
    Del request
        Entry : 'cn=TestOne,dc=dataone,dc=org'
org.apache.directory.api.ldap.model.message.DeleteRequestImpl@39c2dd2a    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'

[DEBUG] 2019-11-12 05:07:49,003 (DirectoryStringSyntaxChecker:isValidSyntax:100) Syntax valid for 'testone'
[DEBUG] 2019-11-12 05:07:49,003 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'dataone'
[DEBUG] 2019-11-12 05:07:49,003 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:49,003 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=TestOne,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:49,003 (DefaultDnFactory:create:123) Dn 2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org found in the cache
[DEBUG] 2019-11-12 05:07:49,003 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:49,003 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:49,003 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=admin,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:49,003 (MaxImmSubFilter:filter:81) Filtering MaxImmSub...
[DEBUG] 2019-11-12 05:07:49,004 (HighestPrecedenceFilter:filter:42) Filtering HighestPrecedence...
[DEBUG] 2019-11-12 05:07:49,004 (HighestPrecedenceFilter:filter:46) HighestPrecedence : nothing to do
[DEBUG] 2019-11-12 05:07:49,004 (AdministrativePointInterceptor:delete:1239) >>> Entering into the Administrative Interceptor, delRequest
[DEBUG] 2019-11-12 05:07:49,004 (CsnSyntaxChecker:isValidSyntax:78) Syntax valid for '20191112050749.004000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,004 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:49,004 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=TestOne,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:49,004 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'subentry'
[DEBUG] 2019-11-12 05:07:49,004 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'cn=TestOne,dc=dataone,dc=org'
[DEBUG] 2019-11-12 05:07:49,004 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'alias'
[DEBUG] 2019-11-12 05:07:49,004 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,004 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,004 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,004 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = d1principal, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'd1principal' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'd1principal'
[DEBUG] 2019-11-12 05:07:49,005 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = d1principal, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organizationalperson' with 'person'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'subentry' with 'person'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'person' with 'person'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'person' with 'person'
[DEBUG] 2019-11-12 05:07:49,005 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = person, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organizationalperson' with 'person'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'subentry' with 'person'
[DEBUG] 2019-11-12 05:07:49,005 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'person' with 'person'
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'person' with 'person'
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organizationalperson' with 'person'
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'subentry' with 'person'
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'person' with 'person'
[DEBUG] 2019-11-12 05:07:49,006 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = person, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organizationalperson' with 'organizationalperson'
[DEBUG] 2019-11-12 05:07:49,006 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = organizationalperson, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organizationalperson' with 'organizationalperson'
[DEBUG] 2019-11-12 05:07:49,006 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = organizationalperson, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,006 (JdbmTable:remove:686) ---> Remove 2.5.4.0_forward = inetorgperson, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,006 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,007 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,007 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'inetorgperson' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,007 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'organization' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,007 (ObjectIdentifierComparator:compare:57) comparing ObjectIdentifier objects 'dcobject' with 'inetorgperson'
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:remove:744) <--- Remove AVL 2.5.4.0_forward = inetorgperson, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:2, nbD:2]
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:2, nbD:2]
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:1, nbD:1]
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:1, nbD:1]
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = e5ee9b06-6833-4a19-847b-d716d848c4a9
[DEBUG] 2019-11-12 05:07:49,007 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:5]
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:5]
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:4]
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:4]
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:put:584) ---> Add 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:put:605) <--- Add ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:49,008 (CsnComparator:compare:64) comparing CSN objects '20191112050745.705000Z#000000#000#000000' with '20191112050748.861000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,008 (CsnComparator:compare:64) comparing CSN objects '20191112050748.861000Z#000000#000#000000' with '20191112050748.861000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:remove:686) ---> Remove 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.861000Z#000000#000#000000, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,008 (CsnComparator:compare:64) comparing CSN objects '20191112050745.705000Z#000000#000#000000' with '20191112050748.861000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,008 (CsnComparator:compare:64) comparing CSN objects '20191112050748.861000Z#000000#000#000000' with '20191112050748.861000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,008 (CsnComparator:compare:64) comparing CSN objects '20191112050745.705000Z#000000#000#000000' with '20191112050748.861000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,008 (JdbmTable:remove:744) <--- Remove AVL 1.3.6.1.4.1.4203.666.1.7_forward = 20191112050748.861000Z#000000#000#000000, 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,009 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=TestOne'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:49,009 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_forward = ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=TestOne'>[nbC:0, nbD:0]
[DEBUG] 2019-11-12 05:07:49,009 (JdbmTable:remove:799) ---> Remove 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,009 (JdbmTable:remove:825) <--- Remove ONE 1.3.6.1.4.1.18060.0.4.1.2.50_reverse = 636dbec7-029d-4dc7-9b8e-f5d03b285efa
IndexEntry[ ParentIdAndRdn<00000000-0000-0000-0000-000000000000, 'dc=org'>[nbC:3, nbD:4], 0734da6c-75f8-497f-b1be-0e04a057935c ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=cilogon'>[nbC:0, nbD:0], 91d42a7e-2b33-4870-8c60-7918fac56448 ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'dc=dataone'>[nbC:1, nbD:1], e5ee9b06-6833-4a19-847b-d716d848c4a9 ]
    IndexEntry[ ParentIdAndRdn<e5ee9b06-6833-4a19-847b-d716d848c4a9, 'cn=admin'>[nbC:0, nbD:0], 24ca1543-cf91-4994-8af9-37303df661ea ]
  IndexEntry[ ParentIdAndRdn<0734da6c-75f8-497f-b1be-0e04a057935c, 'cn=orgAuthorizationRequirementsACISubentry'>[nbC:0, nbD:0], 122892d5-0447-49ef-b000-84bd013be835 ]
-----------------------------
[DEBUG] 2019-11-12 05:07:49,009 (JdbmTable:remove:799) ---> Remove master = 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,009 (JdbmTable:remove:825) <--- Remove ONE master = 636dbec7-029d-4dc7-9b8e-f5d03b285efa
[DEBUG] 2019-11-12 05:07:49,015 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'collectiveattributesubentry'
[DEBUG] 2019-11-12 05:07:49,015 (AdministrativePointInterceptor:delete:1251) Exit from Administrative Interceptor
[DEBUG] 2019-11-12 05:07:49,015 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'accesscontrolsubentry'
[DEBUG] 2019-11-12 05:07:49,015 (OidSyntaxChecker:isValidSyntax:132) Syntax valid for 'referral'
[DEBUG] 2019-11-12 05:07:49,015 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 92
[DEBUG] 2019-11-12 05:07:49,016 (DeleteResponseHandler:handle:40) Message sent : MessageType : DEL_RESPONSE
Message ID : 2
    Delete Response
        Ldap Result
            Result code : (SUCCESS) success
            Matched Dn : 'null'
            Diagnostic message : 'null'

[DEBUG] 2019-11-12 05:07:49,016 (ProtocolCodecFilter:messageReceived:210) Processing a MESSAGE_RECEIVED for session 92
[DEBUG] 2019-11-12 05:07:49,016 (DirtiesContextTestExecutionListener:afterTestMethod:86) After test method: context [[TestContext@6d229b1c testClass = LogServiceSessionAuthorizationFilterTestUnit, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestUnit@22dc59b2, testMethod = testInit@LogServiceSessionAuthorizationFilterTestUnit, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@2b6a0ea9 testClass = LogServiceSessionAuthorizationFilterTestUnit, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]], class dirties context [false], class mode [null], method dirties context [false].
[DEBUG] 2019-11-12 05:07:49,016 (AbstractGrammar:executeAction:130) Transition from state <START_STATE> to state <LDAP_MESSAGE_STATE>, tag <0x30>, action : LdapMessage initialization
[DEBUG] 2019-11-12 05:07:49,016 (AbstractGrammar:executeAction:130) Transition from state <LDAP_MESSAGE_STATE> to state <MESSAGE_ID_STATE>, tag <0x02>, action : Store MessageID
[DEBUG] 2019-11-12 05:07:49,016 (StoreMessageId:action:100) Ldap Message Id has been decoded : 3
[DEBUG] 2019-11-12 05:07:49,016 (AbstractGrammar:executeAction:130) Transition from state <MESSAGE_ID_STATE> to state <UNBIND_REQUEST_STATE>, tag <0x42>, action : Unbind Request initialization
[DEBUG] 2019-11-12 05:07:49,016 (DirtiesContextTestExecutionListener:afterTestClass:113) After test class: context [[TestContext@6d229b1c testClass = LogServiceSessionAuthorizationFilterTestUnit, testInstance = [null], testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@2b6a0ea9 testClass = LogServiceSessionAuthorizationFilterTestUnit, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]], dirtiesContext [false].
[DEBUG] 2019-11-12 05:07:49,016 (AbstractGrammar:executeAction:130) Transition from state <UNBIND_REQUEST_STATE> to state <CONTROLS_STATE>, tag <0xA0>, action : Initialize a control
[DEBUG] 2019-11-12 05:07:49,016 (InitControls:action:78) A new list of controls has been initialized
[DEBUG] 2019-11-12 05:07:49,016 (AbstractGrammar:executeAction:130) Transition from state <CONTROLS_STATE> to state <CONTROL_STATE>, tag <0x30>, action : Check that the length is not null
[DEBUG] 2019-11-12 05:07:49,016 (AbstractGrammar:executeAction:130) Transition from state <CONTROL_STATE> to state <CONTROL_TYPE_STATE>, tag <0x04>, action : Add a new control
[DEBUG] 2019-11-12 05:07:49,016 (AddControl:action:106) Control OID : 2.16.840.1.113730.3.4.2
[DEBUG] 2019-11-12 05:07:49,017 (LdapProtocolHandler:cleanUpSession:130) Cleaning the LdapSession : <2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org,/127.0.0.1:54970> session
[DEBUG] 2019-11-12 05:07:49,017 (IoFilterEvent:fire:68) Firing a MESSAGE_RECEIVED event for session 92
[DEBUG] 2019-11-12 05:07:49,017 (LdapProtocolHandler:cleanUpSession:130) Cleaning the LdapSession : <2.5.4.3=admin,0.9.2342.19200300.100.1.25=dataone,0.9.2342.19200300.100.1.25=org,/127.0.0.1:55010> session
[ WARN] 2019-11-12 05:07:49,018 (DirContextUnsolicitedNotificationListener:namingExceptionThrown:37) javax.naming.CommunicationException: localhost:21389 connection closed
[DEBUG] 2019-11-12 05:07:49,019 (UnbindRequestHandler:handle:45) Received: MessageType : UNBIND_REQUEST
Message ID : 3
    UnBind Requestorg.apache.directory.api.ldap.model.message.UnbindRequestImpl@98de3166    ManageDsaITImpl Control
        Type OID    : '2.16.840.1.113730.3.4.2'
        Criticality : 'false'
'

[DEBUG] 2019-11-12 05:07:49,019 (IoFilterEvent:fire:117) Event MESSAGE_RECEIVED has been fired for session 92
[DEBUG] 2019-11-12 05:07:49,019 (LdapProtocolHandler:cleanUpSession:126) Null LdapSession given to cleanUpSession.
[ WARN] 2019-11-12 05:07:49,020 (DirContextUnsolicitedNotificationListener:namingExceptionThrown:37) javax.naming.CommunicationException: localhost:21389 connection closed
[ INFO] 2019-11-12 05:07:49,020 (LdapServer:stop:611) Unbind of an LDAP service (21389) is complete.
[ INFO] 2019-11-12 05:07:49,021 (LdapServer:stop:612) Sending notice of disconnect to existing clients sessions.
[ INFO] 2019-11-12 05:07:49,022 (LdapServer:stop:647) Ldap service stopped.
[DEBUG] 2019-11-12 05:07:49,022 (ApacheDSSuiteRunner:run:221) Shuting down DS for org
[DEBUG] 2019-11-12 05:07:49,022 (DefaultDirectoryService:shutdown:1276) +++ DirectoryService Shutdown required
[DEBUG] 2019-11-12 05:07:49,022 (DefaultDirectoryService:shutdown:1286) --- Syncing the nexus 
[DEBUG] 2019-11-12 05:07:49,022 (DefaultDirectoryService:shutdown:1287) --- Flushing everything before quitting
[DEBUG] 2019-11-12 05:07:49,022 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'ou=schema'
[DEBUG] 2019-11-12 05:07:49,023 (CsnSyntaxChecker:isValidSyntax:78) Syntax valid for '20191112050745.658000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,023 (AbstractBTreePartition:saveContextCsn:3405) Saved context CSN 20191112050745.658000Z#000000#000#000000 for the partition ou=schema
[DEBUG] 2019-11-12 05:07:49,023 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'dc=org'
[DEBUG] 2019-11-12 05:07:49,023 (CsnSyntaxChecker:isValidSyntax:78) Syntax valid for '20191112050748.861000Z#000000#000#000000'
[DEBUG] 2019-11-12 05:07:49,023 (JdbmTable:put:584) ---> Add master = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:49,023 (JdbmTable:put:605) <--- Add ONE master = 0734da6c-75f8-497f-b1be-0e04a057935c
[DEBUG] 2019-11-12 05:07:49,023 (AbstractBTreePartition:saveContextCsn:3405) Saved context CSN 20191112050748.861000Z#000000#000#000000 for the partition dc=org
[DEBUG] 2019-11-12 05:07:49,029 (DefaultDirectoryService:shutdown:1295) --- Syncing the changeLog 
[DEBUG] 2019-11-12 05:07:49,206 (DefaultDirectoryService:shutdown:1313) --- Destroying the nexus
[DEBUG] 2019-11-12 05:07:49,206 (DefaultDnFactory:create:123) Dn 2.5.4.11=schema found in the cache
[DEBUG] 2019-11-12 05:07:49,206 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'ou=schema'
[DEBUG] 2019-11-12 05:07:49,207 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'ou=schema'
[DEBUG] 2019-11-12 05:07:49,207 (AbstractBTreePartition:doDestroy:491) destroy() called on store for ou=schema
[DEBUG] 2019-11-12 05:07:49,231 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.5 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,231 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.4203.666.1.7 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,231 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.6 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,231 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.7 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,231 (AbstractBTreePartition:doDestroy:524) Closed 2.5.4.0 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,231 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.3 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,232 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.50 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,232 (AbstractBTreePartition:doDestroy:524) Closed 2.5.18.5 system index for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,232 (AbstractBTreePartition:doDestroy:536) ERR_125 Closed master table for ou=schema partition.
[DEBUG] 2019-11-12 05:07:49,232 (DefaultDnFactory:create:101) Dn 0.9.2342.19200300.100.1.25=org not found in the cache, creating
[DEBUG] 2019-11-12 05:07:49,232 (Ia5StringSyntaxChecker:isValidSyntax:84) Syntax valid for 'org'
[DEBUG] 2019-11-12 05:07:49,232 (DefaultDnFactory:create:123) Dn 0.9.2342.19200300.100.1.25=org found in the cache
[DEBUG] 2019-11-12 05:07:49,232 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'dc=org'
[DEBUG] 2019-11-12 05:07:49,232 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'dc=org'
[DEBUG] 2019-11-12 05:07:49,232 (AbstractBTreePartition:doDestroy:491) destroy() called on store for dc=org
[DEBUG] 2019-11-12 05:07:49,235 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.5 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,236 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.4203.666.1.7 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,237 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.6 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,239 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.7 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,240 (AbstractBTreePartition:doDestroy:524) Closed 2.5.4.0 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,241 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.3 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,243 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.50 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,244 (AbstractBTreePartition:doDestroy:524) Closed 2.5.18.5 system index for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,245 (AbstractBTreePartition:doDestroy:536) ERR_125 Closed master table for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,246 (JdbmPartition:doDestroy:509) Closed record manager for dc=org partition.
[DEBUG] 2019-11-12 05:07:49,246 (DefaultDnFactory:create:123) Dn 2.5.4.11=system found in the cache
[DEBUG] 2019-11-12 05:07:49,246 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'ou=system'
[DEBUG] 2019-11-12 05:07:49,246 (DnSyntaxChecker:isValidSyntax:93) Syntax valid for 'ou=system'
[DEBUG] 2019-11-12 05:07:49,246 (AbstractBTreePartition:doDestroy:491) destroy() called on store for ou=system
[DEBUG] 2019-11-12 05:07:49,248 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.5 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,249 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.4203.666.1.7 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,250 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.6 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,252 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.7 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,254 (AbstractBTreePartition:doDestroy:524) Closed objectClass system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,255 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.3 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,256 (AbstractBTreePartition:doDestroy:524) Closed 1.3.6.1.4.1.18060.0.4.1.2.50 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,258 (AbstractBTreePartition:doDestroy:524) Closed 2.5.18.5 system index for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,258 (AbstractBTreePartition:doDestroy:536) ERR_125 Closed master table for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,259 (JdbmPartition:doDestroy:509) Closed record manager for ou=system partition.
[DEBUG] 2019-11-12 05:07:49,259 (DefaultDirectoryService:shutdown:1319) --- Deleting the cache service
[ INFO] 2019-11-12 05:07:49,259 (CacheService:destroy:180) clearing all the caches
[DEBUG] 2019-11-12 05:07:49,259 (CacheManager:clearAll:1608) Clearing all caches
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,260 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,261 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,262 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,263 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,264 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,265 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,266 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,267 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,268 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,269 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,270 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,271 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,272 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,273 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,274 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,275 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,276 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,277 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,278 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:709) cleared heap usage
[DEBUG] 2019-11-12 05:07:49,279 (Segment:clear:711) cleared disk usage
[DEBUG] 2019-11-12 05:07:49,283 (DefaultDirectoryService:shutdown:1322) ---Deleting the DnCache
[DEBUG] 2019-11-12 05:07:49,283 (DefaultDirectoryService:shutdown:1338) +++ DirectoryService stopped
Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 6.352 sec
[ INFO] 2019-11-12 05:07:49,351 (AbstractApplicationContext:doClose:1032) Closing org.springframework.web.context.support.GenericWebApplicationContext@10f7918f: startup date [Tue Nov 12 05:07:46 UTC 2019]; root of context hierarchy
[DEBUG] 2019-11-12 05:07:49,352 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'lifecycleProcessor'
[ INFO] 2019-11-12 05:07:49,352 (DefaultSingletonBeanRegistry:destroySingletons:434) Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7c51782d: defining beans [test,mylog,log4jInitialization,contextSourceConfiguration,contextSource,ldapTemplate,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.annotation.internalPersistenceAnnotationProcessor,subjectLdapPopulation,nodeLdapPopulation,x509CertificateGenerator,org.springframework.context.annotation.ConfigurationClassPostProcessor.importAwareProcessor]; root of factory hierarchy
[DEBUG] 2019-11-12 05:07:49,352 (DefaultSingletonBeanRegistry:destroyBean:490) Retrieved dependent beans for bean 'x509CertificateGenerator': [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestUnit]

Results :

Tests run: 5, Failures: 0, Errors: 0, Skipped: 0

[JENKINS] Recording test results
[INFO] 
[INFO] --- maven-resources-plugin:2.5:copy-resources (copy-resources) @ d1_solr_extensions ---
[debug] execute contextualize
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 7 resources
[INFO] 
[INFO] --- maven-jar-plugin:2.4:jar (default-jar) @ d1_solr_extensions ---
[INFO] Building jar: /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/d1_solr_extensions-2.4.0-SNAPSHOT.jar
[INFO] 
[INFO] --- maven-shade-plugin:3.0.0:shade (default) @ d1_solr_extensions ---
[INFO] Including aopalliance:aopalliance:jar:1.0 in the shaded jar.
[INFO] Including org.springframework:spring-beans:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including commons-logging:commons-logging:jar:1.1.1 in the shaded jar.
[INFO] Including commons-lang:commons-lang:jar:2.5 in the shaded jar.
[INFO] Including org.springframework:spring-tx:jar:3.0.5.RELEASE in the shaded jar.
[INFO] Including org.bouncycastle:bcmail-jdk15on:jar:1.52 in the shaded jar.
[INFO] Including org.bouncycastle:bcprov-jdk15on:jar:1.52 in the shaded jar.
[INFO] Including org.bouncycastle:bcpkix-jdk15on:jar:1.52 in the shaded jar.
[INFO] Including org.apache.commons:commons-lang3:jar:3.1 in the shaded jar.
[INFO] Including commons-cli:commons-cli:jar:1.2 in the shaded jar.
[INFO] Excluding commons-codec:commons-codec:jar:1.10 from the shaded jar.
[INFO] Including commons-collections:commons-collections:jar:3.2.1 in the shaded jar.
[INFO] Excluding commons-fileupload:commons-fileupload:jar:1.2.1 from the shaded jar.
[INFO] Excluding commons-io:commons-io:jar:2.4 from the shaded jar.
[INFO] Including dom4j:dom4j:jar:1.6.1 in the shaded jar.
[INFO] Including joda-time:joda-time:jar:2.2 in the shaded jar.
[INFO] Including log4j:log4j:jar:1.2.17 in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpcore:jar:4.4.1 in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpmime:jar:4.4.1 in the shaded jar.
[INFO] Including org.ow2.asm:asm:jar:4.1 in the shaded jar.
[INFO] Including javax.mail:mail:jar:1.4.1 in the shaded jar.
[INFO] Including javax.activation:activation:jar:1.1 in the shaded jar.
[INFO] Including javax.xml.bind:jaxb-api:jar:2.2.3 in the shaded jar.
[INFO] Including javax.xml.stream:stax-api:jar:1.0-2 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-container-default:jar:1.0-alpha-9-stable-1 in the shaded jar.
[INFO] Including classworlds:classworlds:jar:1.1-alpha-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-api:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-artifact:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-settings:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-profile:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven.wagon:wagon-provider-api:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-repository-metadata:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-artifact-manager:jar:2.0.6 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-utils:jar:2.0.5 in the shaded jar.
[INFO] Including org.apache.maven.plugins:maven-jar-plugin:maven-plugin:2.3.1 in the shaded jar.
[INFO] Including org.apache.maven:maven-project:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-registry:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-model:jar:2.0.6 in the shaded jar.
[INFO] Including org.apache.maven:maven-archiver:jar:2.4.1 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-interpolation:jar:1.13 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-archiver:jar:1.0 in the shaded jar.
[INFO] Including org.codehaus.plexus:plexus-io:jar:1.0 in the shaded jar.
[INFO] Including org.apache.maven.plugins:maven-clean-plugin:maven-plugin:2.4.1 in the shaded jar.
[INFO] Including org.apache.commons:commons-collections4:jar:4.0 in the shaded jar.
[INFO] Including org.dataone:d1_libclient_java:jar:2.4.0-SNAPSHOT in the shaded jar.
[INFO] Including net.sf.jsignature.io-tools:easystream:jar:1.2.12 in the shaded jar.
[INFO] Including org.jibx:jibx-run:jar:1.2.4.5 in the shaded jar.
[INFO] Including xpp3:xpp3:jar:1.1.3.4.O in the shaded jar.
[INFO] Including org.dataone:d1_common_java:jar:2.4.0-SNAPSHOT in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpclient-cache:jar:4.3.6 in the shaded jar.
[INFO] Including com.googlecode.foresite-toolkit:foresite:jar:1.0-SNAPSHOT in the shaded jar.
[INFO] Including com.hp.hpl.jena:jena:jar:2.5.5 in the shaded jar.
[INFO] Including com.hp.hpl.jena:arq:jar:2.2 in the shaded jar.
[INFO] Including com.hp.hpl.jena:arq-extra:jar:2.2 in the shaded jar.
[INFO] Including com.hp.hpl.jena:jenatest:jar:2.5.5 in the shaded jar.
[INFO] Including com.hp.hpl.jena:iri:jar:0.5 in the shaded jar.
[INFO] Including antlr:antlr:jar:2.7.5 in the shaded jar.
[INFO] Including com.hp.hpl.jena:concurrent-jena:jar:1.3.2 in the shaded jar.
[INFO] Including com.ibm.icu:icu4j:jar:3.4.4 in the shaded jar.
[INFO] Including com.hp.hpl.jena:json-jena:jar:1.0 in the shaded jar.
[INFO] Including stax:stax-api:jar:1.0 in the shaded jar.
[INFO] Including org.codehaus.woodstox:wstx-asl:jar:3.0.0 in the shaded jar.
[INFO] Including xerces:xmlParserAPIs:jar:2.0.2 in the shaded jar.
[INFO] Including rome:rome:jar:0.9 in the shaded jar.
[INFO] Including jdom:jdom:jar:1.0 in the shaded jar.
[INFO] Including xalan:xalan:jar:2.7.0 in the shaded jar.
[INFO] Including org.dataone:d1_cn_common:jar:2.4.0-SNAPSHOT in the shaded jar.
[INFO] Including com.hazelcast:hazelcast:jar:2.4.1 in the shaded jar.
[INFO] Including com.hazelcast:hazelcast-client:jar:2.4.1 in the shaded jar.
[INFO] Including org.springframework.data:spring-data-jpa:jar:1.4.5.RELEASE in the shaded jar.
[INFO] Including org.aspectj:aspectjrt:jar:1.7.2 in the shaded jar.
[INFO] Including org.slf4j:jcl-over-slf4j:jar:1.7.1 in the shaded jar.
[INFO] Including org.springframework.data:spring-data-commons:jar:1.6.5.RELEASE in the shaded jar.
[INFO] Including org.hibernate:hibernate-entitymanager:jar:3.6.10.Final in the shaded jar.
[INFO] Including org.hibernate:hibernate-core:jar:3.6.10.Final in the shaded jar.
[INFO] Including org.hibernate:hibernate-commons-annotations:jar:3.2.0.Final in the shaded jar.
[INFO] Including javax.transaction:jta:jar:1.1 in the shaded jar.
[INFO] Including javassist:javassist:jar:3.12.0.GA in the shaded jar.
[INFO] Including org.hibernate.javax.persistence:hibernate-jpa-2.0-api:jar:1.0.1.Final in the shaded jar.
[INFO] Including cglib:cglib:jar:3.1 in the shaded jar.
[INFO] Including commons-dbcp:commons-dbcp:jar:1.2.2 in the shaded jar.
[INFO] Including commons-pool:commons-pool:jar:1.3 in the shaded jar.
[INFO] Including postgresql:postgresql:jar:8.4-702.jdbc4 in the shaded jar.
[INFO] Including org.springframework:spring-jdbc:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.springframework:spring-orm:jar:3.1.4.RELEASE in the shaded jar.
[INFO] Including org.apache.commons:commons-pool2:jar:2.4.2 in the shaded jar.
[INFO] Including org.dataone:d1_identity_manager:jar:2.4.0-SNAPSHOT in the shaded jar.
[INFO] Including org.dataone:d1_cn_noderegistry:jar:2.4.0-SNAPSHOT in the shaded jar.
[INFO] Including org.dataone:d1_portal:jar:2.4.0-SNAPSHOT in the shaded jar.
[INFO] Including com.nimbusds:nimbus-jose-jwt:jar:3.1.2 in the shaded jar.
[INFO] Including net.jcip:jcip-annotations:jar:1.0 in the shaded jar.
[INFO] Including net.minidev:json-smart:jar:1.1.1 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.myproxy:oa4mp-client-api:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-delegation-client:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-util:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-delegation-common:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-storage:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-servlet:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-core:jar:3.3 in the shaded jar.
[INFO] Including javax.inject:javax.inject:jar:1 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.myproxy:oa4mp-client-oauth1:war:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.myproxy:oa4mp-client-loader-oauth1:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.myproxy:myproxy-logon:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-oauth-1.0a:jar:3.3 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-delegation-server:jar:3.3 in the shaded jar.
[INFO] Including net.oauth.core:oauth-httpclient4:jar:20090617 in the shaded jar.
[INFO] Including net.oauth.core:oauth:jar:20100527 in the shaded jar.
[INFO] Including net.oauth.core:oauth-consumer:jar:20100527 in the shaded jar.
[INFO] Including net.oauth.core:oauth-provider:jar:20100527 in the shaded jar.
[INFO] Including org.apache.httpcomponents:httpclient:jar:4.3.3 in the shaded jar.
[INFO] Including xerces:xercesImpl:jar:2.9.1 in the shaded jar.
[INFO] Excluding xml-apis:xml-apis:jar:1.3.04 from the shaded jar.
[INFO] Including commons-beanutils:commons-beanutils:jar:1.8.3 in the shaded jar.
[INFO] Including commons-configuration:commons-configuration:jar:1.7 in the shaded jar.
[INFO] Including commons-digester:commons-digester:jar:1.8.1 in the shaded jar.
[INFO] Including org.slf4j:slf4j-api:jar:1.7.7 in the shaded jar.
[INFO] Including org.slf4j:slf4j-log4j12:jar:1.7.7 in the shaded jar.
[WARNING] stax-api-1.0-2.jar, stax-api-1.0.jar define 37 overlapping classes: 
[WARNING]   - javax.xml.stream.XMLEventReader
[WARNING]   - javax.xml.stream.StreamFilter
[WARNING]   - javax.xml.stream.FactoryFinder$ClassLoaderFinderConcrete
[WARNING]   - javax.xml.stream.util.StreamReaderDelegate
[WARNING]   - javax.xml.stream.events.StartDocument
[WARNING]   - javax.xml.stream.EventFilter
[WARNING]   - javax.xml.stream.XMLEventWriter
[WARNING]   - javax.xml.stream.XMLStreamConstants
[WARNING]   - javax.xml.stream.events.EntityDeclaration
[WARNING]   - javax.xml.stream.events.ProcessingInstruction
[WARNING]   - 27 more...
[WARNING] commons-logging-1.1.1.jar, jcl-over-slf4j-1.7.1.jar define 6 overlapping classes: 
[WARNING]   - org.apache.commons.logging.impl.SimpleLog$1
[WARNING]   - org.apache.commons.logging.Log
[WARNING]   - org.apache.commons.logging.impl.SimpleLog
[WARNING]   - org.apache.commons.logging.LogConfigurationException
[WARNING]   - org.apache.commons.logging.impl.NoOpLog
[WARNING]   - org.apache.commons.logging.LogFactory
[WARNING] xpp3-1.1.3.4.O.jar, stax-api-1.0.jar define 1 overlapping classes: 
[WARNING]   - javax.xml.namespace.QName
[WARNING] xmlParserAPIs-2.0.2.jar, xercesImpl-2.9.1.jar define 1 overlapping classes: 
[WARNING]   - org.w3c.dom.html.HTMLDOMImplementation
[WARNING] commons-collections-3.2.1.jar, commons-beanutils-1.8.3.jar define 10 overlapping classes: 
[WARNING]   - org.apache.commons.collections.FastHashMap$EntrySet
[WARNING]   - org.apache.commons.collections.FastHashMap$KeySet
[WARNING]   - org.apache.commons.collections.FastHashMap$CollectionView$CollectionViewIterator
[WARNING]   - org.apache.commons.collections.ArrayStack
[WARNING]   - org.apache.commons.collections.FastHashMap$Values
[WARNING]   - org.apache.commons.collections.FastHashMap$CollectionView
[WARNING]   - org.apache.commons.collections.FastHashMap$1
[WARNING]   - org.apache.commons.collections.Buffer
[WARNING]   - org.apache.commons.collections.FastHashMap
[WARNING]   - org.apache.commons.collections.BufferUnderflowException
[WARNING] maven-shade-plugin has detected that some class files are
[WARNING] present in two or more JARs. When this happens, only one
[WARNING] single version of the class is copied to the uber jar.
[WARNING] Usually this is not harmful and you can skip these warnings,
[WARNING] otherwise try to manually exclude artifacts based on
[WARNING] mvn dependency:tree -Ddetail=true and the above output.
[WARNING] See http://maven.apache.org/plugins/maven-shade-plugin/
[INFO] 
[INFO] --- maven-install-plugin:2.4:install (default-install) @ d1_solr_extensions ---
[INFO] Installing /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/d1_solr_extensions-2.4.0-SNAPSHOT.jar to /var/lib/jenkins/.m2/repository/org/dataone/d1_solr_extensions/2.4.0-SNAPSHOT/d1_solr_extensions-2.4.0-SNAPSHOT.jar
[INFO] Installing /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/pom.xml to /var/lib/jenkins/.m2/repository/org/dataone/d1_solr_extensions/2.4.0-SNAPSHOT/d1_solr_extensions-2.4.0-SNAPSHOT.pom
[INFO] 
[INFO] >>> maven-javadoc-plugin:2.10.4:javadoc (default-cli) > generate-sources @ d1_solr_extensions >>>
[INFO] 
[INFO] --- buildnumber-maven-plugin:1.4:create (default) @ d1_solr_extensions ---
[INFO] Executing: /bin/sh -c cd '/var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions' && 'svn' '--non-interactive' 'info'
[INFO] Working directory: /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions
[INFO] Storing buildNumber: null at timestamp: 1573535275954
[INFO] Executing: /bin/sh -c cd '/var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions' && 'svn' '--non-interactive' 'info'
[INFO] Working directory: /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions
[INFO] Storing buildScmBranch: UNKNOWN_BRANCH
[WARNING] Failed to getClass for org.apache.maven.plugin.javadoc.JavadocReport
[INFO] 
[INFO] <<< maven-javadoc-plugin:2.10.4:javadoc (default-cli) < generate-sources @ d1_solr_extensions <<<
[INFO] 
[INFO] 
[INFO] --- maven-javadoc-plugin:2.10.4:javadoc (default-cli) @ d1_solr_extensions ---
[INFO] 
Loading source files for package org.dataone.solr.servlet...
Loading source files for package org.dataone.solr.response...
Loading source files for package org.dataone.solr.handler...
Loading source files for package org.dataone.solr.handler.component...
Constructing Javadoc information...
Standard Doclet version 1.8.0_222
Building tree for all the packages and classes...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/LogServiceSessionAuthorizationFilter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/SearchServiceSessionAuthorizationFilter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/SessionAuthorizationFilterStrategy.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/SessionAuthorizationUtil.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/LogSolrQueryEngineDescriptionResponseWriter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/QueryEngineDescriptionResponseWriter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/SolrQueryEngineDescriptionResponseWriter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/LogSolrQueryEngineDescriptionHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/QueryEngineDescriptionHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/SolrQueryEngineDescriptionHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/SolrLoggingHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/SolrSearchHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/SolrSearchHandlerUtil.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/overview-frame.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/package-frame.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/package-summary.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/package-tree.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/package-frame.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/package-summary.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/package-tree.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/package-frame.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/package-summary.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/package-tree.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/package-frame.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/package-summary.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/package-tree.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/constant-values.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/class-use/SessionAuthorizationUtil.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/class-use/SessionAuthorizationFilterStrategy.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/class-use/LogServiceSessionAuthorizationFilter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/class-use/SearchServiceSessionAuthorizationFilter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/class-use/SolrQueryEngineDescriptionResponseWriter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/class-use/QueryEngineDescriptionResponseWriter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/class-use/LogSolrQueryEngineDescriptionResponseWriter.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/class-use/QueryEngineDescriptionHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/class-use/SolrQueryEngineDescriptionHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/class-use/LogSolrQueryEngineDescriptionHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/class-use/SolrLoggingHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/class-use/SolrSearchHandler.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/class-use/SolrSearchHandlerUtil.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/package-use.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/handler/component/package-use.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/response/package-use.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/org/dataone/solr/servlet/package-use.html...
Building index for all the packages and classes...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/overview-tree.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/index-all.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/deprecated-list.html...
Building index for all classes...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/allclasses-frame.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/allclasses-noframe.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/index.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/overview-summary.html...
Generating /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/site/apidocs/help-doc.html...
4 warnings
[WARNING] Javadoc Warnings
[WARNING] /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/src/main/java/org/dataone/solr/servlet/SessionAuthorizationFilterStrategy.java:130: warning - Tag @author cannot be used in method documentation.  It can only be used in the following types of documentation: overview, package, class/interface.
[WARNING] /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/src/main/java/org/dataone/solr/servlet/SessionAuthorizationFilterStrategy.java:164: warning - Tag @author cannot be used in method documentation.  It can only be used in the following types of documentation: overview, package, class/interface.
[WARNING] /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/src/main/java/org/dataone/solr/servlet/SessionAuthorizationFilterStrategy.java:164: warning - @returns is an unknown tag.
[WARNING] /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/src/main/java/org/dataone/solr/handler/component/SolrLoggingHandler.java:72: warning - Tag @author cannot be used in method documentation.  It can only be used in the following types of documentation: overview, package, class/interface.
[JENKINS] Archiving  javadoc
Notifying upstream projects of job completion
Join notifier requires a CauseAction
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  19.456 s
[INFO] Finished at: 2019-11-12T05:07:58Z
[INFO] ------------------------------------------------------------------------
Waiting for Jenkins to finish collecting data