Bluepill fails to create process silently

[everestx]

I have a problem where I load a bluepill file and rather than bluepill creating the process and monitoring the new pid, it reports pid of zero. Bluepill is running as root, but dropping privileges to a non-privileged user for the created process.

Some more details:

1. The pid file shows an actual pid number and a sock file is generated. Notice that the journals are not created.

find /var/run/bluepill/ | grep myapp
/var/run/bluepill/pids/myapp.pid
/var/run/bluepill/pids/myapp
/var/run/bluepill/socks/myapp.sock

/var/run/bluepill/pids/myapp.pid
10602

1. The bluepill log shows a pid as well, but doesn't report any stats. Missing stats makes sense because there is no process matching the pid

bluepilld[10602]: [myapp:sidekiq] cpu_usage: [0.0, 0.0, 0.0, 0.0, 0.0]
bluepilld[10602]: [myapp:sidekiq] mem_usage: [0KB, 0KB, 0KB, 0KB, 0KB]
bluepilld[10602]: [myapp:sidekiq] mem_usage: [0KB, 0KB, 0KB]
bluepilld[10602]: [myapp:sidekiq] cpu_usage: [0.0, 0.0, 0.0, 0.0]
bluepilld[10602]: [myapp:sidekiq] mem_usage: [0KB, 0KB, 0KB, 0KB]
bluepilld[10602]: [myapp:sidekiq] cpu_usage: [0.0, 0.0, 0.0, 0.0, 0.0]

1. And finally bluepill status reports pid 0, but there is not a process created.

bluepill myapp status
myapp:sidekiq(pid:0): up

Any hints or tips to troubleshoot further? Is there any way to get more verbosity into this logging?

[deanmax]

Same issue met but with slightly different symptom
bluepill status shows a fake pid which doesn't exist

root@myhost:TESTING:~> bluepill test status
testing-memory-leak(pid:31511): up

root@myhost:TESTING:~> ps -ef | grep 31511
root     31456 15095  0 10:58 pts/0    00:00:00 grep 31511

While the actual job is running with a different pid, which is way passing it's memory threshold

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
20194 deployer  20   0 4355m 4.1g 2548 S  0.2 17.6   0:24.97 ruby

Below is the bluepill log that reflects what was happening(mem monitoring turns into 0KB, which is understandable because it's monitoring a pid that doesn't exist)

2019-04-17T23:04:50.401267-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] mem_usage: [99MB, 100MB, 100MB*, 101MB*, 101MB*]
2019-04-17T23:04:50.403241-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] mem_usage dispatched: restart
2019-04-17T23:04:50.403259-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] No restart_command specified. Must stop and start to restart
2019-04-17T23:04:50.403264-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] Executing default stop command. Sending TERM signal to 31511
2019-04-17T23:04:50.403269-04:00 myhost bluepilld[7398]: [test] pid journal file: /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak
2019-04-17T23:04:50.403272-04:00 myhost bluepilld[7398]: [test] pid journal = 31511
2019-04-17T23:04:50.403275-04:00 myhost bluepilld[7398]: [test] Acquired lock /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.403278-04:00 myhost bluepilld[7398]: [test] Termed old process 31511
2019-04-17T23:04:50.403281-04:00 myhost bluepilld[7398]: [test] Journal cleanup completed
2019-04-17T23:04:50.403284-04:00 myhost bluepilld[7398]: [test] Cleared lock /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.403287-04:00 myhost bluepilld[7398]: [test] pgid journal file: /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak
2019-04-17T23:04:50.403291-04:00 myhost bluepilld[7398]: [test] pgid journal = 31508
2019-04-17T23:04:50.403880-04:00 myhost bluepilld[7398]: [test] Acquired lock /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.403893-04:00 myhost bluepilld[7398]: [test] Termed old process group 31508
2019-04-17T23:04:50.403900-04:00 myhost bluepilld[7398]: [test] Journal cleanup completed
2019-04-17T23:04:50.403905-04:00 myhost bluepilld[7398]: [test] Cleared lock /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.403909-04:00 myhost bluepilld[7398]: [test] pid journal file: /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak
2019-04-17T23:04:50.403914-04:00 myhost bluepilld[7398]: [test] No previous process journal - Skipping cleanup
2019-04-17T23:04:50.403917-04:00 myhost bluepilld[7398]: [test] pgid journal file: /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak
2019-04-17T23:04:50.403920-04:00 myhost bluepilld[7398]: [test] No previous process journal - Skipping cleanup
2019-04-17T23:04:50.403922-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] Executing start command: scl enable rh-ruby24 -- ruby /home/deployer/mem_increase.rb
2019-04-17T23:04:50.445252-04:00 myhost bluepilld[7398]: [test] Acquired lock /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.445274-04:00 myhost bluepilld[7398]: [test] pgid journal file: /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak
2019-04-17T23:04:50.445279-04:00 myhost bluepilld[7398]: [test] Saving pgid 20141 to process journal testing-memory-leak
2019-04-17T23:04:50.445284-04:00 myhost bluepilld[7398]: [test] Saved pgid 20141 to journal testing-memory-leak
2019-04-17T23:04:50.445288-04:00 myhost bluepilld[7398]: [test] Journal now = 20141
2019-04-17T23:04:50.445293-04:00 myhost bluepilld[7398]: [test] Cleared lock /var/run/bluepill/journals/.bluepill_pgids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.445297-04:00 myhost bluepilld[7398]: [test] Acquired lock /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.445301-04:00 myhost bluepilld[7398]: [test] pid journal file: /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak
2019-04-17T23:04:50.445305-04:00 myhost bluepilld[7398]: [test] Saving pid 20146 to process journal testing-memory-leak
2019-04-17T23:04:50.445310-04:00 myhost bluepilld[7398]: [test] Saved pid 20146 to journal testing-memory-leak
2019-04-17T23:04:50.445314-04:00 myhost bluepilld[7398]: [test] Journal now = 20146
2019-04-17T23:04:50.445963-04:00 myhost bluepilld[7398]: [test] Cleared lock /var/run/bluepill/journals/.bluepill_pids_journal.testing-memory-leak.lock
2019-04-17T23:04:50.445976-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] Going from up => restarting
...
2019-04-17T23:06:50.471164-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] Going from restarting => up
2019-04-17T23:06:50.499239-04:00 myhost bluepilld[7398]: [test:testing-memory-leak] mem_usage: [0KB]