add rcptid to message related trace messages

[bazsi]

The new log_msg_evt_tags() macro adds the rcptid value to the trace messages
making it easier to identify which msg we are manipulating at the moment.

In order to have a non-zero value for rcptid, one needs to enable
use-rcptid() in the configuration.

Fixes portions of #3967

[kira-syslogng]

Build SUCCESS

[kira-syslogng]

Build SUCCESS

[gaborznagy]

I'm not entirely convinced that adding rcptid to trace messages would help much by itself.
Trace messages are useful when only one message is sent to syslog-ng to debug the route a specific message takes.
For one message, an additional rcptid field to the trace message is redundant next to the address of the LogMessage address.

Of course, when a copy-on-write takes place that address is changed, so this is the scenario where rcptid would be useful, but then should we use the address of the LogMessage too?

And wouldn't be more convenient if trace level would turn on rcptid too ? (only from a user's point of view, as on code level they are very distant).

What do you think @rfaircloth-splunk, @bazsi?

[gaborznagy]

@bazsi you've updated the internal ivykis in this PR too. I guess that's accidental.

[gaborznagy]

Just a note about what we discussed:

• we could enable rcptid by default, if it doesn't have significant negative effects on performance. We'll do a perf test on this.
• we agreed that rcptid in the trace messages is better than the address of the LogMessage object.

[Kokan]

Just out of curiosity did some testing:

use_rcptid(no)
center;;received;a;processed;32729670
center;;received;a;processed;32791101
center;;received;a;processed;33424028
center;;received;a;processed;32887275
center;;received;a;processed;31181524
; (32729670+32791101+33424028+32887275+31181524)/5
        32602719.6

use_rcptid(yes)
center;;received;a;processed;26653406
center;;received;a;processed;27627752
center;;received;a;processed;29596720
center;;received;a;processed;29943992
center;;received;a;processed;30723320
; (26653406+27627752+29596720+29943992+30723320)/5
        28909038

; 28909038/32602719.6
        ~0.88670633476846514363

The configuration:

@version: 3.35

options {
#use_rcptid(yes);
};

source s {
    example_msg_generator (
        freq(0.00001)
        template("test message")
    );
    example_msg_generator (
        freq(0.00001)
        template("test message#2")
    );
    example_msg_generator (
        freq(0.00001)
        template("test message#2")
    );
};

log {
    source(s);
destination { file("/dev/null"); };
};

Running: syslog-ng -Fe & ; sleep 60 ; syslog-ng-ctl stats|grep 'center;;received' >> nouniqid ; syslog-ng-ctl stop

Based on this, it does not look like promising.

[kira-syslogng]

Build SUCCESS

[mitzkia]

@kira-syslogng do stresstest this please test branch=micek_perf_with_rcptid

[mitzkia]

@kira-syslogng do stresstest branch=micek_perf_with_rcptid

[kira-syslogng]

Build SUCCESS

[kira-syslogng]

Kira-stress-test: Build SUCCESS

[mitzkia]

I have also run an internal perf test for enabled rcptid and it shows a ~30% decrease in our fastest combination.

• it was a 5 minutes run
• config

options {
    keep_hostname(yes);
    keep_timestamp(no);
    use_rcptid(yes);
    stats_level(2);
    use_dns(no);
};
source s_network_d7e6b375b62e415f8924fd4d883e0e80 {
network(
    ip(0.0.0.0)
    log_fetch_limit(1000)
    log_iw_size(10000)
    max_connections(10)
    port(61001)
);
};
destination d_file_91b6a8918dc742e98e8f447485517f5f {
file(
    "/tmp/output.$HOST" 
    flush_lines(1000)
    log_fifo_size(20000)
);
};
log {
source(s_network_d7e6b375b62e415f8924fd4d883e0e80);
destination(d_file_91b6a8918dc742e98e8f447485517f5f);
flags(flow-control);
};

• loggen was used with the following parameters:

bin/loggen --active-connections=10 --dont-parse --inet --interval=300 --loop-reading --quiet --rate=1000000 --read-file=/tmp/loggen_input_file.txt --size=512 [ip] [port]

[Kokan]

I think using the rcptid is a good idea, but the current implementation is hungry.
According to the documentation it should be a monotone number, but I do not think that is really required. If we can let that requirement go, and focus on uniqueness. Maybe we can come up with a different implementation that does not require locking.
One such idea would be to have a per thread counter, which is prefixed with thread id.

[bazsi]

The original idea of rcptid was to be able to reorder the messages to its reception order, so the reason it is monotonous was this. I am not sure anyone uses it for this purpose though. Such a number is useful in cases where you have multiple parallel paths to storage. Before changing semantics, I'd probably revisit the locking strategy within rcptid, because I am sure it could be improved. But I'd merge this as is, maybe with the addition of -t command line option enabling rcptid as well.

…

On Tue, Apr 12, 2022, 10:59 Kókai Péter ***@***.***> wrote: I think using the rcptid is a good idea, but the current implementation is hungry. According to the documentation it should be a monotone number, but I do not think that is really *required*. If we can let that requirement go, and focus on uniqueness. Maybe we can come up with a different implementation that does not require locking. One such idea would be to have a per thread counter, which is prefixed with thread id. — Reply to this email directly, view it on GitHub <#3972 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAFOK5WL7HXRBZPZP6HSEZTVEU3QVANCNFSM5SM6V7JQ> . You are receiving this because you were mentioned.Message ID: ***@***.***>

[ryanfaircloth]

This PR is exciting. One comment early on in the PR was trace is really only useful for a single message. I think that is a very legacy way of thinking. Using trace on console this is true if I was to get a json blog with a the rcpti field into Splunk, Humio or other observability tools I could much more easily troubleshoot a running problem

[bazsi]

I have now added a commit to enable rcptid generation when --trace is passed as a command line option.

Also, I went back and added rcptid to the very first debug message we emit about a new incoming log message.

We can't enable rcptid now due to performance reasons, I'll revisit that in the future.

But with all of this, this can be merged in my opinion.

[kira-syslogng]

Build FAILURE

[bazsi]

@kira-syslogng retest this please;

[kira-syslogng]

Build FAILURE

[mitzkia]

@kira-syslogng retest this please;

[kira-syslogng]

Build SUCCESS

[gaborznagy]

@bazsi, the local ivykis is still updated in this PR.

Sorry for putting request for change flag on it, but I would like to avoid others accidentally merge this.

Otherwise looks good to me.

[bazsi]

Sorry. git seems to add submodules to patches automatically during rebase, if I have it updated locally.

I now removed it explicitly.

[gaborznagy]

Thanks, approve!

[kira-syslogng]

Build SUCCESS

[bazsi]

I have done one last rebase in which I've renamed the macro generating the tags to match conventions, as these functions
tend to be called evt_tag_*()

The trigger was that I was adding another set of these tags and it felt somewhat alien, I did some grepping:

lib/gprocess.c:evt_tag_cap_t(const char *tag, cap_t cap)
lib/value-pairs/evttag.c:evt_tag_value_pairs(const char *key, ValuePairs *vp, LogMessage *msg, LogTemplateEvalOptions *options)

We have some inconsistent names still:

bazsi@bzorp:~/src/syslog-ng/syslog-ng$ git grep ^EVTTAG *.h
lib/cfg-lexer.h:EVTTAG *cfg_lexer_format_location_tag(CfgLexer *self, CFG_LTYPE *yylloc);
lib/cfg-tree.h:EVTTAG *log_expr_node_location_tag(LogExprNode *self);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_str(const char *tag, const char *value);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_mem(const char *tag, const void *value, size_t len);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_int(const char *tag, int value);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_long(const char *tag, long long value);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_errno(const char *tag, int err);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_printf(const char *tag, const char *format, ...) G_GNUC_PRINTF(2, 3);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_inaddr(const char *tag, const struct in_addr *addr);
lib/eventlog/src/evtlog.h:EVTTAG *evt_tag_inaddr6(const char *tag, const struct in6_addr *addr);
lib/logpipe.h:EVTTAG *log_pipe_location_tag(LogPipe *pipe);
lib/tlscontext.h:EVTTAG *tls_context_format_tls_error_tag(TLSContext *self);
lib/tlscontext.h:EVTTAG *tls_context_format_location_tag(TLSContext *self);
lib/value-pairs/evttag.h:EVTTAG *evt_tag_value_pairs(const char *key, ValuePairs *vp, LogMessage *msg, LogTemplateEvalOptions *options);

Nevertheless, I like the one with evt_tag prefix better, so I quickly renamed the change in this patchset.

There are no other changes since @gaborznagy approved it, so please reapprove.

[kira-syslogng]

Build SUCCESS

[bazsi]

@gaborznagy I am afraid the new additions to this branch as described in #3972 (comment) warrant a new review.

This branch is now a lot more than the rcptid tags in trace messages. The changes should be trivial but are quite sizable. Let me know if you want to split this.

[kira-syslogng]

Build SUCCESS

[MrAnno]

Thank you for the refactor commits, they look really good.

[kira-syslogng]

Build SUCCESS

[gaborznagy]

Sorry for kept you waiting, I've checked the internal build as discussed.
Approve.

[abalage]

I think #2828 can be closed thanks to this feature. :)