search

hanami / cli

Hanami command line
MIT License
27 stars 28 forks source link

`hanami server` not taking into account `activate_control_app` option supported by Puma config #83

Open jiggneshhgohel opened 1 year ago

jiggneshhgohel commented 1 year ago

ruby 3.1.2 puma (6.2.2) hanami (2.0.3) hanami-cli (2.0.3) rack (2.2.7)

Following shown is my Puma config file containing my custom changes:

config/puma.rb

# frozen_string_literal: true

max_threads_count = ENV.fetch("HANAMI_MAX_THREADS", 5)
min_threads_count = ENV.fetch("HANAMI_MIN_THREADS") { max_threads_count }
threads min_threads_count, max_threads_count

#port        ENV.fetch("HANAMI_PORT", 2300) 
port        ENV.fetch("HANAMI_PORT", 2400) # Note this change
activate_control_app ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01:9294") # Note this change
environment ENV.fetch("HANAMI_ENV", "development")
workers     ENV.fetch("HANAMI_WEB_CONCURRENCY", 2)

on_worker_boot do
  Hanami.shutdown
end

preload_app!

When I start the server using hanami server following are the logs

my_api$ bundle exec hanami server
13:20:22 - INFO - Using Guardfile at /.../my_api/Guardfile.
13:20:22 - INFO - Puma starting on port 2300 in development environment.
13:20:22 - INFO - Guard is now watching at ' /.../my_api/'
[9743] Puma starting in cluster mode...
[9743] * Puma version: 6.2.1 (ruby 3.1.2-p20) ("Speaking of Now")
[9743] *  Min threads: 5
[9743] *  Max threads: 5
[9743] *  Environment: development
[9743] *   Master PID: 9743
[9743] *      Workers: 2
[9743] *     Restarts: (✔) hot (✖) phased
[9743] * Preloading application
[9743] * Listening on http://0.0.0.0:2400
[9743] Use Ctrl-C to stop
[9743] * Starting control server on http://127.0.0.1:9293
[9743] * Starting control server on http://[::1]:9293
[9743] - Worker 0 (PID: 9749) booted in 0.0s, phase: 0
[9743] - Worker 1 (PID: 9750) booted in 0.0s, phase: 0

From above it is clear that port option change is picked up but the activate_control_app option specified is not taken into account which is evident from following in the logs:

[9743] * Starting control server on http://127.0.0.1:9293
[9743] * Starting control server on http://[::1]:9293

Also one more thing I noticed related to port is the following inconsistency:

13:20:22 - INFO - Puma starting on port 2300 in development environment.
....
....
[9743] * Listening on http://0.0.0.0:2400

Coming back to my point: activate_control_app is a supported config option as can be seen at https://github.com/puma/puma/blob/v6.2.2/lib/puma/dsl.rb#L198-L235.

But when I directly start the server using following command

bundle exec puma --control-url tcp://127.0.01:9294 --port=2400

then the options are correctly picked-up.

my_api$ bundle exec puma --control-url tcp://127.0.01:9294 --port=2400 
[13389] Puma starting in cluster mode...
[13389] * Puma version: 6.2.1 (ruby 3.1.2-p20) ("Speaking of Now")
[13389] *  Min threads: 5
[13389] *  Max threads: 5
[13389] *  Environment: development
[13389] *   Master PID: 13389
[13389] *      Workers: 2
[13389] *     Restarts: (✔) hot (✖) phased
[13389] * Preloading application
[13389] * Listening on http://0.0.0.0:2400
[13389] Use Ctrl-C to stop
[13389] * Starting control server on http://127.0.0.1:9294
[13389] - Worker 0 (PID: 13393) booted in 0.0s, phase: 0
[13389] - Worker 1 (PID: 13395) booted in 0.0s, phase: 0

Is this a bug on hanami-cli side or it looks like Puma-side issue related to when options are defined in configuration file?

Thanks.

timriley commented 1 year ago

Thanks for the really detailed bug report, @jiggneshhgohel!

Seeing the mention of the Guardfile at the top of your hanami server tells me that you have hanami-reloader installed (which makes sense, this is our default arrangement for new apps).

hanami-reloader's implementation of the hanami server command is just a thin wrapper around guard: https://github.com/hanami/reloader/blob/aff1348b8938b515a472efbe0e2a0590c62be4ea/lib/hanami/reloader/commands.rb#L102-L103

So this makes me wonder if this is actually an issue with https://github.com/jc00ke/guard-puma (which you'll see used in your Guardfile) rather than Hanami itself.

If you bypass running hanami server and instead run bundle exec guard --no-interactions, do you still see the issue? If so, then that would confirm the issue is within guard-puma.

Out of interest, I took a quick look at the guard-puma and it does do a few different things in relation to the control server URL (e.g. https://github.com/jc00ke/guard-puma/blob/560e82ceaf6901cacf76f329260a200b2c5310a4/lib/guard/puma/runner.rb#L13-L15), so this does make me feel like the issue may reside there.

Thank you for your help here!

jiggneshhgohel commented 1 year ago

@timriley Thanks for your prompt response in comment https://github.com/hanami/cli/issues/83#issuecomment-1536983654.

Regarding following in that comment

Seeing the mention of the Guardfile at the top of your hanami server tells me that you have hanami-reloader installed (which makes sense, this is our default arrangement for new apps).

You are correct. The logs I shared are from a Hanami 2.0 application and it has hanami-reloader in the Gemfile.

Regarding following

If you bypass running hanami server and instead run bundle exec guard --no-interactions, do you still see the issue? If so, then that would confirm the issue is within guard-puma.

I did following changes my puma config file 

port        ENV.fetch("HANAMI_PORT", 2400)
activate_control_app ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01:9294")

and ran your suggested command bundle exec guard --no-interactions and below is the output:

13:56:46 - INFO - Puma starting on port 2300 in development environment.
13:56:46 - INFO - Guard is now watching at '/.../my_api'
[7674] Puma starting in cluster mode...
[7674] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[7674] *  Min threads: 5
[7674] *  Max threads: 5
[7674] *  Environment: development
[7674] *   Master PID: 7674
[7674] *      Workers: 2
[7674] *     Restarts: (✔) hot (✖) phased
[7674] * Preloading application
[7674] * Listening on http://0.0.0.0:2400
[7674] Use Ctrl-C to stop
[7674] * Starting control server on http://127.0.0.1:9293
[7674] * Starting control server on http://[::1]:9293
[7674] - Worker 0 (PID: 7688) booted in 0.0s, phase: 0
[7674] - Worker 1 (PID: 7690) booted in 0.0s, phase: 0

That shows that the port change was taken into account but the control-url was ignored.

Regarding following

Out of interest, I took a quick look at the guard-puma and it does do a few different things in relation to the control server URL (e.g. https://github.com/jc00ke/guard-puma/blob/560e82ceaf6901cacf76f329260a200b2c5310a4/lib/guard/puma/runner.rb#L13-L15), so this does make me feel like the issue may reside there.

Thank you for your proactive behavior on that. I took a look at the guard-puma's options documentation at https://github.com/jc00ke/guard-puma/blob/main/README.md#options and following options took my attention:

:config is the path to the Puma config file (optional) :bind is URI to bind to (tcp:// and unix:// only) (optional) :control_token is the token to use as authentication for the control server(optional) :control_port is the port to use for the control server(optional)

So I opened Guardfile at the root of my hanami application and following were the contents in it:

group :server do
  guard "puma", port: ENV.fetch("HANAMI_PORT", 2300) do
    watch(%r{config/*})
    watch(%r{lib/*})
    watch(%r{app/*})
    watch(%r{slices/*})
  end
end

Now an immediate thing which I came to my mind while looking at it is that why the port option is explicitly configured considering the fact that it is also set in puma config file and it gets picked up from the config file instead of the guard-puma's configuration as is evident from the logs I shared before.

Now I updated following in Guardfile

guard "puma", port: ENV.fetch("HANAMI_PORT", 2300) do

TO

guard "puma", bind: ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01"), control_port: ENV.fetch("PUMA_CONTROL_APP_PORT", 9294)

and then removed following from puma config (this change I made as mentioned at the start of this comment)

activate_control_app ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01:9294")

Note: Above changes are made with an assumption that the port configuration should be picked up from puma's config file and the puma's control-url from the Guardfile.

Then I ran bundle exec guard --no-interactions and following is the output:

14:14:35 - INFO - Puma starting on port 4000 in development environment.
14:14:35 - INFO - Guard is now watching at '/.../my_api'
[11541] Puma starting in cluster mode...
[11541] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[11541] *  Min threads: 5
[11541] *  Max threads: 5
[11541] *  Environment: development
[11541] *   Master PID: 11541
[11541] *      Workers: 2
[11541] *     Restarts: (✔) hot (✖) phased
[11541] * Preloading application
[11541] * Listening on http://127.0.0.1:45981
[11541] Use Ctrl-C to stop
[11541] * Starting control server on http://127.0.0.1:9294
[11541] * Starting control server on http://[::1]:9294
[11541] - Worker 0 (PID: 11546) booted in 0.0s, phase: 0
[11541] - Worker 1 (PID: 11547) booted in 0.0s, phase: 0

As can be seen the control-url config was taken into account (see below from the logs)

[11541] * Starting control server on http://127.0.0.1:9294
[11541] * Starting control server on http://[::1]:9294

but the application's port (configured as default to be 2400) is not picked up from the puma config file (see below from the logs) 

Listening on http://127.0.0.1:45981

So my following assumption I shared before is incorrect:

Now an immediate thing which I came to my mind while looking at is why the port option is explicitly configured considering the fact that it is also set in puma config file and it gets picked up from the config file instead of the guard-puma's configuration as is evident from the logs I shared before.

So I updated following in Guardfile 

guard "puma", bind: ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01"), control_port: ENV.fetch("PUMA_CONTROL_APP_PORT", 9294)

TO

guard "puma", port: ENV.fetch("HANAMI_PORT", 2400), bind: ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01"), control_port: ENV.fetch("PUMA_CONTROL_APP_PORT", 9294)

and then removed following from puma config (this change I made as mentioned at the start of this comment)

port        ENV.fetch("HANAMI_PORT", 2400)

Then I ran bundle exec guard --no-interactions and following is the output:

14:25:47 - INFO - Puma starting on port 2400 in development environment.
14:25:47 - INFO - Guard is now watching at  '/.../my_api'
[13914] Puma starting in cluster mode...
[13914] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[13914] *  Min threads: 5
[13914] *  Max threads: 5
[13914] *  Environment: development
[13914] *   Master PID: 13914
[13914] *      Workers: 2
[13914] *     Restarts: (✔) hot (✖) phased
[13914] * Preloading application
[13914] * Listening on http://127.0.0.1:34087
[13914] Use Ctrl-C to stop
[13914] * Starting control server on http://127.0.0.1:9294
[13914] * Starting control server on http://[::1]:9294
[13914] - Worker 0 (PID: 13927) booted in 0.0s, phase: 0
[13914] - Worker 1 (PID: 13928) booted in 0.0s, phase: 0

So again as can be seen the control-url config was taken into account (see below from the logs)

[11541] * Starting control server on http://127.0.0.1:9294
[11541] * Starting control server on http://[::1]:9294

but the application's port (configured as default to be 2400) is not picked up from Guardfile (see below from the logs)

Listening on http://127.0.0.1:34087

This is strange!

Then I again added back following to puma config file

port        ENV.fetch("HANAMI_PORT", 2400)

and ran bundle exec guard --no-interactions and following is the output:

14:28:59 - INFO - Puma starting on port 2400 in development environment.
14:28:59 - INFO - Guard is now watching at  '/.../my_api'
[14763] Puma starting in cluster mode...
[14763] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[14763] *  Min threads: 5
[14763] *  Max threads: 5
[14763] *  Environment: development
[14763] *   Master PID: 14763
[14763] *      Workers: 2
[14763] *     Restarts: (✔) hot (✖) phased
[14763] * Preloading application
[14763] * Listening on http://127.0.0.1:34361
[14763] Use Ctrl-C to stop
[14763] * Starting control server on http://127.0.0.1:9294
[14763] * Starting control server on http://[::1]:9294
[14763] - Worker 0 (PID: 14769) booted in 0.0s, phase: 0
[14763] - Worker 1 (PID: 14770) booted in 0.0s, phase: 0

So again the application's port (configured as default to be 2400) is neither picked up from Guardfile nor from puma's config file (see below from the logs)

[14763] * Listening on http://127.0.0.1:34361

That's again weird. Now I updated following in Guardfile

guard "puma", port: ENV.fetch("HANAMI_PORT", 2400), bind: ENV.fetch("PUMA_CONTROL_APP_URL", "tcp://127.0.01"), control_port: ENV.fetch("PUMA_CONTROL_APP_PORT", 9294) do

TO

guard "puma" do

Note that at this point I haven't updated puma config file w.r.t sequential changes I made and mentioned before while we are investigating the issue. So the puma config file doesn't have the following default configured option in the config file generated by Hanami 2.0 application.

port        ENV.fetch("HANAMI_PORT", 2400)

Now I ran bundle exec guard --no-interactions and following is the output:

14:42:14 - INFO - Puma starting on port 4000 in development environment.
14:42:14 - INFO - Guard is now watching at '/.../my_api'
[17784] Puma starting in cluster mode...
[17784] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[17784] *  Min threads: 5
[17784] *  Max threads: 5
[17784] *  Environment: development
[17784] *   Master PID: 17784
[17784] *      Workers: 2
[17784] *     Restarts: (✔) hot (✖) phased
[17784] * Preloading application
[17784] * Listening on http://0.0.0.0:9292
[17784] Use Ctrl-C to stop
[17784] * Starting control server on http://127.0.0.1:9293
[17784] * Starting control server on http://[::1]:9293
[17784] - Worker 0 (PID: 17790) booted in 0.0s, phase: 0
[17784] - Worker 1 (PID: 17792) booted in 0.0s, phase: 0

So now the application's port is 9292 (see below from the logs below)

[17784] * Listening on http://0.0.0.0:9292

and the control-url's port is 9293 (see below from the logs below)

[17784] * Starting control server on http://127.0.0.1:9293
[17784] * Starting control server on http://[::1]:9293

Now I again updated following in Guardfile

guard "puma" do

TO

guard "puma", port: ENV.fetch("HANAMI_PORT", 2400) do

and again in puma config file there is no configuration for port available.

Now I ran bundle exec guard --no-interactions and following is the output:

15:02:12 - INFO - Puma starting on port 2300 in development environment.
15:02:12 - INFO - Guard is now watching at '/.../my_api'
[22224] Puma starting in cluster mode...
[22224] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[22224] *  Min threads: 5
[22224] *  Max threads: 5
[22224] *  Environment: development
[22224] *   Master PID: 22224
[22224] *      Workers: 2
[22224] *     Restarts: (✔) hot (✖) phased
[22224] * Preloading application
[22224] * Listening on http://0.0.0.0:9292
[22224] Use Ctrl-C to stop
[22224] * Starting control server on http://127.0.0.1:9293
[22224] * Starting control server on http://[::1]:9293
[22224] - Worker 0 (PID: 22229) booted in 0.0s, phase: 0
[22224] - Worker 1 (PID: 22231) booted in 0.0s, phase: 0

So again the application's port is 9292 (see below from the logs below)

[17784] * Listening on http://0.0.0.0:9292

Now adding back following to puma config file 

port        ENV.fetch("HANAMI_PORT", 2400)

and running bundle exec guard --no-interactions and following is the output:

15:03:43 - INFO - Puma starting on port 2300 in development environment.
15:03:43 - INFO - Guard is now watching at  '/.../my_api'
[22630] Puma starting in cluster mode...
[22630] * Puma version: 6.2.2 (ruby 3.1.2-p20) ("Speaking of Now")
[22630] *  Min threads: 5
[22630] *  Max threads: 5
[22630] *  Environment: development
[22630] *   Master PID: 22630
[22630] *      Workers: 2
[22630] *     Restarts: (✔) hot (✖) phased
[22630] * Preloading application
[22630] * Listening on http://0.0.0.0:2400
[22630] Use Ctrl-C to stop
[22630] * Starting control server on http://127.0.0.1:9293
[22630] * Starting control server on http://[::1]:9293
[22630] - Worker 0 (PID: 22643) booted in 0.0s, phase: 0
[22630] - Worker 1 (PID: 22645) booted in 0.0s, phase: 0

So now the application's port is 2400 (see below from the logs below) as is configured in puma config file:

[22630] * Listening on http://0.0.0.0:2400

So the gist is:

Thanks.