Galaxy: Unable to reload data_table.

[FredericBGA]

I notice that watch_tool_data_dir does not work (galaxy 19-01).
(watchdog is installed and watch_tools works, it takes a bit more than one minute to reload the toolbox, but it works)

I notice then that the reload button in /admin/data_tables does not work.
Even when I try to access data /data_manager/reload_tool_data_table?table_name=all_fasta data are not reloaded.
If I reboot Galaxy, data are reloaded.

maybe related to #7564

[selten]

Out of curiosity (from what I noticed), do you have more than 1 processes and/or more than 1 thread in the uWSGI settings?

Because in my case, I checked the log files and saw that the tool data watcher is actually picking it up, however it doesn't seem to cascade through Galaxy correctly. So other processes and threads wouldn't have the updated data, therefore appearing as not being functional, even though it was working.

[FredericBGA]

I do:

processes: 4
threads: 8
offload-threads: 4

[selten]

So, for a test what I did was scale both the processes and threads down to 1 each.
This might help (although it slows Galaxy down a lot). Then, if my theory is correct, it should work again when accessing those things (e.g. reload button) and the data should start showing up.

[dannon]

The reload should work now with #7548 please reopen if you still have issues. (edit: correct issue linked now)

[FredericBGA]

The reload should work now with #7564; please reopen if you still have issues.

This is still the same behavior. The reload button as no action.

[mvdbeek]

This is targeting 19.05.

[FredericBGA]

This is targeting 19.05.

ok, it's fine. I've tried to fetch the code of #7565 and then the whole dev branch.

It's not a big deal, it's a bit annoying because we won't be able to reload a .loc file during the day if we need to add a blast databank. I could wait for 19.05
thank you!

[mvdbeek]

That's not the right PR, but if you want to try https://github.com/galaxyproject/galaxy/pull/7548 on 19.01 and if it works fine we can consider backporting it.

[mvdbeek]

Actually this involves an additional database migration, I think we want to avoid backporting that PR, migrations should be limited to releases I think.

[FredericBGA]

That's not the right PR, but if you want to try #7548 on 19.01 and if it works fine we can consider backporting it.

sorry, misspelling..., I really tried #7548:

git fetch origin refs/pull/7548/head:pr-7548
git checkout pr-7548

And I had to upgrade the database to version 0151. And the reload button was not working neither (and my jobs where then stuck with python metadata/set.py that never ends...`

I'm back with release_19.01, and it's fine (except the reload button, I will wait for 19.05). Thank you.

[FredericBGA]

Actually this involves an additional database migration, I think we want to avoid backporting that PR, migrations should be limited to releases I think.

I agree, it's not blocking.

[mvdbeek]

And the reload button was not working neither (and my jobs where then stuck with python metadata/set.py that never ends...`

What were the symptoms of this ? The reload button does work for me, if you try this you should see something like

galaxy.queue_worker INFO 2019-04-04 14:08:01,778 [p:22997,w:0,m:2] [Thread-2] Instance 'main.job-handlers.2' received 'reload_tool_data_tables' task, executing now.
galaxy.queue_worker INFO 2019-04-04 14:08:01,697 [p:22998,w:0,m:3] [Thread-2] Instance 'main.job-handlers.3' received 'reload_tool_data_tables' task, executing now.
galaxy.queue_worker INFO 2019-04-04 14:08:02,462 [p:22992,w:1,m:0] [Thread-1] Instance 'main.web.1' received 'reload_tool_data_tables' task, executing now.
galaxy.queue_worker DEBUG 2019-04-04 14:08:02,463 [p:22992,w:1,m:0] [Thread-1] Executing tool data table reload for all tables
galaxy.queue_worker INFO 2019-04-04 14:08:02,464 [p:22994,w:3,m:0] [Thread-1] Instance 'main.web.3' received 'reload_tool_data_tables' task, executing now.
galaxy.queue_worker DEBUG 2019-04-04 14:08:02,464 [p:22994,w:3,m:0] [Thread-1] Executing tool data table reload for all tables
galaxy.queue_worker INFO 2019-04-04 14:08:02,468 [p:22995,w:4,m:0] [Thread-1] Instance 'main.web.4' received 'reload_tool_data_tables' task, executing now.
galaxy.queue_worker DEBUG 2019-04-04 14:08:02,469 [p:22995,w:4,m:0] [Thread-1] Executing tool data table reload for all tables

For each process that is serving requests or handling jobs.

[FredericBGA]

@mvdbeek I re-open this. My dev is now under 19_05 and the issue is still here.

On this page when I hit the reload button, it doesn't reload the data:
https://galaxydev.biogemma.fr/admin/data_tables

I can see in the log:

192.168.29.12 - - [24/Jun/2019:15:36:20 +0200] "GET /data_manager/reload_tool_data_table?table_name=all_fasta HTTP/1.1" 302 509 "https://galaxydev.biogemma.fr/admin/data_tables" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"
[pid: 27737|app: 0|req: 16/40] 192.168.29.12 () {64 vars in 1493 bytes} [Mon Jun 24 15:36:20 2019] GET /data_manager/reload_tool_data_table?table_name=all_fasta => generated 509 bytes in 17 msecs (HTTP/1.1 302) 4 headers in 279 bytes (1 switches on core 6)
192.168.29.12 - - [24/Jun/2019:15:36:20 +0200] "GET /data_manager/tool_data_table_items?status=done&table_name=all_fasta&message=The+data+table+%22all_fasta%22+has+been+reloaded. HTTP/1.1" 200 - "https://galaxydev.biogemma.fr/admin/data_tables" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"
[pid: 27747|app: 0|req: 9/41] 192.168.29.12 () {64 vars in 1628 bytes} [Mon Jun 24 15:36:20 2019] GET /data_manager/tool_data_table_items?status=done&table_name=all_fasta&message=The+data+table+%22all_fasta%22+has+been+reloaded. => generated 58663 bytes in 26 msecs (HTTP/1.1 200) 2 headers in 95 bytes (1 switches on core 0)

On this page, I don't see the updated value of the file (if I insert a new line manually):
https://galaxydev.biogemma.fr/data_manager/tool_data_table_items?status=done&table_name=all_fasta&message=The+data+table+%22all_fasta%22+has+been+reloaded.

I can see in the log:

192.168.29.12 - - [24/Jun/2019:15:35:14 +0200] "GET /data_manager/tool_data_table_items?status=done&table_name=all_fasta&message=The+data+table+%22all_fasta%22+has+been+reloaded. HTTP/1.1" 200 - "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"
[pid: 27737|app: 0|req: 9/33] 192.168.29.12 () {66 vars in 1661 bytes} [Mon Jun 24 15:35:14 2019] GET /data_manager/tool_data_table_items?status=done&table_name=all_fasta&message=The+data+table+%22all_fasta%22+has+been+reloaded. => generated 58663 bytes in 27 msecs (HTTP/1.1 200) 2 headers in 95 bytes (1 switches on core 0)

[mvdbeek]

I really can't reproduce this. At the very minimum you should be seeing Sending reload_tool_data_tables control task. in the logs. If that is the case (and it really must be) the only other reason I could imagine is if all your web handlers have the same name.
fwiw this is what I see on the handler named xxx0 (started with ./scripts/galaxy-main -c config/galaxy.yml --server-name xxx0):

galaxy.queue_worker INFO 2019-06-24 16:06:52,073 Instance 'xxx0' received 'reload_tool_data_tables' task, executing now.
galaxy.queue_worker DEBUG 2019-06-24 16:06:52,073 Executing tool data table reload for all tables
galaxy.tools.data DEBUG 2019-06-24 16:06:52,079 Loaded 0 lines from '/Users/mvandenb/src/galaxy/tool-data/toolshed.g2.bx.psu.edu/repos/devteam/bwa/4d82cf59895e/bwa_mem_index.loc' for 'bwa_mem_indexes'
galaxy.tools.data DEBUG 2019-06-24 16:06:52,079 Loaded 0 lines from '/Users/mvandenb/src/galaxy/tool-data/toolshed.g2.bx.psu.edu/repos/devteam/bwa/4d82cf59895e/bwa_mem_index.loc' for 'bwa_mem_indexes'
galaxy.tools.data DEBUG 2019-06-24 16:06:52,080 Loaded 2 lines from '/Users/mvandenb/src/tool-data/toolshed.g2.bx.psu.edu/repos/devteam/data_manager_bwa_mem_index_builder/46066df8813d/bwa_mem_index.loc' for 'bwa_mem_indexes'
galaxy.tools.data DEBUG 2019-06-24 16:06:52,080 Loaded 2 lines from '/Users/mvandenb/src/tool-data/toolshed.g2.bx.psu.edu/repos/devteam/data_manager_bwa_mem_index_builder/46066df8813d/bwa_mem_index.loc' for 'bwa_mem_indexes'
galaxy.tools.data DEBUG 2019-06-24 16:06:52,080 Attempted to add fields (['saccer10', 'saccer10', 'saccer10', '/Users/mvandenb/src/tool-data/saccer10/bwa_mem_index/saccer10/saccer10.fa']) to data table 'bwa_mem_indexes', but this entry already exists and allow_duplicates is False.
galaxy.tools.data DEBUG 2019-06-24 16:06:52,080 Attempted to add fields (['with+key', 'with+key', 'with+key', '/Users/mvandenb/src/tool-data/with+key/bwa_mem_index/with+key/with+key.fa']) to data table 'bwa_mem_indexes', but this entry already exists and allow_duplicates is False.
galaxy.tools.data DEBUG 2019-06-24 16:06:52,080 Reloaded tool data table 'bwa_mem_indexes' from files.
galaxy.queue_worker DEBUG 2019-06-24 16:06:52,080 Finished data table reload for ['bwa_mem_indexes']

[mvdbeek]

It might be interesting to see how you start Galaxy.

[FredericBGA]

@mvdbeek
sample of my galaxy.yml file
init.d script

[mvdbeek]

Can you also include the startup log please?

[FredericBGA]

server startup log

[mvdbeek]

This all looks correct, there's no name conflict, I'm seeing

galaxy.queue_worker INFO 2019-06-24 15:27:18,439 [p:25698,w:2,m:0] [MainThread] Binding and starting galaxy control worker for main.web.2
galaxy.queue_worker INFO 2019-06-24 15:27:18,477 [p:25703,w:3,m:0] [MainThread] Binding and starting galaxy control worker for main.web.3

etc.

What is missing from the logs as far as I can see is Sending reload_tool_data_tables control task. ... is that really completely absent from your logs ?

[mvdbeek]

It might also be helpful to check that your server processes are reporting themselves in the database.
With your Galaxy's virtualenv activated you can do

python -i scripts/db_shell.py -c config/galaxy.yml

>>> for wp in sa_session.query(WorkerProcess).all():
...     print(wp.server_name, wp.update_time)
...

[FredericBGA]

for wp in sa_session.query(WorkerProcess).all():
... print(wp.server_name, wp.update_time)
...
main.web.2 2019-06-25 15:01:28.352285
main.web.3 2019-06-25 15:01:28.400902
main.web.4 2019-06-25 15:01:28.401917
main.web.1 2019-06-25 15:01:28.430597
main.job-handlers.3 2019-06-25 15:00:53.990658
main.job-handlers.1 2019-06-25 15:00:54.068512
main.job-handlers.4 2019-06-25 15:00:54.990208
main.job-handlers.2 2019-06-25 15:00:55.066853

And about reload_tool_data_table

-rw-r--r-- 1 galaxymgr webmgr 6 25 juin 11:47 galaxy-dev.pid
-rw-r--r-- 1 galaxymgr webmgr 1723901 25 juin 16:24 galaxy_web_0.log
-rw-rw-rw- 1 galaxymgr webmgr 2567711 25 juin 16:55 galaxy_job-handlers_3.log
-rw-rw-rw- 1 galaxymgr webmgr 1948781 25 juin 16:56 galaxy_job-handlers_1.log
-rw-rw-rw- 1 galaxymgr webmgr 1948865 25 juin 16:58 galaxy_job-handlers_4.log
-rw-rw-rw- 1 galaxymgr webmgr 1930402 25 juin 16:58 galaxy_job-handlers_2.log
-rw-r----- 1 galaxymgr webmgr 44013143 25 juin 17:03 galaxy-dev.log
(.venv) galaxymgr@sxgalaxyx64d 17:03:07 /var/log/galaxy >grep reload_tool_data_table *log
galaxy-dev.log:192.168.29.12 - - [25/Jun/2019:17:05:41 +0200] "GET /data_manager/reload_tool_data_table?table_name=all_fasta HTTP/1.1" 302 509 "https://galaxydev.biogemma.fr/admin/data_tables" "Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:67.0) Gecko/20100101 Firefox/67.0"
galaxy-dev.log:[pid: 11806|app: 0|req: 4627/18528] 192.168.29.12 () {64 vars in 1493 bytes} [Tue Jun 25 17:05:41 2019] GET /data_manager/reload_tool_data_table?table_name=all_fasta => generated 509 bytes in 22 msecs (HTTP/1.1 302) 4 headers in 279 bytes (1 switches on core 7)
(.venv) galaxymgr@sxgalaxyx64d 17:03:16 /var/log/galaxy >

Maybe a problem with Apache and proxy?

[mvdbeek]

Oh, good catch, this should be a POST. Is there maybe some redirect happening ? I feel like I've seen something like that before.

[mvdbeek]

This is probably a red herring, this is a GET for me as well, we're not limiting the type of request for this controller endpoint.

[FredericBGA]

I share my Apache configuration for Galaxy.
It's based on this doc
I'm not a specialist of Apache so maybe there is something obviously wrong!

ie:

Redirect permanent / https://galaxydev.biogemma.fr
\

I don't remember why this is here. I can't see it in the doc