Ossec 2.9.1 Reports not being sent out

[hafeezy2j]

I have recently, upgraded ossec from 2.8.3 to 2.9.1 and I have noticed that reports are being generated but not being sent out. These reports were being sent out without a hitch before the upgrade.

I see that in /var/ossec/logs/ossec.log, reports are being generated..

2017/08/16 00:01:59 ossec-monitord: INFO: Starting daily reporting for 'Daily report: File changes'
2017/08/16 00:02:05 ossec-monitord: INFO: Report 'Daily report: File changes' completed. Creating output...
2017/08/16 00:02:05 INFO: Connected to 1X2.30.XX.X1 at address 1X2.30.XX.X1, port 25

2017/08/16 00:02:45 ossec-monitord: INFO: Report 'Daily report: Windows Authentication Failure Report' completed. Creating output...
2017/08/16 00:02:45 INFO: Connected to 1X2.30.XX.X1 at address 1X2.30.XX.X1, port 25

2017/08/17 00:01:33 ossec-monitord: INFO: Starting daily reporting for 'Daily report: Authentication Failure Report'
2017/08/17 00:01:43 ossec-monitord: INFO: Report 'Daily report: Authentication Failure Report' completed. Creating output...
2017/08/17 00:01:43 ossec-monitord: INFO: Report 'Daily report: File changes' completed. Creating output...
2017/08/17 00:01:44 ossec-monitord: INFO: Report 'Daily report: Windows Authentication Failure Report' completed. Creating output...

2017/08/17 00:01:44 INFO: Connected to 1X2.30.XX.X1 at address 1X2.30.XX.X1, port 25
2017/08/17 00:01:44 INFO: Connected to 1X2.30.XX.X1 at address 1X2.30.XX.X1, port 25
2017/08/17 00:01:44 INFO: Connected to 1X2.30.XX.X1 at address 1X2.30.XX.X1, port 25

Here what I see in /var/log/messages which could be the culprit.

Aug 16 00:02:05 mtc-ossec-01p kernel: ossec-monitord[20805]: segfault at 17 ip 00007f4cba3908c5 sp 00007fff4f190950 error 4 in libc-2.12.so[7f4cba2ed000+18a000]
Aug 16 00:02:45 mtc-ossec-01p kernel: ossec-monitord[20817]: segfault at 17 ip 00007f4cba3908c5 sp 00007fff4f190950 error 4 in libc-2.12.so[7f4cba2ed000+18a000

Aug 17 00:01:44 mtc-ossec-01p kernel: ossec-monitord[11545]: segfault at 18 ip 00007f258b2798c5 sp 00007ffcce43b4a0 error 4 in libc-2.12.so[7f258b1d6000+18a000]
Aug 17 00:01:44 mtc-ossec-01p kernel: ossec-monitord[11615]: segfault at 18 ip 00007f258b2798c5 sp 00007ffcce43b4a0 error 4 in libc-2.12.so[7f258b1d6000+18a000]
Aug 17 00:01:44 mtc-ossec-01p kernel: ossec-monitord[11614]: segfault at 18 ip 00007f258b2798c5 sp 00007ffcce43b4a0 error 4 in libc-2.12.so[7f258b1d6000+18a000]

Any clue how to fix this?

[hafeezy2j]

Tried running monitord under gdb

[XXX@mXX-ossec-XX ~]# gdb /var/ossec/bin/ossec-monitord
GNU gdb (GDB) Red Hat Enterprise Linux (7.2-92.el6)
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
http://www.gnu.org/software/gdb/bugs/...
Reading symbols from /var/ossec/bin/ossec-monitord...(no debugging symbols found)...done.
(gdb) set follow-fork-mode child
(gdb) run -df
Starting program: /var/ossec/bin/ossec-monitord -df
[Thread debugging using libthread_db enabled]
2017/08/17 09:40:14 ossec-monitord: DEBUG: Starting ...
2017/08/17 09:40:14 ossec-monitord: INFO: Chrooted to directory: /var/ossec
2017/08/17 09:40:14 ossec-monitord: INFO: Using user: ossec
2017/08/17 09:40:14 ossec-monitord: INFO: Started (pid: 21697).
2017/08/17 09:40:24 ossec-monitord: INFO: (unix_domain) Maximum send buffer set to: '124928'.

[ddpbsd]

This may be related: #1088

[ddpbsd]

Can you provide your report configuration? I'll try to reproduce the crash.

[hafeezy2j]

Here's my ossec.conf file.
ossec_conf.txt

[zvanderbilt]

Yeah I jumped the gun on assuming scheduled reports worked. I have the same symptoms as those listed in here (im running 2.9.2)

from messages:
Aug 23 00:00:14 XXXXXXX kernel: [95675.528218] traps: ossec-monitord[11165] general protection ip:7fa0a163ea11 sp:7fffc57057a0 error:0
Aug 23 00:00:14 XXXXXXX kernel: [95675.533235] in libc-2.17.so[7fa0a1589000+1b8000]
Aug 23 00:00:34 XXXXXXX kernel: [95695.484513] traps: ossec-monitord[11284] general protection ip:7fa0a163ea11 sp:7fffc57057a0 error:0
Aug 23 00:00:34 XXXXXXX kernel: [95695.488728] in libc-2.17.so[7fa0a1589000+1b8000]
Aug 23 00:00:54 XXXXXXX kernel: [95715.488127] traps: ossec-monitord[11592] general protection ip:7fa0a163ea11 sp:7fffc57057a0 error:0
Aug 23 00:00:54 XXXXXXX kernel: [95715.492572] in libc-2.17.so[7fa0a1589000+1b8000]

ossec log:
2017/08/23 00:00:09 ossec-monitord: INFO: Starting daily reporting for 'Daily OSSEC Report'
2017/08/23 00:00:14 ossec-monitord: INFO: Report 'Daily OSSEC Report' completed. Creating output...
2017/08/23 00:00:14 INFO: Connected to 127.0.0.1 at address 127.0.0.1, port 25
2017/08/23 00:00:26 INFO: Connected to 127.0.0.1 at address 127.0.0.1, port 25
2017/08/23 00:00:29 ossec-monitord: INFO: Starting daily reporting for 'Daily report: File changes'
2017/08/23 00:00:34 ossec-monitord: INFO: Report 'Daily report: File changes' completed. Creating output...
2017/08/23 00:00:34 INFO: Connected to 127.0.0.1 at address 127.0.0.1, port 25
2017/08/23 00:00:46 INFO: Connected to 127.0.0.1 at address 127.0.0.1, port 25
2017/08/23 00:00:49 ossec-monitord: INFO: Starting daily reporting for 'OssecTest'
2017/08/23 00:00:54 ossec-monitord: INFO: Report 'OssecTest' completed. Creating output...
2017/08/23 00:00:54 INFO: Connected to 127.0.0.1 at address 127.0.0.1, port 25
2017/08/23 00:01:06 INFO: Connected to 127.0.0.1 at address 127.0.0.1, port 25

and the maillog (this is after disabling all restrictions such as reject_unauth_pipelining):
Aug 23 00:00:14 XXXXXXX postfix/smtpd[6962]: connect from localhost[127.0.0.1]
Aug 23 00:00:14 XXXXXXX postfix/smtpd[6962]: 590C841097: client=localhost[127.0.0.1]
Aug 23 00:00:14 XXXXXXX postfix/smtpd[6962]: lost connection after DATA (63 bytes) from localhost[127.0.0.1]
Aug 23 00:00:14 XXXXXXX postfix/smtpd[6962]: disconnect from localhost[127.0.0.1]

Aug 23 00:00:34 XXXXXXX postfix/smtpd[6962]: connect from localhost[127.0.0.1]
Aug 23 00:00:34 XXXXXXX postfix/smtpd[6962]: 4E5D841097: client=localhost[127.0.0.1]
Aug 23 00:00:34 XXXXXXX postfix/smtpd[6962]: lost connection after DATA (57 bytes) from localhost[127.0.0.1]
Aug 23 00:00:34 XXXXXXX postfix/smtpd[6962]: disconnect from localhost[127.0.0.1]

Aug 23 00:00:54 XXXXXXX postfix/smtpd[6962]: connect from localhost[127.0.0.1]
Aug 23 00:00:54 XXXXXXX postfix/smtpd[6962]: 4F296410DA: client=localhost[127.0.0.1]
Aug 23 00:00:54 XXXXXXX postfix/smtpd[6962]: lost connection after DATA (57 bytes) from localhost[127.0.0.1]
Aug 23 00:00:54 XXXXXXX postfix/smtpd[6962]: disconnect from localhost[127.0.0.1]

Also attached the relevant sections from my ossec.conf
ossec_report.txt

[hafeezy2j]

@ddpbsd Did you able to reproduce this ?

[ddpbsd]

Sorry, it fell through the cracks. I have just put your reports config into my ossec.conf (running master). Hopefully I'll know more tomorrow.

[ddpbsd]

Actually I managed to find this:

# cd logs
# ls -a
.                    .report-19827.log    .report-36264.log    .report-49323.log    .report-56506.log    .report-66346.log    .report-73896.log    .report-85379.log    .report-93274.log    alerts
..                   .report-20494.log    .report-37217.log    .report-49919.log    .report-56959.log    .report-66359.log    .report-74670.log    .report-87503.log    .report-94708.log    archives
.report-13709.log    .report-23090.log    .report-38160.log    .report-52074.log    .report-5880.log     .report-68815.log    .report-80204.log    .report-88425.log    .report-9499.log     firewall
.report-17532.log    .report-2465.log     .report-40649.log    .report-52524.log    .report-58811.log    .report-70703.log    .report-8105.log     .report-88894.log    .report-95669.log    ossec.log
.report-17919.log    .report-27070.log    .report-42430.log    .report-5295.log     .report-62155.log    .report-71189.log    .report-84815.log    .report-89253.log    .report-97645.log
.report-18056.log    .report-30981.log    .report-45508.log    .report-54745.log    .report-65600.log    .report-71193.log    .report-85239.log    .report-92909.log    active-responses.log

So I'll be trying to dig into monitord this weekend.

[ddpbsd]

After adding some debugging, I'm not sure the email addresses are getting picked up out of the configuration. Still digging.

EDIT: got my logic in the test wrong, oops. This isn't the problem.

[ddpbsd]

Oct  9 00:01:09 kaitain kernel: [825879.536072] ossec-monitord[26749]: segfault at 811 ip 00007f39c3bff071 sp 00007ffeafa0e5c0 error 4 in libc-2.23.so[7f39c3b3c000+1c0000]

[ddpbsd]

Something funky with the strftime?

(gdb) bt
#0  __strftime_internal (s=0x7fffffffd410 "", maxsize=127, format=0x434a5e "Date: %a, %d %b %Y %T %z\r\n",
    tp=0x7e1, tzset_called=tzset_called@entry=0x7fffffffd3cf, loc=0x7ffff7bb5420 <_nl_global_locale>)
    at strftime_l.c:533
#1  0x00007ffff78b50a6 in __GI___strftime_l (s=<optimized out>, maxsize=<optimized out>, format=<optimized out>,
    tp=<optimized out>, loc=<optimized out>) at strftime_l.c:459
#2  0x000000000041dcda in OS_SendCustomEmail ()
#3  0x0000000000403d3e in generate_reports ()
#4  0x00000000004036a6 in Monitord ()
#5  0x0000000000402c2e in main ()

[nbuuck]

The usage looks right and the visible parameter values (out string, maxsize, format) look okay. About the only thing I can imagine could cause a segfault then is the time value being passed in (whatever value is at pointer tp=0x7e1) which, being a pointer, we can't see in a backtrace like this.

[nbuuck]

This post makes a decent comment: strftime could segfault if there are one or more values in the struct tm *tm unset that are needed for one of the fields in the format string.

https://www.gidforums.com/t-26087.html#edit95374

[nbuuck]

I checked the Coverity defects for sendcustomemail.c and didn't find anything there that would seemingly cause a segfault in strftime().

[ddpbsd]

I've had some success with "rebuilding" p in generate_reports.c before the call to OS_SendCustomEmail(). I think it only affects the date used in the smtp conversation.
It feels dirty, but any objections to adding that?

[nbuuck]

I'd be curious to see the diff, but I expect what you describe will be necessary to get this stable.

Not necessarily an objection, but my inclination would be to add one or - likely - more null checks upon entry to OS_SendCustomEmail(), probably best in a separate private function since OS_SendCustomEmail() is already over 200 lines. I say that because it could save some time and frustration later if other atypical conditions cause one of the required parameters on struct tm *tm to be null.

[ddpbsd]

It's pretty simple, but I don't think it's the (only?) problem:

diff --git src/monitord/generate_reports.c src/monitord/generate_reports.c
index 7c2df1f7..f2e9133a 100644
--- src/monitord/generate_reports.c
+++ src/monitord/generate_reports.c
@@ -63,6 +63,12 @@ void generate_reports(int cday, int cmon, int cyear, const struct tm *p)
                          ALERTS, cyear, monthss[cmon], "alerts", cday);
                 os_strdup(aname, mond.reports[s]->r_filter.filename);

+                time_t tm;
+                tm = time(NULL);
+                const struct tm *p2;
+                p2 = localtime(&tm);
+
+
                 /* Start report */
                 os_ReportdStart(&mond.reports[s]->r_filter);
                 fflush(mond.reports[s]->r_filter.fp);
@@ -75,7 +81,7 @@ void generate_reports(int cday, int cmon, int cyear, const struct tm *p)
                                               mond.emailfrom,
                                               mond.emailidsname,
                                               mond.reports[s]->r_filter.fp,
-                                              p)
+                                              p2)
                            != 0) {
                     merror("%s: WARN: Unable to send report email.", ARGV0);
                 }

mond.emailidsname appears to be null, sometimes? Trying to fill that in too, but I have to figure out what's supposed to be there eventually. If I had my choice, as a unix guy, I'd rip this whole feature out in favor of ossec-reportd and cron.

[ddpbsd]

Latest crash:

Thread 4.1 "ossec-monitord" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff7fed700 (LWP 22811)]
0x00007ffff7865f20 in __GI_fseek (fp=0x7ffff7bb94a0 <_tmbuf>, offset=0, whence=0) at fseek.c:35
35      fseek.c: No such file or directory.
(gdb)
(gdb) bt
#0  0x00007ffff7865f20 in __GI_fseek (fp=0x7ffff7bb94a0 <_tmbuf>, offset=0, whence=0) at fseek.c:35
#1  0x000000000042ffdf in OS_SendCustomEmail (to=0x65a5e0, subject=0x655890 "REPORT REPORT REPORT: File changes", smtpserver=0x65a1b0 "192.168.17.9", from=0x6574a0 "ossecm@kaitain", replyto=0x4421c5 "NOPE",
    idsname=0x65a1f0 "\200,\255\373\377\177", fp=0x7ffff7bb94a0 <_tmbuf>, p=0x404312 <generate_reports+1256>) at os_maild/sendcustomemail.c:285
#2  0x00000000004043db in generate_reports (cday=17, cmon=9, cyear=2017, p=0x7ffff7bb94a0 <_tmbuf>) at monitord/generate_reports.c:97
#3  0x0000000000403424 in Monitord () at monitord/monitord.c:66
#4  0x0000000000403e2a in main (argc=2, argv=0x7fffffffe618) at monitord/main.c:215

line 285 from sendcustomemail.c starts here:

    fseek(fp, 0, SEEK_SET);
    while (fgets(buffer, 2048, fp) != NULL) {
        if (sendmail) {
            fprintf(sendmail, "%s", buffer);
        } else {
            OS_SendTCP(socket, buffer);
        }
    }