Processing stuck with all processbufferprocessor threads used up

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

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.

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.

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

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.

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.



1 Like

@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.

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

2 Likes

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]);
   ...

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

1 Like

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

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

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:

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