Skip to content
This repository has been archived by the owner on Jan 15, 2019. It is now read-only.

[dev.icinga.com #9106] Icinga no longer sending acknowledgement notifications #1551

Closed
icinga-migration opened this issue Apr 17, 2015 · 13 comments

Comments

@icinga-migration
Copy link

This issue has been migrated from Redmine: https://dev.icinga.com/issues/9106

Created by ziesemer on 2015-04-17 16:46:46 +00:00

Assignee: mfriedrich
Status: Resolved (closed on 2015-05-01 10:53:59 +00:00)
Target Version: 1.13.3
Last Update: 2015-07-15 09:41:36 +00:00 (in Redmine)

Icinga Version: 1.13.2
OS Version: Red Hat Enterprise Linux Server release 6.5 (Santiago)

After upgrading from 1.12.2 to 1.13.2, acknowledgements are taking effect - but no longer sending the notifications concerning them. Other notifications (problem, custom, recovery) continue to work as expected.

The ACK shows in the event log, but not in the notification log.

Running with full debug logging: In 1.12.2, immediately after "Making callbacks (type 29)..." is a "service_notification()" call - followed by many lines related to sending the notification, followed by schedule_new_event(). In 1.13.2, service_notification() is skipped, and everything jumps directly to schedule_new_event(). Reverting to 1.12.2 - keeping the same configurations - resumes proper functionality.

This is reproducible on multiple servers - each running builds from source.

Attachments

Changesets

2015-04-29 17:27:42 +00:00 by (unknown) 4a40a06

Classic UI: Assume enabled for 'send_notification' if value was not set in cmd.cgi

refs #9106

2015-04-30 20:38:32 +00:00 by mfriedrich 9c47932

Classic UI: Ensure passing checkbox values for 'send_notification'

refs #9106

Relations:

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-04-20 09:18:38 +00:00

  • Status changed from New to Feedback
  • Assigned to set to ziesemer

Please post the external command being logged.

@icinga-migration
Copy link
Author

Updated by ziesemer on 2015-04-20 12:08:45 +00:00

Are you looking for the external command of the acknowledgement action?

Here is a sanitized (host and service description) log snippet:

[1429235317.519832] [008.2] [pid=27914] No events to execute at the moment.  Idling for a bit...
[1429235317.519834] [001.0] [pid=27914] check_for_external_commands()
[1429235317.519854] [001.0] [pid=27914] process_external_command1()
[1429235317.519861] [128.2] [pid=27914] Raw command entry: [1429235317] ACKNOWLEDGE_SVC_PROBLEM_EXPIRE;***hostDesc***;***serviceDesc***;1;0;0;1429321713;mziesemer;Test - The acknowledgement expires at: 2015-04-17 20:48:33.
[1429235317.519976] [064.1] [pid=27914] Making callbacks (type 9)...
[1429235317.519998] [064.1] [pid=27914] Making callbacks (type 24)...
[1429235317.520011] [001.0] [pid=27914] process_external_command2()
[1429235317.520016] [128.1] [pid=27914] External Command Type: 175
[1429235317.520019] [128.1] [pid=27914] Command Entry Time: 1429235317
[1429235317.520021] [128.1] [pid=27914] Command Arguments: ***hostDesc***;***serviceDesc***;1;0;0;1429321713;mziesemer;Test - The acknowledgement expires at: 2015-04-17 20:48:33.
[1429235317.520033] [064.1] [pid=27914] Making callbacks (type 29)...
[1429235317.520071] [001.0] [pid=27914] schedule_new_event()
[1429235317.520097] [001.0] [pid=27914] add_event()
[1429235317.520101] [064.1] [pid=27914] Making callbacks (type 8)...
[1429235317.520104] [064.1] [pid=27914] Making callbacks (type 20)...
[1429235317.520113] [064.1] [pid=27914] Making callbacks (type 15)...
[1429235317.520142] [064.1] [pid=27914] Making callbacks (type 15)...
[1429235317.520145] [064.1] [pid=27914] Making callbacks (type 24)...
[1429235317.520147] [064.1] [pid=27914] Making callbacks (type 8)...
[1429235317.770237] [008.1] [pid=27914] ** Event Check Loop
[1429235317.770280] [008.1] [pid=27914] Next High Priority Event Time: Thu Apr 16 20:48:41 2015
[1429235317.770295] [008.1] [pid=27914] Next Low Priority Event Time:  Thu Apr 16 20:48:54 2015
[1429235317.770318] [008.1] [pid=27914] Current/Max Service Checks: 0/0
[1429235317.770336] [008.2] [pid=27914] No events to execute at the moment.  Idling for a bit...

(I will work on also reproducing with a sample configuration so that we don't need to be concerned with sanitizing outputs here.)

@icinga-migration
Copy link
Author

Updated by ziesemer on 2015-04-29 02:11:00 +00:00

  • File added Ack-1.12.2.txt
  • File added NoAck-1.13.2.txt

Sorry for the delay.

  • A fresh Icinga install of 1.12.2, followed by "make install-config". (So my sample configuration is now your sample configuration.)
    • I only replaced "icingaadmin" with my username in cgi.cfg to ease in running as admin (I'm already authenticated to Apache HTTPD), and replaced the notify-*-by-email commands in objects/commands.cfg with /bin/true as to not flood anything.
  • I've enabled all the host checks, service checks, and notifications - such that it's a green dashboard.
  • All checks pass except for localhost:HTTP, as I'm running on :8080 instead of :80.
  • Set debug_level=-1 in icinga.cfg per https://wiki.icinga.org/display/Dev/Icinga+Core+Debug+Config, and restart the process.

I acknowledged the critical service. The debugging log is attached in attachment:Ack-1.12.2.txt. Everything looks exactly as expected.

I then shutdown, upgraded to 1.13.2 - replacing everything but the "etc" and "var" folders to keep the same configuration. Also removed the "objects.cache" and "retention.dat" from "var" - clearing out my acknowledgement in the process. Restarted with 1.13.2, and re-acknowledged the critical service. The debugging log is attached in attachment:NoAck-1.13.2.txt. Note how much smaller it is - and again, it skips the "Making callbacks (type 29)..." and everything that follows, and again skips to "Making callbacks (type 24)..." and everything related to the notification in-between.

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-04-29 17:21:37 +00:00

  • Status changed from Feedback to New

  • Assigned to deleted ziesemer

    ACKNOWLEDGE_SVC_PROBLEM_EXPIRE;hostDesc;serviceDesc;1;0;0;1429321713;mziesemer;Test - The acknowledgement expires at: 2015-04-17 20:48:33.

http://docs.icinga.org/latest/en/extcommands2.html

ACKNOWLEDGE_SVC_PROBLEM_EXPIRE

ACKNOWLEDGE_SVC_PROBLEM_EXPIRE;;;;;;;;

Allows you to define the time (seconds since the UNIX epoch) when the acknowledgement will expire (will be deleted).

notify=0

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-04-29 17:29:32 +00:00

  • Status changed from New to Feedback
  • Assigned to set to ziesemer

I've pushed 4a40a06 to the git master which probably fixes your problem. Please test that patch and report back.

@icinga-migration
Copy link
Author

Updated by ziesemer on 2015-04-29 19:42:31 +00:00

Sorry - didn't seem to have helped:

[1430336019.988169] [008.1] [pid=14006] ** Event Check Loop
[1430336019.988212] [008.1] [pid=14006] Next High Priority Event Time: Wed Apr 29 14:33:41 2015
[1430336019.988228] [008.1] [pid=14006] Next Low Priority Event Time:  Wed Apr 29 14:33:47 2015
[1430336019.988250] [008.1] [pid=14006] Current/Max Service Checks: 0/0
[1430336019.988256] [008.2] [pid=14006] No events to execute at the moment.  Idling for a bit...
[1430336019.988259] [001.0] [pid=14006] check_for_external_commands()
[1430336019.988265] [001.0] [pid=14006] process_external_command1()
[1430336019.988269] [128.2] [pid=14006] Raw command entry: [1430336019] ACKNOWLEDGE_SVC_PROBLEM;localhost;HTTP;1;0;0;mziesemer;Test
[1430336019.988315] [064.1] [pid=14006] Making callbacks (type 9)...
[1430336019.988322] [064.1] [pid=14006] Making callbacks (type 24)...
[1430336019.988326] [001.0] [pid=14006] process_external_command2()
[1430336019.988329] [128.1] [pid=14006] External Command Type: 34
[1430336019.988333] [128.1] [pid=14006] Command Entry Time: 1430336019
[1430336019.988336] [128.1] [pid=14006] Command Arguments: localhost;HTTP;1;0;0;mziesemer;Test
[1430336019.988349] [064.1] [pid=14006] Making callbacks (type 29)...
[1430336019.988354] [064.1] [pid=14006] Making callbacks (type 20)...
[1430336019.988362] [064.1] [pid=14006] Making callbacks (type 15)...
[1430336019.988366] [064.1] [pid=14006] Making callbacks (type 15)...
[1430336019.988370] [064.1] [pid=14006] Making callbacks (type 24)...
[1430336019.988374] [064.1] [pid=14006] Making callbacks (type 8)...
[1430336020.238453] [008.1] [pid=14006] ** Event Check Loop
[1430336020.238500] [008.1] [pid=14006] Next High Priority Event Time: Wed Apr 29 14:33:41 2015
[1430336020.238525] [008.1] [pid=14006] Next Low Priority Event Time:  Wed Apr 29 14:33:47 2015
[1430336020.238548] [008.1] [pid=14006] Current/Max Service Checks: 0/0
[1430336020.238553] [008.2] [pid=14006] No events to execute at the moment.  Idling for a bit...
[1430336020.238562] [001.0] [pid=14006] check_for_external_commands()
[1430336020.238654] [064.1] [pid=14006] Making callbacks (type 8)...
[1430336020.488776] [008.1] [pid=14006] ** Event Check Loop

I downloaded https://github.com/Icinga/icinga-core/archive/master.zip , verified the referenced changes were in my cgi/cmd.c, re-built and re-tested.

I repeated the test after running:

./update-version '1.13.2a'

... just to validate that I was using the latest code, as this became visible on the UI and in the logs:

[1430336767] Icinga 1.13.2a starting... (PID=19618)

... and still experienced the same results. No notifications, or all the extra related debugging concerning them.

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-04-30 20:39:20 +00:00

  • Target Version set to 1.13.3

Mh ok, think I've found it.

Ticking off the checkbox (no notifications)

[2015-04-30 22:36:07 +0200] information/ExternalCommandListener: Executing external command: [1430426167] ACKNOWLEDGE_SVC_PROBLEM;imagine.Speedport_W_921V_1_36_000;disk;2;0;0;Icinga 2 Admin;fsfds

Enabling it

[2015-04-30 22:37:27 +0200] information/ExternalCommandListener: Executing external command: [1430426247] ACKNOWLEDGE_SVC_PROBLEM;imagine.Speedport_W_921V_1_36_000;disk;2;1;0;Icinga 2 Admin;dfsfsfsfs
[2015-04-30 22:37:27 +0200] information/Checkable: Checking for configured notifications for object 'imagine.Speedport_W_921V_1_36_000!disk'
[2015-04-30 22:37:27 +0200] information/Notification: Sending notification 'imagine.Speedport_W_921V_1_36_000!disk!mail-icingaadmin' for user 'icingaadmin'
[2015-04-30 22:37:27 +0200] information/Notification: Completed sending notification 'imagine.Speedport_W_921V_1_36_000!disk!mail-icingaadmin' for checkable 'imagine.Speedport_W_921V_1_36_000!disk'

Please test the pushed fix to git master.

@icinga-migration
Copy link
Author

Updated by ziesemer on 2015-05-01 01:16:37 +00:00

Working much better now, thank you! (Will eagerly await the 1.13.3 release.)

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-05-01 10:53:29 +00:00

  • Subject changed from Icinga no longer sending acknowledgement notifications after upgrading from 1.12.2 to 1.13.2 to Icinga no longer sending acknowledgement notifications
  • Status changed from Feedback to Assigned
  • Assigned to changed from ziesemer to mfriedrich

Ok thanks for your patience :)

Let's see how long it takes for the next bugfix release.

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-05-01 10:53:59 +00:00

  • Status changed from Assigned to Resolved
  • Done % changed from 0 to 100

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-05-01 10:54:10 +00:00

  • Category changed from Notifications to Classic UI

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-06-09 17:28:22 +00:00

  • Duplicated set to 9396

@icinga-migration
Copy link
Author

Updated by mfriedrich on 2015-07-15 09:41:36 +00:00

  • Priority changed from Normal to High

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

1 participant