No "output" in logs when watch fires?

[ssenaria]

First off, thanks a lot for this code. Everything seems to be working just fine. I do have a question though. I was wondering why I'm not seeing any output in the logs. Or are the log outputs you mention in the README only display in STDIN?

Here's my watch config:

{
    "watches": [
        {
            "type":"key",
            "key":"apichecks/braintree/status",
            "handler": "/tmp/sifter key -e '/etc/consul/handlers/watch-kv-apichecks.py braintree'"
        }
    ]
}

From log file ... should there be some sort of output?

Apr 14 12:41:22 indeploy001 consul[32017]: agent: watch handler '/tmp/sifter key -e '/etc/consul/handlers/watch-kv-apichecks.py braintree'' output:

[darron]

If there's output from your command - then yes - you should be able to see it - but I'm not logging the output that Consul sends to sifter via STDIN anywhere.

If I was - I would log it here:

https://github.com/darron/sifter/blob/master/commands/sifter.go#L37-L44

Or maybe in decodeKeyStdin and decodeEventStdin.

Does that answer your question?

[ssenaria]

Ah ok. While I was debugging my handler, I was printing the output to the screen. I was expecting to see the output in the logs. Actually, I was looking for this stuff but pertaining to my code.

location='blank' elapsed='226.912µs' exec='chef-client'

[darron]

Ahh yes - makes more sense now. That's sent via the RunTime function and should be visible wherever your syslogs go.

I may have broke something and that's why they're not showing up.

I will dig into that as soon as I can.

[darron]

I took a look at this today on my local machine.

I blew away my entire Go environment, upgraded to 1.6.1 and then grabbed it from scratch: go get -u -v github.com/darron/sifter

And it does appear to be logging - like I'd expect. I started Consul in one terminal: make consul

In another window I triggered some changes/events:

[master]:~/Dropbox/src/gopath/src/github.com/darron/sifter
DarronFroeseDD@: consul-cli kv write singlekey dude234234234
[master]:~/Dropbox/src/gopath/src/github.com/darron/sifter
DarronFroeseDD@: consul event -name chef-client
Event ID: f1914070-5652-d58e-29b7-bcb04c59bc1c

And logs appeared to show up in the Console:

Do you have any additional information that might help me track this down? What's your environment like?

[darron]

I also have this environment variable exported - export SIFTER_DEBUG=1

[ssenaria]

Could it be that watch type is a key and not an event?

As far as my environment is set up, nothing fancy. For now I have a single node that I'm prototyping on and Consul is running in standalone mode. Other than the message not appearing in the logs, everything else seems to be working fine.

Do I need to run sifter in debug mode?

[darron]

Hmm - so I added a Vagrantfile to spin up a Linux box with Consul - and here was how I tested it:

vagrant up
vagrant ssh
sudo service consul stop
cd /vagrant
make deps
make
make consul

That loads Consul with the config/ folder - so it starts with some basic watches.

I found sifter's logs in /var/log/syslog:

Apr 21 02:54:09 vagrant-ubuntu-trusty-64 sifter[9074]: 2016/04/21 02:54:09 location='blank' elapsed='181.866µs' watch='event' exec='w'
Apr 21 02:54:14 vagrant-ubuntu-trusty-64 sifter[9079]: 2016/04/21 02:54:14 location='blank' elapsed='289.842µs' watch='key' exec='w'

So - maybe check there - or if you've got some centralized logging that takes all of your logs and forwards them - maybe take a look there.

You shouldn't have to run with debug mode - I didn't in this case.

[darron]

I just triggered a couple watches inside of the Vagrant VM:

vagrant@vagrant-ubuntu-trusty-64:~$ consul-cli kv write singlekey this-is-what-i-am-writing
vagrant@vagrant-ubuntu-trusty-64:~$ consul event -name=chef-client
Event ID: 49c5c95a-d572-8779-ac35-bf61313a2a57

and here's the output:

Apr 21 03:02:12 vagrant-ubuntu-trusty-64 sifter[9373]: 2016/04/21 03:02:12 key='sifter/key/singlekey/vagrant-ubuntu-trusty-64' value='77a87374e85359f8b2ccac83513bc3564c61aae8bfefff423ae057054384e1bf'
Apr 21 03:02:12 vagrant-ubuntu-trusty-64 sifter[9373]: 2016/04/21 03:02:12 location='complete' elapsed='29.584028ms' watch='key' exec='w' sha='77a87374e85359f8b2ccac83513bc3564c61aae8bfefff423ae057054384e1bf'
Apr 21 03:02:21 vagrant-ubuntu-trusty-64 sifter[9383]: 2016/04/21 03:02:21 key='sifter/event/chef-client/vagrant-ubuntu-trusty-64' value='2'
Apr 21 03:02:21 vagrant-ubuntu-trusty-64 sifter[9383]: 2016/04/21 03:02:21 location='complete' elapsed='23.267799ms' watch='event' exec='w' ltime='2'

[ssenaria]

I'm so sorry for having you go on a wild chase. So I have logrotate send consul related messages to /var/log/consul.log. Looks like I didn't account for sifter and it's going to /var/log/messages. This whole time I was looking at the wrong log file!!!

All is well!

[darron]

I'm glad it's all good - good to hear!