rsyslog error reporting improved

Rsyslog provides many up-to-the point error messages for config file and operational problems. These immensly helps when troubleshooting issues. Unfortunately, many users never see them. The prime reason is that most distros do never log syslog.* messages and so they are just throw away and invisible to the user. While we have been trying to make distros change their defaults, this has not been very successful. The result is a lot of user frustration and fruitless support work for the community — many things can very simple be resolved if only the error message is seen and acted on.

We have now changed our approach to this. Starting with v8.21, rsyslog now by default logs its messages via the syslog API instead of processing them internally. This is a big plus especially on systems running systemd journal: messages from rsyslogd will now show up when giving

$ systemctl status rsyslog.service

This is the place where nowadays error messages are expected and this is definitely a place where the typical administrator will see them. So while this change causes the need for some config adjustment on few exotic installations (more below), we expect this to be something that will generally improve the rsyslog user experience.

Along the same lines, we will also work on some better error reporting especially for TLS and queue-related issues, which turn out high in rsyslog suport discussions.

Some fine details on the change of behaviour:

Note: you can usually skip reading the rest of this post if you run only a single instance of rsyslog and do so with more or less default configuration.

The new behaviour was actually available for longer, It needed to be explicitly turned on in rsyslog.conf via

global(processInternalMessages="off")

Of course, distros didn’t do that by default. Also, it required rsyslog to be build with liblogging-stdlog, what many distros do not do. While our intent when we introduced this capability was to provide the better error logging we now have, it simply did not turn out in practice. The original approach was that it was less intrusive. The new method uses the native syslog() API if liblogging-stdlog is not available, so the setting always works (we even consider moving away from liblogging-stdlog, as we see this wasn’t really adopted). In essence, we have primarily changed the default setting for the “processInternalMessages” parameter. This means that by default, internal messages are no longer logged via the internal bridge to rsyslog but via the syslog() API call [either directly or
via liblogging). For the typical single-rsyslogd-instance installation this is mostly unnoticable (except for some additional latency). If multiple instances are run, only the “main” (the one processing system log messages) will see all messages. To return to the old behaviour, do either of those two:

  1. add in rsyslog.conf:
    global(processInternalMessages="on")
  2. export the environment variable RSYSLOG_DFLT_LOG_INTERNAL=1
    This will set a new default – the value can still be overwritten via rsyslog.conf (method 1). Note that the environment variable must be set in your startup script (which one is depending on your init system or systemd configuration).

Note that in most cases even in multiple-instance-setups rsyslog error messages were thrown away. So even in this case the behaviour is superior to the previous state – at least errors are now properly being recorded. This also means that even in multiple-instance-setups it often makes sense to keep the new default!

rsyslog 8.20.0 (v8-stable) released

We have released rsyslog 8.20.0.

This release brings a few new additions and requirements. Omrelp now has a configurable connection timeout and pmrfc3164 has a new option to allow slashes in the hostname. Apart from that, there is quite a set of bugfixes.

Please note, to use rsyslog 8.20.0 it is required to update librelp to version 1.2.12.

To get a full overview over the changes, please take a look at the Changelog.
ChangeLog:

libfastjson 0.99.3 released

We have released libfastjson 0.99.3.

This is a new fork of the json-c library, which is optimized for liblognorm processing.

The changes are mostly for cleanup purposes. Also some bug have been fixed, like a potential segfault issue, “make distcheck” not working and more.

Changelog:

0.99.3 2016-07-11
– new dependency: autoconf-archive
– exit() is no longer called in unexpected situations
The previous code called exit on some occasions and did not
give the caller a chance to do any cleanup or handling on
it’s own. This has completely been removed. Note that it was
very unlikely that this problem affected a caller, as exit()
was only called under very rare circumstances (e.g. OOM).
– fjson_version now returns configure VERSION
This avoid inconsistency.
– removal of Windows and Android bits
Thanks to Michael Biebl for the patch.
– fixes of the build system
Thanks to Michael Biebl for the patch.
– dropped support for Windows and Android as we do not target
these platforms
– “make distcheck” now works
– fix invalid Unicode representation for some non US-ASCII
characters when printed as string. Note that this could
potentially also lead to a segfault

Download:

http://download.rsyslog.com/libfastjson/libfastjson-0.99.3.tar.gz

sha256sum: be5604a9f61b3b247b45bc6234e8bfb5da5dd1e405d07fb8e52b1ea6e2a27fee

As always, feedback is appreciated.

Best regards,
Florian Riedl

librelp 1.2.12

librelp 1.2.12 [download]

This new release of librelp provides a few changes and cleanups. It provides an API enhancement to permit to set a connection timeout and it has some dynamic tests added to allow the use of rsyslog to test librelp.

For more details, please take a look at the changelog below.

———————————————————————-
Version 1.2.12 – 2016-07-07
– API enhancement: permit to set connection timeout
  Thanks to Nathan Brown for the patch.
– cleanup: replace deprecated GnuTLS data types by current ones
– CI improvements: added dynamic tests
  we now use the rsyslog testbench to do dynamic librelp tests. This
  currently happens only under Travis CI.

sha256sum: 0355730524f7b20bed1b85697296b6ce57ac593ddc8dddcdca263da71dee7bd7 

librelp 1.2.11

librelp 1.2.11 [download]

This new release of librelp is mostly a bugfixing release that fixes several issues, especially a potential segfault. The new version also has an API enhancement that adds a configurable connection timeout.

For more details, please take a look at the changelog below.

———————————————————————-
Version 1.2.11 – 2016-06-22
– bugfix: do not accept more than one “open” verb on a connection
  closes https://github.com/rsyslog/librelp/issues/37
– bugfix: potential segfault when high-numbered fd is used in sender
  When a fd (socket) with value >= 1024 was used by the client sender
  process, the library could segfault in select(). This depended a bit
  on the platform.
  This patch solves the issue by replacing the select() call with
  poll(). Note that we do not changed to epoll(), because
  (a) we only wait on a single fd
  (b) poll() is more portable
  closes https://github.com/rsyslog/librelp/issues/38
– bugfix: make librelp not run in thight loop when out of sockets
  If the process can no longer accept new connections (via accept)
  because it has reached its file handle maximum, librelp runs in
  a thight loop until either the client connection request is aborted
  or a file handle becomes available.
  This happens due to the fact that we get event notifications on
  connection requests. As we can’t satisfy it, we librelp always
  retries. Unfortunately, there is no socket call to cancel a
  connection request, so we cannot push the client request out.
  An alternative solution would be to close and re-open the
  listening socket, but in that case it is uncertain if we ever can
  re-aquire a socket (an easy DoS). So the best thing we can
  probably do is delay retries a bit. We must be careful, however,
  not to use a too long delay, as that would also affect other
  connections. We could address that problem via a dedicated thread
  for the listening process, but librelp is designed so that it can
  be used by callers with any threading library and threading model,
  and that would violate this design principle.
  Judging the alternatives, a slight delay probably is the best
  solution, especially as the situation is uncommon and will hopefully
  not last too long. This patch implements that solution.
  closes https://github.com/rsyslog/librelp/issues/34
– bugfix: flush the current recv frame if it exists if the client
  session is restarting
  Thanks to Nate Brown for the patch.
– API enhancement: add configurable connection timeout
  Thanks to Nate Brown for the patch.

sha256sum: 84de48f46caba0106d8853af572aa7b625c82dfbcf5f7cd13d2e57cce786e929

rsyslog 8.19.0 (v8-stable) released

We have released rsyslog 8.19.0.

This is mostly a bug-fixing release. Among the big number of fixes are a few additions to the testbench and some minor enhancements for several modules (like imrelp, omelasticsearch) to provide more convenience.

To get a full overview over the changes, please take a look at the Changelog.
ChangeLog:

Using rsyslog to Reindex/Migrate Elasticsearch data

Original post: Scalable and Flexible Elasticsearch Reindexing via rsyslog by @Sematext

This recipe is useful in a two scenarios:

  • migrating data from one Elasticsearch cluster to another (e.g. when you’re upgrading from Elasticsearch 1.x to 2.x or later)
  • reindexing data from one index to another in a cluster pre 2.3. For clusters on version 2.3 or later, you can use the Reindex API

Back to the recipe, we used an external application to scroll through Elasticsearch documents in the source cluster and push them to rsyslog via TCP. Then we used rsyslog’s Elasticsearch output to push logs to the destination cluster. The overall flow would be:

rsyslog to Elasticsearch reindex flow

This is an easy way to extend rsyslog, using whichever language you’re comfortable with, to support more inputs. Here, we piggyback on the TCP input. You can do a similar job with filters/parsers – you can find GeoIP implementations, for example – by piggybacking the mmexternal module, which uses stdout&stdin for communication. The same is possible for outputs, normally added via the omprog module: we did this to add a Solr output and one for SPM custom metrics.

The custom script in question doesn’t have to be multi-threaded, you can simply spin up more of them, scrolling different indices. In this particular case, using two scripts gave us slightly better throughput, saturating the network:

rsyslog to Elasticsearch reindex flow multiple scripts

Writing the custom script

Before starting to write the script, one needs to know how the messages sent to rsyslog would look like. To be able to index data, rsyslog will need an index name, a type name and optionally an ID. In this particular case, we were dealing with logs, so the ID wasn’t necessary.

With this in mind, I see a number of ways of sending data to rsyslog:

  • one big JSON per line. One can use mmnormalize to parse that JSON, which then allows rsyslog do use values from within it as index name, type name, and so on
  • for each line, begin with the bits of “extra data” (like index and type names) then put the JSON document that you want to reindex. Again, you can use mmnormalize to parse, but this time you can simply trust that the last thing is a JSON and send it to Elasticsearch directly, without the need to parse it
  • if you only need to pass two variables (index and type name, in this case), you can piggyback on the vague spec of RFC3164 syslog and send something like
    destination_index document_type:{"original": "document"}
    

This last option will parse the provided index name in the hostname variable, the type in syslogtag and the original document in msg. A bit hacky, I know, but quite convenient (makes the rsyslog configuration straightforward) and very fast, since we know the RFC3164 parser is very quick and it runs on all messages anyway. No need for mmnormalize, unless you want to change the document in-flight with rsyslog.

Below you can find the Python code that can scan through existing documents in an index (or index pattern, like logstash_2016.05.*) and push them to rsyslog via TCP. You’ll need the Python Elasticsearch client (pip install elasticsearch) and you’d run it like this:

python elasticsearch_to_rsyslog.py source_index destination_index

The script being:

from elasticsearch import Elasticsearch
import json, socket, sys

source_cluster = ['server1', 'server2']
rsyslog_address = '127.0.0.1'
rsyslog_port = 5514

es = Elasticsearch(source_cluster,
      retry_on_timeout=True,
      max_retries=10)
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s.connect((rsyslog_address, rsyslog_port))


result = es.search(index=sys.argv[1], scroll='1m', search_type='scan', size=500)

while True:
  res = es.scroll(scroll_id=result['_scroll_id'], scroll='1m')
  for hit in result['hits']['hits']:
    s.send(sys.argv[2] + ' ' + hit["_type"] + ':' + json.dumps(hit["_source"])+'\n')
  if not result['hits']['hits']:
    break

s.close()

If you need to modify messages, you can parse them in rsyslog via mmjsonparse and then add/remove fields though rsyslog’s scripting language. Though I couldn’t find a nice way to change field names – for example to remove the dots that are forbidden since Elasticsearch 2.0 – so I did that in the Python script:

def de_dot(my_dict):
  for key, value in my_dict.iteritems():
    if '.' in key:
      my_dict[key.replace('.','_')] = my_dict.pop(key)
    if type(value) is dict:
      my_dict[key] = de_dot(my_dict.pop(key))
  return my_dict

And then the “send” line becomes:

s.send(sys.argv[2] + ' ' + hit["_type"] + ':' + json.dumps(de_dot(hit["_source"]))+'\n')

Configuring rsyslog

The first step here is to make sure you have the lastest rsyslog, though the config below works with versions all the way back to 7.x (which can be found in most Linux distributions). You just need to make sure the rsyslog-elasticsearch package is installed, because we need the Elasticsearch output module.

# messages bigger than this are truncated
$maxMessageSize 10000000  # ~10MB

# load the TCP input and the ES output modules
module(load="imtcp")
module(load="omelasticsearch")

main_queue(
  # buffer up to 1M messages in memory
  queue.size="1000000"
  # these threads process messages and send them to Elasticsearch
  queue.workerThreads="4"
  # rsyslog processes messages in batches to avoid queue contention
  # this will also be the Elasticsearch bulk size
  queue.dequeueBatchSize="4000"
)

# we use templates to specify how the data sent to Elasticsearch looks like
template(name="document" type="list"){
  # the "msg" variable contains the document
  property(name="msg")
}
template(name="index" type="list"){
  # "hostname" has the index name
  property(name="hostname")
}
template(name="type" type="list"){
  # "syslogtag" has the type name
  property(name="syslogtag")
}

# start the TCP listener on the port we pointed the Python script to
input(type="imtcp" port="5514")

# sending data to Elasticsearch, using the templates defined earlier
action(type="omelasticsearch"
  template="document"
  dynSearchIndex="on" searchIndex="index"
  dynSearchType="on" searchType="type"
  server="localhost"  # destination Elasticsearch host
  serverport="9200"   # and port
  bulkmode="on"  # use the bulk API
  action.resumeretrycount="-1"  # retry indefinitely if Elasticsearch is unreachable
)

This configuration doesn’t have to disturb your local syslog (i.e. by replacing /etc/rsyslog.conf). You can put it someplace else and run a different rsyslog process:

rsyslogd -i /var/run/rsyslog_reindexer.pid -f /home/me/rsyslog_reindexer.conf

And that’s it! With rsyslog started, you can start the Python script(s) and do the reindexing.

rsyslog 8.18.0 (v8-stable) released

We have released rsyslog 8.18.0.

This is mostly a bug-fixing release. Among the big number of fixes are a few additions to the testbench and some minor enhancements for several modules (like redis, omkafka, imfile) to provide more convenience.

To get a full overview over the changes, please take a look at the Changelog.
ChangeLog:

Changelog for 8.18.0 (v8-stable)

Version 8.18.0 [v8-stable] 2016-04-19

  • testbench: When running privdrop tests testbench tries to drop
    user to “rsyslog”, “syslog” or “daemon” when running as root and
    you don’t explict set RSYSLOG_TESTUSER environment variable.
    Make sure the unprivileged testuser can write into tests/ dir!
  • templates: add option to convert timestamps to UTC
    closes https://github.com/rsyslog/rsyslog/issues/730
  • omjournal: fix segfault (regression in 8.17.0)
  • imptcp: added AF_UNIX support
    Thanks to Nathan Brown for implementing this feature.
  • new template options
    • compressSpace
    • date-utc
  • redis: support for authentication
    Thanks to Manohar Ht for the patch
  • omkafka: makes kafka-producer on-HUP restart optional
    As of now, omkafka kills and re-creates kafka-producer on HUP. This
    is not always desirable. This change introduces an action param
    (reopenOnHup=”on|off”) which allows user to control re-cycling of
    kafka-producer.
    It defaults to on (for backward compatibility). Off allows user to
    ignore HUP as far as kafka-producer is concerned.
    Thanks to Janmejay Singh for implementing this feature
  • imfile: new “FreshStartTail” input parameter
    Thanks to Curu Wong for implementing this.
  • omjournal: fix libfastjson API issues
    This module accessed private data members of libfastjson
  • ommongodb: fix json API issues
    This module accessed private data members of libfastjson
  • testbench improvements (more tests and more thourough tests)
    among others:

    • tests for omjournal added
    • tests for KSI subsystem
    • tests for priviledge drop statements
    • basic test for RELP with TLS
    • some previously disabled tests have been re-enabled
  • dynamic stats subsystem: a couple of smaller changes
    they also involve the format, which is slightly incompatible to
    previous version. As this was out only very recently (last version),
    we considered this as acceptable.
    Thanks to Janmejay Singh for developing this.
  • foreach loop: now also iterates over objects (not just arrays)
    Thanks to Janmejay Singh for developing this.
  • improvements to the CI environment
  • enhancement: queue subsystem is more robst in regard to some corruptions
    It is now detected if a .qi file states that the queue contains more
    records than there are actually inside the queue files. Previously this
    resulted in an emergency switch to direct mode, now the problem is only
    reported but processing continues.
  • enhancement: Allow rsyslog to bind UDP ports even w/out specific
    interface being up at the moment.
    Alternatively, rsyslog could be ordered after networking, however,
    that might have some negative side effects. Also IP_FREEBIND is
    recommended by systemd documentation.
    Thanks to Nirmoy Das and Marius Tomaschewski for the patch.
  • cleanup: removed no longer needed json-c compatibility layer
    as we now always use libfastjson, we do not need to support old
    versions of json-c (libfastjson was based on the newest json-c
    version at the time of the fork, which is the newest in regard
    to the compatibility layer)
  • new External plugin for sending metrics to SPM Monitoring SaaS
    Thanks to Radu Gheorghe for the patch.
  • bugfix imfile: fix memory corruption bug when appending @cee
    Thanks to Brian Knox for the patch.
  • bugfix: memory misallocation if position.from and position.to is used
    a negative amount of memory is tried to be allocated if position.from
    is smaller than the buffer size (at least with json variables). This
    usually leads to a segfault.
    closes https://github.com/rsyslog/rsyslog/issues/915
  • bugfix: fix potential memleak in TCP allowed sender definition
    depending on circumstances, a very small leak could happen on each
    HUP. This was caused by an invalid macro definition which did not rule
    out side effects.
  • bugfix: $PrivDropToGroupID actually did a name lookup
    … instead of using the provided ID
  • bugfix: small memory leak in imfile
    Thanks to Tomas Heinrich for the patch.
  • bugfix: double free in jsonmesg template
    There has to be actual json data in the message (from mmjsonparse,
    mmnormalize, imjournal, …) to trigger the crash.
    Thanks to Tomas Heinrich for the patch.
  • bugfix: incorrect formatting of stats when CEE/Json format is used
    This lead to ill-formed json being generated
  • bugfix omfwd: new-style keepalive action parameters did not work
    due to being inconsistently spelled inside the code. Note that legacy
    parameters $keepalive… always worked
    see also: https://github.com/rsyslog/rsyslog/issues/916
    Thanks to Devin Christensen for alerting us and an analysis of the
    root cause.
  • bugfix: memory leaks in logctl utility
    Detected by clang static analyzer. Note that these leaks CAN happen in
    practice and may even be pretty large. This was probably never detected
    because the tool is not often used.
  • bugfix omrelp: fix segfault if no port action parameter was given
    closes https://github.com/rsyslog/rsyslog/issues/911
  • bugfix imtcp: Messages not terminated by a NL were discarded
    … upon connection termination.
    Thanks to Tomas Heinrich for the patch.

Monitoring rsyslog’s impstats with Kibana and SPM

Original post: Monitoring rsyslog with Kibana and SPM by @Sematext

A while ago we published this post where we explained how you can get stats about rsyslog, such as the number of messages enqueued, the number of output errors and so on. The point was to send them to Elasticsearch (or Logsene, our logging SaaS, which exposes the Elasticsearch API) in order to analyze them.

This is part 2 of that story, where we share how we process these stats in production. We’ll cover:

  • an updated config, working with Elasticsearch 2.x
  • what Kibana dashboards we have in Logsene to get an overview of what rsyslog is doing
  • how we send some of these metrics to SPM as well, in order to set up alerts on their values: both threshold-based alerts and anomaly detection

Continue reading “Monitoring rsyslog’s impstats with Kibana and SPM”

Scroll to top