Difference between running minion as a service or directly

[Kevin Dodge]

I am fighting a bug where my salt-minion doesn't return any info when the master does a state.show_highstate

If I start my minion via -- service salt-minion start  ---   and then I do a state.show_highstate my request never makes it to the minion

If I start my minion via -- salt-minion   -- and then I do a state.show_highstate my request always works.

What is the difference.   How do I debug the problem?   Should I just startup salt-minion in the background and let it run forever?

[Sean Channel]

What OS is this? Can you try setting ``log_level_logfile: debug`` in the
minion config (then restart) and grep your system logs, to
/var/log/salt/*, and see if ``dmesg | grep -i salt`` reveals anything``?

There are issues with spawning a process that spawns a daemon vs.
directly executing or maybe exec'ing the daemon in the system startup
that tend can lead to different results. We've tried different tweaks
with Upstart on Ubuntu.

_S

[Kevin Dodge]

I am running on Centos 5.6

Here are the results of the logging

2013-04-01 09:11:42,688 [salt.minion                                 ][INFO    ] User root Executing command state.show_highstate with jid 20130401091142677587

2013-04-01 09:11:42,689 [salt.minion                                 ][DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20130401091142677587', 'tgt': 'stgweb02*', 'ret': '', 'user': 'root', 'arg': [], 'fun': 'state.show_highstate'}

2013-04-01 09:11:42,727 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

2013-04-01 09:11:42,900 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key

2013-04-01 09:11:42,900 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

2013-04-01 09:11:43,301 [salt.loader                                 ][DEBUG   ] loading grain in ['/var/cache/salt/minion/extmods/grains', '/usr/lib/python2.6/site-packages/salt/grains']

2013-04-01 09:11:43,302 [salt.loader                                 ][DEBUG   ] Skipping /var/cache/salt/minion/extmods/grains, it is not a directory

2013-04-01 09:11:43,423 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

2013-04-01 09:11:43,633 [salt.crypt                                  ][DEBUG   ] Decrypting the current master AES key

2013-04-01 09:11:43,634 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

2013-04-01 09:11:44,003 [salt.crypt                                  ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

2013-04-01 09:11:44,088 [salt.state                                  ][INFO    ] Loading fresh modules for state activity

2013-04-01 09:11:44,088 [salt.loader                                 ][DEBUG   ] loading module in ['/var/cache/salt/minion/extmods/modules', '/usr/lib/python2.6/site-packages/salt/modules']

2013-04-01 09:11:44,089 [salt.loader                                 ][DEBUG   ] Skipping /var/cache/salt/minion/extmods/modules, it is not a directory

2013-04-01 09:11:52,969 [salt.minion                                 ][INFO    ] User root Executing command saltutil.find_job with jid 20130401091152958328

2013-04-01 09:11:52,970 [salt.minion                                 ][DEBUG   ] Command details {'tgt_type': 'glob', 'jid': '20130401091152958328', 'tgt': 'stgweb02*', 'ret': '', 'user': 'root', 'arg': ['20130401091142677587'], 'fun': 'saltutil.find_job'}

2013-04-01 09:11:52,980 [salt.loaded.int.module.cmdmod               ][INFO    ] Executing command 'ps -efH' in directory '/root'

2013-04-01 09:11:53,003 [salt.loaded.int.module.cmdmod               ][DEBUG   ] output: UID

Doing the dmesg grep I get a bunch of messages that look like this

salt-minion[18964] general protection rip:2aaab000e7dd rsp:7ffffb0a7d10 error:0 

I have had a few people suggest that I need to update my zmq version, and I have tried but the packages for centos are nearly non-existant for a newer pyzmq on centos, and building it myself has not been working very well for me.

[Sean Channel]

Whoa.. that is a seg fault. Is it possible you have multiple versions of
zmq or python (or *something*) e.g. in /usr/local/bin that is also in
the main system? My first suspicion is that the service command is
invoking this in a way that picks up a different binary of something
(e.g. uses a different PATH vs. when you run from the command line).

The zmq version problem is certainly not to be ruled out.
_S

[Kevin Dodge]

The server is a VM so whenever I play with it I try to have a snapshot I can revert back to after I am done.  So currently nothing would have been installed manually, it should all be via yum packages.  I did find two zmq versions installed (checking via yum for installed packages) and I ended up removing salt entirely, along with pyzmq and the two zmq versions, and then reloading the default salt back on.    This doesn't solve my problem but it hopefully eliminates that as a questionable area.

In the logging I tried debugging both (daemon vs direct) from startup on and found there is a slight difference between the two in the logs.   The logs below show the startup process, and in them the daemon startup gets a WARNING message -- "Failed to import module win_disk" -- The manual startup does not get this error.   Otherwise they are both the same.

[salt             ][INFO    ] Setting up the Salt Minion "minion_server"

[salt.loader      ][DEBUG   ] loading grain in ['/var/cache/salt/minion/extmods/grains', '/usr/lib/python2.6/site-packages/salt/grains']

[salt.loader      ][DEBUG   ] Skipping /var/cache/salt/minion/extmods/grains, it is not a directory

[salt.minion      ][DEBUG   ] Attempting to authenticate with the Salt Master at 10.111.45.80

[salt.crypt       ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

[salt.crypt       ][DEBUG   ] Decrypting the current master AES key

[salt.crypt       ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

[salt.minion      ][INFO    ] Authentication with master successful!

[salt.crypt       ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

[salt.crypt       ][DEBUG   ] Decrypting the current master AES key

[salt.crypt       ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

[salt.crypt       ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

[salt.loader      ][DEBUG   ] loading grain in ['/var/cache/salt/minion/extmods/grains', '/usr/lib/python2.6/site-packages/salt/grains']

[salt.loader      ][DEBUG   ] Skipping /var/cache/salt/minion/extmods/grains, it is not a directory

[salt.loader      ][DEBUG   ] loading module in ['/var/cache/salt/minion/extmods/modules', '/usr/lib/python2.6/site-packages/salt/modules']

[salt.loader      ][DEBUG   ] Skipping /var/cache/salt/minion/extmods/modules, it is not a directory

[salt.loader      ][WARNING ] Failed to import module win_disk, this is due most likely to a syntax error: Traceback (most recent call last):

  File "/usr/lib/python2.6/site-packages/salt/loader.py", line 544, in gen_functions

    ), fn_, path, desc

  File "/usr/lib/python2.6/site-packages/salt/modules/win_disk.py", line 8, in <module>

    import ctypes

  File "/usr/lib64/python2.6/ctypes/__init__.py", line 546, in <module>

    CFUNCTYPE(c_int)(lambda: None)

MemoryError

[salt.loader      ][DEBUG   ] Loaded groupadd as virtual group

[salt.loader      ][DEBUG   ] Loaded rh_service as virtual service

[salt.loader      ][DEBUG   ] Loaded linux_sysctl as virtual sysctl

[salt.loader      ][DEBUG   ] Loaded parted as virtual partition

[salt.loader      ][DEBUG   ] Loaded mdadm as virtual raid

[salt.loader      ][DEBUG   ] Loaded linux_acl as virtual acl

[salt.loader      ][DEBUG   ] Loaded sysmod as virtual sys

[salt.loader      ][DEBUG   ] Loaded yumpkg5 as virtual pkg

[salt.loader      ][DEBUG   ] Loaded useradd as virtual user

[salt.loader      ][DEBUG   ] Loaded grub_legacy as virtual grub

[salt.loader      ][DEBUG   ] Loaded rh_ip as virtual ip

[salt.loader      ][DEBUG   ] Loaded djangomod as virtual django

[salt.loader      ][DEBUG   ] Loaded cmdmod as virtual cmd

[salt.loader      ][DEBUG   ] Loaded linux_lvm as virtual lvm

[salt.loader      ][DEBUG   ] loading returner in ['/var/cache/salt/minion/extmods/returners', '/usr/lib/python2.6/site-packages/salt/returners']

[salt.loader      ][DEBUG   ] Skipping /var/cache/salt/minion/extmods/returners, it is not a directory

[salt.loader      ][DEBUG   ] Loaded syslog_return as virtual syslog

[salt.loader      ][DEBUG   ] Loaded carbon_return as virtual carbon

[salt.utils.process][DEBUG   ] Created pidfile: /var/run/salt-minion.pid

[salt.utils.process][DEBUG   ] Chowned pidfile: /var/run/salt-minion.pid to user: root

[salt.minion      ][INFO    ] Minion is starting as user 'root'

[salt.minion      ][DEBUG   ] Minion "minion_server" trying to tune in

[salt.minion      ][DEBUG   ] Minion PUB socket URI: ipc:///var/run/salt/minion/minion_event_5838fd2bc50d2f61093574fdd4b299af_pub.ipc

[salt.minion      ][DEBUG   ] Minion PULL socket URI: ipc:///var/run/salt/minion/minion_event_5838fd2bc50d2f61093574fdd4b299af_pull.ipc

How would I look for multiple packages installed?   How should I continue to debug this problem?  

[Sean Channel]

[ *Dave*: why would it fail to import win_disk for only one of these
cases? ]

What are the contents of your startup config / scripts? There must be
something in there that starts the minion somehow differently than what
happens from the command line. Do you have any of these:
/etc/init.d/salt-minion
/etc/rc*.d/*salt-minion
/etc/init/salt-minion.conf
..or something under /etc/systemd?

Is there anything in /usr/local/bin, such as a different version of
python? By 'multiple packages' I mean something that was installed
manually or through pip or some means other than an RPM package, some of
which could be in the main system /usr/*bin paths.

Apologies as I've not looked at a CentOS system for some time.
_S

[Kevin Dodge]

While looking through the system trying to answer your questions I decided to start comparing the environment between when the daemon runs the file and when I run it directly.   I found that setting all of the direct environment variables in the salt-minion script fixes my problems.   Then I went and whittled down the list of environment variables I am setting to find the exact one that causes it to work correctly, and this is it.

export HOME="/root"

So, why would that make a difference?   If I set the variable in the /etc/init.d/salt-minion script everything starts to work and my error message (Failed to import module win_disk) goes away.

[Kevin Dodge]

One other observation, I decided to see if the root directory itself was needed, or if simply it wants a home directory.   So I created a new directory ( mkdir /root_temp ) and then change setting the HOME variable to be /root_temp.   This also worked.   If I set the HOME variable to be a non-existant directory then it stops working and I start getting the WARNING again.

[Sean Channel]

Good find! I'm not sure why that is, actually (and am about to be gone
for the week, apologies). However, I think your system should be using
upstart via a file at /etc/init/salt-minion.conf instead of the sys-v
style /etc/init.d scripts. If you have both you might try removing the
init.d script along with any /etc/rc*.d links and using only the upstart
config file. I could be wrong about upstart on Centos 5.6, though it is
looking like that init.d script is where the problem is.

Depending on how well that works I would ask if you could perhaps file
an issue on github since it's news to me that the minion needs a $HOME,
though not very surprising now that I hear this. This might be a
packaging problem; all the upstart/init setups are technically outside
of Salt's source & not published on PyPI with the official release.
Please mention me ("@seanchannel") in the issue if you open one.

That is enlightening to know about & I appreciate your looking into it!
_S

[Kevin Dodge]

I really appreciate your help.  I haven't done anything in python other than salt and therefore debugging the issues I am having is very difficult without someone to at least point me in various directions.

Here are the scripts that I can find, and they are all the same.

/etc/rc.d/init.d/salt-minion

/etc/rc.d/rc4.d/S99salt-minion

/etc/rc.d/rc6.d/K99salt-minion

/etc/rc.d/rc2.d/K99salt-minion

/etc/rc.d/rc0.d/K99salt-minion

/etc/rc.d/rc5.d/S99salt-minion

/etc/rc.d/rc3.d/S99salt-minion

/etc/rc.d/rc1.d/K99salt-minion

Note, /etc/init.d is a symbolic link to /etc/rc.d/init.d

[Kevin Dodge]

One last thing to add to the conversation.   After talking to IT it turns out that the environment I am running on is not Centos but RedHat.   I have other minions running on Centos and they are connecting just fine without having the HOME environment variable set.

[Sean Channel]

Our RPM guy would like to merge your change to fix this if you can send
a pull request on github (get your name in the source!), or maybe just a
snip here of the diff & I can pass it along (meh!). :)

If you login on github then go to
https://github.com/saltstack/salt/blob/develop/pkg/rpm/salt-minion you
should be able to make edits directly in the browser. It's pretty friendly.
_S

[Kevin Dodge]

I tried pulling down the git salt source but couldn't find the same file that is in my RedHat installation.   I am guessing it is this file "pkg/rpm/salt-minion"

Here is a snippet of the top of the file with the last line being the one I added

#!/bin/sh

#

# Salt minion

###################################

# LSB header

### BEGIN INIT INFO

# Provides: salt-minion

# Required-Start: network

# Short-Description: salt minion control daemon

# Description: This is a daemon that controls the salt minions

### END INIT INFO

# chkconfig header

# chkconfig: 345 99 99

# description:  This is a daemon that controls the salt mininons

#

# processname: /usr/bin/salt-minion

# Sanity checks.

[ -x /usr/bin/salt-minion ] || exit 0

export HOME="/root"