search

saltstack / salt

Software to automate the management and configuration of any infrastructure or application at scale. Get access to the Salt software package repository here:
https://repo.saltproject.io/
Apache License 2.0
14.1k stars 5.47k forks source link

remote log gets concatenated lines #3061

Closed ghost closed 11 years ago

ghost commented 11 years ago

Hey @s0undt3ch I'm getting multiple log messages mashed into one long line in my remote log about 2048 characters long each. Here's an example with log_level at debug (this is all one line):

Dec 28 14:41:41 giraffe.local inion.pem#000<15>2012-12-28 14:41:40,824 [salt.crypt ][DEBUG ] Loaded minion key: /etc/salt/pki/minion/minion.pem#000<15>2012-12-28 14:41:41,029 [salt.loader ][DEBUG ] loading grain in ['/var/cache/salt/minion/extmods/grains', '/usr/lib/pymodules/python2.7/salt/grains']#000<15>2012-12-28 14:41:41,030 [salt.loader ][DEBUG ] Skipping /var/cache/salt/minion/extmods/grains, it is not a directory#000<15>2012-12-28 14:41:41,300 [salt.loader ][DEBUG ] loading module in ['/var/cache/salt/minion/extmods/modules', '/usr/lib/pymodules/python2.7/salt/modules']#000<15>2012-12-28 14:41:41,301 [salt.loader ][DEBUG ] Skipping /var/cache/salt/minion/extmods/modules, it is not a directory#000<15>2012-12-28 14:41:41,644 [salt.loader ][DEBUG ] Loaded groupadd as virtual group#000<15>2012-12-28 14:41:41,657 [salt.loader ][DEBUG ] Loaded linux_sysctl as virtual sysctl#000<15>2012-12-28 14:41:41,679 [salt.loader ][DEBUG ] Loaded bluez as virtual bluetooth#000<15>2012-12-28 14:41:41,707 [salt.loader ][DEBUG ] Loaded parted as virtual partition#000<15>2012-12-28 14:41:41,713 [salt.loader ][DEBUG ] Loaded apt as virtual pkg#000<15>2012-12-28 14:41:41,731 [salt.loader ][DEBUG ] Loaded upstart as virtual service#000<15>2012-12-28 14:41:41,736 [salt.loader ][DEBUG ] Loaded useradd as virtual user#000<15>2012-12-28 14:41:41,752 [salt.loader ][DEBUG ] Loaded debconfmod as virtual debconf#000<15>2012-12-28 14:41:41,773 [salt.loader ][DEBUG ] Loaded cmdmod as virtual cmd#000<15>2012-12-28 14:41:41,801 [salt.loader ][DEBUG ] Loaded djangomod as virtual django#000<15>2012-12-28 14:41:41,822 [salt.loader ][DEBUG ] loading returner in ['/var/cache/salt/minion/extmods/returners', '/usr/lib/pymodules/python2.7/salt/returners']#000<15>2012-12-28 14:41:41,823 [salt.loader ][DEBUG ] Skipping /var/cache/salt/minion/extmods/returners, it is not a directory#000<15>2012-12-28 14:41:41,835 [salt.loader ][DEBUG ] Loaded syslog_retur

thatch45 commented 11 years ago

I assume this is using the syslog backend and then having syslog send to the remote log server? (sorry if this is inferred)

ghost commented 11 years ago

Well, that is a very good question. Salt is using a python API to talk directly to the remote log server, and that is very different from using the local syslog facility and having rsyslog forward the message along. In other words, we bypass the local rsyslog daemon entirely.

Going through rsyslogd would be great and more standard on Unix/Linux platforms, but there is no such thing for windows.

thatch45 commented 11 years ago

Yes, I thought were were going to go through syslog. But yes, that would omit windows

ghost commented 11 years ago

I was thinking about this article below and it makes a pretty good case for doing platform detection and switching to syslog if there is a performance impact.

http://www.aminus.org/blogs/index.php/2008/07/03/writing-high-efficiency-large-python-sys-1?blog=2

UtahDave commented 11 years ago

There is syslog-win32 here: http://syslog-win32.sourceforge.net/

It's public domain. I haven't used it, but maybe it would be worth bundling with the Windows Salt installer.

Thoughts?

s0undt3ch commented 11 years ago

Well, @seanchannel, the good news is that, by revisiting this issue, I noticed that there was a bug when using syslog with a salt master. The bad news is that, I'm unable to reproduce your issue:

Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,430 [salt.loader      ][DEBUG   ] Skipping /var/cache/salt/master/extmods/grains, it is not a directory
Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,521 [salt.loader      ][DEBUG   ] loading grain in ['/var/cache/salt/master/extmods/grains', '/salt/source/salt/grains']
Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,534 [salt.loader      ][DEBUG   ] Skipping /var/cache/salt/master/extmods/grains, it is not a directory
Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,555 [salt.loader      ][DEBUG   ] loading grain in ['/var/cache/salt/master/extmods/grains', '/salt/source/salt/grains']
Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,581 [salt.loader      ][DEBUG   ] Skipping /var/cache/salt/master/extmods/grains, it is not a directory
Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,656 [salt.loader      ][DEBUG   ] loading grain in ['/var/cache/salt/master/extmods/grains', '/salt/source/salt/grains']
Dec 31 03:41:37 ubuntu-10-04-4-server-i386 2012-12-31 03:41:37,675 [salt.loader      ][DEBUG   ] Skipping /var/cache/salt/master/extmods/grains, it is not a directory
Dec 31 03:41:39 ubuntu-10-04-4-server-i386 2012-12-31 03:41:39,478 [salt.loader      ][DEBUG   ] loading module in ['/var/cache/salt/master/extmods/modules', '/salt/source/salt/modules']
Dec 31 03:41:39 ubuntu-10-04-4-server-i386 2012-12-31 03:41:39,526 [salt.loader      ][DEBUG   ] Skipping /var/cache/salt/master/extmods/modules, it is not a directory
Dec 31 03:41:39 ubuntu-10-04-4-server-i386 2012-12-31 03:41:39,583 [salt.master      ][WARNING ] Stopping the Salt Master

The above is output from a vagrant machine running Ubuntu 10.04.4 server i386

So what additional info can you provide so that I can trigger this issue? Linux Distro? Syslog version, etc...

ghost commented 11 years ago

Happy new year, @s0undt3ch ! :)

This is with ubuntu (precise and quantal, local or remote). I'm seeing the string "#000<15>" (without the quotes) in place of what should be a new line and timestamp.

s0undt3ch commented 11 years ago

@seanchannel Happy New Year! ;)

Well, some more bad news:

vagrant@ubuntu-12-04-1-server-i386:~$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 12.04.1 LTS
Release:        12.04
Codename:       precise
vagrant@ubuntu-12-04-1-server-i386:~$ tail /var/log/syslog 
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,429 [salt.loader         :165 ][TRACE   ] Added core.os_data to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,430 [salt.loader         :165 ][TRACE   ] Added core.path to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,430 [salt.loader         :165 ][TRACE   ] Added core.pythonpath to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,430 [salt.loader         :165 ][TRACE   ] Added core.pythonversion to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,431 [salt.loader         :165 ][TRACE   ] Added core.saltpath to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,431 [salt.loader         :165 ][TRACE   ] Added core.saltversion to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,431 [salt.loader         :165 ][TRACE   ] Added opts.opts to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,431 [salt.loader         :165 ][TRACE   ] Added extra.shell to grain
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,825 [salt.minion         :541 ][DEBUG   ] Attempting to authenticate with the Salt Master at 192.168.33.1
Jan  4 12:30:39 ubuntu-12-04-1-server-i386 2013-01-04 12:30:39,846 [salt.crypt          :162 ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem

Can you please post your logging settings? From the salt config files.

ghost commented 11 years ago

The log host is ubuntu 12.10 (quantal) w/ rsyslog 5.8.6 listening on port 10514. The minion is configured with "log_file: tcp://loghost.local:10514".

Sorry to leave that out!

s0undt3ch commented 11 years ago

Ah, your using tcp, so far I've tested using the log soket I'll try with your settings.

ghost commented 11 years ago

it's the same result even on localhost.. you don't even need two systems

s0undt3ch commented 11 years ago

Ok, setting rsyslog to tcp makes this issue appear. Finding out if this is a python logging issue or not

s0undt3ch commented 11 years ago
  1. Python's syslog handler appends a nulll byte \000 to each message.
  2. rsyslog converts null bytes to #000, check here and search for #000.
  3. Ubuntu's rsyslog needs nulll terminated strings.

Still haven't found a solution.

s0undt3ch commented 11 years ago 
'<12>2013-01-04 19:49:59,337 [salt                :121 ][WARNING ] Stopping the Salt Minion\x00'

That's the repr() of the message that is going to be sent through the wire.

s0undt3ch commented 11 years ago

There seems to be no issue if you set it to log to UDP instead of TCP

Jan  4 20:19:17 2013-01-04 20: 19:17,051 [salt.loader         :165 ][TRACE   ] Added core.path to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,053 [salt.loader         :165 ][TRACE   ] Added core.pythonpath to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,058 [salt.loader         :165 ][TRACE   ] Added core.pythonversion to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,060 [salt.loader         :165 ][TRACE   ] Added core.saltpath to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,062 [salt.loader         :165 ][TRACE   ] Added core.saltversion to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,064 [salt.loader         :165 ][TRACE   ] Added opts.opts to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,072 [salt.loader         :165 ][TRACE   ] Added extra.shell to grain
Jan  4 20:19:17 2013-01-04 20: 19:17,581 [salt.minion         :541 ][DEBUG   ] Attempting to authenticate with the Salt Master at 192.168.33.1
Jan  4 20:19:17 2013-01-04 20: 19:17,618 [salt.crypt          :162 ][DEBUG   ] Loaded minion key: /etc/salt/pki/minion/minion.pem
Jan  4 20:19:34 2013-01-04 20: 19:34,473 [salt                :121 ][WARNING ] Stopping the Salt Minion
s0undt3ch commented 11 years ago

Now I'm unable to log using TCP :\

s0undt3ch commented 11 years ago

Anyway, all this seems to be rsyslog related, not salt.

s0undt3ch commented 11 years ago

Since it's not salt, I'm closing this. Please reopen if need be.

ghost commented 11 years ago

using file:///dev/log and letting the local syslog daemon forward that to the remote host works far, far better than either tcp or udp directly, and we should consider emphasizing that in the config file while I eat my hat. :)

This might be an issue for windows hosts logging to an ubuntu log server at some point, but I think you're right and we can cross that bridge when we get to it.

ghost commented 11 years ago

@UtahDave actually bundling syslog for windows is really not a bad idea at all, or at least having the option. The results on the remote log host from a proper syslog daemon are what anyone using remote logging is going to want. I had no idea your windows work included such extensive package & repo management, which sheds a different light on the idea (just watched Salt Air).

UtahDave commented 11 years ago

:) Yes, I have a vision. I envision Salt taking over the Windows world.

:)