Syslog keys in rabbitmq.conf are rejected by schema validator

[Garagoth]

I tried to run syslog logger, with very strange results.

1. trying to specity log.syslog.ip, log.syslog.transport, log.syslog.protocol all result in:

Config file generation failed 15:59:56.550 [error] You've tried to set log.syslog.transport, but there is no setting with that name. 
15:59:56.550 [error] Did you mean one of these? 
15:59:56.575 [error] log.syslog.facility 
15:59:56.575 [error] log.syslog.identity 
15:59:56.575 [error] log.syslog.level 
15:59:56.575 [error] Error generating configuration in phase transform_datatypes 
15:59:56.576 [error] Conf file attempted to set unknown variable: log.syslog.transport

2. Setting up whole config using advanced config file worked, with one exception from documentation:
   It is required to write
   {syslog, [{protocol, {rfc3164, udp} }, ...
   version from docs suggesting {syslog, [{protocol, {udp, rfc3164} }, ... (different order of parameters) causes error:

  crasher:
    initial call: syslog_logger:init/1
    pid: <0.78.0>
    registered_name: []
    exception error: no function clause matching 
                     syslog_logger:open_device({rfc5424,[]},
                                               {state,undefined,
                                                #Ref<0.111759511.2413297668.26585>,
                                                {udp,rfc5424},
                                                {10,1,28,91},
                                                514}) (src/syslog_logger.erl, line 279)
      in function  syslog_logger:init/1 (src/syslog_logger.erl, line 202)

3. Both rfc3164 and rcf5424 formats look OK, but message field is bit messed up due to inclusion of severity in message itself, duplicating the information:

lager_event - [info] <0.406.0> Message store "A2VC0RQ0BWZV1PRT01XBOFR3H/msg_store_transient": using rabbit_msg_store_ets_index to provide index
Not every message thought, there are some like:
lager_event - rebuilding indices from scratch
lager_event - * rabbitmq_management
For rfc3164 message intercepted in wire looks like this:

Facility daemon (3), Severity info (6)
	Msg: <30>Jul 11 15:55:15 srv1-rabbitmq rabbitmq-srv1[426] lager_event - [info] <0.6683.0> Deleting message store directory for vhost '...' at '...'

For rfc5424 it looks like:

Facility daemon (3), Severity info (6)
	Msg: <30>1 2018-07-11T16:05:01.806397+02:00 srv1-rabbitmq.service.platform-lab.int rabbitmq-srv1 427 lager_event - [info] <0.370.0> rabbit on node 'rabbit@srv1-rabbitmq.service.platform-lab.int' up

Maybe it would be nice to add some extra (like conn_pid and logger_name) data in STRUCTURED-DATA as rfc5424 permits.
And maybe tag so programname is parsed as well...

=========================================================================

• RabbitMQ version - 3.7.7
• Erlang version - 20.3.8
• RabbitMQ server and client application log files
• RabbitMQ plugin information via rabbitmq-plugins list

[  ] rabbitmq_amqp1_0                  3.7.7
[  ] rabbitmq_auth_backend_cache       3.7.7
[  ] rabbitmq_auth_backend_http        3.7.7
[  ] rabbitmq_auth_backend_ldap        3.7.7
[  ] rabbitmq_auth_mechanism_ssl       3.7.7
[  ] rabbitmq_consistent_hash_exchange 3.7.7
[  ] rabbitmq_event_exchange           3.7.7
[  ] rabbitmq_federation               3.7.7
[  ] rabbitmq_federation_management    3.7.7
[  ] rabbitmq_jms_topic_exchange       3.7.7
[E*] rabbitmq_management               3.7.7
[e*] rabbitmq_management_agent         3.7.7
[  ] rabbitmq_mqtt                     3.7.7
[  ] rabbitmq_peer_discovery_aws       3.7.7
[e*] rabbitmq_peer_discovery_common    3.7.7
[E*] rabbitmq_peer_discovery_consul    3.7.7
[  ] rabbitmq_peer_discovery_etcd      3.7.7
[  ] rabbitmq_peer_discovery_k8s       3.7.7
[  ] rabbitmq_random_exchange          3.7.7
[  ] rabbitmq_recent_history_exchange  3.7.7
[  ] rabbitmq_sharding                 3.7.7
[  ] rabbitmq_shovel                   3.7.7
[  ] rabbitmq_shovel_management        3.7.7
[  ] rabbitmq_stomp                    3.7.7
[  ] rabbitmq_top                      3.7.7
[  ] rabbitmq_tracing                  3.7.7
[  ] rabbitmq_trust_store              3.7.7
[e*] rabbitmq_web_dispatch             3.7.7
[  ] rabbitmq_web_mqtt                 3.7.7
[  ] rabbitmq_web_mqtt_examples        3.7.7
[  ] rabbitmq_web_stomp                3.7.7
[  ] rabbitmq_web_stomp_examples       3.7.7

• Client library version (for all libraries used) - n/a
• Operating system, version, and patch level - running docker image from dockerhub: rabbitmq-management:3.7.7 (Linux 3.10.0-514.21.1.el7.x86_64, Debian GNU/Linux 9 (stretch))

[lukebakken]

For your first item, please provide the rabbitmq.conf file where you tried to set log.syslog.ip, log.syslog.transport and log.syslog.protocol. As you can see here and here, it should be supported.

[Garagoth]

Nothing serious in rabbitmq.conf:

# Cluster formation settings
cluster_formation.peer_discovery_backend = rabbit_peer_discovery_consul
cluster_formation.consul.host = 10.1.28.90
cluster_formation.consul.deregister_after = 300
cluster_formation.consul.svc_addr_auto = true
cluster_formation.consul.svc_addr_use_nodename = true
# use long RabbitMQ node names?
cluster_formation.consul.use_longname = false

cluster_formation.node_type = disc
cluster_partition_handling = pause_minority
cluster_partition_handling.pause_if_all_down.recover = ignore
mirroring_sync_batch_size = 4096

disk_free_limit.relative = 1.4
vm_memory_high_watermark.relative = 0.4
vm_memory_high_watermark_paging_ratio = 0.6

net_ticktime = 30

# Logging
log.console = true
log.console.level = info
log.syslog = true
log.syslog.level = info
log.syslog.protocol = rfc5424
log.syslog.transport = udp
log.syslog.ip = 10.1.28.90
log.syslog.port = 514
loopback_users.guest = false
total_memory_available_override_value = 536870912
listeners.tcp.default = 5672
hipe_compile = false
management.listener.port = 15672
management.listener.ssl = false

And yes, I saw those files and was suprised it is not working.
Works with this in advanced.config:

[
 %% Advanced configuration file - see https://www.rabbitmq.com/configure.html#advanced-config-file
 {syslog, [{protocol, {rfc5424, udp} },
           {dest_port, 514},
           {dest_host, "10.1.28.90" },
           {app_name, "rabbitmq" },
           {facility, daemon},
           {multiline_mode, true}
          ]
 }
].

[lukebakken]

Yep, I'm surprised too. I'll check this out when I get some time.

[lukebakken]

I can't reproduce this using the following configuration files for RabbitMQ and syslog-ng:

https://gist.github.com/lukebakken/cb11303fd8c66384dccd039c2936ad69

I tested this using Erlang 21.0.2 and RabbitMQ 3.7.7 via the generic-unix package. I started RabbitMQ with this command run from the root of the extracted archive:

RABBITMQ_NODENAME='rabbit@shostakovich' \
RABBITMQ_ALLOW_INPUT=true \
RABBITMQ_CONFIG_FILE=/home/lbakken/issues/rabbitmq/rabbitmq-server/gh-1639/rabbitmq \
./sbin/rabbitmq-server

At this point my guess is that there is something up with your installation.

@michaelklishin do we want to open a separate issue for the suggestions that @Garagoth made in point #3?

[Garagoth]

Please note that docker images are running on different erlang. I did not try this with standalone erlang and rabbit.

Hard to mess installation there, only thing I added to docker image is consul plugin.

[lukebakken]

I can't reproduce this with 20.3.8.2, either. syslog-ng output is as follows:

[2018-07-12T13:32:18.951307] Outgoing message; message='Jul 12 13:32:18 localhost rabbit[18530]: [info] <0.5.0> Server startup complete; 5 plugins started.\x0a'
[2018-07-12T13:32:18.951312] Outgoing message; message='Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_top\x0a'
[2018-07-12T13:32:18.951316] Outgoing message; message='Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_management\x0a'
[2018-07-12T13:32:18.951320] Outgoing message; message='Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_web_dispatch\x0a'
[2018-07-12T13:32:18.951323] Outgoing message; message='Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_stomp\x0a'
[2018-07-12T13:32:18.951327] Outgoing message; message='Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_management_agent\x0a'
Jul 12 13:32:18 localhost rabbit[18530]: [info] <0.5.0> Server startup complete; 5 plugins started.
Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_top
Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_management
Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_web_dispatch
Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_stomp
Jul 12 13:32:18 localhost rabbit[18530]:  * rabbitmq_management_agent

Just FYI, the RabbitMQ core team doesn't maintain those docker images. At this point, this issue is most likely in your environment or in the docker image itself. If you can reproduce this outside of Docker we can continue investigating, or if you can provide a Dockerfile and instructions on how to reproduce this using your configuration file, I can try that out.

[michaelklishin]

@lukebakken we can address what we understand/can reproduce and then close.

[lukebakken]

Closing, but I will be notified if the information I requested here is provided.