Console Output

<===[JENKINS REMOTING CAPACITY]===>channel started
Executing Maven:  -B -f /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/pom.xml clean install javadoc:javadoc
[INFO] Scanning for projects...
[WARNING] 
[WARNING] Some problems were encountered while building the effective model for org.dataone:d1_solr_extensions:jar:2.0.0-SNAPSHOT
[WARNING] 'dependencies.dependency.(groupId:artifactId:type:classifier)' must be unique: org.slf4j:slf4j-api:jar -> version 1.7.7 vs 1.7.5 @ line 348, column 15
[WARNING] 'dependencies.dependency.(groupId:artifactId:type:classifier)' must be unique: org.slf4j:slf4j-log4j12:jar -> version 1.7.7 vs 1.7.5 @ line 354, column 15
[WARNING] 'build.plugins.plugin.version' for org.apache.maven.plugins:maven-shade-plugin is missing. @ line 96, column 21
[WARNING] 'build.plugins.plugin.version' for org.apache.maven.plugins:maven-compiler-plugin is missing. @ line 71, column 21
[WARNING] 'build.plugins.plugin.version' for org.codehaus.mojo:buildnumber-maven-plugin is missing. @ line 80, column 21
[WARNING] 'build.plugins.plugin.version' for com.mycila.maven-license-plugin:maven-license-plugin is missing. @ line 163, column 21
[WARNING] 'build.plugins.plugin.version' for org.apache.maven.plugins:maven-jar-plugin is missing. @ line 149, column 21
[WARNING] The expression ${artifactId} is deprecated. Please use ${project.artifactId} instead.
[WARNING] 
[WARNING] It is highly recommended to fix these problems because they threaten the stability of your build.
[WARNING] 
[WARNING] For this reason, future Maven versions might no longer support building such malformed projects.
[WARNING] 
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building DataONE_Solr_Extensions 2.0.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- maven-clean-plugin:2.3:clean (default-clean) @ d1_solr_extensions ---
[INFO] 
[INFO] --- buildnumber-maven-plugin:1.2:create (default) @ d1_solr_extensions ---
[INFO] Checking for local modifications: skipped.
[INFO] Updating project files from SCM: skipped.
[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: 16367 at timestamp: 1442602869563
[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: trunk
[INFO] 
[INFO] --- maven-resources-plugin:2.5:resources (default-resources) @ d1_solr_extensions ---
[debug] execute contextualize
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 1 resource
[INFO] Copying 3 resources
[INFO] 
[INFO] --- maven-compiler-plugin:2.0.2:compile (default-compile) @ d1_solr_extensions ---
[INFO] Compiling 13 source files to /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/classes
[INFO] 
[INFO] --- maven-resources-plugin:2.5:testResources (default-testResources) @ d1_solr_extensions ---
[debug] execute contextualize
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] Copying 12 resources
[INFO] 
[INFO] --- maven-compiler-plugin:2.0.2:testCompile (default-testCompile) @ d1_solr_extensions ---
[INFO] Compiling 7 source files to /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/test-classes
[INFO] 
[INFO] --- maven-surefire-plugin:2.10:test (default-test) @ d1_solr_extensions ---
[INFO] Surefire report directory: /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/surefire-reports

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase
[ INFO] 2015-09-18 19:01:17,616 (TestContextManager:retrieveTestExecutionListeners:185) @TestExecutionListeners is not present for class [class org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]: using defaults.
[ INFO] 2015-09-18 19:01:18,237 (XmlBeanDefinitionReader:loadBeanDefinitions:315) Loading XML bean definitions from class path resource [webapp/mockController-dispatcher.xml]
[ INFO] 2015-09-18 19:01:18,532 (XmlBeanDefinitionReader:loadBeanDefinitions:315) Loading XML bean definitions from class path resource [webapp/mockController-beans.xml]
[ INFO] 2015-09-18 19:01:18,640 (ClassPathScanningCandidateComponentProvider:registerDefaultFilters:210) JSR-330 'javax.inject.Named' annotation found and supported for component scanning
[ INFO] 2015-09-18 19:01:18,700 (ClassPathScanningCandidateComponentProvider:registerDefaultFilters:210) JSR-330 'javax.inject.Named' annotation found and supported for component scanning
[ INFO] 2015-09-18 19:01:18,713 (AbstractApplicationContext:prepareRefresh:495) Refreshing org.springframework.web.context.support.GenericWebApplicationContext@2c11008e: startup date [Fri Sep 18 19:01:18 UTC 2015]; root of context hierarchy
[ INFO] 2015-09-18 19:01:18,832 (AutowiredAnnotationBeanPostProcessor:<init>:139) JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
[ INFO] 2015-09-18 19:01:18,849 (DefaultListableBeanFactory:preInstantiateSingletons:557) Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7f25ab41: 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$ImportAwareBeanPostProcessor#0]; root of factory hierarchy
[DEBUG] 2015-09-18 19:01:19,006 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'log4jInitialization'
[DEBUG] 2015-09-18 19:01:19,006 (DefaultSingletonBeanRegistry:getSingleton:217) Creating shared instance of singleton bean 'contextSourceConfiguration'
[DEBUG] 2015-09-18 19:01:19,007 (AbstractAutowireCapableBeanFactory:createBean:430) Creating instance of bean 'contextSourceConfiguration'
[DEBUG] 2015-09-18 19:01:19,028 (AbstractAutowireCapableBeanFactory:doCreateBean:504) Eagerly caching bean 'contextSourceConfiguration' to allow for resolving potential circular references
[DEBUG] 2015-09-18 19:01:19,033 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'contextSourceConfiguration'
[DEBUG] 2015-09-18 19:01:19,033 (DefaultSingletonBeanRegistry:getSingleton:217) Creating shared instance of singleton bean 'contextSource'
[DEBUG] 2015-09-18 19:01:19,034 (AbstractAutowireCapableBeanFactory:createBean:430) Creating instance of bean 'contextSource'
[DEBUG] 2015-09-18 19:01:19,037 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'contextSourceConfiguration'
[DEBUG] 2015-09-18 19:01:19,046 (AbstractAutowireCapableBeanFactory:doCreateBean:504) Eagerly caching bean 'contextSource' to allow for resolving potential circular references
[DEBUG] 2015-09-18 19:01:19,059 (AbstractAutowireCapableBeanFactory:invokeInitMethods:1498) Invoking afterPropertiesSet() on bean with name 'contextSource'
[DEBUG] 2015-09-18 19:01:19,061 (AbstractContextSource:afterPropertiesSet:328) AuthenticationSource not set - using default implementation
[DEBUG] 2015-09-18 19:01:19,062 (AbstractContextSource:setupAnonymousEnv:350) Not using LDAP pooling
[DEBUG] 2015-09-18 19:01:19,062 (AbstractContextSource:setupAnonymousEnv:371) Trying provider Urls: ldap://localhost:389/dc=org
[DEBUG] 2015-09-18 19:01:19,062 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'contextSource'
[DEBUG] 2015-09-18 19:01:19,063 (DefaultSingletonBeanRegistry:getSingleton:217) Creating shared instance of singleton bean 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,063 (AbstractAutowireCapableBeanFactory:createBean:430) Creating instance of bean 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,072 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'contextSource'
[DEBUG] 2015-09-18 19:01:19,085 (AbstractAutowireCapableBeanFactory:doCreateBean:504) Eagerly caching bean 'ldapTemplate' to allow for resolving potential circular references
[DEBUG] 2015-09-18 19:01:19,096 (AbstractAutowireCapableBeanFactory:invokeInitMethods:1498) Invoking afterPropertiesSet() on bean with name 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,096 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,096 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'
[DEBUG] 2015-09-18 19:01:19,097 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'org.springframework.context.annotation.internalAutowiredAnnotationProcessor'
[DEBUG] 2015-09-18 19:01:19,097 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'org.springframework.context.annotation.internalRequiredAnnotationProcessor'
[DEBUG] 2015-09-18 19:01:19,097 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'org.springframework.context.annotation.internalCommonAnnotationProcessor'
[DEBUG] 2015-09-18 19:01:19,098 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'org.springframework.context.annotation.internalPersistenceAnnotationProcessor'
[DEBUG] 2015-09-18 19:01:19,098 (DefaultSingletonBeanRegistry:getSingleton:217) Creating shared instance of singleton bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,099 (AbstractAutowireCapableBeanFactory:createBean:430) Creating instance of bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,110 (InjectionMetadata:<init>:60) Found injected element on class [org.dataone.cn.ldap.v1.SubjectLdapPopulation]: AutowiredFieldElement for private org.springframework.ldap.core.LdapTemplate org.dataone.cn.ldap.v1.SubjectLdapPopulation.ldapTemplate
[DEBUG] 2015-09-18 19:01:19,111 (AbstractAutowireCapableBeanFactory:doCreateBean:504) Eagerly caching bean 'subjectLdapPopulation' to allow for resolving potential circular references
[DEBUG] 2015-09-18 19:01:19,115 (InjectionMetadata:inject:85) Processing injected method of bean 'subjectLdapPopulation': AutowiredFieldElement for private org.springframework.ldap.core.LdapTemplate org.dataone.cn.ldap.v1.SubjectLdapPopulation.ldapTemplate
[DEBUG] 2015-09-18 19:01:19,118 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,119 (AutowiredAnnotationBeanPostProcessor:registerDependentBeans:424) Autowiring by type from bean name 'subjectLdapPopulation' to bean named 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,120 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,120 (DefaultSingletonBeanRegistry:getSingleton:217) Creating shared instance of singleton bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,120 (AbstractAutowireCapableBeanFactory:createBean:430) Creating instance of bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,125 (InjectionMetadata:<init>:60) Found injected element on class [org.dataone.cn.ldap.v1.NodeLdapPopulation]: AutowiredFieldElement for private org.springframework.ldap.core.LdapTemplate org.dataone.cn.ldap.v1.NodeLdapPopulation.ldapTemplate
[DEBUG] 2015-09-18 19:01:19,126 (AbstractAutowireCapableBeanFactory:doCreateBean:504) Eagerly caching bean 'nodeLdapPopulation' to allow for resolving potential circular references
[DEBUG] 2015-09-18 19:01:19,129 (InjectionMetadata:inject:85) Processing injected method of bean 'nodeLdapPopulation': AutowiredFieldElement for private org.springframework.ldap.core.LdapTemplate org.dataone.cn.ldap.v1.NodeLdapPopulation.ldapTemplate
[DEBUG] 2015-09-18 19:01:19,131 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,131 (AutowiredAnnotationBeanPostProcessor:registerDependentBeans:424) Autowiring by type from bean name 'nodeLdapPopulation' to bean named 'ldapTemplate'
[DEBUG] 2015-09-18 19:01:19,131 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,132 (DefaultSingletonBeanRegistry:getSingleton:217) Creating shared instance of singleton bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:19,132 (AbstractAutowireCapableBeanFactory:createBean:430) Creating instance of bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:19,698 (AbstractAutowireCapableBeanFactory:doCreateBean:504) Eagerly caching bean 'x509CertificateGenerator' to allow for resolving potential circular references
[DEBUG] 2015-09-18 19:01:19,702 (AbstractAutowireCapableBeanFactory:createBean:458) Finished creating instance of bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:19,703 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'org.springframework.context.annotation.ConfigurationClassPostProcessor$ImportAwareBeanPostProcessor#0'
[DEBUG] 2015-09-18 19:01:19,705 (AbstractApplicationContext:initLifecycleProcessor:845) Unable to locate LifecycleProcessor with name 'lifecycleProcessor': using default [org.springframework.context.support.DefaultLifecycleProcessor@618f9de]
[DEBUG] 2015-09-18 19:01:19,706 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'lifecycleProcessor'
[DEBUG] 2015-09-18 19:01:19,715 (TestContext:getApplicationContext:150) Storing ApplicationContext for test class [class org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase] in cache under key [[MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']].
[DEBUG] 2015-09-18 19:01:19,725 (InjectionMetadata:<init>:60) Found injected element on class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]: ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.SubjectLdapPopulation)
[DEBUG] 2015-09-18 19:01:19,726 (InjectionMetadata:<init>:60) Found injected element on class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]: ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.NodeLdapPopulation)
[DEBUG] 2015-09-18 19:01:19,726 (InjectionMetadata:<init>:60) Found injected element on class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]: ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setX509CertificateGenerator(org.dataone.cn.auth.X509CertificateGenerator)
[DEBUG] 2015-09-18 19:01:19,727 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.SubjectLdapPopulation)
[DEBUG] 2015-09-18 19:01:19,729 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,730 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.NodeLdapPopulation)
[DEBUG] 2015-09-18 19:01:19,731 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:19,732 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setX509CertificateGenerator(org.dataone.cn.auth.X509CertificateGenerator)
[DEBUG] 2015-09-18 19:01:19,733 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:19,883 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,000 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNCore-v1
[DEBUG] 2015-09-18 19:01:20,010 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,012 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRead-v1
[DEBUG] 2015-09-18 19:01:20,014 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,022 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNAuthorization-v1
[DEBUG] 2015-09-18 19:01:20,023 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,030 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNIdentity-v1
[DEBUG] 2015-09-18 19:01:20,032 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,034 (NodeLdapPopulation:populateTestCN:249) sqrm adding restriction mapIdentity
[DEBUG] 2015-09-18 19:01:20,036 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,044 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNReplication-v1
[DEBUG] 2015-09-18 19:01:20,045 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,047 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRegister-v1
[DEBUG] 2015-09-18 19:01:20,066 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,074 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,102 (SessionAuthorizationFilterStrategy:init:136) about to cache admin
[DEBUG] 2015-09-18 19:01:20,103 (SessionAuthorizationFilterStrategy:cacheAdministrativeSubjectList:304) AdminList entry CN=Test1,O=Test,C=US,DC=cilogon,DC=org
[DEBUG] 2015-09-18 19:01:20,104 (LDAPService:getContext:76) context is null
[DEBUG] 2015-09-18 19:01:20,252 (NodeRegistryService:listNodes:101) found 4 nodes
[DEBUG] 2015-09-18 19:01:20,253 (LDAPService:getContext:76) context is null
[DEBUG] 2015-09-18 19:01:20,259 (LDAPService:getContext:76) context is null
[DEBUG] 2015-09-18 19:01:20,266 (LDAPService:getContext:76) context is null
[DEBUG] 2015-09-18 19:01:20,291 (SessionAuthorizationFilterStrategy:init:144) init SessionAuthorizationFilter: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[ INFO] 2015-09-18 19:01:20,291 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNCore-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,295 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,297 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRead-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,298 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,300 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNAuthorization-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,302 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,303 (NodeLdapPopulation:deleteNodeServiceRestriction:151) deleting : d1ServiceMethodName=mapIdentity,d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,304 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,306 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,307 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,309 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNReplication-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,310 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,312 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,313 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,314 (NodeLdapPopulation:deleteNode:131) deleting : cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,315 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,318 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,320 (DirtiesContextTestExecutionListener:afterTestMethod:86) After test method: context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@16959a3c, testMethod = testInit@LogServiceSessionAuthorizationFilterTestCase, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, 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] 2015-09-18 19:01:20,321 (ProfileValueUtils:retrieveProfileValueSource:68) Retrieved @ProfileValueSourceConfiguration [null] for test class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:20,322 (ProfileValueUtils:retrieveProfileValueSource:80) Retrieved ProfileValueSource type [class org.springframework.test.annotation.SystemProfileValueSource] for class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:20,323 (DependencyInjectionTestExecutionListener:prepareTestInstance:73) Performing dependency injection for test context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@668dd96c, testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]].
[DEBUG] 2015-09-18 19:01:20,323 (TestContext:getApplicationContext:162) Retrieved ApplicationContext for test class [class org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase] from cache with key [[MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']].
[DEBUG] 2015-09-18 19:01:20,324 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.SubjectLdapPopulation)
[DEBUG] 2015-09-18 19:01:20,325 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:20,325 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.NodeLdapPopulation)
[DEBUG] 2015-09-18 19:01:20,326 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:20,327 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setX509CertificateGenerator(org.dataone.cn.auth.X509CertificateGenerator)
[DEBUG] 2015-09-18 19:01:20,327 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:20,329 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,331 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNCore-v1
[DEBUG] 2015-09-18 19:01:20,332 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,334 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRead-v1
[DEBUG] 2015-09-18 19:01:20,336 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,337 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNAuthorization-v1
[DEBUG] 2015-09-18 19:01:20,339 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,341 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNIdentity-v1
[DEBUG] 2015-09-18 19:01:20,342 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,344 (NodeLdapPopulation:populateTestCN:249) sqrm adding restriction mapIdentity
[DEBUG] 2015-09-18 19:01:20,345 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,347 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNReplication-v1
[DEBUG] 2015-09-18 19:01:20,349 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,350 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRegister-v1
[DEBUG] 2015-09-18 19:01:20,352 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,355 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,357 (SessionAuthorizationFilterStrategy:init:136) about to cache admin
[DEBUG] 2015-09-18 19:01:20,357 (SessionAuthorizationFilterStrategy:cacheAdministrativeSubjectList:304) AdminList entry CN=Test1,O=Test,C=US,DC=cilogon,DC=org
[DEBUG] 2015-09-18 19:01:20,362 (NodeRegistryService:listNodes:101) found 4 nodes
[DEBUG] 2015-09-18 19:01:20,394 (SessionAuthorizationFilterStrategy:init:144) init SessionAuthorizationFilter: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:20,407 (SessionAuthorizationFilterStrategy:doFilter:173) SessionAuthorizationFilterStrategy doFilter invoked by: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:20,433 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,433 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,434 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,434 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,435 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,435 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,436 (PortalCertificateManager:putPortalCertificateOnRequest:232) Proxy certificate for the request = null
[DEBUG] 2015-09-18 19:01:20,436 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,436 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,437 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,437 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,438 (SessionAuthorizationFilterStrategy:doFilter:250) Solr Session auth - NO SESSION
[DEBUG] 2015-09-18 19:01:20,438 (LogServiceSessionAuthorizationFilter:handleNoCertificateManagerSession:55) solr search filter handling no cert.
[DEBUG] 2015-09-18 19:01:20,445 (SessionAuthorizationUtil:handleNoCertificateManagerSession:65) session is null: default to public
[ INFO] 2015-09-18 19:01:20,445 (LogServiceSessionAuthorizationFilterTestCase:testDoPublicFilter:141) 
[ INFO] 2015-09-18 19:01:20,446 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNCore-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,448 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,449 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRead-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,451 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,453 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNAuthorization-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,454 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,455 (NodeLdapPopulation:deleteNodeServiceRestriction:151) deleting : d1ServiceMethodName=mapIdentity,d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,457 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,458 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,460 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,461 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNReplication-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,462 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,464 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,465 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,467 (NodeLdapPopulation:deleteNode:131) deleting : cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,468 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,470 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,472 (DirtiesContextTestExecutionListener:afterTestMethod:86) After test method: context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@668dd96c, testMethod = testDoPublicFilter@LogServiceSessionAuthorizationFilterTestCase, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, 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] 2015-09-18 19:01:20,473 (ProfileValueUtils:retrieveProfileValueSource:68) Retrieved @ProfileValueSourceConfiguration [null] for test class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:20,474 (ProfileValueUtils:retrieveProfileValueSource:80) Retrieved ProfileValueSource type [class org.springframework.test.annotation.SystemProfileValueSource] for class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:20,475 (DependencyInjectionTestExecutionListener:prepareTestInstance:73) Performing dependency injection for test context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@75a33238, testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]].
[DEBUG] 2015-09-18 19:01:20,475 (TestContext:getApplicationContext:162) Retrieved ApplicationContext for test class [class org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase] from cache with key [[MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']].
[DEBUG] 2015-09-18 19:01:20,476 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.SubjectLdapPopulation)
[DEBUG] 2015-09-18 19:01:20,477 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:20,478 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.NodeLdapPopulation)
[DEBUG] 2015-09-18 19:01:20,479 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:20,479 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setX509CertificateGenerator(org.dataone.cn.auth.X509CertificateGenerator)
[DEBUG] 2015-09-18 19:01:20,480 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:20,482 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,484 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNCore-v1
[DEBUG] 2015-09-18 19:01:20,486 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,488 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRead-v1
[DEBUG] 2015-09-18 19:01:20,504 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,506 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNAuthorization-v1
[DEBUG] 2015-09-18 19:01:20,508 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,510 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNIdentity-v1
[DEBUG] 2015-09-18 19:01:20,512 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,513 (NodeLdapPopulation:populateTestCN:249) sqrm adding restriction mapIdentity
[DEBUG] 2015-09-18 19:01:20,515 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,516 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNReplication-v1
[DEBUG] 2015-09-18 19:01:20,518 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,520 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRegister-v1
[DEBUG] 2015-09-18 19:01:20,522 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,524 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,526 (SessionAuthorizationFilterStrategy:init:136) about to cache admin
[DEBUG] 2015-09-18 19:01:20,527 (SessionAuthorizationFilterStrategy:cacheAdministrativeSubjectList:304) AdminList entry CN=Test1,O=Test,C=US,DC=cilogon,DC=org
[DEBUG] 2015-09-18 19:01:20,532 (NodeRegistryService:listNodes:101) found 4 nodes
[DEBUG] 2015-09-18 19:01:20,562 (SessionAuthorizationFilterStrategy:init:144) init SessionAuthorizationFilter: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:20,563 (SessionAuthorizationFilterStrategy:doFilter:173) SessionAuthorizationFilterStrategy doFilter invoked by: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:20,563 (SessionAuthorizationFilterStrategy:doFilter:182) removing attempt at supplying authorized user by client
[DEBUG] 2015-09-18 19:01:20,564 (SessionAuthorizationFilterStrategy:doFilter:187) removing attempt at supplying authorized administrative user by client
[DEBUG] 2015-09-18 19:01:20,564 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,565 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,565 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,566 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,566 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,566 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,567 (PortalCertificateManager:putPortalCertificateOnRequest:232) Proxy certificate for the request = null
[DEBUG] 2015-09-18 19:01:20,567 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,568 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,568 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = null
[DEBUG] 2015-09-18 19:01:20,569 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:20,569 (SessionAuthorizationFilterStrategy:doFilter:250) Solr Session auth - NO SESSION
[DEBUG] 2015-09-18 19:01:20,569 (LogServiceSessionAuthorizationFilter:handleNoCertificateManagerSession:55) solr search filter handling no cert.
[DEBUG] 2015-09-18 19:01:20,570 (SessionAuthorizationUtil:handleNoCertificateManagerSession:65) session is null: default to public
[ INFO] 2015-09-18 19:01:20,570 (LogServiceSessionAuthorizationFilterTestCase:testDoPublicWipeFilter:169) 
[ INFO] 2015-09-18 19:01:20,571 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNCore-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,572 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,574 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRead-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,576 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,577 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNAuthorization-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,578 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,580 (NodeLdapPopulation:deleteNodeServiceRestriction:151) deleting : d1ServiceMethodName=mapIdentity,d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,582 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,583 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,584 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,586 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNReplication-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,587 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,589 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,590 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,591 (NodeLdapPopulation:deleteNode:131) deleting : cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:20,593 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,595 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,597 (DirtiesContextTestExecutionListener:afterTestMethod:86) After test method: context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@75a33238, testMethod = testDoPublicWipeFilter@LogServiceSessionAuthorizationFilterTestCase, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, 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] 2015-09-18 19:01:20,598 (ProfileValueUtils:retrieveProfileValueSource:68) Retrieved @ProfileValueSourceConfiguration [null] for test class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:20,599 (ProfileValueUtils:retrieveProfileValueSource:80) Retrieved ProfileValueSource type [class org.springframework.test.annotation.SystemProfileValueSource] for class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:20,600 (DependencyInjectionTestExecutionListener:prepareTestInstance:73) Performing dependency injection for test context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@1328aa26, testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]].
[DEBUG] 2015-09-18 19:01:20,600 (TestContext:getApplicationContext:162) Retrieved ApplicationContext for test class [class org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase] from cache with key [[MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']].
[DEBUG] 2015-09-18 19:01:20,601 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.SubjectLdapPopulation)
[DEBUG] 2015-09-18 19:01:20,602 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:20,603 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.NodeLdapPopulation)
[DEBUG] 2015-09-18 19:01:20,604 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:20,604 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setX509CertificateGenerator(org.dataone.cn.auth.X509CertificateGenerator)
[DEBUG] 2015-09-18 19:01:20,605 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:20,606 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,608 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNCore-v1
[DEBUG] 2015-09-18 19:01:20,610 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,612 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRead-v1
[DEBUG] 2015-09-18 19:01:20,613 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,615 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNAuthorization-v1
[DEBUG] 2015-09-18 19:01:20,617 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,618 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNIdentity-v1
[DEBUG] 2015-09-18 19:01:20,620 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,622 (NodeLdapPopulation:populateTestCN:249) sqrm adding restriction mapIdentity
[DEBUG] 2015-09-18 19:01:20,624 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,625 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNReplication-v1
[DEBUG] 2015-09-18 19:01:20,627 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,628 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRegister-v1
[DEBUG] 2015-09-18 19:01:20,630 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:20,633 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:20,997 (X509CertificateGenerator:generateCACert:149) CN=cn.dataone.org Mock CA,DC=dataone,DC=org
[ INFO] 2015-09-18 19:01:21,101 (X509CertificateGenerator:generateSelfSignedCertificate:177) Self Signed Certificat is DC=org,DC=dataone,CN=TestOne
[DEBUG] 2015-09-18 19:01:21,126 (X509CertificateGenerator:locateCertificate:298) Calculated certificate location: /tmp/x509up_u106
[ INFO] 2015-09-18 19:01:21,140 (CertificateManager:selectSession:1080) selectSession: using the default certificate location
[DEBUG] 2015-09-18 19:01:21,147 (CertificateManager:locateDefaultCertificate:1301) Calculated certificate location: /tmp/x509up_u106
[DEBUG] 2015-09-18 19:01:21,147 (CertificateManager:selectSession:1082) selectSession: certificate location = /tmp/x509up_u106
[DEBUG] 2015-09-18 19:01:21,167 (CertificateManager:getKeyStore:1131) getKeyStore: privateKey value: sun.security.rsa.RSAPrivateCrtKeyImpl@b01063e
[DEBUG] 2015-09-18 19:01:21,168 (SessionAuthorizationFilterStrategy:init:136) about to cache admin
[DEBUG] 2015-09-18 19:01:21,169 (SessionAuthorizationFilterStrategy:cacheAdministrativeSubjectList:304) AdminList entry CN=Test1,O=Test,C=US,DC=cilogon,DC=org
[DEBUG] 2015-09-18 19:01:21,174 (NodeRegistryService:listNodes:101) found 4 nodes
[DEBUG] 2015-09-18 19:01:21,204 (SessionAuthorizationFilterStrategy:init:144) init SessionAuthorizationFilter: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:21,204 (SessionAuthorizationFilterStrategy:doFilter:173) SessionAuthorizationFilterStrategy doFilter invoked by: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:21,205 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = [Ljava.security.cert.X509Certificate;@30a777ed
[DEBUG] 2015-09-18 19:01:21,205 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:21,205 (CertificateManager:displayCertificate:1319) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[DEBUG] 2015-09-18 19:01:21,206 (CertificateManager:displayCertificate:1321)  Issuer: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,208 (CertificateManager:displayCertificate:1324)    From: Sep 18, 2015 7:01:21 PM
[DEBUG] 2015-09-18 19:01:21,208 (CertificateManager:displayCertificate:1326)      To: Sep 19, 2115 7:01:21 PM
[DEBUG] 2015-09-18 19:01:21,209 (CertificateManager:displayCertificate:1327) Subject: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,209 (CertificateManager:displayCertificate:1334) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[DEBUG] 2015-09-18 19:01:21,210 (CertificateManager:getSubjectInfo:539) Certificate subjectInfoValue: null
[DEBUG] 2015-09-18 19:01:21,211 (SessionAuthorizationFilterStrategy:doFilter:204) Solr Session Auth found subject: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,217 (NodeRegistryService:listNodes:101) found 4 nodes
[DEBUG] 2015-09-18 19:01:21,246 (CNIdentityLDAPImpl:getSubjectInfo:765) subjectInfo requested for: 'CN=TestOne,DC=dataone,DC=org'
[DEBUG] 2015-09-18 19:01:21,246 (CNIdentityLDAPImpl:getSubjectInfo:766) checking if redaction holds for the calling user: 'CN=TestOne,DC=dataone,DC=org'
[DEBUG] 2015-09-18 19:01:21,246 (CNIdentityLDAPImpl:getSubjectInfo:773) subject MATCH. lifting redaction for the calling user: 'CN=TestOne,DC=dataone,DC=org'
[DEBUG] 2015-09-18 19:01:21,247 (LDAPService:getContext:76) context is null
[DEBUG] 2015-09-18 19:01:21,250 (CertificateManager:standardizeDN:572) name: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,250 (CertificateManager:standardizeDN:576) standardizedName: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,251 (CNIdentityLDAPImpl:processAttributes:1084) Found attribute: mail=testt@nothing.info
[DEBUG] 2015-09-18 19:01:21,251 (CNIdentityLDAPImpl:processAttributes:1094) Found attribute: givenName=Testest
[DEBUG] 2015-09-18 19:01:21,251 (CNIdentityLDAPImpl:processAttributes:1075) Found attribute: sn=TestOne
[DEBUG] 2015-09-18 19:01:21,252 (CNIdentityLDAPImpl:processAttributes:1100) Found attribute: isVerified=TRUE
[DEBUG] 2015-09-18 19:01:21,252 (CNIdentityLDAPImpl:processAttributes:1070) Found attribute: cn=TestOne
[DEBUG] 2015-09-18 19:01:21,253 (CNIdentityLDAPImpl:getSubjectInfo:784) Retrieved SubjectList for: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,255 (AuthUtils:findPersonsSubjects:121) traversing person: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,256 (CertificateManager:standardizeDN:572) name: CN=TestOne,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,256 (CertificateManager:standardizeDN:576) standardizedName: CN=TestOne,DC=dataone,DC=org
[ INFO] 2015-09-18 19:01:21,259 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNCore-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,261 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,263 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRead-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,264 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,266 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNAuthorization-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,267 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,269 (NodeLdapPopulation:deleteNodeServiceRestriction:151) deleting : d1ServiceMethodName=mapIdentity,d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,273 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,275 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,277 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,278 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNReplication-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,280 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,281 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,283 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,284 (NodeLdapPopulation:deleteNode:131) deleting : cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,286 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:21,289 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:21,291 (DirtiesContextTestExecutionListener:afterTestMethod:86) After test method: context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@1328aa26, testMethod = testDoAuthorizedSubjectFilter@LogServiceSessionAuthorizationFilterTestCase, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, 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] 2015-09-18 19:01:21,292 (ProfileValueUtils:retrieveProfileValueSource:68) Retrieved @ProfileValueSourceConfiguration [null] for test class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:21,293 (ProfileValueUtils:retrieveProfileValueSource:80) Retrieved ProfileValueSource type [class org.springframework.test.annotation.SystemProfileValueSource] for class [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]
[DEBUG] 2015-09-18 19:01:21,294 (DependencyInjectionTestExecutionListener:prepareTestInstance:73) Performing dependency injection for test context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@2f122921, testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]].
[DEBUG] 2015-09-18 19:01:21,294 (TestContext:getApplicationContext:162) Retrieved ApplicationContext for test class [class org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase] from cache with key [[MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']].
[DEBUG] 2015-09-18 19:01:21,295 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.SubjectLdapPopulation)
[DEBUG] 2015-09-18 19:01:21,296 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'subjectLdapPopulation'
[DEBUG] 2015-09-18 19:01:21,296 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setCNLdapPopulation(org.dataone.cn.ldap.v1.NodeLdapPopulation)
[DEBUG] 2015-09-18 19:01:21,297 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'nodeLdapPopulation'
[DEBUG] 2015-09-18 19:01:21,298 (InjectionMetadata:inject:85) Processing injected method of bean 'org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase': ResourceElement for public void org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase.setX509CertificateGenerator(org.dataone.cn.auth.X509CertificateGenerator)
[DEBUG] 2015-09-18 19:01:21,298 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'x509CertificateGenerator'
[DEBUG] 2015-09-18 19:01:21,300 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,302 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNCore-v1
[DEBUG] 2015-09-18 19:01:21,304 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,305 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRead-v1
[DEBUG] 2015-09-18 19:01:21,307 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,308 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNAuthorization-v1
[DEBUG] 2015-09-18 19:01:21,310 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,312 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNIdentity-v1
[DEBUG] 2015-09-18 19:01:21,314 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,315 (NodeLdapPopulation:populateTestCN:249) sqrm adding restriction mapIdentity
[DEBUG] 2015-09-18 19:01:21,317 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,319 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNReplication-v1
[DEBUG] 2015-09-18 19:01:21,321 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,323 (NodeLdapPopulation:populateTestCN:235) sqrm1 adding service CNRegister-v1
[DEBUG] 2015-09-18 19:01:21,324 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:21,327 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,616 (X509CertificateGenerator:generateCACert:149) CN=cn.dataone.org Mock CA,DC=dataone,DC=org
[ INFO] 2015-09-18 19:01:21,677 (X509CertificateGenerator:generateSelfSignedCertificate:177) Self Signed Certificat is DC=org,DC=dataone,CN=TestCN
[DEBUG] 2015-09-18 19:01:21,682 (X509CertificateGenerator:locateCertificate:298) Calculated certificate location: /tmp/x509up_u106
[ INFO] 2015-09-18 19:01:21,685 (CertificateManager:selectSession:1080) selectSession: using the default certificate location
[DEBUG] 2015-09-18 19:01:21,687 (CertificateManager:locateDefaultCertificate:1301) Calculated certificate location: /tmp/x509up_u106
[DEBUG] 2015-09-18 19:01:21,687 (CertificateManager:selectSession:1082) selectSession: certificate location = /tmp/x509up_u106
[DEBUG] 2015-09-18 19:01:21,690 (CertificateManager:getKeyStore:1131) getKeyStore: privateKey value: sun.security.rsa.RSAPrivateCrtKeyImpl@3b2000a5
[DEBUG] 2015-09-18 19:01:21,690 (SessionAuthorizationFilterStrategy:init:136) about to cache admin
[DEBUG] 2015-09-18 19:01:21,691 (SessionAuthorizationFilterStrategy:cacheAdministrativeSubjectList:304) AdminList entry CN=Test1,O=Test,C=US,DC=cilogon,DC=org
[DEBUG] 2015-09-18 19:01:21,696 (NodeRegistryService:listNodes:101) found 4 nodes
[DEBUG] 2015-09-18 19:01:21,743 (SessionAuthorizationFilterStrategy:init:144) init SessionAuthorizationFilter: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:21,743 (SessionAuthorizationFilterStrategy:doFilter:173) SessionAuthorizationFilterStrategy doFilter invoked by: org.dataone.solr.servlet.LogServiceSessionAuthorizationFilter
[DEBUG] 2015-09-18 19:01:21,743 (CertificateManager:getCertificate:689) javax.servlet.request.X509Certificate  = [Ljava.security.cert.X509Certificate;@320a6ef6
[DEBUG] 2015-09-18 19:01:21,744 (CertificateManager:getCertificate:692) javax.servlet.request.ssl_session  = null
[DEBUG] 2015-09-18 19:01:21,744 (CertificateManager:displayCertificate:1319) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[DEBUG] 2015-09-18 19:01:21,744 (CertificateManager:displayCertificate:1321)  Issuer: CN=TestCN,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,745 (CertificateManager:displayCertificate:1324)    From: Sep 18, 2015 7:01:21 PM
[DEBUG] 2015-09-18 19:01:21,746 (CertificateManager:displayCertificate:1326)      To: Sep 19, 2115 7:01:21 PM
[DEBUG] 2015-09-18 19:01:21,746 (CertificateManager:displayCertificate:1327) Subject: CN=TestCN,DC=dataone,DC=org
[DEBUG] 2015-09-18 19:01:21,746 (CertificateManager:displayCertificate:1334) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[DEBUG] 2015-09-18 19:01:21,747 (CertificateManager:getSubjectInfo:539) Certificate subjectInfoValue: null
[DEBUG] 2015-09-18 19:01:21,747 (SessionAuthorizationFilterStrategy:doFilter:204) Solr Session Auth found subject: CN=TestCN,DC=dataone,DC=org
[ INFO] 2015-09-18 19:01:21,749 (LogServiceSessionAuthorizationFilterTestCase:testDoAdministrativeSubjectFilter:224) testest
[ INFO] 2015-09-18 19:01:21,749 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNCore-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,751 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,753 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRead-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,754 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,756 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNAuthorization-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,757 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,759 (NodeLdapPopulation:deleteNodeServiceRestriction:151) deleting : d1ServiceMethodName=mapIdentity,d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,765 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,767 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNIdentity-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,769 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,771 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNReplication-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,772 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,774 (NodeLdapPopulation:deleteNodeService:140) deleting : d1NodeServiceId=CNRegister-v1,cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,775 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[ INFO] 2015-09-18 19:01:21,777 (NodeLdapPopulation:deleteNode:131) deleting : cn=urn:node:sqrm1,dc=dataone
[DEBUG] 2015-09-18 19:01:21,778 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:21,781 (AbstractContextSource:createContext:259) Got Ldap context on server 'ldap://localhost:389/dc=org'
[DEBUG] 2015-09-18 19:01:21,783 (DirtiesContextTestExecutionListener:afterTestMethod:86) After test method: context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase@2f122921, testMethod = testDoAdministrativeSubjectFilter@LogServiceSessionAuthorizationFilterTestCase, testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, 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] 2015-09-18 19:01:21,784 (DirtiesContextTestExecutionListener:afterTestClass:113) After test class: context [[TestContext@27b3f109 testClass = LogServiceSessionAuthorizationFilterTestCase, testInstance = [null], testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@4a6e1c9a testClass = LogServiceSessionAuthorizationFilterTestCase, locations = '{classpath:/webapp/mockController-dispatcher.xml, classpath:/webapp/mockController-beans.xml}', classes = '{}', activeProfiles = '{}', contextLoader = 'org.dataone.cn.web.mock.MockWebApplicationContextLoader']]], dirtiesContext [false].
Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.451 sec
[ INFO] 2015-09-18 19:01:21,786 (AbstractApplicationContext:doClose:1020) Closing org.springframework.web.context.support.GenericWebApplicationContext@2c11008e: startup date [Fri Sep 18 19:01:18 UTC 2015]; root of context hierarchy
[DEBUG] 2015-09-18 19:01:21,788 (AbstractBeanFactory:doGetBean:245) Returning cached instance of singleton bean 'lifecycleProcessor'
[ INFO] 2015-09-18 19:01:21,788 (DefaultSingletonBeanRegistry:destroySingletons:433) Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@7f25ab41: 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$ImportAwareBeanPostProcessor#0]; root of factory hierarchy
[DEBUG] 2015-09-18 19:01:21,788 (DefaultSingletonBeanRegistry:destroyBean:488) Retrieved dependent beans for bean 'x509CertificateGenerator': [org.dataone.solr.extensions.LogServiceSessionAuthorizationFilterTestCase]

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.2: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.0.0-SNAPSHOT.jar
[INFO] 
[INFO] --- maven-shade-plugin:2.2: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.1.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] Including commons-configuration:commons-configuration:jar:1.6 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 org.dataone:d1_libclient_java:jar:2.0.0-SNAPSHOT in the shaded jar.
[INFO] Including net.sf.jsignature.io-tools:easystream:jar:1.2.12 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 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.0.0-SNAPSHOT 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-plugin-api:jar:2.0.6 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-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:maven-artifact-manager:jar:2.0.6 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.wagon:wagon-provider-api:jar:1.0-beta-2 in the shaded jar.
[INFO] Including org.apache.maven:maven-plugin-registry:jar:2.0.6 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-model: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-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.codehaus.plexus:plexus-utils:jar:2.0.5 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_jibx_extensions:jar:1.2.0-SNAPSHOT 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 jcs:jcs:jar:1.3 in the shaded jar.
[INFO] Including commons-pool:commons-pool:jar:1.3 in the shaded jar.
[INFO] Including concurrent:concurrent:jar:1.0 in the shaded jar.
[INFO] Including mysql:mysql-connector-java:jar:3.0.10 in the shaded jar.
[INFO] Including javax.sql:jdbc-stdext:jar:2.0 in the shaded jar.
[INFO] Including javax.transaction:jta:jar:1.0.1B in the shaded jar.
[INFO] Including hsqldb:hsqldb:jar:1.7.3.3 in the shaded jar.
[INFO] Excluding javax.servlet:servlet-api:jar:2.3 from the shaded jar.
[INFO] Including tomcat:tomcat-util:jar:3.2.1 in the shaded jar.
[INFO] Including velocity:velocity:jar:1.5 in the shaded jar.
[INFO] Including oro:oro:jar:2.0.8 in the shaded jar.
[INFO] Including xmlrpc:xmlrpc:jar:2.0 in the shaded jar.
[INFO] Including berkeleydb:berkeleydb:jar:1.5.1 in the shaded jar.
[INFO] Including org.dataone:d1_cn_common:jar:2.0.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] Excluding org.slf4j:jcl-over-slf4j:jar:1.7.1 from 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 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 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.dataone:d1_identity_manager:jar:2.0.0-SNAPSHOT in the shaded jar.
[INFO] Including org.dataone:d1_cn_noderegistry:jar:2.0.0-SNAPSHOT in the shaded jar.
[INFO] Including org.apache.directory.server:apacheds-all:jar:2.0.0-M17 in the shaded jar.
[INFO] Including org.dataone:d1_portal:jar:2.0.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:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-delegation-client:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-util:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-delegation-common:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-storage:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-servlet:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security:ncsa-security-core:jar:1.0.7 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:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.myproxy:myproxy-logon:jar:1.4.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-oauth-1.0a:jar:1.0.7 in the shaded jar.
[INFO] Including edu.uiuc.ncsa.security.delegation:ncsa-security-delegation-server:jar:1.0.7 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.
[WARNING] apacheds-all-2.0.0-M17.jar, bcpkix-jdk15on-1.52.jar define 6 overlappping classes: 
[WARNING]   - org.bouncycastle.voms.VOMSAttribute
[WARNING]   - org.bouncycastle.openssl.PEMUtilities
[WARNING]   - org.bouncycastle.openssl.PasswordFinder
[WARNING]   - org.bouncycastle.mozilla.SignedPublicKeyAndChallenge
[WARNING]   - org.bouncycastle.openssl.PEMWriter
[WARNING]   - org.bouncycastle.voms.VOMSAttribute$FQAN
[WARNING] xmlrpc-2.0.jar, xmlParserAPIs-2.0.2.jar define 11 overlappping classes: 
[WARNING]   - org.xml.sax.SAXException
[WARNING]   - org.xml.sax.HandlerBase
[WARNING]   - org.xml.sax.DTDHandler
[WARNING]   - org.xml.sax.SAXParseException
[WARNING]   - org.xml.sax.ErrorHandler
[WARNING]   - org.xml.sax.AttributeList
[WARNING]   - org.xml.sax.InputSource
[WARNING]   - org.xml.sax.DocumentHandler
[WARNING]   - org.xml.sax.EntityResolver
[WARNING]   - org.xml.sax.Locator
[WARNING]   - 1 more...
[WARNING] xercesImpl-2.9.1.jar, xmlParserAPIs-2.0.2.jar define 1 overlappping classes: 
[WARNING]   - org.w3c.dom.html.HTMLDOMImplementation
[WARNING] apacheds-all-2.0.0-M17.jar, commons-pool-1.3.jar define 39 overlappping classes: 
[WARNING]   - org.apache.commons.pool.impl.StackObjectPool
[WARNING]   - org.apache.commons.pool.PoolUtils$SynchronizedKeyedObjectPool
[WARNING]   - org.apache.commons.pool.impl.GenericKeyedObjectPool$Evictor
[WARNING]   - org.apache.commons.pool.impl.GenericObjectPool$Evictor
[WARNING]   - org.apache.commons.pool.ObjectPool
[WARNING]   - org.apache.commons.pool.KeyedObjectPoolFactory
[WARNING]   - org.apache.commons.pool.BaseKeyedPoolableObjectFactory
[WARNING]   - org.apache.commons.pool.impl.GenericKeyedObjectPool$ObjectTimestampPair
[WARNING]   - org.apache.commons.pool.impl.SoftReferenceObjectPool
[WARNING]   - org.apache.commons.pool.PoolUtils$ObjectPoolAdaptor
[WARNING]   - 29 more...
[WARNING] xpp3-1.1.3.4.O.jar, stax-api-1.0.jar define 1 overlappping classes: 
[WARNING]   - javax.xml.namespace.QName
[WARNING] bcprov-jdk15on-1.52.jar, apacheds-all-2.0.0-M17.jar define 884 overlappping classes: 
[WARNING]   - org.bouncycastle.asn1.ocsp.ResponderID
[WARNING]   - org.bouncycastle.crypto.params.DSAPublicKeyParameters
[WARNING]   - org.bouncycastle.crypto.engines.DESEngine
[WARNING]   - org.bouncycastle.jce.provider.JCEElGamalPrivateKey
[WARNING]   - org.bouncycastle.i18n.filter.UntrustedInput
[WARNING]   - org.bouncycastle.asn1.x9.X962NamedCurves$5
[WARNING]   - org.bouncycastle.jce.X509KeyUsage
[WARNING]   - org.bouncycastle.asn1.pkcs.EncryptionScheme
[WARNING]   - org.bouncycastle.crypto.params.NaccacheSternKeyParameters
[WARNING]   - org.bouncycastle.asn1.pkcs.CertificationRequest
[WARNING]   - 874 more...
[WARNING] apacheds-all-2.0.0-M17.jar, antlr-2.7.5.jar define 217 overlappping classes: 
[WARNING]   - antlr.build.ANTLR$1
[WARNING]   - antlr.MismatchedTokenException
[WARNING]   - antlr.ASTVisitor
[WARNING]   - antlr.PythonBlockFinishingInfo
[WARNING]   - antlr.LLkParser
[WARNING]   - antlr.debug.misc.JTreeASTModel
[WARNING]   - antlr.FileLineFormatter
[WARNING]   - antlr.ANTLRTokdefLexer
[WARNING]   - antlr.build.Tool
[WARNING]   - antlr.debug.InputBufferListener
[WARNING]   - 207 more...
[WARNING] apacheds-all-2.0.0-M17.jar, log4j-1.2.17.jar define 314 overlappping classes: 
[WARNING]   - org.apache.log4j.net.DefaultEvaluator
[WARNING]   - org.apache.log4j.helpers.FileWatchdog
[WARNING]   - org.apache.log4j.xml.DOMConfigurator$5
[WARNING]   - org.apache.log4j.net.SyslogAppender
[WARNING]   - org.apache.log4j.chainsaw.ControlPanel$4
[WARNING]   - org.apache.log4j.chainsaw.LoggingReceiver
[WARNING]   - org.apache.log4j.NDC$DiagnosticContext
[WARNING]   - org.apache.log4j.lf5.viewer.configure.ConfigurationManager
[WARNING]   - org.apache.log4j.lf5.viewer.LogBrokerMonitor$14
[WARNING]   - org.apache.log4j.spi.ErrorHandler
[WARNING]   - 304 more...
[WARNING] concurrent-jena-1.3.2.jar, concurrent-1.0.jar define 140 overlappping classes: 
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.ClockDaemon$TaskNode
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.LinkedQueue
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.WaitableLong
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.BoundedLinkedQueue
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.PooledExecutor$DiscardOldestWhenBlocked
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.SynchronizedFloat
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.ReaderPreferenceReadWriteLock
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.PooledExecutor$AbortWhenBlocked
[WARNING]   - EDU.oswego.cs.dl.util.concurrent.ConcurrentHashMap$KeySet
[WARNING]   - 130 more...
[WARNING] apacheds-all-2.0.0-M17.jar, commons-collections-3.2.1.jar define 448 overlappping classes: 
[WARNING]   - org.apache.commons.collections.collection.TypedCollection
[WARNING]   - org.apache.commons.collections.map.AbstractHashedMap$HashEntry
[WARNING]   - org.apache.commons.collections.FastTreeMap$CollectionView$CollectionViewIterator
[WARNING]   - org.apache.commons.collections.map.ListOrderedMap$EntrySetView
[WARNING]   - org.apache.commons.collections.set.ListOrderedSet
[WARNING]   - org.apache.commons.collections.keyvalue.DefaultKeyValue
[WARNING]   - org.apache.commons.collections.collection.CompositeCollection
[WARNING]   - org.apache.commons.collections.map.AbstractReferenceMap$WeakRef
[WARNING]   - org.apache.commons.collections.list.AbstractSerializableListDecorator
[WARNING]   - org.apache.commons.collections.functors.IdentityPredicate
[WARNING]   - 438 more...
[WARNING] apacheds-all-2.0.0-M17.jar, commons-lang-2.5.jar define 132 overlappping classes: 
[WARNING]   - org.apache.commons.lang.text.StrBuilder$StrBuilderReader
[WARNING]   - org.apache.commons.lang.reflect.FieldUtils
[WARNING]   - org.apache.commons.lang.text.StrLookup$MapStrLookup
[WARNING]   - org.apache.commons.lang.math.IntRange
[WARNING]   - org.apache.commons.lang.reflect.ConstructorUtils
[WARNING]   - org.apache.commons.lang.math.RandomUtils
[WARNING]   - org.apache.commons.lang.time.FastDateFormat$TimeZoneDisplayKey
[WARNING]   - org.apache.commons.lang.time.FastDateFormat$PaddedNumberField
[WARNING]   - org.apache.commons.lang.time.StopWatch
[WARNING]   - org.apache.commons.lang.CharSet
[WARNING]   - 122 more...
[WARNING] commons-beanutils-1.8.3.jar, apacheds-all-2.0.0-M17.jar, commons-collections-3.2.1.jar define 10 overlappping classes: 
[WARNING]   - org.apache.commons.collections.FastHashMap$EntrySet
[WARNING]   - org.apache.commons.collections.ArrayStack
[WARNING]   - org.apache.commons.collections.FastHashMap$1
[WARNING]   - org.apache.commons.collections.FastHashMap$KeySet
[WARNING]   - org.apache.commons.collections.FastHashMap$CollectionView
[WARNING]   - org.apache.commons.collections.BufferUnderflowException
[WARNING]   - org.apache.commons.collections.Buffer
[WARNING]   - org.apache.commons.collections.FastHashMap$CollectionView$CollectionViewIterator
[WARNING]   - org.apache.commons.collections.FastHashMap$Values
[WARNING]   - org.apache.commons.collections.FastHashMap
[WARNING] maven-shade-plugin has detected that some .class files
[WARNING] are present in two or more JARs. When this happens, only
[WARNING] one single version of the class is copied in the uberjar.
[WARNING] Usually this is not harmful and you can skeep these
[WARNING] warnings, otherwise try to manually exclude artifacts
[WARNING] based on mvn dependency:tree -Ddetail=true and the above
[WARNING] output
[WARNING] See http://docs.codehaus.org/display/MAVENUSER/Shade+Plugin
[INFO] 
[INFO] --- maven-install-plugin:2.3:install (default-install) @ d1_solr_extensions ---
[INFO] Installing /var/lib/jenkins/jobs/d1_solr_extensions/workspace/d1_solr_extensions/target/d1_solr_extensions-2.0.0-SNAPSHOT.jar to /var/lib/jenkins/.m2/repository/org/dataone/d1_solr_extensions/2.0.0-SNAPSHOT/d1_solr_extensions-2.0.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.0.0-SNAPSHOT/d1_solr_extensions-2.0.0-SNAPSHOT.pom
[INFO] 
[INFO] --- buildnumber-maven-plugin:1.2:create (default) @ d1_solr_extensions ---
[INFO] Checking for local modifications: skipped.
[INFO] Updating project files from SCM: skipped.
[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: 16367 at timestamp: 1442602895659
[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: trunk
[WARNING] Failed to getClass for org.apache.maven.plugin.javadoc.JavadocReport
[INFO] 
[INFO] --- maven-javadoc-plugin:2.9.1:javadoc (default-cli) @ d1_solr_extensions ---
[INFO] 
Loading source files for package org.dataone.solr.response...
Loading source files for package org.dataone.solr.servlet...
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.7.0_79
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/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/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/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/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/servlet/class-use/SearchServiceSessionAuthorizationFilter.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/SessionAuthorizationUtil.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/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/QueryEngineDescriptionHandler.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/SolrSearchHandlerUtil.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/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:134: 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:171: 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:171: 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:71: 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: 37.829s
[INFO] Finished at: Fri Sep 18 19:01:41 UTC 2015
[INFO] Final Memory: 62M/449M
[INFO] ------------------------------------------------------------------------
Waiting for Jenkins to finish collecting data