Processing stuck with all processbufferprocessor threads used up

Spoth · January 21, 2020, 12:14pm

Hi all,

I currently seeing a repeated full freeze of message processing in Graylog. Version is 3.1.4-1, the official docker image. It started as I added a pipeline for processing of proftpd xfer logs, and it seems to get stuck in these. I repeatedly removed the rule from the pipeline and restarted Graylog, then processing works fine forever, but when enabling my parsing rule again, it gets into a state where it stops processing quickly.

I first suspected the flex_parse, that is why it is disabled, but it’s not the cause. According to the threaddump it seems to get lost in pattern matching, and I currently don’t know how to identify the lines causing this. Lots of lines get parsed fine, and the simluation also works find with the data I used for testing.

rule "parse_proftpd_xferlogs"
when
  true
then
  let r = grok("%{PROFTPD_XFERLOG}", to_string($message.message));
  set_fields(r);
  //let new_date = flex_parse_date(to_string(r.proftpd_xfer_timestamp), now(), "Europe/Berlin");
  //set_field("timestamp", new_date);
  remove_field("DAY");
  remove_field("HOUR");
  remove_field("MINUTE");
  remove_field("MONTH");
  remove_field("MONTHDAY");
  remove_field("PROFTPD_XFERLOG");
  remove_field("SECOND");
  remove_field("YEAR");
end

PROFTPD_XFERLOG %{PROFTPDXFER_TIMESTAMP:proftpd_xfer_timestamp} %{DATA:proftpd_xfer_transfer-time:int} %{HOSTNAME:proftpd_xfer_remote-host} %{INT:proftpd_xfer_file-size} %{UNIXPATH:proftpd_xfer_filename} %{WORD:proftpd_xfer_transfer-type} %{WORD:proftpd_xfer_action-flag} %{WORD:proftpd_xfer_direction} %{WORD:proftpd_xfer_access-mode} %{USERNAME:proftpd_xfer_username} %{WORD:proftpd_xfer_service-name} %{INT:proftpd_xfer_auth-method} %{DATA:proftpd_xfer_auth-userid} %{WORD:proftpd_xfer_completion-status}

PROFTPDXFER_TIMESTAMP %{DAY} %{MONTH} %{MONTHDAY} %{HOUR}:%{MINUTE}:%{SECOND} %{YEAR}

The threaddump shows that all the “processbufferprocessor” threads seem to get stuck in regex matching:
(hope this gets formatted ok)

"processbufferprocessor-0" id=29 state=RUNNABLE
    at java.util.regex.Pattern$5.isSatisfiedBy(Pattern.java:5265)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3790)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4241)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4293)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4815)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Ques.match(Pattern.java:4196)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4808)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4293)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.match(Pattern.java:4799)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Loop.matchInit(Pattern.java:4818)
    at java.util.regex.Pattern$Prolog.match(Pattern.java:4755)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Bound.match(Pattern.java:5343)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match1(Pattern.java:4301)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4250)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Curly.match0(Pattern.java:4286)
    at java.util.regex.Pattern$Curly.match(Pattern.java:4248)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4616)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$Ques.match(Pattern.java:4195)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$Ques.match(Pattern.java:4195)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$CharProperty.match(Pattern.java:3791)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$Bound.match(Pattern.java:5343)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4616)
    at java.util.regex.Pattern$Slice.match(Pattern.java:3986)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Bound.match(Pattern.java:5343)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$BmpCharProperty.match(Pattern.java:3812)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$GroupTail.match(Pattern.java:4731)
    at java.util.regex.Pattern$BranchConn.match(Pattern.java:4582)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4616)
    at java.util.regex.Pattern$Slice.match(Pattern.java:3986)
    at java.util.regex.Pattern$Branch.match(Pattern.java:4618)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$GroupHead.match(Pattern.java:4672)
    at java.util.regex.Pattern$Start.match(Pattern.java:3475)
    at java.util.regex.Matcher.search(Matcher.java:1248)
    at java.util.regex.Matcher.find(Matcher.java:637)
    at com.google.code.regexp.Matcher.find(Unknown Source)
    at io.krakens.grok.api.Grok.match(Grok.java:171)
    at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:65)
    at org.graylog.plugins.pipelineprocessor.functions.strings.GrokMatch.evaluate(GrokMatch.java:34)
    at org.graylog.plugins.pipelineprocessor.ast.expressions.FunctionExpression.evaluateUnsafe(FunctionExpression.java:63)
    at org.graylog.plugins.pipelineprocessor.ast.expressions.Expression.evaluate(Expression.java:41)
    at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:33)
    at org.graylog.plugins.pipelineprocessor.ast.statements.VarAssignStatement.evaluate(VarAssignStatement.java:22)
    at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStatement(PipelineInterpreter.java:385)
    at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.executeRuleActions(PipelineInterpreter.java:369)
    at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.evaluateStage(PipelineInterpreter.java:309)
    at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.processForResolvedPipelines(PipelineInterpreter.java:267)
    at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:147)
    at org.graylog.plugins.pipelineprocessor.processors.PipelineInterpreter.process(PipelineInterpreter.java:103)
    at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.handleMessage(ProcessBufferProcessor.java:126)
    at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.dispatchMessage(ProcessBufferProcessor.java:112)
    at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:89)
    at org.graylog2.shared.buffers.processors.ProcessBufferProcessor.onEvent(ProcessBufferProcessor.java:45)
    at com.lmax.disruptor.WorkProcessor.run(WorkProcessor.java:143)
    at com.codahale.metrics.InstrumentedThreadFactory$InstrumentedRunnable.run(InstrumentedThreadFactory.java:66)
    at java.lang.Thread.run(Thread.java:748)

Do you have any idea how I can identify the line causing this, or how to debug this any further?

This is a picture of the node status. The system just fills up the journal slowly:

Regards,
Sven

Spoth · January 21, 2020, 1:38pm

It seems to mitigate the problem when I change the matching for the filename:

I changed UNIXPATH to DATA, as UNIXPATH seemed to be the only complex regex in this Grok pattern. It did not freeze again yet since an hour, usually it took only 1-2 minutes.

jan · January 22, 2020, 10:22am

He @Spoth

whenever I run into issues I tend to use a snipped like the following to make me aware about the regex result that is created from a grok pattern.

#!/usr/bin/env python

import argparse
import re
from os import walk
from os.path import join


def get_patterns(patterns_dir):
    patterns = {}

Taking only the the PROFTPDXFER_TIMESTAMP will result in the following regex:

(?:Mon(?:day)?|Tue(?:sday)?|Wed(?:nesday)?|Thu(?:rsday)?|Fri(?:day)?|Sat(?:urday)?|Sun(?:day)?) \b(?:[Jj]an(?:uary|uar)?|[Ff]eb(?:ruary|ruar)?|[Mm](?:a|ä)?r(?:ch|z)?|[Aa]pr(?:il)?|[Mm]a(?:y|i)?|[Jj]un(?:e|i)?|[Jj]ul(?:y)?|[Aa]ug(?:ust)?|[Ss]ep(?:tember)?|[Oo](?:c|k)?t(?:ober)?|[Nn]ov(?:ember)?|[Dd]e(?:c|z)(?:ember)?)\b (?:(?:0[1-9])|(?:[12][0-9])|(?:3[01])|[1-9]) (?:2[0123]|[01]?[0-9]):(?:[0-5][0-9]):(?:(?:[0-5]?[0-9]|60)(?:[:.,][0-9]+)?) (?>\d\d){1,2}

After that the initial is added like:

(?<proftpd_xfer_transfer-time>.*?) (?<proftpd_xfer_remote-host>\b(?:[0-9A-Za-z][0-9A-Za-z-]{0,62})(?:\.(?:[0-9A-Za-z][0-9A-Za-z-]{0,62}))*(\.?|\b)) (?<proftpd_xfer_file-size>(?:[+-]?(?:[0-9]+))) (?<proftpd_xfer_filename>.*?) (?<proftpd_xfer_transfer-type>\b\w+\b) (?<proftpd_xfer_action-flag>\b\w+\b) (?<proftpd_xfer_direction>\b\w+\b) (?<proftpd_xfer_access-mode>\b\w+\b) (?<proftpd_xfer_username>[a-zA-Z0-9._-]+) (?<proftpd_xfer_service-name>\b\w+\b) (?<proftpd_xfer_auth-method>(?:[+-]?(?:[0-9]+))) (?<proftpd_xfer_auth-userid>.*?) (?<proftpd_xfer_completion-status>\b\w+\b)

I assume that you have not (many) dedicated CPU cores available for that host if you run that inside of docker, so it is either to complex to run or you have not enought cpu power to work on that problem in the needed speed.

Spoth · January 22, 2020, 11:49am

Hi Jan,

I don’t think this is a performance issue. It’s not a development environment. The system is having 8 dedicated Xeon cores, 64gig of memory, an NVME SSD and is currently processing a stream of 2000 messages per second continously without problems, using other complex regular expressions.

When using the UNIXPATH pattern in the parsing of proftpd xfer logs, it’s not getting slow, it just suddenly completely stops. The threaddump shows that the processor threads get completely stuck inside the regex classes. This pipeline processes hundreds of messages per second until it hits a message that causes this issue. I think that is a bug that causes the parser to never return, so all the processor threads get used up.

I’m trying to figure out how to identify the type of message that causes this and thougt someone here might have an idea. If not, I will set up a test environment where I can attach a debugger and check what’s going on.

Regards,
Sven

tmacgbay · January 22, 2020, 3:38pm

I have a similar issue on a MUCH smaller system - two virtuals(Graylog, Elastic) handling about 80 messages a second - occasionally the process buffer fills up and nothing ever makes it over to the output buffer. Nothing in the logs and the only way to clear it is restart the Graylog server. Timing for me is random, I can go days before this happens or rarely it might be only 10 minutes. … I have not been able to narrow it down to anything so it was hard to post for help… So… keeping an eye on this one and chiming in to help momentum.

Zerobot · January 22, 2020, 8:29pm

It sounds like Graylog 3.1.4 should fix those issues.

From 3.1.4 changelog:

Fix message indexing issue that could potentially stop message indexing completely.

github.com/Graylog2/graylog2-server

Graylog doesn't handle Elasticsearch "413 Request Entity Too Large" reply

opened 12:15PM - 10 Sep 18 UTC

closed 05:33PM - 10 Jan 20 UTC

macko003

bug triaged

One graylog node lost the connection with elastic cluster. It seems sometimes, …somehow the graylog make bigger batch (based on output_batch_size), then the elasticsearch can allow (ES bulk_max_body_size default 100mb). The graylog can't recognize the received error from ES. After a graylog service restart can send the logs out to elasticsearch. After time the GL lost the connection with all ES nodes, and can't store logs. Journal start to grow. Issue details: https://community.graylog.org/t/elastic-cluster-connection-lost/6189/8 ## Expected Behavior GL create smaller size of batch then the ES limit, or handle the error, and refregment the batch if iit receive "413 Request Entity Too Large" error ## Current Behavior GL makes a batch, try to send to ES, ES denies it, ES send TCP reset, GL try another ES with the same batch. GL: log: ``` 2018-09-10T11:49:04.401+02:00 ERROR [Messages] Caught exception during bulk indexing: java.net.SocketException: Connection reset, retrying (attempt #28). ``` slice of TCPdump ``` 12:05:45.204959 IP SUBNET.41.57818 > SUBNET.36.9200: Flags [P.], seq 18272:18503, ack 489, win 269, options [nop,nop,TS val 1985608753 ecr 1984697849], length 231 .......PV..d....E...p1@.@...dN.)dN.$..#.g.9..x@'........... vY.1vL..POST /_bulk HTTP/1.1 Content-Length: 230363373 Content-Type: application/json; charset=UTF-8 Host: SUBNET.36:9200 Connection: Keep-Alive User-Agent: Apache-HttpClient/4.5.4 (Java/1.8.0_181) Accept-Encoding: gzip,deflate 12:05:45.205301 IP SUBNET.36.9200 > SUBNET.41.57818: Flags [P.], seq 489:549, ack 31535, win 752, options [nop,nop,TS val 1984716154 ecr 1985608753], length 60 .......PV.......E..p..@.@...dN.$dN.)#....x@'g.m.....md..... vL]zvY.1HTTP/1.1 413 Request Entity Too Large content-length: 0 12:05:45.205709 IP SUBNET.36.9200 > SUBNET.41.57818: Flags [R.], seq 848, ack 90903, win 1272, options [nop,nop,TS val 0 ecr 1985608754], length 0 .......PV.......E..4..@.@...dN.$dN.)#....xA.g.U{....bK..... ....vY.2{"index":{"_id": 12:05:45.967516 IP SUBNET.41.34322 > SUBNET.38.9200: Flags [P.], seq 95405:95636, ack 1034, win 245, options [nop,nop,TS val 1985609516 ecr 1983368835], length 231 .......PV..d....E.....@.@..TdN.)dN.&..#.....OW`............ vY.,v7..POST /_bulk HTTP/1.1 Content-Length: 230363373 Content-Type: application/json; charset=UTF-8 Host: SUBNET.38:9200 Connection: Keep-Alive User-Agent: Apache-HttpClient/4.5.4 (Java/1.8.0_181) Accept-Encoding: gzip,deflate 12:05:45.967917 IP SUBNET.38.9200 > SUBNET.41.34322: Flags [P.], seq 1034:1094, ack 108668, win 1432, options [nop,nop,TS val 1983383888 ecr 1985609516], length 60 .......PV.BS....E..p..@.@...dN.&dN.)#...OW`..........&..... v8 PvY.,HTTP/1.1 413 Request Entity Too Large content-length: 0 12:05:45.968792 IP SUBNET.38.9200 > SUBNET.41.34322: Flags [R], seq 1331126799, win 0, length 0 .......PV.BS....E..(..@.@.V3dN.&dN.)#...OWb.....P...{..........,v7............ 12:05:46.708613 IP SUBNET.41.47776 > SUBNET.78.9200: Flags [P.], seq 33578:33809, ack 505, win 458, options [nop,nop,TS val 1985610257 ecr 1984247522], length 231 .......PV..d....E...AU@.@..udN.)dN.N..#..V.`ubS...... ..... vZ..vE6.POST /_bulk HTTP/1.1 Content-Length: 230363373 Content-Type: application/json; charset=UTF-8 Host: SUBNET.78:9200 Connection: Keep-Alive User-Agent: Apache-HttpClient/4.5.4 (Java/1.8.0_181) Accept-Encoding: gzip,deflate 12:05:46.709076 IP SUBNET.78.9200 > SUBNET.41.47776: Flags [P.], seq 505:565, ack 46841, win 6634, options [nop,nop,TS val 1984261327 ecr 1985610257], length 60 .......PV.3{....E..p..@.@...dN.NdN.)#...ubS..W./....eH..... vEl.vZ..HTTP/1.1 413 Request Entity Too Large content-length: 0 ``` // it contains the GL uncommited log entries, sample every 5min ![kep](https://user-images.githubusercontent.com/25004494/45296660-06e4fe00-b503-11e8-9fc8-edc7ae815f14.png) ## Possible Solution Recreate batch if ES denies with error 413 Request Entity Too Large Chech the bulk_max_body_size before communication and don't create bigger batch then the bulk_max_body_size Or make a new variable in server.conf to set the max size of batch size (in KB or MB) ## Steps to Reproduce (for bugs) 1. Set GL output_batch_size to higher (eg. 10000, def 1000) 2. send lot of log under one sec log_number*log_size > ES bulk_max_body_size && log_number < GL output_batch_size eg. 1000 piece*1M log ## Context ## Your Environment * Graylog Version: v2.4.6+ceaa7e4 * Elasticsearch Version: 5.6.10 * MongoDB Version: NA * Operating System: CentOS 7, 3.10.0-862.11.6.el7.x86_64 * Browser version: NA

github.com/Graylog2/graylog2-server

Server message processing blocked in some cases when index optimization occurs

opened 01:22PM - 10 Dec 19 UTC

closed 05:33PM - 10 Jan 20 UTC

hulkk

bug

## Expected Behavior Message processing should not be blocked when indices are …optimized or if processing is temporarily blocked processing should recover when the reason for block is resolved. ## Current Behavior When index optimization starts in some cases it causes message processing to stop and currently only known way to resolve this is to restart graylog service. When this bug is triggered it seems that Graylog has issues opening network connections to Elasticsearch. Normally there should always be some number of established connections to Elasticsearch but when this issue is active there is zero established connections from Graylog to Elasticsearch. ![Screenshot 2019-12-10 at 14 42 01 copy](https://user-images.githubusercontent.com/24830359/70532678-32202800-1b60-11ea-896f-3395b8d8ccbe.png) As you can see from the screenshot, there is only one active system job which is started on the Master node, but it is different node which can't output any messages. When bug is active following command returns 0. `sudo netstat -antpu | grep 9200 | grep ESTABLISHED | wc -l` After service restart there are always some number of established connections even in our smallest test envinronment. The outgoing message metrics from the applicable node. ![Screenshot 2019-12-10 at 15 30 17](https://user-images.githubusercontent.com/24830359/70533732-54b34080-1b62-11ea-82ed-4c9b0d034550.png) About at the same time there is following event in the logs `2019-12-10T14:13:21.729+02:00 ERROR [Messages] Caught exception during bulk indexing: java.net.SocketException: Broken pipe (Write failed), retrying (attempt #88).` ## Steps to Reproduce (for bugs) Currently I don't have steps for reproducing this. For example today this has happened in our largest cluster two times in four hours, both at different nodes. This does not happen every time and this is not related to the Graylog Master node or multiple index optimization tasks as per #4637 . We have also updated the connection limits, but it did not help, because this issue is not caused by the limit because Graylog doesn't open any connections. ## Context Currently Graylog is unreliable because message processing gets jammed multiple times per day and requires service restart. We have implemented monitoring for this so we notice can react to it immediately. As you can see from the screenshot, we have quite large volumes incoming - constantly over 10.000 msg/sec and over 1 terabyte of logs per day. ## Your Environment * Graylog Version: 3.0.2 * Elasticsearch Version: 6.8.4 * MongoDB Version: 4.0.13 * Operating System: CentOS 7.7

github.com/Graylog2/graylog2-server

Handle Request Entity Too Large errors in ElasticSearchOutput

Graylog2:master ← Graylog2:issue-5091

opened 11:21AM - 02 Jan 20 UTC

mpfz0r

+207 -32

If we try to bulk index a batch of messages that exceeds the elastic search `ht…tp.max_content_length` setting. (default 100MB) Elastic will respond with an HTTP 413 Entity Too Large error. In this case we retry the request by splitting the message batch in half. When responding with an HTTP 413 error, the server is allowed to close the connection immediately. This means that our HTTP client (Jest) will simply report an IOException (Broken pipe) instead of the actual error. This can be avoided by sending the request with an Expect-Continue header, which also avoids sending data that will be discarded later on. Fixes #5091 Fixes #6965

jan · January 23, 2020, 2:36pm

@Zerobot

that might be one of the reasons - but it is hard to tell. When the processing is stuck a thread dump might reveal where the processing has issues with.

But it could be, that some specific kind of message creates an issue - but with such a complex rule and no knowledge what is inside the messages that are parsed it is hard to tell.

Spoth · January 24, 2020, 9:56am

Problem can be reproduced:

Use this patterns:

"name":"PROFTPDXFER_TIMESTAMP"
"pattern":"%{DAY} %{MONTH} %{MONTHDAY} %{HOUR}:%{MINUTE}:%{SECOND} %{YEAR}"
"name":"PROFTPD_XFERLOG",
"pattern":"%{PROFTPDXFER_TIMESTAMP:proftpd_xfer_timestamp} %{DATA:proftpd_xfer_transfer-time:int} %{HOSTNAME:proftpd_xfer_remote-host} %{INT:proftpd_xfer_file-size} %{UNIXPATH:proftpd_xfer_filename} %{WORD:proftpd_xfer_transfer-type} %{WORD:proftpd_xfer_action-flag} %{WORD:proftpd_xfer_direction} %{WORD:proftpd_xfer_access-mode} %{USERNAME:proftpd_xfer_username} %{WORD:proftpd_xfer_service-name} %{INT:proftpd_xfer_auth-method} %{DATA:proftpd_xfer_auth-userid} %{WORD:proftpd_xfer_completion-status}"

Test the pattern PROFTPDXFER_TIMESTAMP with this value:

Thu Jan 23 07:51:21 2020 0 1.2.3.4 1234 /ftproot/stuff/Tmp/filexxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx{xxxx}xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx.xml b _ i r abcdef sftp 0 * c

This causes the io.krakens.grok.api.Grok.match() to never return. The pattern matching goes into a loop and uses up a cpu core. The actual loop occurs inside java.util.regex.Pattern, so it’s not really a Graylog specifiy problem. I think it’s some kind of bug in the JRE classes. A pattern should either match or not, and not cause the parser to loop forever.

If you have multiple messages in a pipeline that trigger this problem, it will completely halt the pipeline processing in Graylog.

Regards,
Sven

tmacgbay · January 24, 2020, 4:11pm

Maybe not as elegant but a reasonable/possible workaround for this test case…

let coffee = split(" ", to_string($message.message));
   set_field("proftpd_xfer_timestamp",           coffee[0]);
   set_field("proftpd_xfer_transfer-time",       coffee[1]);
   ...

Spoth · January 24, 2020, 4:41pm

Yeah, this is easy to work around when you know what happens. I just use DATA instead of UNIXPATH in the pattern and it works fine. Maybe splitting by space would be even faster, but then you have to cat the timestamp back together from all the little fields to parse the timestamp. Splitting seems to be always the fastest way to process logs, when they are structured in a nice splittable way.

But regarding the problem, I was just curious about why this freezes.

I could reproduce this without Graylog, using the example code from https://github.com/thekrakken/java-grok . Just register the patterns und have it parse the line, then it also makes one thread go looping and use up a cpu core. I tried to understand it with a debugger, but the regex parsing is pretty complex and I did not get far yet. I don’t know if it’s expected behavior that you can create a regex pattern that loops forever. The loop occurs inside java.util.regex.Pattern, so if this was a bug it would be part of the jre libraries. I’ll try to reproduce this with other java versions.

I was thinking about what Graylog could do to mitigate this. It’s a bad situation to have all your processing threads frozen, even when it’s not your own fault. Maybe it would be helpful to have a mechanism to print out the current line that a processor thread is stuck on, so you at least can find out what line causes the problem, without having to use a debugger.

And yes, I know that filename is pretty awkward. But I really found something similar on our production environment that triggers this problem, a long filename including { } characters. I just changed the filename I posted, to clean it from data I may not expose, so thats why it’s consisting of so many x characters.

Regards,
Sven

jan · January 26, 2020, 1:51pm

He @Spoth

thank you for your deep investigation into this. I have created the following issue from that:

We have added in 3.1.3 the ability to debug processing ( see changelog: https://docs.graylog.org/en/3.1/pages/changelog.html#id4 ). This has not been announced in a proper way - from my point of view. But that might be a proper way at least during setup to take some insides.

Does that help you?

Jan

Spoth · January 27, 2020, 10:31am

Hi Jan,

thanks for creating the issue. The debug looks very useful to analyze slow processing, but won’t help with a frozen thread. Lets see what the issue brings. I think I would create a watchdog that checks the processing threads every few minutes and logs pattern + data when it finds a processor working on a message for longer than a minute or so. For me it’s fine now, this seems to be a very rare problem and I can work around it.

Regards,
Sven

jan · January 27, 2020, 10:43am

he @Spoth

you are not the only running into this issues - or similar. We have in 3.2 some helpers for that, because you can identify the messages better that cause the problems.

Depending on your environment I would check if the in and out numbers are equal and if the journal grows. Depending on the used monitoring that might be trivial. This might give you an idea:

system · February 10, 2020, 10:43am

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Grok pattern makes output processing stop Graylog Central (peer support) pipeline-rules , grok-patternspl	2	575	January 13, 2022
Graylog not processing messages / processing buffer full Graylog Central (peer support) pipeline-rules	1	6399	July 2, 2020
Process Buffer Full - How do i fault find? Graylog Central (peer support)	6	4564	June 19, 2020
Pipeline processing appears to get stuck at times Graylog Central (peer support)	8	535	August 7, 2022
Problem - unprocessed messages Graylog Central (peer support)	4	768	November 14, 2019

Processing stuck with all processbufferprocessor threads used up

Related topics