Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Fluentd input plugin syslog is truncating syslog entry #2585

Closed
Tesseract242 opened this issue Aug 26, 2019 · 7 comments · Fixed by #2599
Closed

Fluentd input plugin syslog is truncating syslog entry #2585

Tesseract242 opened this issue Aug 26, 2019 · 7 comments · Fixed by #2599
Labels
bug Something isn't working

Comments

@Tesseract242
Copy link

Tesseract242 commented Aug 26, 2019 •
edited
Loading

Check CONTRIBUTING guideline first and here is the list to help us investigate the problem.

Describe the bug
Incoming syslog entry RFC3164 is being truncated by the syslog plugin without before being processed by a filter plugin. It appears that this syslog entry with a ":" towards the end is affecting the syslog plugin's ability to format the "message" part of the syslog entry correctly.
Confirmation that fluentd syslog plugin is the issue, is down to packet capture which shows the syslog entry being intact and in correct format when it is sent to td-agent:

Full syslog entry from tcpdump:

09:50:12.297340 IP lxlog001v.telecom.net.41780 > lxlog340v.telecom.net.5140: UDP, length 426
0x0000: 4500 01c6 f718 4000 4011 801a c0a8 a026 E.....@.@......&
0x0010: c0a8 a07c a334 1414 01b2 2a8c 3c33 383e ...|.4....*.<38>
0x0020: 4175 6720 3235 2032 333a 3530 3a32 3720 Aug.25.23:50:27.
0x0030: 3230 332e 3532 2e31 3330 2e37 3020 4369 203.52.130.70.Ci
0x0040: 7341 4353 5f30 335f 5241 4449 5553 4163 sACS_03_RADIUSAc
0x0050: 6320 3169 347a 6961 6c69 6f20 3120 3020 c.1i4zialio.1.0.
0x0060: 5573 6572 2d4e 616d 653d 7761 7572 656e User-Name=wanger
0x0070: 3332 3840 6175 726f 7261 656e 6572 6779 328@auroenergy
0x0080: 2e63 6f6d 2e61 752c 4772 6f75 702d 4e61 .com.au,Group-Na
0x0090: 6d65 3d41 7572 6f72 6120 456e 6572 6779 me=Auro.Energy
0x00a0: 204d 6f62 696c 6520 4950 2c43 616c 6c69 .Mobile.IP,Calli
0x00b0: 6e67 2d53 7461 7469 6f6e 2d49 643d 3631 ng-Station-Id=61
0x00c0: 3431 3831 3837 3833 392c 4163 6374 2d53 418187839,Acct-S
0x00d0: 7461 7475 732d 5479 7065 3d53 7461 7274 tatus-Type=Start
0x00e0: 2c41 6363 742d 5365 7373 696f 6e2d 4964 ,Acct-Session-Id
0x00f0: 3d39 3038 3542 4432 425b 5d31 3239 3831 =9085BD2B[]12981
0x0100: 3234 3137 2c53 6572 7669 6365 2d54 7970 2417,Service-Typ
0x0110: 653d 4672 616d 6564 2c46 7261 6d65 642d e=Framed,Framed-
0x0120: 5072 6f74 6f63 6f6c 3d50 5050 2c46 7261 Protocol=PPP,Fra
0x0130: 6d65 642d 4950 2d41 6464 7265 7373 3d31 med-IP-Address=x
0x0140: 3932 2e31 3638 2e31 3233 2e37 362c 4e41 xx.xxx.xxx.xx,NA
0x0150: 532d 506f 7274 3d31 3334 3231 3831 3337 S-Port=134218137
0x0160: 352c 4e41 532d 4950 2d41 6464 7265 7373 5,NAS-IP-Address
0x0170: 3d31 3434 2e31 3330 2e34 2e35 2c43 616c =x.x.x.x,Cal
0x0180: 6c65 642d 5374 6174 696f 6e2d 4964 3d74 led-Station-Id=t
0x0190: 656c 7374 7261 2e63 6f72 702c 436c 6173 elstra.corp,Clas
0x01a0: 733d 4341 4353 3a30 2f32 3465 6535 6530 s=CACS:0/24ee5e0
0x01b0: 2f39 3038 3230 3430 352f 3133 3432 3138 /90820405/134218
0x01c0: 3133 3735 2c0a 1375,.

To Reproduce

This particular string type with a ":" in it causes the syslog fluentd plugin to behave not as expected.

Output truncated entry:

syslog_default20190825_23.log:2019-08-25T23:50:27+10:00 syslog_default.auth.info {"host":"203.52.130.70","ident":"CisACS_03_RADIUSAcc","message":"0/24ee5e0/90820405/1342181375,"}

Expected behavior

Fluentd should output the syslog entry like the following (taken from a syslog server receiving the same feed as Fluentd syslog plugin):

Aug 26 09:50:27 203.52.130.70 CisACS_03_RADIUSAcc 1i4zialio 1 0 User-Name=[email protected],Group-Name=Auro Energy Mobile IP,Calling-Station-Id=61418187839,Acct-Status-Type=Start,Acct-Session-Id=9085BD2B[]129812417,Service-Type=Framed,Framed-Protocol=PPP,Framed-IP-Address=xxx.xxx.xxx.xxx,NAS-Port=1342181375,NAS-IP-Address=xxx.xxx.x.x,Called-Station-Id=thellstra.corp,Class=CACS:0/24ee5e0/90820405/1342181375,

Your Environment

  • td-agent 1.4.2
  • NAME="Red Hat Enterprise Linux Server"
    VERSION="7.4 (Maipo)"
    ID="rhel"
    ID_LIKE="fedora"
    VARIANT="Server"
    VARIANT_ID="server"
    VERSION_ID="7.4"
    PRETTY_NAME="OpenShift Enterprise"
    ANSI_COLOR="0;31"
    CPE_NAME="cpe:/o:redhat:enterprise_linux:7.4:GA:server"
    HOME_URL="https://www.redhat.com/"
    BUG_REPORT_URL="https://bugzilla.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 7"
REDHAT_BUGZILLA_PRODUCT_VERSION=7.4
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="7.4"

  • 3.10.0-693.el7.x86_64

If you hit the problem with older fluentd version, try latest version first.

Your Configuration

<system>
  workers 4
  log_level debug
</system>


#Log source
<source>
  @type forward
  port 24224
  bind 0.0.0.0
</source>

<source>
  @type syslog
  tag syslog_default
  port 5140
  bind 0.0.0.0
  <parse>
    message_format auto
    emit_unmatched_lines true
  </parse>
  message_length_limit 1MB
</source>

#Filtering

These filters need to be specified individually rather than a single filter with multiple charset mappings

<filter syslog_default.**>
@type record_modifier
char_encoding ISO-8859-1:utf-8

<filter syslog_default.**>
@type record_modifier
char_encoding Windows-1252:utf-8

<filter syslog_default.**>
@type record_modifier
char_encoding ascii-8bit:utf-8

#Output

match tag=* and output to log directory dump

<match **>
@type copy

@type file
path /d/d01/logs/dump/${tag[0]}%Y%m%d_%H
append true
symlink_path /d/d01/logs/current
slow_flush_log_threshold 60.0

@type csv
delimiter TAB
force_quotes False
fields @timestamp, message
time_type string
time_format "%F %T %z"

<buffer tag, time>
@type file
# write into 1 hour chunks
timekey 3600

wait 10 minutes after each timekey interval before writing it

 timekey_wait 600
  timekey_use_utc False
  path /d/d01/logs/_buffers/
  retry_forever true
  flush_thread_count 4
  flush_mode immediate
</buffer>

Your Error Log

No regex match errors or debug warnings from fluentd as to why this syslog entry was truncated.

Additional context
@Tesseract242 Tesseract242 added the bug Something isn't working label Aug 26, 2019
@repeatedly
Copy link
Member

I confirmed this behaviour.
Maybe, (?:[^\:]*\:)? or something causes this weird matching.
We need to find more better regexp to capture : included message.

@Tesseract242
Copy link
Author

Tesseract242 commented Aug 30, 2019 •
edited
Loading

Hi Masahiro,
Thanks for your response. So you have managed to repeat this situation? Is there a fix for this?
On the local syslog host, as a test I used "logger" to send a test syslog message to fluentd/td-agent and the message came through correctly.
So the behaviour of using logger compared to receiving the syslog message from the syslog server may be different - which would account for this behaviour.

Output in fluentd when sending the message via logger on the syslog host instead of the syslog daemon (syslog-ng) sending it directly to fluend/td-agent.

2019-08-30T16:43:12+10:00 syslog_default.kern.notice {"host":"xxx.xxx.xxx.xxx","ident":"CisACS_03_RADIUSAcc","message":"User-Name=[email protected],Group-Name=Aurora Energy Mobile IP,Calling-Station-Id=61418187839,Acct-Status-Type=Start,Acct-Session-Id=9085BD2B[]129812417,Service-Type=Framed,Framed-Protocol=PPP,Framed-IP-Address=xxx.xxx.xxx.xx,NAS-Port=1342181375,NAS-IP-Address=xxx.xxx.x.x,Called-Station-Id=telstra.corp,Class=CACS:0/24ee5e0/90820405/1342181375,"}

@repeatedly repeatedly mentioned this issue Sep 3, 2019
Merged
@repeatedly
Copy link
Member

Patch for this: #2599

So the behaviour of using logger compared to receiving the syslog message from the syslog server may be different

I see. Your via logger message doesn't contain "1i4zialio 1 0" after CisACS_03_RADIUSAcc.

@Tesseract242
Copy link
Author

Tesseract242 commented Sep 5, 2019 •
edited
Loading

I have updated parser_syslog.rb based on the code update in #2599, but I am still getting truncated version of text:

2019-09-05T05:53:00+10:00 syslog_default.auth.info {"host":"xxx.xx.xxx.xx","ident":"CisACS_03_RADIUSAcc","message":"0/2505265/90820405/1342181375,"}

Here is the output from logger, if I use the original syslog entry attached, regarding your previous query. The unique descripter "1i4zialio" is now included .

2019-09-05T16:26:01+10:00 syslog_default.kern.notice {"host":"xxx.xxx.xxx.xxx","ident":"CisACS_03_RADIUSAcc","message":"50:27 203.52.130.70 CisACS_03_RADIUSAcc 1i4zialio 1 0 User-Name=[email protected],Group-Name=Auro Energy Mobile IP,Calling-Station-Id=61418187839,Acct-Status-Type=Start,Acct-Session-Id=9085BD2B[]129812417,Service-Type=Framed,Framed-Protocol=PPP,Framed-IP-Address=xxx.xxx.xxx.xxx,NAS-Port=1342181375,NAS-IP-Address=xxx.xxx.x.x,Called-Station-Id=thellstra.corp,Class=CACS:0/24ee5e0/90820405/1342181375,"}

Thanks for your help!

@repeatedly
Copy link
Member

Did you add parser_type string in your config?

@Tesseract242
Copy link
Author

Thanks , that fixed the issue.

@wangchaoforever
Copy link

@Tesseract242 are you using a nas to collect your log? if the log file is stored on NAS，do you lose some logs?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Implement new parser for parser_syslog fluent/fluentd
3 participants
@repeatedly @wangchaoforever @Tesseract242