Monit always waits for puma to complete restart until its timeout after deployment about opsworks_ruby

[ajgon]

Going from monit to systemd would probably break a lot - especially, because opsworks is not maintained very well by amazon (to say the least), and I'm not sure how old systemd versions are there :)

I like conditional restart/start approach better, because then we are not required to remove/detect restarts in workers. @olbrich what do you think?

[ajgon]

@olbrich Does the fix you created recently applies here (I mean, does it resolve the issue)? Or is it something unrelated?

[olbrich]

@ajgon I don't think I did anything that would explicitly fix this, but it's possible that it improved because the monit handling is a bit better now. I would recommend trying to reproduce with the latest version.

Also the line

Oct 14 17:44:25 myapp-server monit[920]: 'puma_rails' restart action failed

In the output makes me thing that the deploy is failing, so I'm not entirely sure what happens in that situation. I think we stop workers before a deploy and it may be that monit eventually figures out that the process should be running and tries to restart it on a failed deploy.

[kzkn]

I will try v1.21.1, thank!

In the output makes me thing that the deploy is failing, so I'm not entirely sure what happens in that situation.

In my case, the deploy is not failing. The deploy is success, puma and delayed_job processes are running correctly.

[kzkn]

I tried v1.21.1, I got fail to start puma process on create new instance 😢
Outputs:

ubuntu@myapp-server:~$ sudo monit summary
┌─────────────────────────────────┬────────────────────────────┬───────────────┐
│ Service Name                    │ Status                     │ Type          │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ myapp-server                    │ OK                         │ System        │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ puma_rails                      │ Execution failed | Does... │ Process       │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ opsworks-agent                  │ OK                         │ Process       │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ opsworks-agent-master-running   │ OK                         │ Process       │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ delayed_job_rails-1             │ OK                         │ Process       │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ opsworks-agent-statistic-dae... │ OK                         │ File          │
├─────────────────────────────────┼────────────────────────────┼───────────────┤
│ opsworks-agent-keep-alive-da... │ OK                         │ File          │
└─────────────────────────────────┴────────────────────────────┴───────────────┘

ubuntu@myapp-server:~$ sudo monit status puma_rails
Process 'puma_rails'
  status                       Execution failed | Does not exist
  monitoring status            Monitored
  monitoring mode              active
  on reboot                    start
  data collected               Mon, 18 Oct 2021 12:37:44

ubuntu@myapp-server:~$ sudo journalctl | grep puma_rails
Oct 18 21:33:58 myapp-server monit[961]: 'puma_rails' process is not running
Oct 18 21:33:58 myapp-server monit[961]: 'puma_rails' trying to restart
Oct 18 21:33:58 myapp-server monit[961]: 'puma_rails' restart: '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...'
Oct 18 21:35:28 myapp-server monit[961]: 'puma_rails' failed to restart (exit status 2) -- '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...
Oct 18 21:36:13 myapp-server monit[961]: 'puma_rails' start on user request
Oct 18 21:36:13 myapp-server monit[961]: 'puma_rails' process is not running
Oct 18 21:36:13 myapp-server monit[961]: 'puma_rails' trying to restart
Oct 18 21:36:13 myapp-server monit[961]: 'puma_rails' restart: '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...'
Oct 18 21:37:44 myapp-server monit[961]: 'puma_rails' failed to restart (exit status 0) --
Oct 18 21:38:44 myapp-server monit[961]: 'puma_rails' process is not running

ubuntu@myapp-server:~$ ps auxw|grep puma
ubuntu   26696  0.0  0.0  14860  1056 pts/0    S+   21:47   0:00 grep --color=auto puma

ubuntu@myapp-server:~$ cat /run/lock/rails/puma.pid
cat: /run/lock/rails/puma.pid: No such file or directory

[olbrich]

Do the puma logs give you any indication of what the failure was?

[kzkn]

@olbrich
The puma log file did not exist. Is there anything else I should look at?

# puma.rb
pidfile  "/run/lock/rails/puma.pid"
state_path "/run/lock/rails/puma.state"
stdout_redirect "/srv/www/rails/shared/log/puma.stdout.log", "/srv/www/rails/shared/log/puma.stderr.log", true

deploy@myapp-server:~$ cat /run/lock/rails/puma.pid
cat: /run/lock/rails/puma.pid: No such file or directory
deploy@myapp-server:~$ cat /run/lock/rails/puma.state
cat: /run/lock/rails/puma.state: No such file or directory
deploy@myapp-server:~$ cat /srv/www/rails/shared/log/puma.stdout.log
cat: /srv/www/rails/shared/log/puma.stdout.log: No such file or directory
deploy@myapp-server:~$ cat /srv/www/rails/shared/log/puma.stderr.log
cat: /srv/www/rails/shared/log/puma.stderr.log: No such file or directory

[kzkn]

pumactl restart is failed because puma.state file does not exists.
https://github.com/puma/puma/blob/a6cdca85a15b2c277f64a5fa7572effb786fa9a1/lib/puma/control_cli.rb#L148

Oct 19 21:48:34 myapp-server monit[923]: 'puma_rails' process is not running
Oct 19 21:48:34 myapp-server monit[923]: 'puma_rails' trying to restart
Oct 19 21:48:34 myapp-server monit[923]: 'puma_rails' restart: '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...
Oct 19 21:48:34 myapp-server puma-rails[15131]: State file not found: /run/lock/rails/puma.state

[kzkn]

It looks like the monit start on the first deploy is not executed.
When I manually run sudo monit start puma_rails, I have seen the following logs:

Oct 19 22:00:07 myapp-server monit[923]: 'puma_rails' start: '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...

Puma will run successfully after the above log. puma.pid, puma.state files are created.
sudo journalctl | grep "'puma_rails' start:" hits only logs that ran monit start manually.

[kzkn]

This seems to be similar to the problem we addressed in #251.

Oct 19 23:03:54 myapp-server monit[960]: 'myapp-server' Monit reloaded
Oct 19 23:03:54 myapp-server monit[960]: 'puma_rails' process is not running
Oct 19 23:03:54 myapp-server monit[960]: 'puma_rails' trying to restart
Oct 19 23:03:54 myapp-server monit[960]: 'puma_rails' restart: '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...
Oct 19 23:05:24 myapp-server monit[960]: 'puma_rails' failed to restart (exit status 0) -- '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...
...
Oct 19 23:06:07 myapp-server monit[960]: 'puma_rails' start on user request
Oct 19 23:06:07 myapp-server monit[960]: Monit daemon with PID 960 awakened
Oct 19 23:06:07 myapp-server monit[960]: Awakened by User defined signal 1
Oct 19 23:06:07 myapp-server monit[960]: Reinitializing Monit -- control file '/etc/monit/monitrc'
Oct 19 23:06:07 myapp-server monit[25881]: Skipping 'allow localhost' -- host resolved to [::ffff:127.0.0.1] which is present in ACL already
Oct 19 23:06:07 myapp-server monit[960]: 'delayed_job_rails-1' restart on user request
Oct 19 23:06:07 myapp-server monit[960]: Monit daemon with PID 960 awakened
Oct 19 23:06:07 myapp-server monit[960]: Skipping 'allow localhost' -- host resolved to [::ffff:127.0.0.1] which is present in ACL already
Oct 19 23:06:07 myapp-server monit[960]: 'myapp-server' Monit reloaded
Oct 19 23:06:07 myapp-server monit[960]: 'puma_rails' process is not running
Oct 19 23:06:07 myapp-server monit[960]: 'puma_rails' trying to restart
Oct 19 23:06:07 myapp-server monit[960]: 'puma_rails' restart: '/bin/sh -c cd /srv/www/rails/current && AWS_ACCESS_KEY_ID=...

The monit start puma_rails is requested, but actually monit restart is working instead of monit start.
It looks like to be cancelled because it is Reinitializing Monit immediately after requesting monit start.
After that, it looks like monit is repeatedly monit restart by itself without the puma.state file.

I assume this is because monit reload twice, once for puma and once for delayed_job.
The monit reload is now called immediately via notifies from the configure hook of appserver and worker.
When I made the change to call monit reload only once, the problem goes away.

Another approach that worked well was to change the command set for the restart program in puma's monitrc, which dynamically switches between pumactl start and pumactl restart depending on the presence of the puma.state file. See this diff for details.

@ajgon @olbrich
I can't decide which approach (or another approach) is better to use. What do you think?

[kzkn]

...Or should we move from monit to systemd for puma? 😂