search

Graylog2 / graylog2-server

Free and open log management
https://www.graylog.org
Other
7.33k stars 1.06k forks source link

Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes #602

Closed spruchnik closed 8 years ago

spruchnik commented 10 years ago 
15:08:58,959 INFO  [Deflector] Pointing deflector to new target index....
15:08:59,194 INFO  [Deflector] Flushing old index <graylog2_219>.
15:08:59,568 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_163] in [552ms].
15:08:59,716 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_164] in [148ms].
15:08:59,804 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_165] in [87ms].
15:08:59,896 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_166] in [91ms].
15:08:59,983 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_167] in [86ms].
15:09:00,071 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_168] in [87ms].
15:09:00,148 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_169] in [77ms].
15:09:00,152 INFO  [RebuildIndexRangesJob] Index [graylog2_220] is empty. Not calculating ranges.
15:09:00,241 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_171] in [88ms].
15:09:00,338 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_170] in [97ms].
15:09:00,440 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_173] in [101ms].
15:09:00,553 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_172] in [113ms].
15:09:00,643 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_197] in [89ms].
15:09:00,732 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_196] in [88ms].
15:09:00,814 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_199] in [82ms].
15:09:00,907 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_198] in [93ms].
15:09:01,003 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_190] in [95ms].
15:09:01,089 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_191] in [85ms].
15:09:01,168 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_194] in [79ms].
15:09:01,259 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_195] in [90ms].
15:09:01,392 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_192] in [132ms].
15:09:01,482 INFO  [Deflector] Setting old index <graylog2_219> to read-only.
15:09:01,493 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_193] in [101ms].
15:09:01,543 INFO  [SystemJobManager] Submitted SystemJob <feed1f70-0089-11e4-a31d-028925f19857> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]
15:09:01,543 INFO  [Deflector] Done!
15:09:01,546 INFO  [OptimizeIndexJob] Optimizing index <graylog2_219>.
15:09:01,643 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_176] in [149ms].
15:09:01,744 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_177] in [100ms].
15:09:01,864 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_174] in [120ms].
15:09:01,972 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_175] in [107ms].
15:09:02,113 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_178] in [140ms].
15:09:02,263 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_179] in [150ms].
15:09:03,145 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_180] in [882ms].
15:09:03,353 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_184] in [208ms].
15:09:03,451 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_183] in [97ms].
15:09:03,568 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_182] in [116ms].
15:09:03,684 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_181] in [115ms].
15:09:03,814 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_188] in [130ms].
15:09:03,955 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_187] in [140ms].
15:09:04,112 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_186] in [157ms].
15:09:04,340 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_185] in [227ms].
15:09:04,453 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_140] in [112ms].
15:09:04,580 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_189] in [126ms].
15:09:04,738 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_149] in [157ms].
15:09:04,867 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_145] in [128ms].
15:09:05,012 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_146] in [144ms].
15:09:05,253 INFO  [AlertScannerThread] Alert condition [01f5f408-e4e6-46db-a4aa-53e4ac64deb4:MESSAGE_COUNT={time: 30, threshold_type: less, threshold: 1, grace: 5}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts.
15:09:07,993 INFO  [RebuildIndexRangesJob] Calculated range of [graylog2_147] in [2981ms].
spruchnik commented 10 years ago

Actually this might be due to bug: https://github.com/Graylog2/graylog2-server/issues/541

dennisoelkers commented 10 years ago

Hey, thanks for reporting this.

I think it's not related to #541. Are you able to reproduce it intentionally? If yes, can you list the steps you take? Which version of the server are you using?

spruchnik commented 10 years ago

Hi Dennis,

This seems to be an intermittent issue. But I will try to reproduce it and let you know if I am successful.

Regards,

Slawek

From: Dennis Oelkers notifications@github.com<mailto:notifications@github.com> Reply-To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Date: Tuesday, July 1, 2014 at 4:59 AM To: Graylog2/graylog2-server graylog2-server@noreply.github.com<mailto:graylog2-server@noreply.github.com> Cc: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Hey, thanks for reporting this.

I think it's not related to #541https://github.com/Graylog2/graylog2-server/issues/541. Are you able to reproduce it intentionally? If yes, can you list the steps you take? Which version of the server are you using?

— Reply to this email directly or view it on GitHubhttps://github.com/Graylog2/graylog2-server/issues/602#issuecomment-47632739.

spruchnik commented 10 years ago

Got another false alert, from the logs:

11:48:45,316 INFO [Deflector] Cycling from to

11:48:45,316 INFO [Deflector] Creating index target ...

11:48:46,246 INFO [SystemJobManager] Submitted SystemJob <2faa0c60-0137-11e4-a31d-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob]

11:48:46,246 INFO [Deflector] Done!

11:48:46,246 INFO [Deflector] Pointing deflector to new target index....

11:48:46,246 INFO [RebuildIndexRangesJob] Re-calculating index ranges.

11:48:46,767 INFO [Deflector] Flushing old index .

11:48:47,233 INFO [Deflector] Setting old index to read-only.

11:48:47,649 INFO [SystemJobManager] Submitted SystemJob <307ffa00-0137-11e4-a31d-028925f19857> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]

11:48:47,649 INFO [Deflector] Done!

11:48:47,649 INFO [OptimizeIndexJob] Optimizing index .

11:48:48,511 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_227] in [2250ms].

11:48:49,621 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_226] in [1109ms].

11:48:49,627 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_229] in [5ms].

11:48:50,699 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_228] in [1072ms].

11:48:53,686 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_163] in [2987ms].

11:48:54,798 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_223] in [1111ms].

11:48:55,236 INFO [IndexRetentionThread] Number of indices (81) higher than limit (80). Running retention for 1 indices.

11:48:55,240 INFO [IndexRetentionThread] Running retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index

11:48:55,241 INFO [RetentionStrategy] Strategy is deleting.

11:48:55,605 INFO [RetentionStrategy] Finished index retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index in 364ms.

11:48:55,606 ERROR [IndexRetentionThread] Could not re-calculate index ranges after running retention: Maximum concurrency of job is reached.

11:48:56,077 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_164] in [1279ms].

11:48:57,443 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_222] in [1365ms].

11:48:58,628 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_165] in [1184ms].

11:49:00,107 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_225] in [1479ms].

11:49:01,412 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_224] in [1304ms].

11:49:02,933 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_166] in [1520ms].

11:49:04,264 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_167] in [1330ms].

11:49:05,278 INFO [AlertScannerThread] Alert condition [01f5f408-e4e6-46db-a4aa-53e4ac64deb4:MESSAGE_COUNT={time: 30, threshold_type: less, threshold: 1, grace: 5}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts.

11:49:06,665 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_168] in [2401ms].

From: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Date: Tuesday, July 1, 2014 at 10:26 AM To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Cc: Ops ops@appia.com<mailto:ops@appia.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Hi Dennis,

This seems to be an intermittent issue. But I will try to reproduce it and let you know if I am successful.

Regards,

Slawek

From: Dennis Oelkers notifications@github.com<mailto:notifications@github.com> Reply-To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Date: Tuesday, July 1, 2014 at 4:59 AM To: Graylog2/graylog2-server graylog2-server@noreply.github.com<mailto:graylog2-server@noreply.github.com> Cc: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Hey, thanks for reporting this.

I think it's not related to #541https://github.com/Graylog2/graylog2-server/issues/541. Are you able to reproduce it intentionally? If yes, can you list the steps you take? Which version of the server are you using?

— Reply to this email directly or view it on GitHubhttps://github.com/Graylog2/graylog2-server/issues/602#issuecomment-47632739.

spruchnik commented 10 years ago

As to the server version question:

15:23:58,883 INFO [Main] Graylog2 0.20.1 starting up. (JRE: Oracle Corporation 1.7.0_51 on Linux 2.6.32-358.6.2.el6.x86_64)

15:23:58,964 INFO [NodeId] Node ID: 6aff8f6a-0af9-455d-8646-b8b58663ef42

15:23:58,966 INFO [Core] No rest_transport_uri set. Falling back to [http://10.0.1.215:12900].

15:23:59,120 INFO [ProcessBuffer] Initialized ProcessBuffer with ring size <1024> and wait strategy .

15:23:59,132 INFO [OutputBuffer] Initialized OutputBuffer with ring size <1024> and wait strategy .

15:23:59,422 INFO [node] [graylog2-server] version[0.90.10], pid[3994], build[0a5781f/2014-01-10T10:18:37Z]

From: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Date: Tuesday, July 1, 2014 at 11:57 AM To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Got another false alert, from the logs:

11:48:45,316 INFO [Deflector] Cycling from to

11:48:45,316 INFO [Deflector] Creating index target ...

11:48:46,246 INFO [SystemJobManager] Submitted SystemJob <2faa0c60-0137-11e4-a31d-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob]

11:48:46,246 INFO [Deflector] Done!

11:48:46,246 INFO [Deflector] Pointing deflector to new target index....

11:48:46,246 INFO [RebuildIndexRangesJob] Re-calculating index ranges.

11:48:46,767 INFO [Deflector] Flushing old index .

11:48:47,233 INFO [Deflector] Setting old index to read-only.

11:48:47,649 INFO [SystemJobManager] Submitted SystemJob <307ffa00-0137-11e4-a31d-028925f19857> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]

11:48:47,649 INFO [Deflector] Done!

11:48:47,649 INFO [OptimizeIndexJob] Optimizing index .

11:48:48,511 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_227] in [2250ms].

11:48:49,621 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_226] in [1109ms].

11:48:49,627 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_229] in [5ms].

11:48:50,699 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_228] in [1072ms].

11:48:53,686 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_163] in [2987ms].

11:48:54,798 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_223] in [1111ms].

11:48:55,236 INFO [IndexRetentionThread] Number of indices (81) higher than limit (80). Running retention for 1 indices.

11:48:55,240 INFO [IndexRetentionThread] Running retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index

11:48:55,241 INFO [RetentionStrategy] Strategy is deleting.

11:48:55,605 INFO [RetentionStrategy] Finished index retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index in 364ms.

11:48:55,606 ERROR [IndexRetentionThread] Could not re-calculate index ranges after running retention: Maximum concurrency of job is reached.

11:48:56,077 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_164] in [1279ms].

11:48:57,443 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_222] in [1365ms].

11:48:58,628 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_165] in [1184ms].

11:49:00,107 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_225] in [1479ms].

11:49:01,412 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_224] in [1304ms].

11:49:02,933 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_166] in [1520ms].

11:49:04,264 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_167] in [1330ms].

11:49:05,278 INFO [AlertScannerThread] Alert condition [01f5f408-e4e6-46db-a4aa-53e4ac64deb4:MESSAGE_COUNT={time: 30, threshold_type: less, threshold: 1, grace: 5}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts.

11:49:06,665 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_168] in [2401ms].

From: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Date: Tuesday, July 1, 2014 at 10:26 AM To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Cc: Ops ops@appia.com<mailto:ops@appia.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Hi Dennis,

This seems to be an intermittent issue. But I will try to reproduce it and let you know if I am successful.

Regards,

Slawek

From: Dennis Oelkers notifications@github.com<mailto:notifications@github.com> Reply-To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Date: Tuesday, July 1, 2014 at 4:59 AM To: Graylog2/graylog2-server graylog2-server@noreply.github.com<mailto:graylog2-server@noreply.github.com> Cc: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Hey, thanks for reporting this.

I think it's not related to #541https://github.com/Graylog2/graylog2-server/issues/541. Are you able to reproduce it intentionally? If yes, can you list the steps you take? Which version of the server are you using?

— Reply to this email directly or view it on GitHubhttps://github.com/Graylog2/graylog2-server/issues/602#issuecomment-47632739.

dennisoelkers commented 10 years ago

Thanks. 0.20.1 is outdated already. Please upgrade to 0.20.3 (or wait for 0.20.4 which will be released today or tomorrow) and reopen the ticket if the problem still persists.

spruchnik commented 10 years ago

I have updated to the GL server to 0.20.4 and GL web interface to 0.20.5 (see startup output below) This issue is still happening, please reopen the bug.

Basically we have a alert that is defined as:

Triggeredhttps://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/alerts Conditionhttps://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/alerts Descriptionhttps://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/alerts an hour ago e387563d-09e1-47b9-b008-9b4652569dc5https://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/alerts# Stream had 0 messages in the last 50 minutes with trigger condition less than 1 messages. (Current grace time: 10 minutes)

Here is the relevant log entry from the log:

12:30:09,554 INFO [AlertScannerThread] Alert condition [e387563d-09e1-47b9-b008-9b4652569dc5:MESSAGE_COUNT={time: 50, threshold_type: less, threshold: 1, grace: 10}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts.

This is a false alert because if I run the stream now I get the output below. Note that the job should have picked up the messages from 12:20 and from 12:00 and should have not alerted.

Timestamp https://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/messages?q=*&rangetype=relative&relative=7200&sortField=timestamp&sortOrder=asc&fields=message%2Csource Source https://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/messages?q=*&rangetype=relative&relative=7200&sortField=source&sortOrder=asc&fields=message%2Csource https://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/messages?q=*&rangetype=relative&relative=7200&sortField=source&sortOrder=desc&fields=message%2Csource Message https://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/messages?q=*&rangetype=relative&relative=7200&sortField=message&sortOrder=asc&fields=message%2Csource https://prod-logs.appia.com/streams/539d7eb4e4b0c901febebccd/messages?q=*&rangetype=relative&relative=7200&sortField=message&sortOrder=desc&fields=message%2Csource 2014-07-10 13:21:09.438 rs-adsvrsvc01.goprod.com Queued 982 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 13:21:09.438 rs-adsvrsvc01.goprod.com Queued 982 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 13:01:02.847 rs-adsvrsvc01.goprod.com Queued 1039 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 13:01:02.847 rs-adsvrsvc01.goprod.com Queued 1039 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:41:18.861 rs-adsvrsvc01.goprod.com Queued 1027 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:41:18.861 rs-adsvrsvc01.goprod.com Queued 1027 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:20:51.848 rs-adsvrsvc01.goprod.com Queued 978 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:20:51.848 rs-adsvrsvc01.goprod.com Queued 978 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:00:59.856 rs-adsvrsvc01.goprod.com Queued 958 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:00:59.856 rs-adsvrsvc01.goprod.com Queued 958 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 11:40:55.921 rs-adsvrsvc01.goprod.com Queued 952 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 11:40:55.921 rs-adsvrsvc01.goprod.com Queued 952 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback.

Output from when the server was restarted (the 14:24 means yesterday)

14:24:53,792 INFO [Main] Graylog2 0.20.4 starting up. (JRE: Oracle Corporation 1.7.0_55 on Linux 2.6.32-358.6.2.el6.x86_64)

14:24:53,846 INFO [NodeId] Node ID: 311110ed-d625-4fa6-a7db-d3984be96b10

14:24:53,847 INFO [Core] No rest_transport_uri set. Falling back to [http://10.0.1.127:12900].

14:24:54,054 INFO [ProcessBuffer] Initialized ProcessBuffer with ring size <1024> and wait strategy .

14:24:54,066 INFO [OutputBuffer] Initialized OutputBuffer with ring size <1024> and wait strategy .

14:24:54,430 INFO [node] [graylog2-server] version[0.90.10], pid[26654], build[0a5781f/2014-01-10T10:18:37Z]

14:24:54,430 INFO [node] [graylog2-server] initializing ...

14:24:54,435 INFO [plugins] [graylog2-server] loaded [], sites []

14:24:55,913 INFO [node] [graylog2-server] initialized

14:24:55,913 INFO [node] [graylog2-server] starting ...

14:24:56,077 INFO [transport] [graylog2-server] bound_address {inet[/0:0:0:0:0:0:0:0:9350]}, publish_address {inet[/10.0.1.127:9350]}

14:24:59,082 WARN [discovery] [graylog2-server] waited for 3s and no initial state was set by the discovery

14:24:59,082 INFO [discovery] [graylog2-server] graylog2/YaaMyj52QKGTxsdL04ygxw

14:24:59,082 INFO [node] [graylog2-server] started

14:24:59,216 INFO [service] [graylog2-server] detected_master [Eternity][gZLhkeqKRWaS6UMkIbBJew][inet[/10.0.1.103:9300]], added {[Elaine Grey][88FCU4QaQUadj89JoToSOg][inet[/10.0.1.102:9300]],[Artemis][KGHOl9t0QVOhlbvwklMUPQ][inet[/10.0.1.5:9300]],[Eternity][gZLhkeqKRWaS6UMkIbBJew][inet[/10.0.1.103:9300]],[Mysterio][8ymX9ithRCC39dA3Ts_uvQ][inet[/10.0.1.247:9300]],}, reason: zen-disco-receive(from master [[Eternity][gZLhkeqKRWaS6UMkIbBJew][inet[/10.0.1.103:9300]]])

14:24:59,273 INFO [Core] Setting up deflector.

14:24:59,279 INFO [Deflector] Found deflector alias . Using it.

14:24:59,280 ERROR [PluginLoader] Plugin path </plugin/inputs> does not exist or is not a directory.

14:24:59,280 INFO [DroolsInitializer] Not using rules

14:24:59,280 INFO [Initializers] Initialized initializer .

14:24:59,513 INFO [Reflections] Reflections took 211 ms to scan 1 urls, producing 3 keys and 16 values

14:24:59,520 INFO [Periodicals] Starting [org.graylog2.periodical.DeflectorManagerThread] periodical in [0s], polling every [10s].

14:24:59,520 INFO [Periodicals] Starting [org.graylog2.periodical.ClusterHealthCheckThread] periodical in [0s], polling every [20s].

14:24:59,521 INFO [Periodicals] Starting [org.graylog2.periodical.BatchedElasticSearchOutputFlushThread] periodical in [0s], polling every [1s].

14:24:59,522 INFO [Periodicals] Starting [org.graylog2.periodical.AlertScannerThread] periodical in [10s], polling every [60s].

14:24:59,522 INFO [Periodicals] Starting [org.graylog2.periodical.NodePingThread] periodical in [0s], polling every [1s].

14:24:59,524 INFO [Periodicals] Starting [org.graylog2.periodical.StreamThroughputCounterManagerThread] periodical in [0s], polling every [1s].

14:24:59,525 INFO [Periodicals] Starting [org.graylog2.periodical.IndexerClusterCheckerThread] periodical in [0s], polling every [30s].

14:24:59,527 INFO [Periodicals] Starting [org.graylog2.periodical.VersionCheckThread] periodical in [0s], polling every [1800s].

14:24:59,527 INFO [Periodicals] Starting [org.graylog2.periodical.MasterCacheWorkerThread] periodical, running forever.

14:24:59,535 INFO [Periodicals] Starting [org.graylog2.periodical.DeadLetterThread] periodical, running forever.

14:24:59,542 INFO [Periodicals] Starting [org.graylog2.periodical.IndexRetentionThread] periodical in [0s], polling every [300s].

14:24:59,543 INFO [Periodicals] Starting [org.graylog2.periodical.ThroughputCounterManagerThread] periodical in [0s], polling every [1s].

14:24:59,545 INFO [Initializers] Initialized initializer .

14:24:59,545 INFO [OutputRegistry] Initialized output .

14:24:59,582 INFO [InputRegistry] Starting [org.graylog2.inputs.gelf.udp.GELFUDPInput] input with ID <53625caae4b0e1f6dd08c108>

14:24:59,651 INFO [GELFUDPInput] Started GELF UDP input on /0.0.0.0:12201

14:24:59,658 INFO [InputRegistry] Completed starting [org.graylog2.inputs.gelf.udp.GELFUDPInput] input with ID <53625caae4b0e1f6dd08c108>

14:25:02,039 INFO [ApplicationHandler] Initiating Jersey application, version Jersey: 2.5 2013-12-18 14:27:29...

14:25:03,636 INFO [Core] Started REST API at http://0.0.0.0:12900/

14:25:03,637 INFO [Main] Graylog2 up and running.

Output when the issue happens (today at 12:30pm)

12:29:59,560 INFO [DeflectorManagerThread] Number of messages in (20004386) is higher than the limit (20000000). Pointing deflector to new index now!

12:29:59,560 INFO [Deflector] Cycling deflector to next index now.

12:29:59,582 INFO [Deflector] Cycling from to

12:29:59,582 INFO [Deflector] Creating index target ...

12:30:00,355 INFO [SystemJobManager] Submitted SystemJob <7010df32-084f-11e4-a714-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob]

12:30:00,355 INFO [Deflector] Done!

12:30:00,355 INFO [Deflector] Pointing deflector to new target index....

12:30:00,355 INFO [RebuildIndexRangesJob] Re-calculating index ranges.

12:30:00,440 INFO [Deflector] Flushing old index .

12:30:00,713 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_327] in [326ms].

12:30:00,852 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_266] in [138ms].

12:30:01,052 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_267] in [199ms].

12:30:01,055 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_328] in [3ms].

12:30:01,460 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_325] in [404ms].

12:30:01,609 INFO [Deflector] Setting old index to read-only.

12:30:01,664 INFO [SystemJobManager] Submitted SystemJob <70d89c00-084f-11e4-a714-028925f19857> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob]

12:30:01,664 INFO [Deflector] Done!

12:30:01,665 INFO [OptimizeIndexJob] Optimizing index .

12:30:01,731 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_268] in [271ms].

12:30:01,932 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_326] in [201ms].

12:30:02,040 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_269] in [107ms].

12:30:02,201 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_262] in [160ms].

12:30:02,288 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_263] in [86ms].

12:30:02,635 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_264] in [346ms].

12:30:02,754 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_265] in [119ms].

12:30:02,850 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_320] in [95ms].

12:30:02,948 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_323] in [97ms].

12:30:03,490 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_324] in [542ms].

12:30:03,588 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_321] in [98ms].

12:30:03,749 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_322] in [160ms].

12:30:03,858 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_270] in [108ms].

12:30:03,962 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_272] in [104ms].

12:30:04,080 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_271] in [117ms].

12:30:04,181 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_279] in [100ms].

12:30:04,272 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_277] in [91ms].

12:30:04,405 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_278] in [132ms].

12:30:04,489 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_275] in [83ms].

12:30:04,568 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_276] in [79ms].

12:30:04,708 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_273] in [139ms].

12:30:04,820 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_274] in [112ms].

12:30:04,898 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_283] in [77ms].

12:30:05,030 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_282] in [131ms].

12:30:05,257 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_281] in [226ms].

12:30:05,372 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_280] in [114ms].

12:30:05,688 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_309] in [316ms].

12:30:05,777 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_284] in [88ms].

12:30:05,870 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_249] in [92ms].

12:30:06,015 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_248] in [144ms].

12:30:06,178 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_285] in [162ms].

12:30:06,254 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_286] in [76ms].

12:30:06,335 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_307] in [80ms].

12:30:06,414 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_287] in [78ms].

12:30:06,579 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_308] in [165ms].

12:30:06,722 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_288] in [142ms].

12:30:06,806 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_305] in [84ms].

12:30:06,947 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_306] in [140ms].

12:30:07,098 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_289] in [150ms].

12:30:07,136 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_303] in [37ms].

12:30:07,279 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_304] in [143ms].

12:30:07,660 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_301] in [380ms].

12:30:07,777 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_302] in [117ms].

12:30:07,902 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_300] in [125ms].

12:30:08,054 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_250] in [151ms].

12:30:08,196 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_290] in [141ms].

12:30:08,402 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_292] in [206ms].

12:30:08,481 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_291] in [78ms].

12:30:08,586 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_294] in [104ms].

12:30:08,674 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_293] in [88ms].

12:30:08,755 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_297] in [81ms].

12:30:08,771 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_318] in [16ms].

12:30:08,911 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_319] in [139ms].

12:30:08,990 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_298] in [79ms].

12:30:09,121 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_295] in [130ms].

12:30:09,248 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_296] in [127ms].

12:30:09,335 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_259] in [86ms].

12:30:09,351 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_314] in [15ms].

12:30:09,554 INFO [AlertScannerThread] Alert condition [e387563d-09e1-47b9-b008-9b4652569dc5:MESSAGE_COUNT={time: 50, threshold_type: less, threshold: 1, grace: 10}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts.

12:30:09,648 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_315] in [297ms].

12:30:09,696 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_316] in [47ms].

12:30:09,850 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_299] in [154ms].

12:30:09,982 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_317] in [131ms].

12:30:10,092 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_254] in [110ms].

12:30:10,228 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_310] in [135ms].

12:30:10,360 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_311] in [131ms].

12:30:10,563 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_253] in [202ms].

12:30:10,997 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_252] in [433ms].

12:30:11,298 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_312] in [301ms].

12:30:11,305 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_313] in [6ms].

12:30:11,408 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_251] in [102ms].

12:30:11,501 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_258] in [93ms].

12:30:11,579 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_257] in [78ms].

12:30:11,674 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_256] in [94ms].

12:30:11,966 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_255] in [292ms].

12:30:12,085 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_260] in [118ms].

12:30:12,233 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_261] in [147ms].

12:30:12,268 INFO [RebuildIndexRangesJob] Done calculating index ranges for 81 indices. Took 11881ms.

12:30:12,269 INFO [SystemJobManager] SystemJob <7010df32-084f-11e4-a714-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob] finished in 11913ms.

12:34:59,557 INFO [IndexRetentionThread] Number of indices (81) higher than limit (80). Running retention for 1 indices.

12:34:59,563 INFO [IndexRetentionThread] Running retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index

12:34:59,564 INFO [RetentionStrategy] Strategy is deleting.

12:35:00,126 INFO [RetentionStrategy] Finished index retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index in 562ms.

12:35:00,126 INFO [SystemJobManager] Submitted SystemJob <22be4be2-0850-11e4-a714-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob]

12:35:00,127 INFO [RebuildIndexRangesJob] Re-calculating index ranges.

12:35:00,279 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_327] in [135ms].

12:35:00,374 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_266] in [95ms].

From: Dennis Oelkers notifications@github.com<mailto:notifications@github.com> Reply-To: Graylog2/graylog2-server reply@reply.github.com<mailto:reply@reply.github.com> Date: Thursday, July 3, 2014 at 4:10 AM To: Graylog2/graylog2-server graylog2-server@noreply.github.com<mailto:graylog2-server@noreply.github.com> Cc: Slawek Pruchnik slawek.pruchnik@appia.com<mailto:slawek.pruchnik@appia.com> Subject: Re: [graylog2-server] Certain stream alerts (less than 1 in recent index) cause false positives when cycling indexes (#602)

Thanks. 0.20.1 is outdated already. Please upgrade to 0.20.3 (or wait for 0.20.4 which will be released today or tomorrow) and reopen the ticket if the problem still persists.

— Reply to this email directly or view it on GitHubhttps://github.com/Graylog2/graylog2-server/issues/602#issuecomment-47878440.

spruchnik commented 10 years ago

I have updated to the GL server to 0.20.4 and GL web interface to 0.20.5 (see startup output below) This issue is still happening, please reopen the bug.

Basically we have a alert that is defined as:

Triggered Condition Description an hour ago e387563d-09e1-47b9-b008-9b4652569dc5 Stream had 0 messages in the last 50 minutes with trigger condition less than 1 messages. (Current grace time: 10 minutes)

Here is the relevant log entry from the log:

12:30:09,554 INFO [AlertScannerThread] Alert condition [e387563d-09e1-47b9-b008-9b4652569dc5:MESSAGE_COUNT={time: 50, threshold_type: less, threshold: 1, grace: 10}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts.

This is a false alert because if I run the stream now I get the output below. Note that the job should have picked up the messages from 12:20 and from 12:00 and should have not alerted.

Timestamp Source Message
2014-07-10 13:21:09.438 rs-adsvrsvc01.goprod.com Queued 982 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 13:21:09.438 rs-adsvrsvc01.goprod.com Queued 982 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 13:01:02.847 rs-adsvrsvc01.goprod.com Queued 1039 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 13:01:02.847 rs-adsvrsvc01.goprod.com Queued 1039 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:41:18.861 rs-adsvrsvc01.goprod.com Queued 1027 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:41:18.861 rs-adsvrsvc01.goprod.com Queued 1027 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:20:51.848 rs-adsvrsvc01.goprod.com Queued 978 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:20:51.848 rs-adsvrsvc01.goprod.com Queued 978 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:00:59.856 rs-adsvrsvc01.goprod.com Queued 958 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 12:00:59.856 rs-adsvrsvc01.goprod.com Queued 958 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 11:40:55.921 rs-adsvrsvc01.goprod.com Queued 952 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback. 2014-07-10 11:40:55.921 rs-adsvrsvc01.goprod.com Queued 952 install events to java:/jboss/exported/jms/queue/AppiaConversionEventQueue for pingback.

Output from when the server was restarted (the 14:24 means yesterday)

14:24:53,792 INFO [Main] Graylog2 0.20.4 starting up. (JRE: Oracle Corporation 1.7.0_55 on Linux 2.6.32-358.6.2.el6.x86_64) 14:24:53,846 INFO [NodeId] Node ID: 311110ed-d625-4fa6-a7db-d3984be96b10 14:24:53,847 INFO [Core] No rest_transport_uri set. Falling back to [http://10.0.1.127:12900]. 14:24:54,054 INFO [ProcessBuffer] Initialized ProcessBuffer with ring size <1024> and wait strategy . 14:24:54,066 INFO [OutputBuffer] Initialized OutputBuffer with ring size <1024> and wait strategy . 14:24:54,430 INFO [node] [graylog2-server] version[0.90.10], pid[26654], build[0a5781f/2014-01-10T10:18:37Z] 14:24:54,430 INFO [node] [graylog2-server] initializing ... 14:24:54,435 INFO [plugins] [graylog2-server] loaded [], sites [] 14:24:55,913 INFO [node] [graylog2-server] initialized 14:24:55,913 INFO [node] [graylog2-server] starting ... 14:24:56,077 INFO [transport] [graylog2-server] bound_address {inet[/0:0:0:0:0:0:0:0:9350]}, publish_address {inet[/10.0.1.127:9350]} 14:24:59,082 WARN [discovery] [graylog2-server] waited for 3s and no initial state was set by the discovery 14:24:59,082 INFO [discovery] [graylog2-server] graylog2/YaaMyj52QKGTxsdL04ygxw 14:24:59,082 INFO [node] [graylog2-server] started 14:24:59,216 INFO [service] [graylog2-server] detected_master [Eternity][gZLhkeqKRWaS6UMkIbBJew][inet[/10.0.1.103:9300]], added {[Elaine Grey][88FCU4QaQUadj89JoToSOg][inet[/10.0.1.102:9300]],[Artemis][KGHOl9t0QVOhlbvwklMUPQ][inet[/10.0.1.5:9300]],[Eternity][gZLhkeqKRWaS6UMkIbBJew][inet[/10.0.1.103:9300]],[Mysterio][8ymX9ithRCC39dA3Ts_uvQ][inet[/10.0.1.247:9300]],}, reason: zen-disco-receive(from master [[Eternity][gZLhkeqKRWaS6UMkIbBJew][inet[/10.0.1.103:9300]]]) 14:24:59,273 INFO [Core] Setting up deflector. 14:24:59,279 INFO [Deflector] Found deflector alias . Using it. 14:24:59,280 ERROR [PluginLoader] Plugin path </plugin/inputs> does not exist or is not a directory. 14:24:59,280 INFO [DroolsInitializer] Not using rules 14:24:59,280 INFO [Initializers] Initialized initializer . 14:24:59,513 INFO [Reflections] Reflections took 211 ms to scan 1 urls, producing 3 keys and 16 values 14:24:59,520 INFO [Periodicals] Starting [org.graylog2.periodical.DeflectorManagerThread] periodical in [0s], polling every [10s]. 14:24:59,520 INFO [Periodicals] Starting [org.graylog2.periodical.ClusterHealthCheckThread] periodical in [0s], polling every [20s]. 14:24:59,521 INFO [Periodicals] Starting [org.graylog2.periodical.BatchedElasticSearchOutputFlushThread] periodical in [0s], polling every [1s]. 14:24:59,522 INFO [Periodicals] Starting [org.graylog2.periodical.AlertScannerThread] periodical in [10s], polling every [60s]. 14:24:59,522 INFO [Periodicals] Starting [org.graylog2.periodical.NodePingThread] periodical in [0s], polling every [1s]. 14:24:59,524 INFO [Periodicals] Starting [org.graylog2.periodical.StreamThroughputCounterManagerThread] periodical in [0s], polling every [1s]. 14:24:59,525 INFO [Periodicals] Starting [org.graylog2.periodical.IndexerClusterCheckerThread] periodical in [0s], polling every [30s]. 14:24:59,527 INFO [Periodicals] Starting [org.graylog2.periodical.VersionCheckThread] periodical in [0s], polling every [1800s]. 14:24:59,527 INFO [Periodicals] Starting [org.graylog2.periodical.MasterCacheWorkerThread] periodical, running forever. 14:24:59,535 INFO [Periodicals] Starting [org.graylog2.periodical.DeadLetterThread] periodical, running forever. 14:24:59,542 INFO [Periodicals] Starting [org.graylog2.periodical.IndexRetentionThread] periodical in [0s], polling every [300s]. 14:24:59,543 INFO [Periodicals] Starting [org.graylog2.periodical.ThroughputCounterManagerThread] periodical in [0s], polling every [1s]. 14:24:59,545 INFO [Initializers] Initialized initializer . 14:24:59,545 INFO [OutputRegistry] Initialized output . 14:24:59,582 INFO [InputRegistry] Starting [org.graylog2.inputs.gelf.udp.GELFUDPInput] input with ID <53625caae4b0e1f6dd08c108> 14:24:59,651 INFO [GELFUDPInput] Started GELF UDP input on /0.0.0.0:12201 14:24:59,658 INFO [InputRegistry] Completed starting [org.graylog2.inputs.gelf.udp.GELFUDPInput] input with ID <53625caae4b0e1f6dd08c108> 14:25:02,039 INFO [ApplicationHandler] Initiating Jersey application, version Jersey: 2.5 2013-12-18 14:27:29... 14:25:03,636 INFO [Core] Started REST API at http://0.0.0.0:12900/ 14:25:03,637 INFO [Main] Graylog2 up and running.

Output when the issue happens (today at 12:30pm)

12:29:59,560 INFO [DeflectorManagerThread] Number of messages in (20004386) is higher than the limit (20000000). Pointing deflector to new index now! 12:29:59,560 INFO [Deflector] Cycling deflector to next index now. 12:29:59,582 INFO [Deflector] Cycling from to 12:29:59,582 INFO [Deflector] Creating index target ... 12:30:00,355 INFO [SystemJobManager] Submitted SystemJob <7010df32-084f-11e4-a714-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob] 12:30:00,355 INFO [Deflector] Done! 12:30:00,355 INFO [Deflector] Pointing deflector to new target index.... 12:30:00,355 INFO [RebuildIndexRangesJob] Re-calculating index ranges. 12:30:00,440 INFO [Deflector] Flushing old index . 12:30:00,713 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_327] in [326ms]. 12:30:00,852 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_266] in [138ms]. 12:30:01,052 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_267] in [199ms]. 12:30:01,055 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_328] in [3ms]. 12:30:01,460 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_325] in [404ms]. 12:30:01,609 INFO [Deflector] Setting old index to read-only. 12:30:01,664 INFO [SystemJobManager] Submitted SystemJob <70d89c00-084f-11e4-a714-028925f19857> [org.graylog2.indexer.indices.jobs.OptimizeIndexJob] 12:30:01,664 INFO [Deflector] Done! 12:30:01,665 INFO [OptimizeIndexJob] Optimizing index . 12:30:01,731 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_268] in [271ms]. 12:30:01,932 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_326] in [201ms]. 12:30:02,040 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_269] in [107ms]. 12:30:02,201 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_262] in [160ms]. 12:30:02,288 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_263] in [86ms]. 12:30:02,635 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_264] in [346ms]. 12:30:02,754 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_265] in [119ms]. 12:30:02,850 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_320] in [95ms]. 12:30:02,948 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_323] in [97ms]. 12:30:03,490 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_324] in [542ms]. 12:30:03,588 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_321] in [98ms]. 12:30:03,749 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_322] in [160ms]. 12:30:03,858 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_270] in [108ms]. 12:30:03,962 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_272] in [104ms]. 12:30:04,080 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_271] in [117ms]. 12:30:04,181 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_279] in [100ms]. 12:30:04,272 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_277] in [91ms]. 12:30:04,405 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_278] in [132ms]. 12:30:04,489 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_275] in [83ms]. 12:30:04,568 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_276] in [79ms]. 12:30:04,708 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_273] in [139ms]. 12:30:04,820 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_274] in [112ms]. 12:30:04,898 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_283] in [77ms]. 12:30:05,030 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_282] in [131ms]. 12:30:05,257 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_281] in [226ms]. 12:30:05,372 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_280] in [114ms]. 12:30:05,688 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_309] in [316ms]. 12:30:05,777 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_284] in [88ms]. 12:30:05,870 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_249] in [92ms]. 12:30:06,015 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_248] in [144ms]. 12:30:06,178 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_285] in [162ms]. 12:30:06,254 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_286] in [76ms]. 12:30:06,335 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_307] in [80ms]. 12:30:06,414 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_287] in [78ms]. 12:30:06,579 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_308] in [165ms]. 12:30:06,722 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_288] in [142ms]. 12:30:06,806 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_305] in [84ms]. 12:30:06,947 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_306] in [140ms]. 12:30:07,098 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_289] in [150ms]. 12:30:07,136 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_303] in [37ms]. 12:30:07,279 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_304] in [143ms]. 12:30:07,660 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_301] in [380ms]. 12:30:07,777 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_302] in [117ms]. 12:30:07,902 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_300] in [125ms]. 12:30:08,054 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_250] in [151ms]. 12:30:08,196 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_290] in [141ms]. 12:30:08,402 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_292] in [206ms]. 12:30:08,481 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_291] in [78ms]. 12:30:08,586 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_294] in [104ms]. 12:30:08,674 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_293] in [88ms]. 12:30:08,755 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_297] in [81ms]. 12:30:08,771 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_318] in [16ms]. 12:30:08,911 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_319] in [139ms]. 12:30:08,990 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_298] in [79ms]. 12:30:09,121 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_295] in [130ms]. 12:30:09,248 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_296] in [127ms]. 12:30:09,335 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_259] in [86ms]. 12:30:09,351 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_314] in [15ms]. 12:30:09,554 INFO [AlertScannerThread] Alert condition [e387563d-09e1-47b9-b008-9b4652569dc5:MESSAGE_COUNT={time: 50, threshold_type: less, threshold: 1, grace: 10}, stream:={539d7eb4e4b0c901febebccd: "Pingback Watching"}] is triggered. Sending alerts. 12:30:09,648 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_315] in [297ms]. 12:30:09,696 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_316] in [47ms]. 12:30:09,850 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_299] in [154ms]. 12:30:09,982 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_317] in [131ms]. 12:30:10,092 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_254] in [110ms]. 12:30:10,228 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_310] in [135ms]. 12:30:10,360 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_311] in [131ms]. 12:30:10,563 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_253] in [202ms]. 12:30:10,997 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_252] in [433ms]. 12:30:11,298 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_312] in [301ms]. 12:30:11,305 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_313] in [6ms]. 12:30:11,408 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_251] in [102ms]. 12:30:11,501 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_258] in [93ms]. 12:30:11,579 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_257] in [78ms]. 12:30:11,674 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_256] in [94ms]. 12:30:11,966 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_255] in [292ms]. 12:30:12,085 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_260] in [118ms]. 12:30:12,233 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_261] in [147ms]. 12:30:12,268 INFO [RebuildIndexRangesJob] Done calculating index ranges for 81 indices. Took 11881ms. 12:30:12,269 INFO [SystemJobManager] SystemJob <7010df32-084f-11e4-a714-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob] finished in 11913ms. 12:34:59,557 INFO [IndexRetentionThread] Number of indices (81) higher than limit (80). Running retention for 1 indices. 12:34:59,563 INFO [IndexRetentionThread] Running retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index 12:34:59,564 INFO [RetentionStrategy] Strategy is deleting. 12:35:00,126 INFO [RetentionStrategy] Finished index retention strategy [org.graylog2.indexer.retention.strategies.DeletionRetentionStrategy] for index in 562ms. 12:35:00,126 INFO [SystemJobManager] Submitted SystemJob <22be4be2-0850-11e4-a714-028925f19857> [org.graylog2.indexer.ranges.RebuildIndexRangesJob] 12:35:00,127 INFO [RebuildIndexRangesJob] Re-calculating index ranges. 12:35:00,279 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_327] in [135ms]. 12:35:00,374 INFO [RebuildIndexRangesJob] Calculated range of [graylog2_266] in [95ms].

bryanhelmig commented 9 years ago

We too run into this on occasion.

brandongalbraith commented 9 years ago

Has this been fixed in Graylog 1.1?

zexxon commented 9 years ago

Brandon can you please test on 1.1? We haven't been able to reproduce the issue and none of our supported customers have run into this particular defect on 1.0+ that I am aware of.

brandongalbraith commented 9 years ago

@zexxon Yep! I'll test on 1.1.6 and return with results. Thanks!

bernd commented 8 years ago

Closing this. Please re-open if the issue still exists in Graylog 1.3.x or the upcoming 2.0. Thank you.

bryanhelmig commented 8 years ago

We've not seen the issue with 1.3 since upgrading.

-bryan

On Feb 26, 2016, at 3:55 AM, Bernd Ahlers notifications@github.com wrote:

Closing this. Please re-open if the issue still exists in Graylog 1.3.x or the upcoming 2.0. Thank you.

— Reply to this email directly or view it on GitHub.

bernd commented 8 years ago

@bryanhelmig Great, thank you for the feedback! :smiley: