running brew services start dnsmasq reports success erroneously when starting dnsmasq fails

[benlk]

tl;dr: if a service exits with abnormal code 3 and then respawns, shouldn't it throw up an error in brew services list or in the output from brew service restart and brew service start?

Note: if this can't be reproduced in supported versions of OSX, it should be closed. This issue was experienced on an unsupported version of OSX> Replication notes are at the end of this ticket; replication might take ~10 minutes on a machine that has dnsmasq running.

$ sudo brew services restart --verbose dnsmasq
Stopping `dnsmasq`... (might take a while)
/bin/launchctl unload -w /Library/LaunchDaemons/homebrew.mxcl.dnsmasq.plist
==> Successfully stopped `dnsmasq` (label: homebrew.mxcl.dnsmasq)
==> Generated plist for dnsmasq:
   <?xml version="1.0" encoding="UTF-8"?>
   <!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
   <plist version="1.0">
     <dict>
       <key>Label</key>
       <string>homebrew.mxcl.dnsmasq</string>
       <key>ProgramArguments</key>
       <array>
         <string>/usr/local/opt/dnsmasq/sbin/dnsmasq</string>
         <string>--keep-in-foreground</string>
         <string>-C</string>
         <string>/usr/local/etc/dnsmasq.conf</string>
       </array>
       <key>RunAtLoad</key>
       <true/>
       <key>KeepAlive</key>
       <true/>
     </dict>
   </plist>
   

/bin/launchctl enable system/homebrew.mxcl.dnsmasq
/bin/launchctl bootstrap system /Library/LaunchDaemons/homebrew.mxcl.dnsmasq.plist
==> Successfully started `dnsmasq` (label: homebrew.mxcl.dnsmasq)

Running brew services list shows that dnsmasq is running:

$ sudo brew services list
Name    Status  User Plist
dnsmasq started root /Library/LaunchDaemons/homebrew.mxcl.dnsmasq.plist
httpd   stopped      
mysql   started root /Library/LaunchDaemons/homebrew.mxcl.mysql.plist
nginx   started root /Library/LaunchDaemons/homebrew.mxcl.nginx.plist
php     started root /Library/LaunchDaemons/homebrew.mxcl.php.plist

However, dnsmasq is not a running process:

$ ps -ax | grep dnsmasq
72299 ttys001    0:00.00 tail -f dnsmasq.log
73444 ttys003    0:00.00 grep dnsmasq

I attempted reinstalling dnsmasq with brew several times, rebooting the computer, starting dnsmasq with brew services and then stopping and starting it with launchctl, and various other things.

In the end, tail -f system.log | grep --line-buffered dns while running sudo brew services restart --verbose dnsmasq to restart dnsmasq produced the following insightful records:

Jul  4 19:51:00 oyster.local sudo[91780]:      user : TTY=ttys003 ; PWD=/usr/local/etc/nginx ; USER=root ; COMMAND=/usr/local/bin/brew services restart --verbose dnsmasq
Jul  4 19:51:00 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq): This service is defined to be constantly running and is inherently inefficient.
Jul  4 19:51:00 oyster.local dnsmasq[91928]: failed to open pidfile /usr/local/var/run/dnsmasq/dnsmasq.pid: No such file or directory
Jul  4 19:51:00 oyster.local dnsmasq[91928]: FAILED to start up
Jul  4 19:51:00 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq[91928]): Service exited with abnormal code: 3
Jul  4 19:51:00 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Jul  4 19:51:10 oyster.local dnsmasq[92003]: failed to open pidfile /usr/local/var/run/dnsmasq/dnsmasq.pid: No such file or directory
Jul  4 19:51:10 oyster.local dnsmasq[92003]: FAILED to start up
Jul  4 19:51:10 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq[92003]): Service exited with abnormal code: 3
Jul  4 19:51:10 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.

From there, I cd /usr/local/var/run/; ls -al and lo and behold the directory that dnsmasq is trying to create dnsmasq.pid in does not exist:

drwxr-xr-x  2 user   admin    68B Jul  4 16:54 httpd/
drwxr-xr-x  7 user   admin   238B Mar  8  2017 nginx/
-rw-r--r--  1 root  admin     6B Jul  4 19:07 nginx.pid

As user, I ran mkdir dnsmasq; ls -al:

drwxr-xr-x  2 user   admin    68B Jul  4 19:52 dnsmasq/
drwxr-xr-x  2 user   admin    68B Jul  4 16:54 httpd/
drwxr-xr-x  7 user   admin   238B Mar  8  2017 nginx/
-rw-r--r--  1 root  admin     6B Jul  4 19:07 nginx.pid

After that, the service restarted happily:

Jul  4 20:01:33 oyster.local sudo[96641]:      user : TTY=ttys003 ; PWD=/usr/local/var/run ; USER=root ; COMMAND=/usr/local/bin/brew services restart --verbose dnsmasq
Jul  4 20:01:33 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq): This service is defined to be constantly running and is inherently inefficient.
Jul  4 20:01:33 oyster dnsmasq[96792]: setting --bind-interfaces option because of OS limitations
Jul  4 20:01:33 oyster dnsmasq[96792]: ignoring nameserver 127.0.0.1 - local interface

Thoughts on how to reproduce: on a computer where dnsmasq is installed via brew and runs successfully, do the following:

1. sudo brew service stop dnsmasq
2. rm -r /usr/local/var/run/dnsmasq
3. tail -f system.log | grep --line-buffered dns while running sudo brew service start dnsmasq

system details: OSX 10.10.5 (14F2511) and brew 1.6.9

$ brew --version
Homebrew 1.6.9-104-g0c38ceb
Homebrew/homebrew-core (git revision 24657; last commit 2018-07-04)
$ brew doctor
Please note that these warnings are just used to help the Homebrew maintainers
with debugging if you file an issue. If everything you use Homebrew for is
working fine: please don't worry or file an issue; just ignore this. Thanks!

Warning: You are using macOS 10.10.
We (and Apple) do not provide support for this old version.
You may encounter build failures or other breakages.
Please create pull-requests instead of filing issues.

[MikeMcQuaid]

If you set HOMEBREW_DEVELOPER is the output more what you'd expect from brew services list?

[benlk]

$ export HOMEBREW_DEVELOPER=1

$ env | grep HOMEBREW_DEVELOPER
HOMEBREW_DEVELOPER=1

$ brew services list
Name    Status  User Plist
dnsmasq unknown root /Library/LaunchDaemons/homebrew.mxcl.dnsmasq.plist
httpd   stopped      
mysql   started root /Library/LaunchDaemons/homebrew.mxcl.mysql.plist
nginx   unknown root /Library/LaunchDaemons/homebrew.mxcl.nginx.plist
php     unknown root /Library/LaunchDaemons/homebrew.mxcl.php.plist

$ sudo brew services list
Name    Status  User Plist
dnsmasq started root /Library/LaunchDaemons/homebrew.mxcl.dnsmasq.plist
httpd   stopped      
mysql   started root /Library/LaunchDaemons/homebrew.mxcl.mysql.plist
nginx   started root /Library/LaunchDaemons/homebrew.mxcl.nginx.plist
php     started root /Library/LaunchDaemons/homebrew.mxcl.php.plist

$ sudo brew services restart dnsmasq
Stopping `dnsmasq`... (might take a while)
==> Successfully stopped `dnsmasq` (label: homebrew.mxcl.dnsmasq)
==> Successfully started `dnsmasq` (label: homebrew.mxcl.dnsmasq)

"unknown" is a little more honest than differently-colored "started", I guess, but it would be nice if the messages from syslog bubbled up to the user's terminal. I'm specifically thinking about the messages that showed that the service failed to start:

Jul  4 19:51:00 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq[91928]): Service exited with abnormal code: 3
Jul  4 19:51:00 oyster com.apple.xpc.launchd[1] (homebrew.mxcl.dnsmasq): Service only ran for 0 seconds. Pushing respawn out by 10 seconds.
Jul  4 19:51:10 oyster.local dnsmasq[92003]: failed to open pidfile /usr/local/var/run/dnsmasq/dnsmasq.pid: No such file or directory
Jul  4 19:51:10 oyster.local dnsmasq[92003]: FAILED to start up

Alternately, instead of the output of sudo brew services restart dnsmasq saying "Successfully started `dnsmasq` (label: homebrew.mxcl.dnsmasq)", when the status is "unknown", the output should say something like this:

==> Attempted starting `dnsmasq` (label: homebrew.mxcl.dnsmasq)
==> Homebrew could not verify that `dnsmasq` started correctly;
==> Please take the following steps to verify that the service is running:

followed by generic or service-specific instructions for verifying that the service is running, along with generic or specific instructions for checking error messages for services/that service. "Run tail -f /var/log/system.log | grep --line-buffered dnsmasq in a new terminal window while restarting the service in this terminal window" would probably be adequate.

[MikeMcQuaid]

It's confusing because basically unknown typically means "either something is broken or the .plist for your application needs adjusted to follow the correct process ID. I'm definitely open to accepting pull requests to fix bad plists, read from the log or print better information when the service hasn't been started correctly but my previous attempts have failed to make these better than what we have now. I actively would encourage you to try and best me here, though!