Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

remote log gets concatenated lines #3061

Closed
seanchannel opened this Issue · 21 comments

4 participants

@seanchannel

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
Owner

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

@seanchannel

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
Owner

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

@seanchannel

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
Owner

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
Owner

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...

@seanchannel

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
Owner

@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.

@seanchannel

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
Owner

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

@seanchannel

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

@s0undt3ch
Owner

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

@s0undt3ch
Owner
  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
Owner
'<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
Owner

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
Owner

Now I'm unable to log using TCP :\

@s0undt3ch
Owner

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

@s0undt3ch
Owner

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

@s0undt3ch s0undt3ch closed this
@seanchannel

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.

@s0undt3ch s0undt3ch referenced this issue from a commit in s0undt3ch/salt
@s0undt3ch s0undt3ch Less intrusive logging setup when in use as an API access to salt. Fi…
…xes #3155.

* An effort is now made to try and find out if any other library has setup python's logging. If it has, we cooperate, if not, we rule.
* More doc strings.
* Explain a bit on the preferred way to do remote logging using syslog. Refs #3061.
726b62c
@kjkuan kjkuan referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
@kjkuan kjkuan referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
@seanchannel

@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
Owner

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

:)

@jacksontj jacksontj referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
@jacksontj jacksontj referenced this issue from a commit
Commit has since been removed from the repository and is no longer available.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.