New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fromhost and fromhost-ip properties are not available to imfile #545

Open
ymattw opened this Issue Oct 6, 2015 · 27 comments

Comments

10 participants
@ymattw
Contributor

ymattw commented Oct 6, 2015

According to http://www.rsyslog.com/doc/master/configuration/properties.html, fromhost and fromhost-ip should be general properties, however, when I use them in a template for imfile module, they are expanded to empty. Is this a known issue? Thanks.

My template definition

template(name="format_json" type="list") {
    constant(value="{\"hostname\":\"")
    property(name="hostname")
    constant(value="\"")

    constant(value=",\"fromhost-ip\":\"")
    property(name="fromhost-ip")
    constant(value="\"")

    constant(value=",\"app-name\":\"")
    property(name="app-name" caseConversion="lower")
    constant(value="\"")

    constant(value=",\"filename\":\"")
    property(name="$!metadata!filename")
    constant(value="\"")

    constant(value=",\"syslogtag\":\"")
    property(name="syslogtag")
    constant(value="\"")

    constant(value=",\"message\":\"")
    property(name="msg" format="json")
    constant(value="\"")

    constant(value=",\"timestamp\":\"")
    property(name="timestamp" dateFormat="rfc3339")
    constant(value="\"")

    constant(value="}")
}

Ruleset definition

module(load="omkafka")

ruleset(name="rule_omkafka") {
    action(type="omkafka"
           template="format_json"
           broker=["broker01.example.com:9092", "broker02.example.com:9092"]
           partitions.auto="on"
           topic="applog"

           action.resumeRetryCount="-1"
           queue.filename="queue"
           queue.size="100000"
           queue.saveonshutdown="on"
           queue.discardseverity="0"
          )
}

Input definition

module(load="imfile" mode="inotify")

input(type="imfile"
      ruleset="rule_omkafka"
      file="/export/logs/myapp.log"
      addmetadata="on"
      tag="myapp"
)
@rgerhards

This comment has been minimized.

Show comment
Hide comment
@rgerhards

rgerhards Oct 6, 2015

Member

Oh, if that's really a case, that's a bug. They should be populated with the local machine info.

Member

rgerhards commented Oct 6, 2015

Oh, if that's really a case, that's a bug. They should be populated with the local machine info.

@ymattw

This comment has been minimized.

Show comment
Hide comment
@ymattw

ymattw Oct 11, 2015

Contributor

Just reproduced with more simple configs: read from file and output to file (in json format). What could be wrong?

# more *conf
::::::::::::::
00-template.conf
::::::::::::::
template(name="format_json" type="list") {
    constant(value="{\"fromhost\":\"")
    property(name="fromhost")
    constant(value="\"")

    constant(value=",\"fromhost-ip\":\"")
    property(name="fromhost-ip")
    constant(value="\"")

    constant(value=",\"app-name\":\"")
    property(name="app-name" caseConversion="lower")
    constant(value="\"")

    constant(value=",\"filename\":\"")
    property(name="$!metadata!filename")
    constant(value="\"")

    constant(value=",\"syslogtag\":\"")
    property(name="syslogtag")
    constant(value="\"")

    constant(value=",\"message\":\"")
    property(name="msg" format="json")
    constant(value="\"")

    constant(value=",\"timestamp\":\"")
    property(name="timestamp" dateFormat="rfc3339")
    constant(value="\"")

    constant(value="}")
}

::::::::::::::
02-ruleset-omfile.conf
::::::::::::::
module(load="builtin:omfile")

ruleset(name="rule_omfile") {
    action(type="omfile"
           dirCreateMode="0700"
           FileCreateMode="0644"
           template="format_json"
           File="/tmp/omfile.log"
    )
}

::::::::::::::
10-input-default.conf
::::::::::::::
module(load="imfile" mode="inotify")

input(type="imfile"
      ruleset="rule_omfile"
      addmetadata="on"
      tag="myapp"
      file="/tmp/input.log"
)

# echo TEST >> /tmp/input.log

# cat /tmp/omfile.log
{"fromhost":"","fromhost-ip":"","app-name":"myapp","filename":"/tmp/input.log","syslogtag":"myapp","message":"TEST","timestamp":"2015-10-11T12:45:20.456480+00:00"}

This was done from a docker container:

# cat /etc/hosts
172.17.0.54     rtest
127.0.0.1       localhost
::1     localhost ip6-localhost ip6-loopback
fe00::0 ip6-localnet
ff00::0 ip6-mcastprefix
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters

# hostname
rtest

# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
111: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP
    link/ether 02:42:ac:11:00:36 brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.54/16 scope global eth0
       valid_lft forever preferred_lft forever
    inet6 fe80::42:acff:fe11:36/64 scope link
       valid_lft forever preferred_lft forever

I also did the same test on a virtualbox vm, saw the same.

Contributor

ymattw commented Oct 11, 2015

Just reproduced with more simple configs: read from file and output to file (in json format). What could be wrong?

# more *conf
::::::::::::::
00-template.conf
::::::::::::::
template(name="format_json" type="list") {
    constant(value="{\"fromhost\":\"")
    property(name="fromhost")
    constant(value="\"")

    constant(value=",\"fromhost-ip\":\"")
    property(name="fromhost-ip")
    constant(value="\"")

    constant(value=",\"app-name\":\"")
    property(name="app-name" caseConversion="lower")
    constant(value="\"")

    constant(value=",\"filename\":\"")
    property(name="$!metadata!filename")
    constant(value="\"")

    constant(value=",\"syslogtag\":\"")
    property(name="syslogtag")
    constant(value="\"")

    constant(value=",\"message\":\"")
    property(name="msg" format="json")
    constant(value="\"")

    constant(value=",\"timestamp\":\"")
    property(name="timestamp" dateFormat="rfc3339")
    constant(value="\"")

    constant(value="}")
}

::::::::::::::
02-ruleset-omfile.conf
::::::::::::::
module(load="builtin:omfile")

ruleset(name="rule_omfile") {
    action(type="omfile"
           dirCreateMode="0700"
           FileCreateMode="0644"
           template="format_json"
           File="/tmp/omfile.log"
    )
}

::::::::::::::
10-input-default.conf
::::::::::::::
module(load="imfile" mode="inotify")

input(type="imfile"
      ruleset="rule_omfile"
      addmetadata="on"
      tag="myapp"
      file="/tmp/input.log"
)

# echo TEST >> /tmp/input.log

# cat /tmp/omfile.log
{"fromhost":"","fromhost-ip":"","app-name":"myapp","filename":"/tmp/input.log","syslogtag":"myapp","message":"TEST","timestamp":"2015-10-11T12:45:20.456480+00:00"}

This was done from a docker container:

# cat /etc/hosts
172.17.0.54     rtest
127.0.0.1       localhost
::1     localhost ip6-localhost ip6-loopback
fe00::0 ip6-localnet
ff00::0 ip6-mcastprefix
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters

# hostname
rtest

# ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
111: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP
    link/ether 02:42:ac:11:00:36 brd ff:ff:ff:ff:ff:ff
    inet 172.17.0.54/16 scope global eth0
       valid_lft forever preferred_lft forever
    inet6 fe80::42:acff:fe11:36/64 scope link
       valid_lft forever preferred_lft forever

I also did the same test on a virtualbox vm, saw the same.

@rgerhards

This comment has been minimized.

Show comment
Hide comment
@rgerhards

rgerhards Oct 11, 2015

Member

Imfile has a bug

Member

rgerhards commented Oct 11, 2015

Imfile has a bug

@ymattw

This comment has been minimized.

Show comment
Hide comment
@ymattw

ymattw Oct 11, 2015

Contributor

If you tell more detail I could probably jump in to fix it :)

Contributor

ymattw commented Oct 11, 2015

If you tell more detail I could probably jump in to fix it :)

@rgerhards

This comment has been minimized.

Show comment
Hide comment
@rgerhards

rgerhards Oct 11, 2015

Member

I am on the road so hard to type much. Look at where the message is created (msgconstruct()?). I guess the properties are not set. Compare that to other plugins like imptcp.

Member

rgerhards commented Oct 11, 2015

I am on the road so hard to type much. Look at where the message is created (msgconstruct()?). I guess the properties are not set. Compare that to other plugins like imptcp.

@alorbach alorbach self-assigned this Oct 29, 2015

@alorbach

This comment has been minimized.

Show comment
Hide comment
@alorbach

alorbach Oct 30, 2015

Member

From what I can see MsgSetHOSTNAME is properly called, so the properties should be set.
I will run some tests on my dev environment to check this.

Member

alorbach commented Oct 30, 2015

From what I can see MsgSetHOSTNAME is properly called, so the properties should be set.
I will run some tests on my dev environment to check this.

@alorbach

This comment has been minimized.

Show comment
Hide comment
@alorbach

alorbach Oct 30, 2015

Member

Could not reproduce the problem, works as expected with current master-candidate version:

{"hostname":"ubuntu","fromhost-ip":"127.0.0.1","app-name":"rsyslogd","filename":"","syslogtag":"rsyslogd:","message":" [origin software="rsyslogd" swVersion="8.14.0.master" x-pid="36711" x-info="http://www.rsyslog.com"] start","timestamp":"2015-10-30T04:33:11.860421-07:00"}

Member

alorbach commented Oct 30, 2015

Could not reproduce the problem, works as expected with current master-candidate version:

{"hostname":"ubuntu","fromhost-ip":"127.0.0.1","app-name":"rsyslogd","filename":"","syslogtag":"rsyslogd:","message":" [origin software="rsyslogd" swVersion="8.14.0.master" x-pid="36711" x-info="http://www.rsyslog.com"] start","timestamp":"2015-10-30T04:33:11.860421-07:00"}

@ymattw

This comment has been minimized.

Show comment
Hide comment
@ymattw

ymattw Dec 2, 2015

Contributor

Interesting... I can still reproduce this with v8.14.0 on CentOS Linux release 7.1.1503 (Core), from a VM installed on MacOS (NOT inside docker container).

I use static linking with dependencies, with following configure parameters, anything wrong?

--prefix /export/servers/rsyslog \
--enable-static \
--enable-debug \
--enable-elasticsearch \
--enable-elasticsearch-tests \
--enable-liblogging-stdlog \
--enable-imfile \
--enable-imptcp \
--enable-omstdout \
--enable-omruleset \
--enable-omuxsock \
--enable-omkafka \
--disable-libgcrypt \
CFLAGS=-DPATH_PIDFILE='"/export/servers/rsyslog/var/run/rsyslog.pid"' \
PKG_CONFIG_PATH=/tmp/lib/pkgconfig \
LIBESTR_LIBS=/tmp/lib/libestr.a \
JSON_C_LIBS=/tmp/lib/libjson-c.a \
ZLIB_LIBS=/tmp/lib/libz.a \
LIBUUID_LIBS=/tmp/lib/libuuid.a \
CURL_LIBS=/tmp/lib/libcurl.a \
LIBLOGGING_STDLOG_LIBS=/tmp/lib/liblogging-stdlog.a \
LIBRDKAFKA_CFLAGS=-I/tmp/include \
LIBRDKAFKA_LIBS=/tmp/lib/librdkafka.a

Dependencies are:

cf46112b5151e2f1a3fd38439bdade23  curl-7.44.0.tar.gz
39705ae46b1c0c64f1d32d26653c8e7e  json-c-0.12-20140410.tar.gz
f4c9165a23587e77f7efe65d676d5e8e  libestr-0.1.10.tar.gz
44b8ce2daa1bfb84c9feaf42f9925fd7  liblogging-1.0.5.tar.gz
1b77543f9be82d3f700c0ef98f494990  librdkafka-0.8.6.tar.gz
d44d866d06286c08ba0846aba1086d68  libuuid-1.0.3.tar.gz
44d667c142d7cda120332623eab69f40  zlib-1.2.8.tar.gz
Contributor

ymattw commented Dec 2, 2015

Interesting... I can still reproduce this with v8.14.0 on CentOS Linux release 7.1.1503 (Core), from a VM installed on MacOS (NOT inside docker container).

I use static linking with dependencies, with following configure parameters, anything wrong?

--prefix /export/servers/rsyslog \
--enable-static \
--enable-debug \
--enable-elasticsearch \
--enable-elasticsearch-tests \
--enable-liblogging-stdlog \
--enable-imfile \
--enable-imptcp \
--enable-omstdout \
--enable-omruleset \
--enable-omuxsock \
--enable-omkafka \
--disable-libgcrypt \
CFLAGS=-DPATH_PIDFILE='"/export/servers/rsyslog/var/run/rsyslog.pid"' \
PKG_CONFIG_PATH=/tmp/lib/pkgconfig \
LIBESTR_LIBS=/tmp/lib/libestr.a \
JSON_C_LIBS=/tmp/lib/libjson-c.a \
ZLIB_LIBS=/tmp/lib/libz.a \
LIBUUID_LIBS=/tmp/lib/libuuid.a \
CURL_LIBS=/tmp/lib/libcurl.a \
LIBLOGGING_STDLOG_LIBS=/tmp/lib/liblogging-stdlog.a \
LIBRDKAFKA_CFLAGS=-I/tmp/include \
LIBRDKAFKA_LIBS=/tmp/lib/librdkafka.a

Dependencies are:

cf46112b5151e2f1a3fd38439bdade23  curl-7.44.0.tar.gz
39705ae46b1c0c64f1d32d26653c8e7e  json-c-0.12-20140410.tar.gz
f4c9165a23587e77f7efe65d676d5e8e  libestr-0.1.10.tar.gz
44b8ce2daa1bfb84c9feaf42f9925fd7  liblogging-1.0.5.tar.gz
1b77543f9be82d3f700c0ef98f494990  librdkafka-0.8.6.tar.gz
d44d866d06286c08ba0846aba1086d68  libuuid-1.0.3.tar.gz
44d667c142d7cda120332623eab69f40  zlib-1.2.8.tar.gz
@ymattw

This comment has been minimized.

Show comment
Hide comment
@ymattw

ymattw Dec 2, 2015

Contributor

Also reproduced on a VM of version CentOS release 6.4 (Final), which has only 1 network interface (which I thought could be related initially).

Contributor

ymattw commented Dec 2, 2015

Also reproduced on a VM of version CentOS release 6.4 (Final), which has only 1 network interface (which I thought could be related initially).

@alorbach

This comment has been minimized.

Show comment
Hide comment
@alorbach

alorbach Dec 10, 2015

Member

Hrm I think this can only happen if the gethostname() api returns a failure. Unfortunetally rsyslog does not print an error into the debug log if this happens.

I am going to try to reproduce this problem on Centos6 tomorrow. I have a working vmware somewhere ;)

Member

alorbach commented Dec 10, 2015

Hrm I think this can only happen if the gethostname() api returns a failure. Unfortunetally rsyslog does not print an error into the debug log if this happens.

I am going to try to reproduce this problem on Centos6 tomorrow. I have a working vmware somewhere ;)

@alorbach alorbach added this to the v8.15 release milestone Dec 10, 2015

@ymattw

This comment has been minimized.

Show comment
Hide comment
@ymattw

ymattw Jan 6, 2016

Contributor

Weird .. I reproduced this on ubuntu 14.04.3 as well, from inside docker container, where gethostname() works totally fine.

With gdb I see the call trace is as below, the resolveDNS() call does nothing real because pMsg->msgFlags is always 0. I tried git grep that flag but got lost soon. This is low priority for me as I have an easy workaround (writing the values in template with a startup script), hope you can figure out what's going wrong.

(gdb) bt
#0  resolveDNS (pM=0x7ffff0005770) at msg.c:479
#1  getRcvFromIP (pM=0x7ffff0005770) at msg.c:523
#2  0x000000000041f51f in MsgGetProp (pMsg=0x7ffff0005770, pTpe=0x6d37a0, pProp=0x6d37c0, pPropLen=0x7ffff5bcfb0c, pbMustBeFreed=0x7ffff5bcfb1e, ttNow=<value optimized out>)
    at msg.c:3264
#3  0x00000000004460d1 in tplToString (pTpl=0x6d2d20, pMsg=0x7ffff0005770, iparam=0x7fffec002080, ttNow=0x7ffff5bcfbd0) at ../template.c:195
#4  0x0000000000441e1b in prepareDoActionParams (pAction=0x6d0170, pWti=0x6d6ed0, pMsg=0x7ffff0005770, ttNow=0x7ffff5bcfbd0) at ../action.c:937
#5  processMsgMain (pAction=0x6d0170, pWti=0x6d6ed0, pMsg=0x7ffff0005770, ttNow=0x7ffff5bcfbd0) at ../action.c:1303
#6  0x0000000000442481 in processBatchMain (pVoid=0x6d0170, pBatch=0x6d6f08, pWti=0x6d6ed0) at ../action.c:1347
#7  0x00000000004398b4 in ConsumerReg (pThis=0x6d0710, pWti=0x6d6ed0) at queue.c:1898
#8  0x0000000000433cf5 in wtiWorker (pThis=0x6d6ed0) at wti.c:334
#9  0x000000000043284e in wtpWorker (arg=0x6d6ed0) at wtp.c:389
#10 0x00007ffff7bc7a51 in start_thread () from /lib64/libpthread.so.0
#11 0x00007ffff750893d in clone () from /lib64/libc.so.6
(gdb) l
474             prop_t *localName;
475             DEFiRet;
476
477             MsgLock(pMsg);
478             CHKiRet(objUse(net, CORE_COMPONENT));
479             if(pMsg->msgFlags & NEEDS_DNSRESOL) {
480                     localRet = net.cvthname(pMsg->rcvFrom.pfrominet, &localName, NULL, &ip);
481                     if(localRet == RS_RET_OK) {
482                             /* we pass down the props, so no need for AddRef */
483                             MsgSetRcvFromWithoutAddRef(pMsg, localName);
(gdb) p pMsg->msgFlags
$18 = 0
(gdb) fin
Run till exit from #0  resolveDNS (pM=0x7ffff0005770) at msg.c:493
524                     if(pM->pRcvFromIP == NULL)
(gdb) p pM->pRcvFromIP
$20 = (prop_t *) 0x0
(gdb)

(gdb) fin
Run till exit from #0  getRcvFromIP (pM=0x7ffff0005770) at msg.c:524
0x000000000041f51f in MsgGetProp (pMsg=0x7ffff0005770, pTpe=0x6d37a0, pProp=0x6d37c0, pPropLen=0x7ffff5bcfb0c, pbMustBeFreed=0x7ffff5bcfb1e, ttNow=<value optimized out>)
    at msg.c:3264
3264                            pRes = getRcvFromIP(pMsg);
Value returned is $21 = (uchar *) 0x496a5d ""

PS: it's super easy to setup such a test env with docker, and here are the list I installed on top of en empty ubuntu:14.04 image to build rsyslog (from .bash_history):

apt-get install build-essential
apt-get install autoconf
apt-get install libtool
apt-get install zlib1g-dev
apt-get install pkg-config
apt-get install flex
apt-get install bison
apt-get install python-docutils
Contributor

ymattw commented Jan 6, 2016

Weird .. I reproduced this on ubuntu 14.04.3 as well, from inside docker container, where gethostname() works totally fine.

With gdb I see the call trace is as below, the resolveDNS() call does nothing real because pMsg->msgFlags is always 0. I tried git grep that flag but got lost soon. This is low priority for me as I have an easy workaround (writing the values in template with a startup script), hope you can figure out what's going wrong.

(gdb) bt
#0  resolveDNS (pM=0x7ffff0005770) at msg.c:479
#1  getRcvFromIP (pM=0x7ffff0005770) at msg.c:523
#2  0x000000000041f51f in MsgGetProp (pMsg=0x7ffff0005770, pTpe=0x6d37a0, pProp=0x6d37c0, pPropLen=0x7ffff5bcfb0c, pbMustBeFreed=0x7ffff5bcfb1e, ttNow=<value optimized out>)
    at msg.c:3264
#3  0x00000000004460d1 in tplToString (pTpl=0x6d2d20, pMsg=0x7ffff0005770, iparam=0x7fffec002080, ttNow=0x7ffff5bcfbd0) at ../template.c:195
#4  0x0000000000441e1b in prepareDoActionParams (pAction=0x6d0170, pWti=0x6d6ed0, pMsg=0x7ffff0005770, ttNow=0x7ffff5bcfbd0) at ../action.c:937
#5  processMsgMain (pAction=0x6d0170, pWti=0x6d6ed0, pMsg=0x7ffff0005770, ttNow=0x7ffff5bcfbd0) at ../action.c:1303
#6  0x0000000000442481 in processBatchMain (pVoid=0x6d0170, pBatch=0x6d6f08, pWti=0x6d6ed0) at ../action.c:1347
#7  0x00000000004398b4 in ConsumerReg (pThis=0x6d0710, pWti=0x6d6ed0) at queue.c:1898
#8  0x0000000000433cf5 in wtiWorker (pThis=0x6d6ed0) at wti.c:334
#9  0x000000000043284e in wtpWorker (arg=0x6d6ed0) at wtp.c:389
#10 0x00007ffff7bc7a51 in start_thread () from /lib64/libpthread.so.0
#11 0x00007ffff750893d in clone () from /lib64/libc.so.6
(gdb) l
474             prop_t *localName;
475             DEFiRet;
476
477             MsgLock(pMsg);
478             CHKiRet(objUse(net, CORE_COMPONENT));
479             if(pMsg->msgFlags & NEEDS_DNSRESOL) {
480                     localRet = net.cvthname(pMsg->rcvFrom.pfrominet, &localName, NULL, &ip);
481                     if(localRet == RS_RET_OK) {
482                             /* we pass down the props, so no need for AddRef */
483                             MsgSetRcvFromWithoutAddRef(pMsg, localName);
(gdb) p pMsg->msgFlags
$18 = 0
(gdb) fin
Run till exit from #0  resolveDNS (pM=0x7ffff0005770) at msg.c:493
524                     if(pM->pRcvFromIP == NULL)
(gdb) p pM->pRcvFromIP
$20 = (prop_t *) 0x0
(gdb)

(gdb) fin
Run till exit from #0  getRcvFromIP (pM=0x7ffff0005770) at msg.c:524
0x000000000041f51f in MsgGetProp (pMsg=0x7ffff0005770, pTpe=0x6d37a0, pProp=0x6d37c0, pPropLen=0x7ffff5bcfb0c, pbMustBeFreed=0x7ffff5bcfb1e, ttNow=<value optimized out>)
    at msg.c:3264
3264                            pRes = getRcvFromIP(pMsg);
Value returned is $21 = (uchar *) 0x496a5d ""

PS: it's super easy to setup such a test env with docker, and here are the list I installed on top of en empty ubuntu:14.04 image to build rsyslog (from .bash_history):

apt-get install build-essential
apt-get install autoconf
apt-get install libtool
apt-get install zlib1g-dev
apt-get install pkg-config
apt-get install flex
apt-get install bison
apt-get install python-docutils
@elain

This comment has been minimized.

Show comment
Hide comment
@elain

elain Jan 13, 2016

Has this problem been solved? I've had the same problem.

elain commented Jan 13, 2016

Has this problem been solved? I've had the same problem.

@zacharyzhao

This comment has been minimized.

Show comment
Hide comment
@zacharyzhao

zacharyzhao Jan 13, 2016

Contributor

@elain Before the problem is fixed, it can be a temporary solution to use a placeholder in template file, and replace it with external IP by start script.

external_ip=$(echo $(/sbin/ip route get 1.1.1.1 | sed -n 's/.* src //p'))

Taught by @ymattw :-)

Contributor

zacharyzhao commented Jan 13, 2016

@elain Before the problem is fixed, it can be a temporary solution to use a placeholder in template file, and replace it with external IP by start script.

external_ip=$(echo $(/sbin/ip route get 1.1.1.1 | sed -n 's/.* src //p'))

Taught by @ymattw :-)

@rgerhards rgerhards closed this Oct 1, 2017

@tomjonandy

This comment has been minimized.

Show comment
Hide comment
@tomjonandy

tomjonandy Nov 23, 2017

I have just come across this in 8.30.0. imfile is not filling the fromhost-ip property as 127.0.0.1, and so the logs are filtered as if they are from a remote host:

Relevant config files:

01-netconsole.conf

$ModLoad imudp
$UDPServerRun 6666
:fromhost-ip, !isequal, "127.0.0.1"  /var/log/remote.log
& ~

49-irods-elk.conf

local6.info                @@remote.example:11514
& ~
$WorkDirectory /var/spool/rsyslog
module(load="imfile" PollingInterval="10")

input(type="imfile"
 File="/var/lib/irods/iRODS/server/log/rodsLog.*"
 Tag="iRODS-rodsLog"
 Severity="info"
 Facility="local6"
)
input(type="imfile"
 File="/var/lib/irods/iRODS/server/log/reLog.*"
 Tag="iRODS-reLog"
 Severity="info"
 Facility="local6"
 readmode="2"
)

Full debug logs

rsyslogdebug.txt

The relevant section

9199.546242668:imfile.c       : imfile.c: INOTIFY event: watch was MODIFID
9199.546258066:imfile.c       : imfile.c: imfile: in_processEvent process Event 2 for 
9199.546273123:imfile.c       : strm 0x7f5590005960: stream.c: file 11 read 19 bytes
9199.546347681:imfile.c       : ratelimit.c: RRRRRR: localRet 0
9199.546354185:imfile.c       : strm 0x7f5590005960: stream.c: file 11 read 0 bytes
9199.546365514:imfile.c       : stream.c: stream checking for file change on '/var/lib/irods/iRODS/server/log/rodsLog.2017.11.21', inode 131126/131126
9199.546371767:imfile.c       : main Q: queue.c: qqueueAdd: entry added, size now log 1, phys 1 entries
9199.546382074:imfile.c       : main Q: queue.c: MultiEnqObj advised worker start
9199.546403316:main Q:Reg/w0  : wti 0x78f540: wti.c: worker awoke from idle processing
9199.546410173:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
9199.546413782:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
9199.546419391:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
9199.546422668:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: This is a test log
9199.546427217:main Q:Reg/w0  : rainerscript.c:     PROPFILT
9199.546433581:main Q:Reg/w0  : rainerscript.c:         Property.: 'fromhost-ip'
9199.546440482:main Q:Reg/w0  : rainerscript.c:         Operation: NOT 'isequal'
9199.546450248:main Q:Reg/w0  : rainerscript.c:         Value....: '127.0.0.1'
9199.546459848:main Q:Reg/w0  : ruleset.c: Filter: check for property 'fromhost-ip' (value '') NOT isequal '127.0.0.1': TRUE
9199.546466529:main Q:Reg/w0  : ruleset.c: PROPFILT condition result is 1
9199.546469839:main Q:Reg/w0  : rainerscript.c:     ACTION 0 [builtin:omfile:/var/log/remote.log]
9199.546477952:main Q:Reg/w0  : ruleset.c: executing action 0
9199.546482349:main Q:Reg/w0  : ../action.c: action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
9199.546492440:main Q:Reg/w0  : ../action.c: action 'action 0': is transactional - executing in commit phase
9199.546499742:main Q:Reg/w0  : ../action.c: wti 0x78f540: we need to create a new action worker instance for action 0
9199.546503733:main Q:Reg/w0  : ../action.c: wti 0x78f540: created action worker instance 1 for action 0
9199.546507259:main Q:Reg/w0  : ../action.c: action[action 0] transitioned to state: itx
9199.546510482:main Q:Reg/w0  : ../action.c: action 'action 0': set suspended state to 0
9199.546513175:main Q:Reg/w0  : rainerscript.c:     STOP
9199.546519795:main Q:Reg/w0  : ruleset.c: END batch execution phase, entering to commit phase [processed 1 of 1 messages]
9199.546523018:main Q:Reg/w0  : ../action.c: actionCommitAllDirect: action 0, state 1, nbr to commit 1 isTransactional 1
9199.546526413:main Q:Reg/w0  : ../action.c: actionCommit[action 0]: enter, 1 msgs
9199.546529365:main Q:Reg/w0  : ../action.c: actionCommit[action 0]: processing...
9199.546532308:main Q:Reg/w0  : ../action.c: actionTryCommit[action 0] enter
9199.546545221:main Q:Reg/w0  : ../action.c: doTransaction: have commitTransaction IF, using that, pWrkrInfo 0x78f5f0
9199.546548426:main Q:Reg/w0  : ../action.c: entering actionCallCommitTransaction[action 0], state: itx, nMsgs 1
9199.546564793:main Q:Reg/w0  : stream.c: file stream remote.log params: flush interval 0, async write 0
9199.546572037:main Q:Reg/w0  : omfile.c: omfile: write to stream, pData->pStrm 0x7f5588005200, lenBuf 62, strt data Nov 23 12:13:19 ta10-precise iRODS-rodsLog This is a test log

tomjonandy commented Nov 23, 2017

I have just come across this in 8.30.0. imfile is not filling the fromhost-ip property as 127.0.0.1, and so the logs are filtered as if they are from a remote host:

Relevant config files:

01-netconsole.conf

$ModLoad imudp
$UDPServerRun 6666
:fromhost-ip, !isequal, "127.0.0.1"  /var/log/remote.log
& ~

49-irods-elk.conf

local6.info                @@remote.example:11514
& ~
$WorkDirectory /var/spool/rsyslog
module(load="imfile" PollingInterval="10")

input(type="imfile"
 File="/var/lib/irods/iRODS/server/log/rodsLog.*"
 Tag="iRODS-rodsLog"
 Severity="info"
 Facility="local6"
)
input(type="imfile"
 File="/var/lib/irods/iRODS/server/log/reLog.*"
 Tag="iRODS-reLog"
 Severity="info"
 Facility="local6"
 readmode="2"
)

Full debug logs

rsyslogdebug.txt

The relevant section

9199.546242668:imfile.c       : imfile.c: INOTIFY event: watch was MODIFID
9199.546258066:imfile.c       : imfile.c: imfile: in_processEvent process Event 2 for 
9199.546273123:imfile.c       : strm 0x7f5590005960: stream.c: file 11 read 19 bytes
9199.546347681:imfile.c       : ratelimit.c: RRRRRR: localRet 0
9199.546354185:imfile.c       : strm 0x7f5590005960: stream.c: file 11 read 0 bytes
9199.546365514:imfile.c       : stream.c: stream checking for file change on '/var/lib/irods/iRODS/server/log/rodsLog.2017.11.21', inode 131126/131126
9199.546371767:imfile.c       : main Q: queue.c: qqueueAdd: entry added, size now log 1, phys 1 entries
9199.546382074:imfile.c       : main Q: queue.c: MultiEnqObj advised worker start
9199.546403316:main Q:Reg/w0  : wti 0x78f540: wti.c: worker awoke from idle processing
9199.546410173:main Q:Reg/w0  : queue.c: DeleteProcessedBatch: we deleted 0 objects and enqueued 0 objects
9199.546413782:main Q:Reg/w0  : queue.c: doDeleteBatch: delete batch from store, new sizes: log 1, phys 1
9199.546419391:main Q:Reg/w0  : ruleset.c: processBATCH: batch of 1 elements must be processed
9199.546422668:main Q:Reg/w0  : ruleset.c: processBATCH: next msg 0: This is a test log
9199.546427217:main Q:Reg/w0  : rainerscript.c:     PROPFILT
9199.546433581:main Q:Reg/w0  : rainerscript.c:         Property.: 'fromhost-ip'
9199.546440482:main Q:Reg/w0  : rainerscript.c:         Operation: NOT 'isequal'
9199.546450248:main Q:Reg/w0  : rainerscript.c:         Value....: '127.0.0.1'
9199.546459848:main Q:Reg/w0  : ruleset.c: Filter: check for property 'fromhost-ip' (value '') NOT isequal '127.0.0.1': TRUE
9199.546466529:main Q:Reg/w0  : ruleset.c: PROPFILT condition result is 1
9199.546469839:main Q:Reg/w0  : rainerscript.c:     ACTION 0 [builtin:omfile:/var/log/remote.log]
9199.546477952:main Q:Reg/w0  : ruleset.c: executing action 0
9199.546482349:main Q:Reg/w0  : ../action.c: action 'action 0': called, logging to builtin:omfile (susp 0/0, direct q 1)
9199.546492440:main Q:Reg/w0  : ../action.c: action 'action 0': is transactional - executing in commit phase
9199.546499742:main Q:Reg/w0  : ../action.c: wti 0x78f540: we need to create a new action worker instance for action 0
9199.546503733:main Q:Reg/w0  : ../action.c: wti 0x78f540: created action worker instance 1 for action 0
9199.546507259:main Q:Reg/w0  : ../action.c: action[action 0] transitioned to state: itx
9199.546510482:main Q:Reg/w0  : ../action.c: action 'action 0': set suspended state to 0
9199.546513175:main Q:Reg/w0  : rainerscript.c:     STOP
9199.546519795:main Q:Reg/w0  : ruleset.c: END batch execution phase, entering to commit phase [processed 1 of 1 messages]
9199.546523018:main Q:Reg/w0  : ../action.c: actionCommitAllDirect: action 0, state 1, nbr to commit 1 isTransactional 1
9199.546526413:main Q:Reg/w0  : ../action.c: actionCommit[action 0]: enter, 1 msgs
9199.546529365:main Q:Reg/w0  : ../action.c: actionCommit[action 0]: processing...
9199.546532308:main Q:Reg/w0  : ../action.c: actionTryCommit[action 0] enter
9199.546545221:main Q:Reg/w0  : ../action.c: doTransaction: have commitTransaction IF, using that, pWrkrInfo 0x78f5f0
9199.546548426:main Q:Reg/w0  : ../action.c: entering actionCallCommitTransaction[action 0], state: itx, nMsgs 1
9199.546564793:main Q:Reg/w0  : stream.c: file stream remote.log params: flush interval 0, async write 0
9199.546572037:main Q:Reg/w0  : omfile.c: omfile: write to stream, pData->pStrm 0x7f5588005200, lenBuf 62, strt data Nov 23 12:13:19 ta10-precise iRODS-rodsLog This is a test log
@deoren

This comment has been minimized.

Show comment
Hide comment
@deoren

deoren Nov 26, 2017

Contributor

@alorbach @rgerhards I was just bitten by this as well on an Ubuntu 16.04 VM with rsyslog 8.30.0 (Adiscon PPA). I tested with the latest nightly build also (Adiscon PPA).

Here is my test configuration:

$DebugLevel 2
$DebugFile /var/log/rsyslog-debug-full.log

global (
        maxMessageSize="128k"
        action.reportSuspension="on"
        action.reportSuspensionContinuation="on"
        workDirectory="/var/spool/rsyslog"
        processInternalMessages="off"
        parser.permitSlashInProgramName="on"
)

$ActionFileDefaultTemplate RSYSLOG_FileFormat

$RepeatedMsgReduction off

$FileOwner syslog
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022

# rsyslog starts as root, but will attempt to drop privileges to the specified
# user and group if the name-to-id lookup succeeds.
$PrivDropToUser syslog
$PrivDropToGroup syslog

$WorkDirectory /var/spool/rsyslog


module(
    load="impstats"
    interval="30"
    log.syslog="off"
    log.file="/var/log/rsyslog-pstats.log"
)

module(
    load="imuxsock"
    sysSock.use="on"
    SysSock.Annotate="on"
    SysSock.ParseTrusted="on"
)

module(load="imklog" permitnonkernelfacility="on")
module(load="immark")
module(load="imfile")

module(load="mmjsonparse")

module(
    load="builtin:omfile"
    fileOwner="syslog"
    fileGroup="adm"
    dirOwner="syslog"
    dirGroup="adm"
    fileCreateMode="0640"
    dirCreateMode="0755"
)

module(load="omrelp")

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/history.log"
    Tag="apt-history"
    Facility="local7"
    addMetadata="on"
)

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/term.log"
    Tag="apt-term"
    Facility="local7"
    addMetadata="on"
)

# Capture client-side values before forwarding as we will expand them
# later when referencing from templates (some client-side, some receiver).
if ($fromhost-ip == "127.0.0.1") then {

    # Needed here for client-side templates. Receiver rulesets first use
    # a dedicated ruleset to perform a lookup against a JSON table to
    # retrieve a hostname value via source IP used as a search key.
    set $.hostname = $$myhostname;
    set $.ipaddr = "127.0.0.1";

    set $.tag = $syslogtag;
    set $!tag = $.tag;

    # Capture original message (minus leading spaces) since the JSON payload
    # will occupy the entire message and we will want to refer to the original
    # message in its entirety later on.
    set $.msg = ltrim($msg);
    set $!msg = $.msg;


}

action(
    name="rsyslog-debug-local"
    template="RSYSLOG_DebugFormat"
    type="omfile"
    file="/var/log/rsyslog-debug-imfile-apt-history.log"
)

I suspect it could be trimmed further, but I've been able to replicate the issue with this config, so going ahead and posting it now while I have a few minutes to do so.

Here is the debug log:

rsyslog-debug-full.log

Contributor

deoren commented Nov 26, 2017

@alorbach @rgerhards I was just bitten by this as well on an Ubuntu 16.04 VM with rsyslog 8.30.0 (Adiscon PPA). I tested with the latest nightly build also (Adiscon PPA).

Here is my test configuration:

$DebugLevel 2
$DebugFile /var/log/rsyslog-debug-full.log

global (
        maxMessageSize="128k"
        action.reportSuspension="on"
        action.reportSuspensionContinuation="on"
        workDirectory="/var/spool/rsyslog"
        processInternalMessages="off"
        parser.permitSlashInProgramName="on"
)

$ActionFileDefaultTemplate RSYSLOG_FileFormat

$RepeatedMsgReduction off

$FileOwner syslog
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022

# rsyslog starts as root, but will attempt to drop privileges to the specified
# user and group if the name-to-id lookup succeeds.
$PrivDropToUser syslog
$PrivDropToGroup syslog

$WorkDirectory /var/spool/rsyslog


module(
    load="impstats"
    interval="30"
    log.syslog="off"
    log.file="/var/log/rsyslog-pstats.log"
)

module(
    load="imuxsock"
    sysSock.use="on"
    SysSock.Annotate="on"
    SysSock.ParseTrusted="on"
)

module(load="imklog" permitnonkernelfacility="on")
module(load="immark")
module(load="imfile")

module(load="mmjsonparse")

module(
    load="builtin:omfile"
    fileOwner="syslog"
    fileGroup="adm"
    dirOwner="syslog"
    dirGroup="adm"
    fileCreateMode="0640"
    dirCreateMode="0755"
)

module(load="omrelp")

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/history.log"
    Tag="apt-history"
    Facility="local7"
    addMetadata="on"
)

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/term.log"
    Tag="apt-term"
    Facility="local7"
    addMetadata="on"
)

# Capture client-side values before forwarding as we will expand them
# later when referencing from templates (some client-side, some receiver).
if ($fromhost-ip == "127.0.0.1") then {

    # Needed here for client-side templates. Receiver rulesets first use
    # a dedicated ruleset to perform a lookup against a JSON table to
    # retrieve a hostname value via source IP used as a search key.
    set $.hostname = $$myhostname;
    set $.ipaddr = "127.0.0.1";

    set $.tag = $syslogtag;
    set $!tag = $.tag;

    # Capture original message (minus leading spaces) since the JSON payload
    # will occupy the entire message and we will want to refer to the original
    # message in its entirety later on.
    set $.msg = ltrim($msg);
    set $!msg = $.msg;


}

action(
    name="rsyslog-debug-local"
    template="RSYSLOG_DebugFormat"
    type="omfile"
    file="/var/log/rsyslog-debug-imfile-apt-history.log"
)

I suspect it could be trimmed further, but I've been able to replicate the issue with this config, so going ahead and posting it now while I have a few minutes to do so.

Here is the debug log:

rsyslog-debug-full.log

@rgerhards

This comment has been minimized.

Show comment
Hide comment
@rgerhards

rgerhards Nov 26, 2017

Member

:-) for the debug log!

Member

rgerhards commented Nov 26, 2017

:-) for the debug log!

@rgerhards rgerhards reopened this Nov 26, 2017

@rgerhards rgerhards added this to the v8.32 milestone Nov 26, 2017

@deoren

This comment has been minimized.

Show comment
Hide comment
@deoren

deoren Nov 26, 2017

Contributor

@rgerhards Welcome! Thanks for reopening this issue. Pease let me know if you have any changes you'd like to have tested and I'll give them a try.

Contributor

deoren commented Nov 26, 2017

@rgerhards Welcome! Thanks for reopening this issue. Pease let me know if you have any changes you'd like to have tested and I'll give them a try.

deoren added a commit to deoren/rsyslog-examples that referenced this issue Nov 27, 2017

Add example conf file
This is the example conf file that was posted to rsyslog/rsyslog#545.
@rgerhards

This comment has been minimized.

Show comment
Hide comment
@rgerhards

rgerhards Dec 19, 2017

Member

@deoren would it be possible to strip the config down so that imfile is the only input? It would be great if we could then reproduce the issue. I have just waded trough the debug log, and it really is very hard to grasp (not complaining, I am happy I have one ;-)).

Member

rgerhards commented Dec 19, 2017

@deoren would it be possible to strip the config down so that imfile is the only input? It would be great if we could then reproduce the issue. I have just waded trough the debug log, and it really is very hard to grasp (not complaining, I am happy I have one ;-)).

@deoren

This comment has been minimized.

Show comment
Hide comment
@deoren

deoren Dec 19, 2017

Contributor

@rgerhards I will try to get this done later today or tomorrow and report back.

Contributor

deoren commented Dec 19, 2017

@rgerhards I will try to get this done later today or tomorrow and report back.

@deoren

This comment has been minimized.

Show comment
Hide comment
@deoren

deoren Dec 20, 2017

Contributor

Conf file: deoren/rsyslog-examples@cfd6724

Posting here for easy access:

# Example config file used to reproduce the issue noted on rsyslog/rsyslog#545

$DebugLevel 2
$DebugFile /var/log/rsyslog-debug-full.log

global (
        maxMessageSize="128k"
        action.reportSuspension="on"
        action.reportSuspensionContinuation="on"
        workDirectory="/var/spool/rsyslog"
        processInternalMessages="off"
        parser.permitSlashInProgramName="on"
)

$ActionFileDefaultTemplate RSYSLOG_FileFormat

$RepeatedMsgReduction off

# rsyslog starts as root, but will attempt to drop privileges to the specified
# user and group if the name-to-id lookup succeeds.
$PrivDropToUser syslog
$PrivDropToGroup syslog

module(load="imfile")

module(
    load="builtin:omfile"
    fileOwner="syslog"
    fileGroup="adm"
    dirOwner="syslog"
    dirGroup="adm"
    fileCreateMode="0640"
    dirCreateMode="0755"
)

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/history.log"
    Tag="apt-history"
    Facility="local7"
    addMetadata="on"
)

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/term.log"
    Tag="apt-term"
    Facility="local7"
    addMetadata="on"
)

# Capture client-side values before forwarding as we will expand them
# later when referencing from templates (some client-side, some receiver).
if ($fromhost-ip == "127.0.0.1") then {

    # Needed here for client-side templates. Receiver rulesets first use
    # a dedicated ruleset to perform a lookup against a JSON table to
    # retrieve a hostname value via source IP used as a search key.
    set $.hostname = $$myhostname;
    set $.ipaddr = "127.0.0.1";

    set $.tag = $syslogtag;
    set $!tag = $.tag;

    # Capture original message since the JSON payload
    # will occupy the entire message and we will want to refer to the original
    # message in its entirety later on.
    set $.msg = $msg;
    set $!msg = $.msg;


}

action(
    name="rsyslog-debug-local"
    template="RSYSLOG_DebugFormat"
    type="omfile"
    file="/var/log/rsyslog-debug-imfile-apt-history.log"
)

Debug logs: rsyslog-debug-logs-github-issue-545.zip

Inside the zip file is the standard full debug log and a log file generated using the RSYSLOG_DebugFormat template that highlights the missing values.

Contributor

deoren commented Dec 20, 2017

Conf file: deoren/rsyslog-examples@cfd6724

Posting here for easy access:

# Example config file used to reproduce the issue noted on rsyslog/rsyslog#545

$DebugLevel 2
$DebugFile /var/log/rsyslog-debug-full.log

global (
        maxMessageSize="128k"
        action.reportSuspension="on"
        action.reportSuspensionContinuation="on"
        workDirectory="/var/spool/rsyslog"
        processInternalMessages="off"
        parser.permitSlashInProgramName="on"
)

$ActionFileDefaultTemplate RSYSLOG_FileFormat

$RepeatedMsgReduction off

# rsyslog starts as root, but will attempt to drop privileges to the specified
# user and group if the name-to-id lookup succeeds.
$PrivDropToUser syslog
$PrivDropToGroup syslog

module(load="imfile")

module(
    load="builtin:omfile"
    fileOwner="syslog"
    fileGroup="adm"
    dirOwner="syslog"
    dirGroup="adm"
    fileCreateMode="0640"
    dirCreateMode="0755"
)

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/history.log"
    Tag="apt-history"
    Facility="local7"
    addMetadata="on"
)

input(
    type="imfile"
    readMode="1"
    File="/var/log/apt/term.log"
    Tag="apt-term"
    Facility="local7"
    addMetadata="on"
)

# Capture client-side values before forwarding as we will expand them
# later when referencing from templates (some client-side, some receiver).
if ($fromhost-ip == "127.0.0.1") then {

    # Needed here for client-side templates. Receiver rulesets first use
    # a dedicated ruleset to perform a lookup against a JSON table to
    # retrieve a hostname value via source IP used as a search key.
    set $.hostname = $$myhostname;
    set $.ipaddr = "127.0.0.1";

    set $.tag = $syslogtag;
    set $!tag = $.tag;

    # Capture original message since the JSON payload
    # will occupy the entire message and we will want to refer to the original
    # message in its entirety later on.
    set $.msg = $msg;
    set $!msg = $.msg;


}

action(
    name="rsyslog-debug-local"
    template="RSYSLOG_DebugFormat"
    type="omfile"
    file="/var/log/rsyslog-debug-imfile-apt-history.log"
)

Debug logs: rsyslog-debug-logs-github-issue-545.zip

Inside the zip file is the standard full debug log and a log file generated using the RSYSLOG_DebugFormat template that highlights the missing values.

@rgerhards rgerhards added the imfile label Jan 1, 2018

@rgerhards rgerhards added this to To Do in imfile refactoring Jan 4, 2018

@rgerhards rgerhards modified the milestones: v8.32, v8.33 Jan 4, 2018

@rgerhards rgerhards modified the milestones: v8.33, v8.34 Feb 15, 2018

@rgerhards rgerhards modified the milestones: v8.34, v8.35 Apr 3, 2018

@rgerhards rgerhards modified the milestones: v8.35, v8.36 May 14, 2018

@rgerhards rgerhards modified the milestones: v8.36, v8.37 Jun 25, 2018

@rgerhards rgerhards modified the milestones: v8.37, v8.38 Aug 3, 2018

@rgerhards rgerhards modified the milestones: v8.38, v8.39 Sep 18, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment