Starting server in PID 8200.
serving on http://192.168.109.104:8080
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/sql/default_comparator.py:153: SAWarning: The IN-predicate on "request_type.id" was invoked with an empty sequence. This results in a contradiction, which nonetheless can be expensive to evaluate.  Consider alternative strategies for improved performance.
  'strategies for improved performance.' % expr)
192.168.29.12 - - [30/mars/2016:09:00:05 +0200] "GET / HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:07 +0200] "GET /api/genomes HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:07 +0200] "GET /api/datatypes?extension_only=False HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:07 +0200] "GET /welcome HTTP/1.1" 302 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:07 +0200] "GET /history/current_history_json HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:07 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:07 +0200] "GET /api/histories/516029205570d9d3?keys=size%2Cnon_ready_jobs HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
galaxy.tools DEBUG 2016-03-30 09:00:30,881 Validated and populated state for tool request (58.668 ms)
galaxy.tools.actions.upload DEBUG 2016-03-30 09:00:30,976 Persisted uploads (36.999 ms)
galaxy.tools.actions.upload DEBUG 2016-03-30 09:00:31,358 Checked and cleaned uploads (381.470 ms)
galaxy.tools.actions.upload_common INFO 2016-03-30 09:00:31,467 tool upload1 created job id 32
galaxy.tools.actions.upload DEBUG 2016-03-30 09:00:31,568 Created upload job (210.309 ms)
galaxy.tools.execute DEBUG 2016-03-30 09:00:31,568 Tool [upload1] created job [32] (629.664 ms)
galaxy.tools.execute DEBUG 2016-03-30 09:00:31,588 Executed 1 job(s) for tool upload1 request: (707.498 ms)
192.168.29.12 - - [30/mars/2016:09:00:30 +0200] "POST /api/tools HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
192.168.29.12 - - [30/mars/2016:09:00:31 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
galaxy.jobs DEBUG 2016-03-30 09:00:31,977 (32) Working directory for job is: /softs/bioinfo/galaxy-prod/database/job_working_directory/000/32
galaxy.jobs.handler DEBUG 2016-03-30 09:00:31,987 (32) Dispatching to local runner
galaxy.jobs DEBUG 2016-03-30 09:00:32,093 (32) Persisting job destination (destination id: local)
galaxy.jobs.runners DEBUG 2016-03-30 09:00:32,106 Job [32] queued (119.462 ms)
galaxy.jobs.handler INFO 2016-03-30 09:00:32,119 (32) Job dispatched
galaxy.jobs.command_factory INFO 2016-03-30 09:00:32,467 Built script [/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/tool_script.sh] for tool command[python /softs/bioinfo/galaxy-prod/tools/data_source/upload.py /softs/bioinfo/galaxy-prod /softs/bioinfo/galaxy-prod/database/tmp/tmpN3_gMs /softs/bioinfo/galaxy-prod/database/tmp/tmpKxx12Y 32:/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/dataset_32_files:/softs/bioinfo/galaxy-prod/database/files/000/dataset_32.dat]
galaxy.jobs.runners DEBUG 2016-03-30 09:00:32,811 (32) command is: mkdir -p working; cd working; /softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/tool_script.sh; return_code=$?; cd ..; python "/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/set_metadata_Kty5hW.py" "/softs/bioinfo/galaxy-prod/database/tmp/tmpN3_gMs" "/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/working/galaxy.json" "/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/metadata_in_HistoryDatasetAssociation_32_JRWq3L,/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/metadata_kwds_HistoryDatasetAssociation_32_HLzzvk,/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/metadata_out_HistoryDatasetAssociation_32_cRsPCS,/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/metadata_results_HistoryDatasetAssociation_32_D3EmKc,/softs/bioinfo/galaxy-prod/database/files/000/dataset_32.dat,/softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/metadata_override_HistoryDatasetAssociation_32_elSKUI" 5242880; sh -c "exit $return_code"
galaxy.jobs.runners.local DEBUG 2016-03-30 09:00:32,841 (32) executing job script: /softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/galaxy_32.sh
galaxy.jobs DEBUG 2016-03-30 09:00:32,860 (32) Persisting job destination (destination id: local)
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:14:39.344Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:00:35 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A14%3A39.344Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
galaxy.jobs.runners.local DEBUG 2016-03-30 09:00:38,896 execution finished: /softs/bioinfo/galaxy-prod/database/job_working_directory/000/32/galaxy_32.sh
galaxy.model.metadata DEBUG 2016-03-30 09:00:39,062 loading metadata from file for: HistoryDatasetAssociation 32
galaxy.jobs INFO 2016-03-30 09:00:39,383 Collecting metrics for Job 32
galaxy.jobs DEBUG 2016-03-30 09:00:39,403 job 32 ended (finish() executed in (507.021 ms))
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:14:43.547Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:00:39 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A14%3A43.547Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:14:47.662Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:00:44 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A14%3A47.662Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:14:51.780Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:00:48 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A14%3A51.780Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:14:55.875Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:00:52 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A14%3A55.875Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:14:59.993Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:00:56 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A14%3A59.993Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:15:04.115Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:01:00 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A15%3A04.115Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"
/softs/bioinfo/galaxy-prod/.venv/lib/python2.7/site-packages/sqlalchemy/engine/default.py:450: Warning: Incorrect datetime value: '2016-03-30 07:15:08.248Z' for column 'update_time' at row 33
  cursor.execute(statement, parameters)
192.168.29.12 - - [30/mars/2016:09:01:04 +0200] "GET /api/histories/516029205570d9d3/contents?v=dev&q=update_time-ge&qv=2016-03-30T07%3A15%3A08.248Z HTTP/1.1" 200 - "http://192.168.109.104/" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:38.0) Gecko/20100101 Firefox/38.0"