We've just find the problem: mail configuration.

Correcting mail options and fixing dspace/solr/search/conf/solrconfig.xml solved the problem.

On 30-07-2014 16:08, Gustavo Tonini wrote:
I've captured the log (in DEBUG mode):


2014-07-30 15:58:50,356 INFO org.dspace.workflow.WorkflowManager @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:install_item:workflow_id=14416, item_id=127311handle=FIXME


2014-07-30 16:00:01,605 INFO org.dspace.core.ConfigurationManager @ Loading from classloader: file:/home/dspace/dspace/config/dspace.cfg 2014-07-30 16:00:01,618 INFO org.dspace.core.ConfigurationManager @ Using dspace provided log configuration (log.init.config) 2014-07-30 16:00:01,619 INFO org.dspace.core.ConfigurationManager @ Loading: /home/dspace/dspace/config/log4j.properties 2014-07-30 16:00:03,186 DEBUG net.sf.ehcache.config.ConfigurationFactory @ Configuring ehcache from InputStream 2014-07-30 16:00:03,241 DEBUG net.sf.ehcache.config.BeanHandler @ Ignoring ehcache attribute xmlns:xsi 2014-07-30 16:00:03,241 DEBUG net.sf.ehcache.config.BeanHandler @ Ignoring ehcache attribute xsi:noNamespaceSchemaLocation 2014-07-30 16:00:03,242 DEBUG net.sf.ehcache.config.DiskStoreConfiguration @ Disk Store Path: /tmp 2014-07-30 16:00:03,248 DEBUG net.sf.ehcache.config.ConfigurationHelper @ No CacheManagerEventListenerFactory class specified. Skipping... 2014-07-30 16:00:03,257 DEBUG net.sf.ehcache.config.ConfigurationHelper @ No BootstrapCacheLoaderFactory class specified. Skipping... 2014-07-30 16:00:03,257 DEBUG net.sf.ehcache.config.ConfigurationHelper @ No CacheExceptionHandlerFactory class specified. Skipping... 2014-07-30 16:00:03,260 DEBUG net.sf.ehcache.util.UpdateChecker @ Checking for update... 2014-07-30 16:00:03,489 DEBUG net.sf.ehcache.CacheManager @ CacheManager already shutdown



2014-07-30 16:03:50,444 WARN org.dspace.workflow.WorkflowManager @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:notifyOfArchive:cannot email user item_id=127311 2014-07-30 16:03:50,458 INFO org.dspace.usage.LoggerUsageEventListener @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:workflow_item:handle=123456789/122295 2014-07-30 16:03:50,466 INFO org.dspace.statistics.SolrLogger @ solr-statistics.spidersfile:null 2014-07-30 16:03:50,466 INFO org.dspace.statistics.SolrLogger @ solr-statistics.server:http://localhost:8080/solr/statistics 2014-07-30 16:03:50,466 INFO org.dspace.statistics.SolrLogger @ usage-statistics.dbfile:/home/dspace/dspace/config/GeoLiteCity.dat 2014-07-30 16:03:50,578 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection request: [route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,591 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection leased: [id: 0][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 32; total allocated: 1 of 128] 2014-07-30 16:03:50,593 DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator @ Connecting to localhost:8080 2014-07-30 16:03:50,619 DEBUG org.apache.http.client.protocol.RequestAddCookies @ CookieSpec selected: best-match 2014-07-30 16:03:50,631 DEBUG org.apache.http.client.protocol.RequestAuthCache @ Auth cache not set in the context 2014-07-30 16:03:50,632 DEBUG org.apache.http.client.protocol.RequestTargetAuthentication @ Target auth state: UNCHALLENGED 2014-07-30 16:03:50,632 DEBUG org.apache.http.client.protocol.RequestProxyAuthentication @ Proxy auth state: UNCHALLENGED 2014-07-30 16:03:50,633 DEBUG org.apache.http.impl.client.SystemDefaultHttpClient @ Attempt 1 to execute request 2014-07-30 16:03:50,633 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Sending request: GET /solr/statistics/select?q=type%3A2+AND+id%3A1&wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,633 DEBUG org.apache.http.wire @ >> "GET /solr/statistics/select?q=type%3A2+AND+id%3A1&wt=javabin&version=2 HTTP/1.1[\r][\n]" 2014-07-30 16:03:50,635 DEBUG org.apache.http.wire @ >> "User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0[\r][\n]" 2014-07-30 16:03:50,635 DEBUG org.apache.http.wire @ >> "Host: localhost:8080[\r][\n]" 2014-07-30 16:03:50,635 DEBUG org.apache.http.wire @ >> "Connection: Keep-Alive[\r][\n]"
2014-07-30 16:03:50,635 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,635 DEBUG org.apache.http.headers @ >> GET /solr/statistics/select?q=type%3A2+AND+id%3A1&wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,636 DEBUG org.apache.http.headers @ >> User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0 2014-07-30 16:03:50,636 DEBUG org.apache.http.headers @ >> Host: localhost:8080 2014-07-30 16:03:50,636 DEBUG org.apache.http.headers @ >> Connection: Keep-Alive 2014-07-30 16:03:50,660 DEBUG org.apache.http.wire @ << "HTTP/1.1 200 OK[\r][\n]" 2014-07-30 16:03:50,662 DEBUG org.apache.http.wire @ << "Server: Apache-Coyote/1.1[\r][\n]" 2014-07-30 16:03:50,662 DEBUG org.apache.http.wire @ << "Content-Type: application/octet-stream[\r][\n]" 2014-07-30 16:03:50,662 DEBUG org.apache.http.wire @ << "Content-Length: 107[\r][\n]" 2014-07-30 16:03:50,663 DEBUG org.apache.http.wire @ << "Date: Wed, 30 Jul 2014 19:03:50 GMT[\r][\n]"
2014-07-30 16:03:50,663 DEBUG org.apache.http.wire @ << "[\r][\n]"
2014-07-30 16:03:50,664 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Receiving response: HTTP/1.1 200 OK
2014-07-30 16:03:50,664 DEBUG org.apache.http.headers @ << HTTP/1.1 200 OK
2014-07-30 16:03:50,664 DEBUG org.apache.http.headers @ << Server: Apache-Coyote/1.1 2014-07-30 16:03:50,664 DEBUG org.apache.http.headers @ << Content-Type: application/octet-stream 2014-07-30 16:03:50,664 DEBUG org.apache.http.headers @ << Content-Length: 107 2014-07-30 16:03:50,665 DEBUG org.apache.http.headers @ << Date: Wed, 30 Jul 2014 19:03:50 GMT 2014-07-30 16:03:50,674 DEBUG org.apache.http.wire @ << "[0x2][0xa2][0xe0].responseHeader[0xa3][0xe0]&status[0x6][0x0][0x0][0x0][0x0][0xe0]%QTimeD[0xe0]&params[0xa3][0xe0]!q/type:2 AND id:1[0xe0]"wt'javabin[0xe0]'version!2[0xe0](response[0xc][0x83]``[0x0][0x80]" 2014-07-30 16:03:50,676 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection [id: 0][route: {}->http://localhost:8080] can be kept alive for 9223372036854775807 MILLISECONDS 2014-07-30 16:03:50,676 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Connection 0.0.0.0:43835<->127.0.0.1:8080 closed 2014-07-30 16:03:50,677 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection released: [id: 0][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,681 INFO org.dspace.statistics.SolrLogger @ useProxies=false 2014-07-30 16:03:50,735 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection request: [route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,735 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection leased: [id: 1][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 32; total allocated: 1 of 128] 2014-07-30 16:03:50,735 DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator @ Connecting to localhost:8080 2014-07-30 16:03:50,737 DEBUG org.apache.http.client.protocol.RequestAddCookies @ CookieSpec selected: best-match 2014-07-30 16:03:50,737 DEBUG org.apache.http.client.protocol.RequestAuthCache @ Auth cache not set in the context 2014-07-30 16:03:50,737 DEBUG org.apache.http.client.protocol.RequestTargetAuthentication @ Target auth state: UNCHALLENGED 2014-07-30 16:03:50,737 DEBUG org.apache.http.client.protocol.RequestProxyAuthentication @ Proxy auth state: UNCHALLENGED 2014-07-30 16:03:50,737 DEBUG org.apache.http.impl.client.SystemDefaultHttpClient @ Attempt 1 to execute request 2014-07-30 16:03:50,737 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Sending request: POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,738 DEBUG org.apache.http.wire @ >> "POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1[\r][\n]" 2014-07-30 16:03:50,738 DEBUG org.apache.http.wire @ >> "User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0[\r][\n]" 2014-07-30 16:03:50,738 DEBUG org.apache.http.wire @ >> "Transfer-Encoding: chunked[\r][\n]" 2014-07-30 16:03:50,738 DEBUG org.apache.http.wire @ >> "Content-Type: application/xml; charset=UTF-8[\r][\n]" 2014-07-30 16:03:50,738 DEBUG org.apache.http.wire @ >> "Host: localhost:8080[\r][\n]" 2014-07-30 16:03:50,739 DEBUG org.apache.http.wire @ >> "Connection: Keep-Alive[\r][\n]"
2014-07-30 16:03:50,739 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,739 DEBUG org.apache.http.headers @ >> POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,739 DEBUG org.apache.http.headers @ >> User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0 2014-07-30 16:03:50,739 DEBUG org.apache.http.headers @ >> Transfer-Encoding: chunked 2014-07-30 16:03:50,739 DEBUG org.apache.http.headers @ >> Content-Type: application/xml; charset=UTF-8 2014-07-30 16:03:50,740 DEBUG org.apache.http.headers @ >> Host: localhost:8080 2014-07-30 16:03:50,740 DEBUG org.apache.http.headers @ >> Connection: Keep-Alive
2014-07-30 16:03:50,740 DEBUG org.apache.http.wire @ >> "5c6[\r][\n]"
2014-07-30 16:03:50,741 DEBUG org.apache.http.wire @ >> "<add><doc boost="1.0"><field name="id">127311</field><field name="type">2</field><field name="owningColl">2</field><field name="owningColl">2</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="time">2014-07-30T16:03:50.701Z</field><field name="workflowStep">ARCHIVE</field><field name="previousWorkflowStep">STEP3</field><field name="workflowItemId">14416</field><field name="submitter">1</field><field name="statistics_type">workflow</field><field name="actor">1</field></doc></add>"
2014-07-30 16:03:50,741 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,741 DEBUG org.apache.http.wire @ >> "0[\r][\n]"
2014-07-30 16:03:50,741 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,838 DEBUG org.apache.http.wire @ << "HTTP/1.1 200 OK[\r][\n]" 2014-07-30 16:03:50,838 DEBUG org.apache.http.wire @ << "Server: Apache-Coyote/1.1[\r][\n]" 2014-07-30 16:03:50,838 DEBUG org.apache.http.wire @ << "Content-Type: application/octet-stream[\r][\n]" 2014-07-30 16:03:50,839 DEBUG org.apache.http.wire @ << "Content-Length: 41[\r][\n]" 2014-07-30 16:03:50,839 DEBUG org.apache.http.wire @ << "Date: Wed, 30 Jul 2014 19:03:50 GMT[\r][\n]"
2014-07-30 16:03:50,839 DEBUG org.apache.http.wire @ << "[\r][\n]"
2014-07-30 16:03:50,839 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Receiving response: HTTP/1.1 200 OK
2014-07-30 16:03:50,839 DEBUG org.apache.http.headers @ << HTTP/1.1 200 OK
2014-07-30 16:03:50,839 DEBUG org.apache.http.headers @ << Server: Apache-Coyote/1.1 2014-07-30 16:03:50,840 DEBUG org.apache.http.headers @ << Content-Type: application/octet-stream 2014-07-30 16:03:50,840 DEBUG org.apache.http.headers @ << Content-Length: 41 2014-07-30 16:03:50,840 DEBUG org.apache.http.headers @ << Date: Wed, 30 Jul 2014 19:03:50 GMT 2014-07-30 16:03:50,840 DEBUG org.apache.http.wire @ << "[0x2][0xa1][0xe0].responseHeader[0xa2][0xe0]&status[0x6][0x0][0x0][0x0][0x0][0xe0]%QTime[[0x5]" 2014-07-30 16:03:50,841 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection [id: 1][route: {}->http://localhost:8080] can be kept alive for 9223372036854775807 MILLISECONDS 2014-07-30 16:03:50,841 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Connection 0.0.0.0:43836<->127.0.0.1:8080 closed 2014-07-30 16:03:50,841 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection released: [id: 1][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,841 INFO org.dspace.workflow.WorkflowManager @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:advance_workflow:workflow_item_id=14416,item_id=127311,collection_id=2,old_state=6,new_state=7 2014-07-30 16:03:50,842 INFO org.dspace.usage.LoggerUsageEventListener @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:workflow_item:handle=123456789/122295 2014-07-30 16:03:50,874 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection request: [route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,875 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection leased: [id: 2][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 32; total allocated: 1 of 128] 2014-07-30 16:03:50,875 DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator @ Connecting to localhost:8080 2014-07-30 16:03:50,876 DEBUG org.apache.http.client.protocol.RequestAddCookies @ CookieSpec selected: best-match 2014-07-30 16:03:50,876 DEBUG org.apache.http.client.protocol.RequestAuthCache @ Auth cache not set in the context 2014-07-30 16:03:50,876 DEBUG org.apache.http.client.protocol.RequestTargetAuthentication @ Target auth state: UNCHALLENGED 2014-07-30 16:03:50,876 DEBUG org.apache.http.client.protocol.RequestProxyAuthentication @ Proxy auth state: UNCHALLENGED 2014-07-30 16:03:50,876 DEBUG org.apache.http.impl.client.SystemDefaultHttpClient @ Attempt 1 to execute request 2014-07-30 16:03:50,877 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Sending request: POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,877 DEBUG org.apache.http.wire @ >> "POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1[\r][\n]" 2014-07-30 16:03:50,877 DEBUG org.apache.http.wire @ >> "User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0[\r][\n]" 2014-07-30 16:03:50,877 DEBUG org.apache.http.wire @ >> "Transfer-Encoding: chunked[\r][\n]" 2014-07-30 16:03:50,877 DEBUG org.apache.http.wire @ >> "Content-Type: application/xml; charset=UTF-8[\r][\n]" 2014-07-30 16:03:50,877 DEBUG org.apache.http.wire @ >> "Host: localhost:8080[\r][\n]" 2014-07-30 16:03:50,878 DEBUG org.apache.http.wire @ >> "Connection: Keep-Alive[\r][\n]"
2014-07-30 16:03:50,878 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,878 DEBUG org.apache.http.headers @ >> POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,878 DEBUG org.apache.http.headers @ >> User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0 2014-07-30 16:03:50,878 DEBUG org.apache.http.headers @ >> Transfer-Encoding: chunked 2014-07-30 16:03:50,878 DEBUG org.apache.http.headers @ >> Content-Type: application/xml; charset=UTF-8 2014-07-30 16:03:50,879 DEBUG org.apache.http.headers @ >> Host: localhost:8080 2014-07-30 16:03:50,879 DEBUG org.apache.http.headers @ >> Connection: Keep-Alive
2014-07-30 16:03:50,879 DEBUG org.apache.http.wire @ >> "5c8[\r][\n]"
2014-07-30 16:03:50,880 DEBUG org.apache.http.wire @ >> "<add><doc boost="1.0"><field name="id">127311</field><field name="type">2</field><field name="owningColl">2</field><field name="owningColl">2</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="time">2014-07-30T16:03:50.858Z</field><field name="workflowStep">STEP3POOL</field><field name="previousWorkflowStep">STEP2</field><field name="workflowItemId">14416</field><field name="submitter">1</field><field name="statistics_type">workflow</field><field name="actor">1</field></doc></add>"
2014-07-30 16:03:50,880 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,882 DEBUG org.apache.http.wire @ >> "0[\r][\n]"
2014-07-30 16:03:50,882 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,885 DEBUG org.apache.http.wire @ << "HTTP/1.1 200 OK[\r][\n]" 2014-07-30 16:03:50,885 DEBUG org.apache.http.wire @ << "Server: Apache-Coyote/1.1[\r][\n]" 2014-07-30 16:03:50,886 DEBUG org.apache.http.wire @ << "Content-Type: application/octet-stream[\r][\n]" 2014-07-30 16:03:50,886 DEBUG org.apache.http.wire @ << "Content-Length: 40[\r][\n]" 2014-07-30 16:03:50,886 DEBUG org.apache.http.wire @ << "Date: Wed, 30 Jul 2014 19:03:50 GMT[\r][\n]"
2014-07-30 16:03:50,886 DEBUG org.apache.http.wire @ << "[\r][\n]"
2014-07-30 16:03:50,886 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Receiving response: HTTP/1.1 200 OK
2014-07-30 16:03:50,886 DEBUG org.apache.http.headers @ << HTTP/1.1 200 OK
2014-07-30 16:03:50,887 DEBUG org.apache.http.headers @ << Server: Apache-Coyote/1.1 2014-07-30 16:03:50,887 DEBUG org.apache.http.headers @ << Content-Type: application/octet-stream 2014-07-30 16:03:50,887 DEBUG org.apache.http.headers @ << Content-Length: 40 2014-07-30 16:03:50,887 DEBUG org.apache.http.headers @ << Date: Wed, 30 Jul 2014 19:03:50 GMT 2014-07-30 16:03:50,887 DEBUG org.apache.http.wire @ << "[0x2][0xa1][0xe0].responseHeader[0xa2][0xe0]&status[0x6][0x0][0x0][0x0][0x0][0xe0]%QTimeE" 2014-07-30 16:03:50,888 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection [id: 2][route: {}->http://localhost:8080] can be kept alive for 9223372036854775807 MILLISECONDS 2014-07-30 16:03:50,888 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Connection 0.0.0.0:43837<->127.0.0.1:8080 closed 2014-07-30 16:03:50,888 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection released: [id: 2][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,888 INFO org.dspace.workflow.WorkflowManager @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:advance_workflow:workflow_item_id=14416,item_id=127311,collection_id=2,old_state=4,new_state=7 2014-07-30 16:03:50,889 INFO org.dspace.usage.LoggerUsageEventListener @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:workflow_item:handle=123456789/122295 2014-07-30 16:03:50,923 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection request: [route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,923 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection leased: [id: 3][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 32; total allocated: 1 of 128] 2014-07-30 16:03:50,924 DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator @ Connecting to localhost:8080 2014-07-30 16:03:50,925 DEBUG org.apache.http.client.protocol.RequestAddCookies @ CookieSpec selected: best-match 2014-07-30 16:03:50,925 DEBUG org.apache.http.client.protocol.RequestAuthCache @ Auth cache not set in the context 2014-07-30 16:03:50,925 DEBUG org.apache.http.client.protocol.RequestTargetAuthentication @ Target auth state: UNCHALLENGED 2014-07-30 16:03:50,925 DEBUG org.apache.http.client.protocol.RequestProxyAuthentication @ Proxy auth state: UNCHALLENGED 2014-07-30 16:03:50,925 DEBUG org.apache.http.impl.client.SystemDefaultHttpClient @ Attempt 1 to execute request 2014-07-30 16:03:50,925 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Sending request: POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,926 DEBUG org.apache.http.wire @ >> "POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1[\r][\n]" 2014-07-30 16:03:50,926 DEBUG org.apache.http.wire @ >> "User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0[\r][\n]" 2014-07-30 16:03:50,926 DEBUG org.apache.http.wire @ >> "Transfer-Encoding: chunked[\r][\n]" 2014-07-30 16:03:50,926 DEBUG org.apache.http.wire @ >> "Content-Type: application/xml; charset=UTF-8[\r][\n]" 2014-07-30 16:03:50,926 DEBUG org.apache.http.wire @ >> "Host: localhost:8080[\r][\n]" 2014-07-30 16:03:50,926 DEBUG org.apache.http.wire @ >> "Connection: Keep-Alive[\r][\n]"
2014-07-30 16:03:50,927 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,927 DEBUG org.apache.http.headers @ >> POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,927 DEBUG org.apache.http.headers @ >> User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0 2014-07-30 16:03:50,927 DEBUG org.apache.http.headers @ >> Transfer-Encoding: chunked 2014-07-30 16:03:50,927 DEBUG org.apache.http.headers @ >> Content-Type: application/xml; charset=UTF-8 2014-07-30 16:03:50,927 DEBUG org.apache.http.headers @ >> Host: localhost:8080 2014-07-30 16:03:50,927 DEBUG org.apache.http.headers @ >> Connection: Keep-Alive
2014-07-30 16:03:50,928 DEBUG org.apache.http.wire @ >> "5c8[\r][\n]"
2014-07-30 16:03:50,928 DEBUG org.apache.http.wire @ >> "<add><doc boost="1.0"><field name="id">127311</field><field name="type">2</field><field name="owningColl">2</field><field name="owningColl">2</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="time">2014-07-30T16:03:50.906Z</field><field name="workflowStep">STEP2POOL</field><field name="previousWorkflowStep">STEP1</field><field name="workflowItemId">14416</field><field name="submitter">1</field><field name="statistics_type">workflow</field><field name="actor">1</field></doc></add>"
2014-07-30 16:03:50,929 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,929 DEBUG org.apache.http.wire @ >> "0[\r][\n]"
2014-07-30 16:03:50,929 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,933 DEBUG org.apache.http.wire @ << "HTTP/1.1 200 OK[\r][\n]" 2014-07-30 16:03:50,933 DEBUG org.apache.http.wire @ << "Server: Apache-Coyote/1.1[\r][\n]" 2014-07-30 16:03:50,934 DEBUG org.apache.http.wire @ << "Content-Type: application/octet-stream[\r][\n]" 2014-07-30 16:03:50,934 DEBUG org.apache.http.wire @ << "Content-Length: 40[\r][\n]" 2014-07-30 16:03:50,934 DEBUG org.apache.http.wire @ << "Date: Wed, 30 Jul 2014 19:03:50 GMT[\r][\n]"
2014-07-30 16:03:50,934 DEBUG org.apache.http.wire @ << "[\r][\n]"
2014-07-30 16:03:50,934 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Receiving response: HTTP/1.1 200 OK
2014-07-30 16:03:50,934 DEBUG org.apache.http.headers @ << HTTP/1.1 200 OK
2014-07-30 16:03:50,935 DEBUG org.apache.http.headers @ << Server: Apache-Coyote/1.1 2014-07-30 16:03:50,935 DEBUG org.apache.http.headers @ << Content-Type: application/octet-stream 2014-07-30 16:03:50,935 DEBUG org.apache.http.headers @ << Content-Length: 40 2014-07-30 16:03:50,935 DEBUG org.apache.http.headers @ << Date: Wed, 30 Jul 2014 19:03:50 GMT 2014-07-30 16:03:50,935 DEBUG org.apache.http.wire @ << "[0x2][0xa1][0xe0].responseHeader[0xa2][0xe0]&status[0x6][0x0][0x0][0x0][0x0][0xe0]%QTimeD" 2014-07-30 16:03:50,936 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection [id: 3][route: {}->http://localhost:8080] can be kept alive for 9223372036854775807 MILLISECONDS 2014-07-30 16:03:50,936 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Connection 0.0.0.0:43838<->127.0.0.1:8080 closed 2014-07-30 16:03:50,936 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection released: [id: 3][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,936 INFO org.dspace.workflow.WorkflowManager @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:advance_workflow:workflow_item_id=14416,item_id=127311,collection_id=2,old_state=2,new_state=7 2014-07-30 16:03:50,937 INFO org.dspace.usage.LoggerUsageEventListener @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:workflow_item:handle=123456789/122295 2014-07-30 16:03:50,971 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection request: [route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,972 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection leased: [id: 4][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 32; total allocated: 1 of 128] 2014-07-30 16:03:50,972 DEBUG org.apache.http.impl.conn.DefaultClientConnectionOperator @ Connecting to localhost:8080 2014-07-30 16:03:50,973 DEBUG org.apache.http.client.protocol.RequestAddCookies @ CookieSpec selected: best-match 2014-07-30 16:03:50,973 DEBUG org.apache.http.client.protocol.RequestAuthCache @ Auth cache not set in the context 2014-07-30 16:03:50,973 DEBUG org.apache.http.client.protocol.RequestTargetAuthentication @ Target auth state: UNCHALLENGED 2014-07-30 16:03:50,973 DEBUG org.apache.http.client.protocol.RequestProxyAuthentication @ Proxy auth state: UNCHALLENGED 2014-07-30 16:03:50,973 DEBUG org.apache.http.impl.client.SystemDefaultHttpClient @ Attempt 1 to execute request 2014-07-30 16:03:50,974 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Sending request: POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,974 DEBUG org.apache.http.wire @ >> "POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1[\r][\n]" 2014-07-30 16:03:50,974 DEBUG org.apache.http.wire @ >> "User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0[\r][\n]" 2014-07-30 16:03:50,974 DEBUG org.apache.http.wire @ >> "Transfer-Encoding: chunked[\r][\n]" 2014-07-30 16:03:50,974 DEBUG org.apache.http.wire @ >> "Content-Type: application/xml; charset=UTF-8[\r][\n]" 2014-07-30 16:03:50,975 DEBUG org.apache.http.wire @ >> "Host: localhost:8080[\r][\n]" 2014-07-30 16:03:50,975 DEBUG org.apache.http.wire @ >> "Connection: Keep-Alive[\r][\n]"
2014-07-30 16:03:50,975 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,975 DEBUG org.apache.http.headers @ >> POST /solr/statistics/update?wt=javabin&version=2 HTTP/1.1 2014-07-30 16:03:50,975 DEBUG org.apache.http.headers @ >> User-Agent: Solr[org.apache.solr.client.solrj.impl.HttpSolrServer] 1.0 2014-07-30 16:03:50,975 DEBUG org.apache.http.headers @ >> Transfer-Encoding: chunked 2014-07-30 16:03:50,975 DEBUG org.apache.http.headers @ >> Content-Type: application/xml; charset=UTF-8 2014-07-30 16:03:50,976 DEBUG org.apache.http.headers @ >> Host: localhost:8080 2014-07-30 16:03:50,976 DEBUG org.apache.http.headers @ >> Connection: Keep-Alive
2014-07-30 16:03:50,976 DEBUG org.apache.http.wire @ >> "5c9[\r][\n]"
2014-07-30 16:03:50,976 DEBUG org.apache.http.wire @ >> "<add><doc boost="1.0"><field name="id">127311</field><field name="type">2</field><field name="owningColl">2</field><field name="owningColl">2</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="owningComm">33</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">32</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">4</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">5</field><field name="owningComm">1</field><field name="owningComm">1</field><field name="time">2014-07-30T16:03:50.954Z</field><field name="workflowStep">STEP1POOL</field><field name="previousWorkflowStep">SUBMIT</field><field name="workflowItemId">14416</field><field name="submitter">1</field><field name="statistics_type">workflow</field><field name="actor">1</field></doc></add>"
2014-07-30 16:03:50,977 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,977 DEBUG org.apache.http.wire @ >> "0[\r][\n]"
2014-07-30 16:03:50,977 DEBUG org.apache.http.wire @ >> "[\r][\n]"
2014-07-30 16:03:50,981 DEBUG org.apache.http.wire @ << "HTTP/1.1 200 OK[\r][\n]" 2014-07-30 16:03:50,981 DEBUG org.apache.http.wire @ << "Server: Apache-Coyote/1.1[\r][\n]" 2014-07-30 16:03:50,981 DEBUG org.apache.http.wire @ << "Content-Type: application/octet-stream[\r][\n]" 2014-07-30 16:03:50,982 DEBUG org.apache.http.wire @ << "Content-Length: 40[\r][\n]" 2014-07-30 16:03:50,982 DEBUG org.apache.http.wire @ << "Date: Wed, 30 Jul 2014 19:03:50 GMT[\r][\n]"
2014-07-30 16:03:50,982 DEBUG org.apache.http.wire @ << "[\r][\n]"
2014-07-30 16:03:50,982 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Receiving response: HTTP/1.1 200 OK
2014-07-30 16:03:50,982 DEBUG org.apache.http.headers @ << HTTP/1.1 200 OK
2014-07-30 16:03:50,982 DEBUG org.apache.http.headers @ << Server: Apache-Coyote/1.1 2014-07-30 16:03:50,982 DEBUG org.apache.http.headers @ << Content-Type: application/octet-stream 2014-07-30 16:03:50,983 DEBUG org.apache.http.headers @ << Content-Length: 40 2014-07-30 16:03:50,983 DEBUG org.apache.http.headers @ << Date: Wed, 30 Jul 2014 19:03:50 GMT 2014-07-30 16:03:50,983 DEBUG org.apache.http.wire @ << "[0x2][0xa1][0xe0].responseHeader[0xa2][0xe0]&status[0x6][0x0][0x0][0x0][0x0][0xe0]%QTimeD" 2014-07-30 16:03:50,983 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection [id: 4][route: {}->http://localhost:8080] can be kept alive for 9223372036854775807 MILLISECONDS 2014-07-30 16:03:50,983 DEBUG org.apache.http.impl.conn.DefaultClientConnection @ Connection 0.0.0.0:43839<->127.0.0.1:8080 closed 2014-07-30 16:03:50,983 DEBUG org.apache.http.impl.conn.PoolingClientConnectionManager @ Connection released: [id: 4][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 32; total allocated: 0 of 128] 2014-07-30 16:03:50,984 INFO org.dspace.workflow.WorkflowManager @ [email protected]:session_id=9D4F509898E04731DA7C7C8BC183F90A:advance_workflow:workflow_item_id=14416,item_id=127311,collection_id=2,old_state=0,new_state=7 2014-07-30 16:03:51,465 INFO org.dspace.search.DSIndexer @ Writing Item: 123456789/122295 to Index 2014-07-30 16:03:51,485 INFO org.dspace.search.DSIndexer @ Wrote Item: 123456789/122295 to Index 2014-07-30 16:03:51,707 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore hit for PK_G-file-jndi:/localhost/xmlui/aspects/protodocument.xml 2014-07-30 16:03:51,708 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/9/handle/123456789/8/submit/completedStep?pipelinehash=-3983196624749804755_T-Navigation--6111670531050322356 2014-07-30 16:03:51,709 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/8/handle/123456789/8/submit/completedStep?pipelinehash=-2049808326151556963_T-Navigation--6111670531050322356 2014-07-30 16:03:51,711 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/7/handle/123456789/8/submit/completedStep?pipelinehash=4289157564807071806_T-Navigation--6111670531050322356 2014-07-30 16:03:51,712 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/6/handle/123456789/8/submit/completedStep?pipelinehash=-5411568181926810284_T-SystemwideAlerts-1_T-Navigation-3456633283411155094 2014-07-30 16:03:51,767 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/5/handle/123456789/8/submit/completedStep?pipelinehash=-3512701886174954582_T-Navigation--789524589071168455 2014-07-30 16:03:51,771 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/4/handle/123456789/8/submit/completedStep?pipelinehash=-6287374736287972987_T-Navigation-1 2014-07-30 16:03:51,772 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/3/handle/123456789/8/submit/6e4a645474155169728655544f19176960548823.continue 2014-07-30 16:03:51,772 DEBUG net.sf.ehcache.Cache @ cocoon-ehcache cache - Miss 2014-07-30 16:03:51,772 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/2/handle/123456789/8/submit/6e4a645474155169728655544f19176960548823.continue 2014-07-30 16:03:51,773 DEBUG net.sf.ehcache.Cache @ cocoon-ehcache cache - Miss 2014-07-30 16:03:51,773 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-aspect-cocoon://DRI/1/handle/123456789/8/submit/6e4a645474155169728655544f19176960548823.continue_T-PageNotFound-8960754655913467056 2014-07-30 16:03:51,773 DEBUG net.sf.ehcache.Cache @ cocoon-ehcache cache - Miss 2014-07-30 16:03:51,775 DEBUG net.sf.ehcache.Cache @ cocoon-ehcacheCache: cocoon-ehcacheMemoryStore miss for PK_G-file-cocoon://DRI/handle/123456789/8/submit/6e4a645474155169728655544f19176960548823.continue_T-IncludePageMeta-8290317048305919140_T-IncludePageMeta--2223765811167872118_T-xslt-jndi:/localhost/xmlui/themes/UFSC/UFSC.xsl_T-i18n-context://i18n/?pt_BR__T-NamespaceFilter-http://di.tamu.edu/DRI/1.0/_T-NamespaceFilter-http://apache.org/cocoon/i18n/2.1_S-xhtml-;doctype-public=-//W3C//DTD XHTML 1.0 Strict//EN;doctype-system=http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd;encoding=UTF-8;indent=yes 2014-07-30 16:03:51,775 DEBUG net.sf.ehcache.Cache @ cocoon-ehcache cache - Miss



On 30-07-2014 15:45, Gustavo Tonini wrote:
Dear Bram, Victor and all,

We're facing the same problem: dspace submition is taking about 5 minutes to complete in dspace 4.1.

I've already applied the workaround: changing dspace/solr/search/conf/solrconfig.xml line to "buildOnOptimize" but the problem persists.

We also tried to update to version 4.2 on a test environment but the problem persists.

Our dspace database has about 50K itens.

Have you any suggestions?

  -----------------------------------------------
  Gustavo Tonini

   Analista de Tecnologia da Informação
   Departamento de Tecnologia da Informação e de Redes
   Superint. de Governança Eletrônica e Tec. da Inform. e Comunic. -
  SETIC
   Universidade Federal de Santa Catarina - UFSC
  -----------------------------------------------


------------------------------------------------------------------------------
Infragistics Professional
Build stunning WinForms apps today!
Reboot your WinForms applications with our WinForms controls.
Build a bridge from your legacy apps to the future.
http://pubads.g.doubleclick.net/gampad/clk?id=153845071&iu=/4140/ostg.clktrk


_______________________________________________
DSpace-tech mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/dspace-tech
List Etiquette:https://wiki.duraspace.org/display/DSPACE/Mailing+List+Etiquette


--

  -----------------------------------------------
  Gustavo Tonini

   Analista de Tecnologia da Informação
   Departamento de Tecnologia da Informação e de Redes
   Superint. de Governança Eletrônica e Tec. da Inform. e Comunic. -
  SETIC
   Universidade Federal de Santa Catarina - UFSC
  -----------------------------------------------


------------------------------------------------------------------------------
Infragistics Professional
Build stunning WinForms apps today!
Reboot your WinForms applications with our WinForms controls.
Build a bridge from your legacy apps to the future.
http://pubads.g.doubleclick.net/gampad/clk?id=153845071&iu=/4140/ostg.clktrk


_______________________________________________
DSpace-tech mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/dspace-tech
List Etiquette: https://wiki.duraspace.org/display/DSPACE/Mailing+List+Etiquette


--

 -----------------------------------------------
 Gustavo Tonini

  Analista de Tecnologia da Informação
  Departamento de Tecnologia da Informação e de Redes
  Superint. de Governança Eletrônica e Tec. da Inform. e Comunic. -
 SETIC
  Universidade Federal de Santa Catarina - UFSC
 -----------------------------------------------

------------------------------------------------------------------------------
Infragistics Professional
Build stunning WinForms apps today!
Reboot your WinForms applications with our WinForms controls. 
Build a bridge from your legacy apps to the future.
http://pubads.g.doubleclick.net/gampad/clk?id=153845071&iu=/4140/ostg.clktrk
_______________________________________________
DSpace-tech mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/dspace-tech
List Etiquette: https://wiki.duraspace.org/display/DSPACE/Mailing+List+Etiquette

Reply via email to