by

Where communities thrive


  • Join over 1.5M+ people
  • Join over 100K+ communities
  • Free without limits
  • Create your own community
People
Repo info
Activity
Bogdan Ś.
@bodzio131_gitlab
Hello All!,
I'm trying to modify json module to read compressed stream and write multiple log lines. Is it possible that json_parser_process (modules/json/json-parser.c) can add multiple lines at once? At this moment I call json_parser_process for every decompressed chunk of data, and every one is processed successfully (I mean that json_parser_process returns TRUE for every chunk), but in logs I see only last line. Any clues? Maybe other module has such thing? Thanks in advance for any help! (note: I don't want to use python , so just omit this solution, please ;) )
Bogdan Ś.
@bodzio131_gitlab
Or maybe this way: having this LogParser *s, LogMessage **pmsg, const LogPathOptions *path_optionshow can I add several log lines?
Gábor Nagy
@gaborznagy
Hi @bodzio131_gitlab
I would need a little bit more info to understand your use case and help you. You would like to have json module "write multiple log lines".
What do you mean write multiple log lines? Do you prefer that json-parser would emit new log messages?
In your syslog-ng config, do you use a json-parser() or a $(format-json) template function (I guess the former)?
Bogdan Ś.
@bodzio131_gitlab
Hi @gaborznagy ,
I use json-parser(). By default json-parser gets json object {<some pairs>} and produces one log entry. In my case json-parser gets bunch of json objects, so I need to produce separated log entry for every object.
Normally I send a string with json objects separated with line breaks: this way json_parser_process is called from the syslog core separately for every json object. What I want is to send this string compressed: this way json_parser_process is called once and I decompress it inside, but as a result I have several json objects inside json_parser_process.
Gábor Nagy
@gaborznagy
I see. I wouldn't recommend to modify json-parser() for this. It's okay to create new log messages from a parser ,db-parser() does that exactly, see log_msg_new() calls.
If you have created a new log-message, you send it through the same log path with log_pipe_forward_msg().
However these are synthetic messages, and e.g. flow-control wouldn't work on it. This means that the message you send towards could be lost.
Why did you reject the idea to split the original input into multiple lines, so it will be in separate messages at the beginning in syslog-ng?
Bogdan Ś.
@bodzio131_gitlab
@gaborznagy thank you for suggestions. Application caches log messages and then sends them as one string with line breaks. It can produce a lot of data, and I suppose it is kind of optimization. Sometimes it gets noticeable percentage of network bandwidth, so this is why I think about compressing the data. I will read about flow-control as you suggest there could be a problem, and I will dig into db-parser. Thank you!
Gábor Nagy
@gaborznagy
Does this application send the accumulated log messages conforming to the BSD (RFC3164) or the Syslog protocol (RFC5424)?
I mean, is it in some form like this <13>Sep 17 17:27:33 gaborzbot some-program[2222]: {test-json:dummy}?
Bogdan Ś.
@bodzio131_gitlab
Nope, just {test-json:dummy}\n{test-json:dummy}\n{test-json:dummy}... . Would it change a thing if I change it to conform mentioned protocols?
Gábor Nagy
@gaborznagy
I only asked to be able to decide if you need to copy message attributes or not when you are creating new messages (e.g. already parsed HOST or PROGRAM).
I still think that this kind of format should be split up on source-side on newlines, and then each json object could be parsed by the json-parser.
Fabien Wernli
@faxm0dem
how can I detect a file source inode change ?
elasticsearch will rotate its own files, and there's no way to tell it to reload syslog-ng
Gábor Nagy
@gaborznagy
@faxm0dem hmm interesting question, especially without the possibility to reload syslog-ng. That would have been my tip. :)
Balazs Scheidler
@bazsi
syslog-ng's file source is polling the file for changes among others it will detect if the file has been re-created (e.g. inode change). Is there something that you are missing in the current behavior?
Gábor Nagy
@gaborznagy
We do poll files for changes. Shouldn't this be detected in your environment?
Can I see some debug,verbose,trace level logs (some of the poll-file logs are on trace level)?
Ohh slow me :D
As far as I see file polling is triggered by reaching EOF, maybe the original file is still written? Doesn't sound possible.
Fabien Wernli
@faxm0dem
gaborznagy: it's not being written anymore, also lsof +L1 shows it's been renamed and is still open but only by syslog-ng
gaborznagy: but then again I didn't use poll-frequency(1) is that required ?
Gábor Nagy
@gaborznagy
No, follow-freq() will have a default 1 sec timer for file sources.
Fabien Wernli
@faxm0dem
that's what I thought
so yeah, syslog-ng just hangs to the file that was closed and renamed by elasticsearch
Gábor Nagy
@gaborznagy
Interesting. Do you have some internal() logs?
Fabien Wernli
@faxm0dem
gaborznagy: yes but not in that logpath
only log { source(file(...); parser(...); destination(network(...)); };
Fabien Wernli
@faxm0dem
I have a feeling that poll mechanism only activates when explicitly setting the option
Gábor Nagy
@gaborznagy
I think it doesn't matter which log path you put internal() source, it will collect every error/debug messages, from other log paths too.
On the contrary, file polling is on by default and you would have to turn it off with follow-freq(0)
Fabien Wernli
@faxm0dem
gaborznagy: so your question amounted to "is there anything in the internal log which would indicate a failure" ?
I checked: nothing in the logfile
I have a separate log path for internal
Gábor Nagy
@gaborznagy
@faxm0dem Yeah, that's what I meant. :)
I'm looking around how to debug this. There are a lot of trace level messages. Is it possible to turn that on for a while?
Gábor Nagy
@gaborznagy
Well, what I've found is on trace level. On every follow-freq() you can see a Checking if the followed file has new lines trace messages (assuming that EOF is reached once).
Fabien Wernli
@faxm0dem
gaborznagy: I'll check that asap thanks
Fabien Wernli
@faxm0dem
gaborznagy: tried turning on trace, but I'm throttling 10 msgs per second on internal() source
gaborznagy: never seen the message you mentioned
Gábor Nagy
@gaborznagy
Just for confirming, do you see other trace level messages? E.g. Setting value or Initial message parsing follows or affile_open_file ?
And we should check if the internal() source is not queuing messages (although follow-freq() runs every second, so we should see this message coming out from if it happens).
What value do you see in the internal source's statistics? global;internal_source;;a;queued or global;internal_queue_length;;a;processed
Fabien Wernli
@faxm0dem
gaborznagy: I see many trace messages, but they are being throttled
gaborznagy: I found one relevant reference to the file source: The current log file has a mismatching size/inode information, restarting from the beginning; state='affile_sd_curpos(/var/log/elasticsearch/beta_server.json)', stored_inode='336', cur_file_inode='7430', stored_size='6943599', cur_file_size='2358231', raw_stream_pos='15014348'
Gábor Nagy
@gaborznagy
That's the line which shows that the file is restarted because the file had been rotated.
Your new source file seems to being read by syslog-ng.
Is this an intermittent issue?
Fabien Wernli
@faxm0dem
no, it's always doing it
every morning when I come to work, I run lsof +L1 and see the deleted file held by syslog-ng
Gábor Nagy
@gaborznagy

Maybe I'm wrong, but I don't see the problem.
Yeah, it seems that after the file deleted, lsof stil shows it (with a hint, that it's deleted).
The fd is still open by syslog-ng, I think that's the reason.
However after a new file is created on the same path, the new one can be seen.

Here is an experiment with a file source named /tmp/input, showing what I saw.

~/install/syslog-ng-OSE$ lsof +L1 -p `pgrep syslog-ng`|grep input
syslog-ng 27191 gaborznagy   11r      REG              253,1      752     1 11272851 /tmp/input
~/install/syslog-ng-OSE$ mv /tmp/input /tmp/input.1
~/install/syslog-ng-OSE$ lsof +L1 -p `pgrep syslog-ng`|grep input
syslog-ng 27191 gaborznagy   11r      REG              253,1      752     1 11272851 /tmp/input.1
~/install/syslog-ng-OSE$ rm /tmp/input.1
~/install/syslog-ng-OSE$ lsof +L1 -p `pgrep syslog-ng`|grep input
syslog-ng 27191 gaborznagy   11r      REG              253,1      752     0 11272851 /tmp/input.1 (deleted)
~/install/syslog-ng-OSE$ logger -s --rfc3164 --no-act test5  >> /tmp/input 2>&1
~/install/syslog-ng-OSE$ lsof +L1 -p `pgrep syslog-ng`|grep input
syslog-ng 27191 gaborznagy   11r      REG              253,1       47     1 11272427 /tmp/input
~/install/syslog-ng-OSE$ lsof +L1 -p `pgrep syslog-ng`|grep input
syslog-ng 27191 gaborznagy   11r      REG              253,1       47     1 11272427 /tmp/input

Forgetting that /tmp is tmpfs, I've repeated the experiment on an ext4 filesystem too and it's still shown as deleted.

This is syslog-ng console, when a file had been removed and a new one is just created:

[2020-09-21T15:52:59.121362] Follow mode file still does not exist; filename='/home/gaborznagy/input'
[2020-09-21T15:52:59.121412] End of file, following file; follow_filename='/home/gaborznagy/input'
[2020-09-21T15:53:00.122584] Checking if the followed file has new lines; follow_filename='/home/gaborznagy/input'
[2020-09-21T15:53:00.122650] poll-file-changes; pos='951', size='951', fd='11'
[2020-09-21T15:53:00.122690] poll-file-changes: file moved eof; pos='951', size='60', follow_filename='/home/gaborznagy/input'
[2020-09-21T15:53:00.122710] Follow-mode file source moved, tracking of the new file is started; filename='/home/gaborznagy/input'
[2020-09-21T15:53:00.122758] Closing log transport fd; fd='11'
[2020-09-21T15:53:00.122914] affile_open_file; path='/home/gaborznagy/input', fd='11'
[2020-09-21T15:53:00.123025] The current log file has a mismatching size/inode information, restarting from the beginning; state='affile_sd_curpos(/home/gaborznagy/input)', stored_inode='4589762', cur_file_inode='4592317', stored_size='951
', cur_file_size='60', raw_stream_pos='0' 
[2020-09-21T15:53:00.123222] Incoming log entry; line='<13>Sep 21 15:52:59 gaborzbot gaborznagy: test61412421412421'
Gábor Nagy
@gaborznagy
If you do a reload, the fd is closed, and lsof will not show the file being opened. This is not a suggestion, only an observation.
Fabien Wernli
@faxm0dem
gaborznagy: thanks for investigating
gaborznagy: in my case, it does not behave like that
gaborznagy: the new file is being written to by the external application, but syslog-ng never seems to notice
Fabien Wernli
@faxm0dem_twitter
source s_elasticsearch_json {
    file(
        '/var/log/elasticsearch/beta_server.json',
        flags(
            no-parse
        ),
        tags(
            elasticsearch
        ),
        program-override(
            elasticsearch
        ),
        follow-freq(
            1
        )
    );
};
> lsof +L1 -p `pgrep syslog-ng`|grep -P beta.*.json
syslog-ng 30334           root   26r      REG              253,3  15070350     0     3856 /var/log/elasticsearch/beta-2020-09-21-1.json (deleted)
> ls -l /var/log/elasticsearch/beta_server.json
-rw-r--r-- 1 elasticsearch elasticsearch 6964571 Sep 22 11:07 /var/log/elasticsearch/beta_server.json
> date
Tue Sep 22 11:07:46 CEST 2020
of course if I reload everything goes back to normal
Gábor Nagy
@gaborznagy
I was experimenting with an idea how could follow-freq to be turned off at you. I had the idea based on something I saw in the code: that maybe the original log file was a symbolic link, and we don't handle it during the first opening of the file source. I was wrong, it works. Anyway, this would have been detected earlier.
@faxm0dem You mentioned that you see The current log file has a mismatching size/inode information, restarting from the beginning message(s).
Because this means that the file is restarted. We just don't know what caused it (follow-freq() or a reload).
What happens in the internal log, before that message arrives?
It's hard to debug this issue this way. A full internal log with trace level would be helpful, or reproduction steps if you can suggest anything.