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]¶ms[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