Macros missing in notifications?

[jgauthier2112]

Greetings everyone,

The last few days I've noticed that macros in my notifications do not seem to me expanding.
For example, here is the email I have been receiving.

***** Nagios *****

Notification Type: ACKNOWLEDGEMENT (jgu)
Host: v-itutil
State: DOWN
Address: v-itutil2
Info: kpg: Iv / - v-u2
T y

Date/Time: Thu May 28 13:35:30 EDT 2015

The host is correct. The username in the Acknowledgement is not, and the info is also completely wrong.
I typed "This is only a test" as a comment, and it shows up as "T y".

I have no changed my commands. It still looks loke this:

/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: $NOTIFICATIONTYPE$ ($HOSTACKAUTHOR$)\nHost: $HOSTNAME$\nState: $HOSTSTATE$\nAddress: $HOSTADDRESS$\nInfo: $HOSTOUTPUT$\\n$HOSTACKCOMMENT$\n\n\nDate/Time: $LONGDATETIME$\n" | /bin/mail -s "Host $HOSTSTATE$ alert for $HOSTNAME$!" $CONTACTEMAIL$

This seems to have just started happening in the last several days. I was running 4.0.8. I recompiled, and now is running 4.1-rc. Issue still occurs.

Any tips welcomed.

[abrist]

The only I notice about your command is that you have two slashs instead of one between the host output and host comment:

$HOSTOUTPUT$\\n$HOSTACKCOMMENT$

Just to verify, you are using the host notification command for the host and not the service notification command, is that correct?

[ssax]

Hopefully it's not a memory issue.

Are you seeing anything strange in /var/log/messages or in your /usr/local/nagios/var/nagios.log?

[jgauthier2112]

Strange about the double \. I removed those. But it didn't change anything.

I can reproduce this pretty quickly. I submit the command externally like so:
echo "[`date +%s`] ACKNOWLEDGE_HOST_PROBLEM;v-itutil;2;1;0;[email protected];This is only a test" > /opt/nagios/var/rw/nagios.cmd

Then I see this in the nagios logs.

Code: Select all

[1432845451] EXTERNAL COMMAND: ACKNOWLEDGE_HOST_PROBLEM;v-itutil;2;1;0;[email protected];This is only a test
[1432845451] HOST NOTIFICATION: jgauthier;v-itutil;ACKNOWLEDGEMENT (DOWN);host-notify-by-email;check_ping: Invalid hostname/address - v-itutil2;[email protected];This is only a test

That looks good. Then the email looks like trash:
***** Nagios *****

Notification Type: ACKNOWLEDGEMENT (y)
Host: v-itutil
State: DOWN
Address: v-itutil2
Info: kpg: Iv / - v-u2
T y

Date/Time: Thu May 28 16:37:31 EDT 2015

I can change my output command to a file instead of |mail, and I see the same results.

I kicked my debugging up, and took a look through the debug logs.

Code: Select all

[1432845793.330590] [256.1] [pid=17463] Read raw external command '[1432845793] ACKNOWLEDGE_HOST_PROBLEM;v-itutil;2;1;0;[email protected];This is only a test'
[1432845793.330615] [128.2] [pid=17463] Raw command entry: [1432845793] ACKNOWLEDGE_HOST_PROBLEM;v-itutil;2;1;0;[email protected];This is only a test
[1432845793.330727] [128.1] [pid=17463] Command Arguments: v-itutil;2;1;0;[email protected];This is only a test
[1432845793.330784] [032.0] [pid=17463] ** Host Notification Attempt ** Host: 'v-itutil', Type: ACKNOWLEDGEMENT, Options: 0, Current State: 1, Last Notification: Thu May 28 16:36:49 2015
[1432845793.332587] [2048.2] [pid=17463]   Uncleaned macro.  Running output (98): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil'
[1432845793.332593] [2048.2] [pid=17463]   Just finished macro.  Running output (98): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil'
[1432845793.332605] [2048.2] [pid=17463]   Not currently in macro.  Running output (107): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: '
[1432845793.332641] [2048.2] [pid=17463]   Uncleaned macro.  Running output (111): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN'
[1432845793.332654] [2048.2] [pid=17463]   Just finished macro.  Running output (111): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN'
[1432845793.332684] [2048.2] [pid=17463]   Not currently in macro.  Running output (122): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: '
[1432845793.332714] [2048.2] [pid=17463]   Uncleaned macro.  Running output (131): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2'
[1432845793.332720] [2048.2] [pid=17463]   Just finished macro.  Running output (131): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2'
[1432845793.332732] [2048.2] [pid=17463]   Not currently in macro.  Running output (139): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: '
[1432845793.332770] [2048.2] [pid=17463]   Cleaned macro.  Running output (155): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: kpg: Iv / - v-u2'
[1432845793.332776] [2048.2] [pid=17463]   Just finished macro.  Running output (155): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: kpg: Iv / - v-u2'
[1432845793.332794] [2048.2] [pid=17463]   Not currently in macro.  Running output (157): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: kpg: Iv / - v-u2\n'
[1432845793.332831] [2048.2] [pid=17463]   Cleaned macro.  Running output (163): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: kpg: Iv / - v-u2\nT  y  '
[1432845793.332837] [2048.2] [pid=17463]   Just finished macro.  Running output (163): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: kpg: Iv / - v-u2\nT  y  '
[1432845793.332859] [2048.2] [pid=17463]   Not currently in macro.  Running output (180): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil\nState: DOWN\nAddress: v-itutil2\nInfo: kpg: Iv / - v-u2\nT  y  \n\n\nDate/Time: '

So, we can see it building the string here.. and it's building it completely wrong! Even from the first line:

Code: Select all

[1432845793.332587] [2048.2] [pid=17463]   Uncleaned macro.  Running output (98): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y)\nHost: v-itutil'

That (y) should be [email protected].

[jgauthier2112]

A little more from the debug log.

Code: Select all

[1432847786.445135] [2048.1] [pid=32474] **** BEGIN MACRO PROCESSING ***********
[1432847786.442842] [2048.2] [pid=32474]   Processing part: 'HOSTACKAUTHOR'
[1432847786.442857] [2048.2] [pid=32474]   macros[49] (HOSTACKAUTHOR) match.
[1432847786.442877] [2048.2] [pid=32474]   Processed 'HOSTACKAUTHOR', Free: 0
[1432847786.442891] [2048.2] [pid=32474]   Processed 'HOSTACKAUTHOR', Free: 0,  Cleaning options: 3
[1432847786.442907] [2048.2] [pid=32474]   Cleaned macro.  Running output (81): '/usr/bin/printf "%b" "***** Nagios *****\n\nNotification Type: ACKNOWLEDGEMENT (y
'

So there is something happening in the macro processing.

[jdalrymple]

This seems to have just started happening in the last several days. I was running 4.0.8. I recompiled, and now is running 4.1-rc. Issue still occurs.

Hate to be the nay-sayer in the room, but things don't just stop working without changing something. As I read this, it happened on 4.0.8 in addition to now in 4.1-rc? Generally speaking when you have a problem going from stable --> RC is NOT the way to fix it

That said let's figure out what happened.

I can change my output command to a file instead of |mail, and I see the same results.

Did you do this? If so can we see the command and the output?

I might recommend that you output similar macros a few times in succession to see if the funky behavior is even reproducible.

[jgauthier2112]

Hate to be the nay-sayer in the room, but things don't just stop working without changing something. As I read this, it happened on 4.0.8 in addition to now in 4.1-rc? Generally speaking when you have a problem going from stable --> RC is NOT the way to fix it

Whoever said I didn't change anything? It just started happening - true. Of course there are changes. We are continually adding hosts, services, and tweaking what is there. I recently added some performance monitoring changes (which I completely removed after I discovered this issue).

I went to the RC just to determine if it was a fixed bug. I was on 4.0.6, I moved to 4.0.8 after trying the RC, and it also showed the issue.

I can change my output command to a file instead of |mail, and I see the same results.

Did you do this? If so can we see the command and the output?
I might recommend that you output similar macros a few times in succession to see if the funky behavior is even reproducible.

Good idea. I did. Interesting results:

Code: Select all

Notification Type: ACKNOWLEDGEMENT
Ack author: (y)
Ack author: (y)
Ack author: (y)
Ack author: (y)
Host: v-itutil
State: DOWN
Address: v-itutil2
Info: kpg: Iv / - v-u2
comment: T  y
comment: T  y
comment: T  y

Date/Time: Fri May 29 09:22:40 EDT 2015

I don't know what, in the config, could have caused this. But, it has to be something.
I am going to spend more time today, and see if I can figure out where this is breaking down.

[jgauthier2112]

Well, this is disappointing.

I tracked this down to the clean_macro_chars function. This function takes the config option "illegal_macro_output_chars" and it strips this data from the string.

From my debug output, this was basically stripping ALL characters out, with the exception of a few.
I looked at stock Nagios config, and I modified my options to include only the stock Nagios.

I restarted a few times, and this did not change the issue.

So, I started adding debug code in, to confirm the contets of this variable. Mid-test, the problem went away.
I also changed debugging levels. So, thinking this triggered the event I changed the debugging levels back, but that didn't do anything.
So, I undid all my code changes for debugging, and recompiled. Everything is working now

I have no idea what triggered this to break, or what triggered it to start working. But it works now.

Code: Select all

Notification Type: ACKNOWLEDGEMENT
Ack author: ([email protected])
Ack author: ([email protected])
Ack author: ([email protected])
Ack author: ([email protected])
Host: v-itutil
State: DOWN
Address: v-itutil2
Info: check_ping: Invalid hostname/address - v-itutil2
comment: This is only a test
comment: This is only a test
comment: This is only a test

Date/Time: Fri May 29 13:20:44 EDT 2015

[jdalrymple]

From my debug output, this was basically stripping ALL characters out, with the exception of a few.
I looked at stock Nagios config, and I modified my options to include only the stock Nagios.

I restarted a few times, and this did not change the issue.

Possible that the restarts weren't happening properly? `/etc/init.d/nagios restart`and `service nagios restart` aren't the most bulletproof methods of restarting in the world.

Aside from that the only thing I'd wonder is what you had modified that "illegal_macro_output_chars" setting to, but unless the above stated was the situation I don't know how that could have been the culprit anyway. You could try to change it back?

All that said, OK to close or do you want to try further forensic?

[jgauthier2112]

It was definitely restarting, because all of my custom code changes were in place.

Please don't spend any more effort on this. If it happens again, I will start up where I left off debugging the illegal macro substation.
I still wonder if was memory corruption happening from something, somewhere, somehow.

But I've lost the scenario. But i'm working again, so that is positive!

Thanks!