syslog format

[solganik]

Use rfc5424 log format for syslog.
Previously docker used obsolete rfc3164 syslog format for syslog. rfc3164 explicitly
uses semicolon as a separator between 'TAG' and 'Content' section of the log message.
Docker uses semicolon as a separator between image name and version tag.
When {{.ImageName}} was used as a tag expression and contained ":" syslog parser mistreated
"tag" part of the image name as syslog message body, which resulted in incorrect "syslogtag" been reported by syslog
daemon.
Use of rfc5424 log format partually fixes the issue as it does not use semicolon as a separator.
However using default rfc5424 syslog format itroduces backward incompatability because rsyslog template keyword %syslogtag%
is parsed differently. In rfc3164 it uses the "TAG" part reported before the "pid" part. In rfc5424 it uses "appname" part reported
before the pid part, while tag part is introduced by %msgid% part.
For more information on rsyslog configuration properties see: http://www.rsyslog.com/doc/master/configuration/properties.html

[calavera]

I think this also can fix #20053.

[solganik]

@calavera , yes it seems that it is caused by the same semicolon separator.

[calavera]

@solganik you need to run hack/vendor.sh to properly vendor that dependency.

[solganik]

@calavera thanks, fixing

[tiborvass]

@solganik so are you sure this PR will keep backwards compatibility with all syslog readers?

[solganik]

@tiborvass I`m not a syslog expert. however semicolon usage if rfc3164 protocol will not play well with semicolons within the 'TAG' and this is the only solution i was able to find.
Maybe only to use rfc5424 if tag is specified ? else fallback to default one. (which is rfc3164)?
Note that i had added a small "modification" to the Rackspace formatter in order to try to keep backward compatibility of the issue i was able to think about.

[solganik]

how can i re-run the "expiremental" job ? as it seems to experience some issue i suspect unrelated to my PR.

[tiborvass]

@solganik there rebuilt experimental for you.

[tiborvass]

I am not sure I like using tag for APP-NAME: https://tools.ietf.org/html/rfc5424#page-14

@solganik Is there a way of escaping the : in the old rfc ?

[solganik]

Hi @tiborvass check out the rtsyslog source code here
https://github.com/rsyslog/rsyslog/blob/6ff6ae9187de39a912fc1cd2a55fa21c05dc8c46/tools/pmrfc3164.c#L300

The way around this might be to replace the colon separator in the Image name with something else.
However this might create futher issues with programs that will parse the output of rsyslog and collate image names with actual names.

Note also that putting "appname" in application name does not make sense as the reporting unit is "docker service" .. which dost not really bring any additional info as this is not the "application". (workload), moreover image name often is the "workload" identifier, which perfectly suites the APPNAME meaning.

[solganik]

moreover even if you ignore linux implementation and get aligned with rfc 3164, it states:
"It has also been considered to be a good practice to include some
information about the process on the device that generated the
message - if that concept exists. This is usually the process name
and process id (often known as the "pid") for robust operating
systems. The process name is commonly displayed in the TAG field.
Which in docker retrospective was the tag provided in command line.
I mean that prior to my changes what was recommended as "APP NAME" by rfc 3164 was used by docker as a tag.

[tiborvass]

@solganik thanks for the pointer to the syslog code. That means that : is never escaped.

The way around this might be to replace the colon separator in the Image name with something else.

That's not going to happen in the docker code, since we already use that separator.

I mean that prior to my changes what was recommended as "APP NAME" by rfc 3164 was used by docker as a tag.

So are you saying this to show that it's fine to use TAG as APP-NAME? If that's the case then fine, but it's a pity we'd be using TAG twice (from what i understand from your code)

[solganik]

@tiborvass the reason to use the TAG twice is in order to comply with the RFC. We can omit the second tag, putting NILVALUE = "-" instead as suggested by rfc, but what would be the gain of doing so ?

[thaJeztah]

Should we change the format in a .1 release? Looking at #20053, I wonder if we should just strip the sha256: from the image-ID, if there's no way to escape :

[solganik]

@thaJeztah please note that maxim length of rsyslogtag is
#define CONF_TAG_BUFSIZE 32
https://github.com/rsyslog/rsyslog/blob/c7b455524ba54aca27f7a98b5480f10a1db5d507/runtime/rsyslog.h#L48 while sha256 length is 64 characters if i`m not mistaken. so it will be truncated.

[calavera]

@thaJeztah, @tiborvass I think we should not add this change as a fix for #20053. The parsing issue is very unfortunate, but we should not change the format in the patch release. After all, it's not really a bug in the syslog logger implementation, it works as expected, it's an issue with the user defined tag.

See #20053 (comment)

[icecrime]

@tiborvass @calavera Am I correct in my understanding that we shouldn't proceed with this PR as per your comments above?

[solganik]

@calavera The problem will also suffice if colon is used in "repository name", which can be if you are using custom docker repository in non standard port, the ":" serves as a host port separator as well.
I dont think it is an expected behaviour as there would be cases when it is important to know what is the image (and the tag) of the reporting docker.

One proposal can be to keep the rfc 3164 for standard tag (which is id) and only use rfc5424 when non standard tag is used.

[solganik]

One more crazy alternative would be to add an additional parameter and allow user to specify the rfc that he wants to use for syslog.

[thaJeztah]

@solganik I'm not against changing the rfc, or making it configurable, but we should look into it and I don't think we should change to a different rfc in a patch release

[cpuguy83]

Definitely should not change the format from the default, but seems fine to add an option to switch between the two.

From past discussions it seems like this is a hot-button issue between people who need 1 RFC vs the other.

[thaJeztah]

ping @solganik can you update this PR to make the format configurable through an option?

[solganik]

@thaJeztah any preffered name to the flag ?

[solganik]

done

[thaJeztah]

sigh, network issues on Janky

libsystemd-journal-dev amd64 215-17+deb8u3 [30.5 kB]
20:35:07 E: Failed to fetch http://httpredir.debian.org/debian/pool/main/p/python2.7/python2.7-minimal_2.7.9-2_amd64.deb  Error reading from server. Remote end closed connection [IP: 5.153.231.35 80]
20:35:07 
20:35:07 E: Unable to fetch some archives, maybe run apt-get update o

[thaJeztah]

WindowsTP4 had network issues as well 😢

20:34:52 ---> Making bundle: validate-dco (in bundles/1.11.0-dev/validate-dco)
20:34:53 fatal: unable to access 'https://github.com/docker/docker.git/': Couldn't resolve host 'github.com'

[thaJeztah]

Restarted CI for those, fingers crossed

[sashas-lb]

@thaJeztah seems like all checks had passed ..

[thaJeztah]

ping @calavera @cpuguy83 ptal 👍

(@sashas-lb yay, it did! removed the "failing-ci" label \o/)

[calavera]

LGTM

[cpuguy83]

If a non-unix address is specified, should we default to the 3164 format or were we always sending a unix format? Not sure I follow what the old code did.

[calavera]

this should probably be syslog.DefaultFormatter to keep backwards compatibility, shouldn't it?

[calavera]

actually, this should probably be under the default: case. Because empty string is the default value.

[solganik]

Hi, @calavera @thaJeztah: current format keeps srslog behaviour as before the changes, please checkout the srs old code:
https://github.com/RackSec/srslog/blob/1155efef850aadc39aa84576f83a595a6fbdce74/srslog_unix.go#L42
formatter: "<%d>%s %s[%d]: %s"
timestamp := time.Now().Format(time.Stamp)

Now for the master srslog code:
https://github.com/RackSec/srslog/blob/master/formatter.go
default: "<%d> %s %s %s[%d]: %s"
timestamp := time.Now().Format(time.RFC3339)
unix "<%d>%s %s[%d]: %s"
timestamp := time.Now().Format(time.Stamp)
rfc3164 "<%d> %s %s %s[%d]: %s"
timestamp := time.Now().Format(time.Stamp)

So current code which defaults to unixformatter actually preserves original docker behaviour.

[thaJeztah]

@calavera but moving it under default doesn't catch the "default", it catches anything that isn't defined, so --log-format=bogus would use the default, instead of producing an error?

[calavera]

makes sense.

[calavera]

LGTM

[cpuguy83]

LGTM

[camerondavison]

Was it intentional to switch from using the DefaultFormatter https://github.com/RackSec/srslog/blob/259aed10dfa74ea2961eddd1d9847619f6e98837/formatter.go#L17 to the UnixFormatter ? https://github.com/RackSec/srslog/blob/259aed10dfa74ea2961eddd1d9847619f6e98837/formatter.go#L25

For the default ""? f500951#diff-204077a41ab69608a9d60e20344fab80R238

[sashas-lb]

As far as i remember the "old" default formater became "unix fomater". I mean for "content" of course, check "default" formatter at the "previous" hash of syslogf package that is in use by docker.

[camerondavison]

It at least changed from time.Now().Format(time.RFC3339) to time.Now().Format(time.Stamp)

[sashas-lb]

I see where all confusion is from :

1. if you check verndoring than previois commit of srslog was:
   https://github.com/RackSec/srslog/blob/6eb773f331e46fbba8eecb8e794e635e75fc04de/srslog_unix.go

See this:
https://github.com/docker/docker/pull/20121/files#diff-c36e523b64f1ca41293e912113063a92L28

-clone git github.com/RackSec/srslog 6eb773f331e46fbba8eecb8e794e635e75fc04de
+clone git github.com/RackSec/srslog 259aed10dfa74ea2961eddd1d9847619f6e98837

Now if you check the relevant file of the "6eb773f331e46fbba8eecb8e794e635e75fc04de" commit in srslog project you will see that the formatter they use is:
https://github.com/RackSec/srslog/blob/6eb773f331e46fbba8eecb8e794e635e75fc04de/srslog_unix.go#L34

timestamp := time.Now().Format(time.Stamp)

But somehow in "docker" project itself the "copy" of srslog project used this:
https://github.com/docker/docker/pull/20121/files#diff-8fa8e2ea8405ded8a99d0154a1d46bc1L38

So de-facto seems that @a86c6f7964 is correct timestemp was in - timestamp := time.Now().Format(time.RFC3339)
before and + timestamp := time.Now().Format(time.Stamp)
now

If this is a critical issue i guess this can be fixed by creating cutome formatter to keep backwards compatability. Unrelated but @thaJeztah there is an issue with vendoring process.

[camerondavison]

I'm not sure it is a critical issue. I just wanted to bring it up for
future people looking at this issue to know.

On Thu, Jul 7, 2016, 2:55 AM sashas-lb notifications@github.com wrote:

I see where all confusion is from :

1. if you check verndoring than previois commit of srslog was:

https://github.com/RackSec/srslog/blob/6eb773f331e46fbba8eecb8e794e635e75fc04de/srslog_unix.go

See this:

https://github.com/docker/docker/pull/20121/files#diff-c36e523b64f1ca41293e912113063a92L28

-clone git github.com/RackSec/srslog
6eb773f331e46fbba8eecb8e794e635e75fc04de
+clone git github.com/RackSec/srslog
259aed10dfa74ea2961eddd1d9847619f6e98837

Now if you check the relevant file of the
"6eb773f331e46fbba8eecb8e794e635e75fc04de" commit in srslog project you
will see that the formatter they use is:

https://github.com/RackSec/srslog/blob/6eb773f331e46fbba8eecb8e794e635e75fc04de/srslog_unix.go#L34

timestamp := time.Now().Format(time.Stamp)

But somehow in "docker" project itself the "copy" of srslog project used
this:

https://github.com/docker/docker/pull/20121/files#diff-8fa8e2ea8405ded8a99d0154a1d46bc1L38

So de-facto seems that @a86c6f7964 https://github.com/a86c6f7964 is
correct timestemp was in - timestamp := time.Now().Format(time.RFC3339)
before and + timestamp := time.Now().Format(time.Stamp)
now

If this is a critical issue i guess this can be fixed by creating cutome
formatter to keep backwards compatability. Unrelated but @thaJeztah
https://github.com/thaJeztah there is an issue with vendoring process.

—
You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub
#20121 (comment), or mute
the thread
https://github.com/notifications/unsubscribe/AAKGBWU7u2cIqMSXYBxM8wAyDWHFk7m6ks5qTLD7gaJpZM4HV6B7
.