[0.7.0] Journalist and admin notifications can group and cause "SecureDrop Submissions Error" #3368

redshiftzero · 2018-05-04T19:45:51Z

Description

While trying to reproduce #3367, I discovered a related issue, where a "SecureDrop Submissions Error" is sent to the administrator.

Steps to Reproduce

Enable journalist notifications.
Reboot the app server (I just powered off the VM)

Expected Behavior

No journalist notification is sent

Actual Behavior

A notification entitled "SecureDrop Submissions Error" is sent to the administrator, clipped:

OSSEC HIDS Notification.
2018 May 04 06:35:13

Received From: (app) 10.0.1.4->netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort
Rule: 533 fired (level 7) -> "Listened ports status (netstat) changed (new port opened or closed)."
Portion of the log(s):

ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:54579           0.0.0.0:*               LISTEN     
tcp6       0      0 :::111                  :::*                    LISTEN     
tcp6       0      0 :::34144                :::*                    LISTEN     
Previous output:
ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:35431           0.0.0.0:*               LISTEN     
tcp6       0      0 :::111                  :::*                    LISTEN     
tcp6       0      0 :::34203                :::*                    LISTEN     



 --END OF NOTIFICATION



OSSEC HIDS Notification.
2018 May 04 06:35:13

Received From: (app) 10.0.1.4->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 fired (level 1) -> "Boolean value indicating if there were submissions in the past 24h."
Portion of the log(s):

ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
1

Comments

I found a similar issue during review, that should be the first thing to investigate

The text was updated successfully, but these errors were encountered:

redshiftzero · 2018-05-04T20:39:47Z

Ah, so we assumed here that the "level 1" and "level 7" are sent separately, but this is not accurate, so we need another method to prevent alert grouping.

ghost · 2018-05-04T21:08:21Z

Shoot. I'll work on that first thing in the morning tomorrow.

kushaldas · 2018-05-04T21:19:36Z

~~I rebooted (forced reboot) my prod vm a couple of times, but, could not reproduce this. No emails.`~~

Update

I think I have some issues in my instance about emails. Doing an update to make sure of the right state of the system.

Update2

I can confirm this error. Received the SecureDrop Submissions Error email in the admin account.

redshiftzero · 2018-05-04T21:20:31Z

Did you instead see #3367? You should see one or the other with the current configuration, unless we are really misunderstanding something

redshiftzero · 2018-05-04T23:57:33Z

So this bug results from two underlying issues:

The journalist emails are sent on boot. This is bug [0.7.0] Journalist notification sends email every time the app server is manually restarted #3367.
The journalist notifications can group with admin alerts under some previously not understood situations.

Digging more into the second issue, OSSEC notifications are grouped by default. This is set by maild.groupping=1 in internal_options.conf. It looks like this what this option does is when there is an event that will trigger a notification, OSSEC will wait and group together alerts if they are close together in time (within 5 seconds).

However, if we toggle maild.groupping=0 in internal_options.conf, then we should not get the "SecureDrop Submissions Error" as we don't enter the if statement seen here and instead just send the mail here.

To test this, I set this option (maild.groupping=0) and I did not hit the "SecureDrop Submissions Error" as seen previously. The downside of this is that this might generate more OSSEC alerts in the situation where we get a storm of alerts at once and they are all grouped into a single email.

ghost · 2018-05-05T00:09:25Z

For the record I'm looking at email-alerts-config.c and more generally trying to get an understanding of how do_not_group works.

ghost · 2018-05-05T07:43:01Z

The do_not_group element is used in ossec.conf server side

  <email_alerts>
    <email_to>root@localhost</email_to>
    <rule_id>400600</rule_id>
    <do_not_delay />
    <do_not_group />
  </email_alerts>

so the mail triggered by alert_by_email in the the daily notification rule is not grouped with another email alert:

<group name="Ossec daily notifications">
  <rule id="400600" level="1" >
    <if_sid>530</if_sid>
    <options>alert_by_email</options> <!-- force email to be sent -->
    <match>ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt</match>
    <description>Boolean value indicating if there were submissions in the past 24h.</description>
  </rule>
</group>

However... this is apparently ignored or ineffective for some reason.

ghost · 2018-05-05T08:21:24Z

Browsed OSSEC issues looking for group and do_not_group keywords and did not find anything related.

ghost · 2018-05-05T09:35:29Z

The sendmail.c debug flag is set at compile time and maild.c does not implement debug messages. The ossec-maild daemon relies on file-queue.c to get alerts reading files from /var/ossec/logs/alerts/**/ossect-alerts-*.log and interprets them to decide if mails should be sent. The ossec-reportd command may be handy to parse alert files. The alerts are written in the log file by OS_log and does not contain any grouping information. It however includes the mail flag which is used by ossec-maild to know it should act on it:

            lf->generated_rule->alert_opts & DO_MAILALERT?" mail ":"",

The tests should be modified to check the content of /var/ossec/logs/alerts/**/ossect-alerts-*.log and assert that the do_not_group / donotgroup / DONOTGROUP priority is set.

Running ossec-maild with -dddd should set the debug level to 2 or more and create some debug where the debug functions (debug1, debug2 etc.) are called.

ghost · 2018-05-05T11:28:20Z

After running

./testinfra/test.py app-staging

the file /var/ossec/logs/alerts/alerts.log contains:

** Alert 1525519439.229786: mail  - Ossec daily notifications
2018 May 05 11:23:59 (app-staging) 10.0.1.2->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 (level 1) -> 'Boolean value indicating if there were submissions in the past 24h.'
ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0

ghost · 2018-05-05T12:19:52Z

The ossec.conf on the app server

  <localfile>
    <log_format>full_command</log_format>
    <command>head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'</command>
    <frequency>86400</frequency>
  </localfile>

It is run by ossec-logcollector (see logcollector.c). A more verbose output can be configured in /var/ossec/etc/internal_options.conf

# Log collector (server, local or unix agent)
logcollector.debug=2

and when starting again manually it shows in /var/ossec/logs/ossec.log as

2018/05/05 12:33:36 ossec-logcollector: DEBUG: Entering LogCollectorStart().
...
2018/05/05 12:33:36 ossec-logcollector: INFO: Monitoring full output of command(86400): head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'

When logcollector starts, the logff[i]->size field is set to zero

        else if(strcmp(logff[i].logformat, "command") == 0)
        {
            logff[i].file = NULL;
            logff[i].fp = NULL;
            logff[i].size = 0;

and the daemon loop checks this field to compare it with the current time

        /* Checking which file is available */
        for(i = 0; i <= max_file; i++)
        {
            if(!logff[i].fp)
            {
                /* Run the command. */
                if(logff[i].command && (f_check %2))
                {
                    curr_time = time(0);
                    if((curr_time - logff[i].size) >= logff[i].ign)
                    {
                        logff[i].size = curr_time;
                        logff[i].read(i, &r, 0);
                    }
                }
                continue;
            }

and always finds that it needs to run at boot time. This logic did not change in newer versions and a but was reported.

ghost · 2018-05-05T14:06:10Z

On the mon server it is possible to verify the do_not_group option is indeed taken into account by doing the following:

Tmux window 0

$ sudo service postfix start
$ sudo service ossec stop
$ sudo postsuper -d ALL
$ sudo strace /var/ossec/bin/ossec-maild -f -dddd

Tmux window 1

$ sudo cat >> /var/ossec/logs/alerts/2018/May/ossec-alerts-05.log <head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 (level 1) -> 'Boolean value indicating if there were submissions in the past 24h.'
ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0

** Alert 1525529439.229786: mail  - Ossec daily notifications
2018 May 05 13:23:59 (app-staging) 10.0.1.2->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 (level 1) -> 'Boolean value indicating if there were submissions in the past 24h.'
ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0
EOF
$ sudo mailq
# see two mails to [email protected]

Repeat the above after commenting out the do_not_group in /var/ossec/etc/ossec.conf

  <!-- Ossec daily notifications -->
  <email_alerts>
    <email_to>root@localhost</email_to>
    <rule_id>400600</rule_id>
<!--
    <do_not_delay />
    <do_not_group />
-->
  </email_alerts>

and verify that

no mail is sent immediately
after a minute one mail is sent instead of two (the other is silently ignored)

ghost · 2018-05-05T14:09:02Z

@redshiftzero if you are able to repeat the problem, could you please also provide the content of the most recent /var/ossec/logs/alerts/*/*/ossec-alerts-*.log file? After testing a few combinations and reading the maild.c code, I'm unable to reproduce the problem. The code is contorted but does seem to cover all corner cases and I'm puzzled by the aggregation of the two alerts into a single mail.

Thanks!

redshiftzero · 2018-05-06T22:15:06Z

Thanks for looking into this issue @dachary, I have confirmed that do_not_group is indeed set in the following stanza:

  <!-- Ossec daily notifications -->
  <email_alerts>
    <email_to>root@localhost</email_to>
    <rule_id>400600</rule_id>
    <do_not_delay />
    <do_not_group />
  </email_alerts>

is in /var/ossec/etc/ossec.conf but I'm looking at this again in prod VMs and I'm continuing to see the "SecureDrop Submissions Error" due to grouped alerts on some reboots. Here's the tail of /var/ossec/logs/alerts/alerts.log:

** Alert 1525637904.10667: - Ossec start notifications
2018 May 06 20:18:24 (app) 10.0.1.4->ossec
Rule: 400503 (level 1) -> 'This alert overrides 503 to suppress daily email alerts to admins.'
ossec: Agent started: 'app->10.0.1.4'.

** Alert 1525637904.10900: mail  - ossec,
2018 May 06 20:18:24 (app) 10.0.1.4->netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort
Rule: 533 (level 7) -> 'Listened ports status (netstat) changed (new port opened or closed).'
ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN
tcp        0      0 0.0.0.0:37294           0.0.0.0:*               LISTEN
tcp6       0      0 :::111                  :::*                    LISTEN
tcp6       0      0 :::44352                :::*                    LISTEN
Previous output:
ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN
tcp        0      0 0.0.0.0:48638           0.0.0.0:*               LISTEN
tcp6       0      0 :::111                  :::*                    LISTEN
tcp6       0      0 :::37312                :::*                    LISTEN

** Alert 1525637904.11923: mail  - Ossec daily notifications
2018 May 06 20:18:24 (app) 10.0.1.4->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 (level 1) -> 'Boolean value indicating if there were submissions in the past 24h.'
ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0

which produces this (decrypted) "SecureDrop Submissions Error" email:

gpg: encrypted with 4096-bit RSA key, ID 0x[...], created [...]
      "[...] <[...]>"

/var/ossec/process_submissions_today.sh failed to find 0/1 submissions boolean in the following OSSEC alert

>From [email protected]  Sun May  6 20:18:28 2018
Return-Path: <[email protected]>
X-Original-To: root@localhost
Delivered-To: root@localhost
Received: from notify.ossec.net (mon-prod [127.0.0.1])
	by ossec.server (Postfix) with SMTP id D12D41211ED;
	Sun,  6 May 2018 20:18:28 +0000 (UTC)
To: <root@localhost>
From: OSSEC HIDS <[email protected]>
To: <root@localhost>
Date: Sun, 06 May 2018 20:18:28 +0000
Subject: OSSEC Notification - (app) 10.0.1.4 - Alert level 7
Message-Id: <[email protected]>


OSSEC HIDS Notification.
2018 May 06 20:18:24

Received From: (app) 10.0.1.4->netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort
Rule: 533 fired (level 7) -> "Listened ports status (netstat) changed (new port opened or closed)."
Portion of the log(s):

ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:37294           0.0.0.0:*               LISTEN     
tcp6       0      0 :::111                  :::*                    LISTEN     
tcp6       0      0 :::44352                :::*                    LISTEN     
Previous output:
ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:48638           0.0.0.0:*               LISTEN     
tcp6       0      0 :::111                  :::*                    LISTEN     
tcp6       0      0 :::37312                :::*                    LISTEN     



 --END OF NOTIFICATION



OSSEC HIDS Notification.
2018 May 06 20:18:24

Received From: (app) 10.0.1.4->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 fired (level 1) -> "Boolean value indicating if there were submissions in the past 24h."
Portion of the log(s):

ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0



 --END OF NOTIFICATION

ghost · 2018-05-07T06:24:44Z

thanks for the additional information, I'll work on reproducing the problem today

ghost · 2018-05-07T10:52:36Z

I'm able to reproduce the problem with the provided content, every time. Cool :-)

ghost · 2018-05-07T11:59:17Z

Note in the following the timestamp following Alert is set in the distant future so alerts are always parsed and acted upon.

The following does not trigger an error, it sends one mail per alert as expected.

cat >> logs/alerts/2018/May/ossec-alerts-07.log <<'EOF'
** Alert 1625693173.315226: mail  - ossec,syscheck,
2018 May 07 11:39:33 mon-prod->syscheck
Rule: 550 (level 7) -> 'Integrity checksum changed.'
Integrity checksum changed for: '/var/ossec/etc/ossec.conf'
Size changed from '6442' to '6455'
Old md5sum was: '7c1f892fce8df29d304356e13b721748'
New md5sum is : '685ce9610b46c1c5581b35157539d426'
Old sha1sum was: '6b75ff00c135101d474bad5e151dcea6500edc8a'
New sha1sum is : '3cd01be22a8ed70de92aaead01d2ad11d3fe1d6a'

** Alert 1625637904.11923: mail  - Ossec daily notifications
2018 May 06 20:18:24 (app) 10.0.1.4->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 (level 1) -> 'Boolean value indicating if there were submissions in the past 24h.'
ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0

EOF

The following produces a single mail that contains both alerts instead of just one

cat >> logs/alerts/2018/May/ossec-alerts-07.log <<'EOF'
** Alert 1625637904.10900: mail  - ossec,
2018 May 06 20:18:24 (app) 10.0.1.4->netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort
Rule: 552 (level 7) -> 'Listened ports status (netstat) changed (new port opened or closed).'
ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN
tcp        0      0 0.0.0.0:37294           0.0.0.0:*               LISTEN
tcp6       0      0 :::111                  :::*                    LISTEN
tcp6       0      0 :::44352                :::*                    LISTEN
Previous output:
ossec: output: 'netstat -tan |grep LISTEN |grep -v 127.0.0.1 | sort':
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN
tcp        0      0 0.0.0.0:48638           0.0.0.0:*               LISTEN
tcp6       0      0 :::111                  :::*                    LISTEN
tcp6       0      0 :::37312                :::*                    LISTEN

** Alert 1625637904.11923: mail  - Ossec daily notifications
2018 May 06 20:18:24 (app) 10.0.1.4->head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'
Rule: 400600 (level 1) -> 'Boolean value indicating if there were submissions in the past 24h.'
ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'':
0

EOF

The difference between the two is that Rule: 552 does not send a mail alert. It could be a bug in how ossec-maild handles that particular case.

ghost · 2018-05-07T12:11:03Z

Filed a bug report against OSSEC ossec/ossec-hids#1416

ghost · 2018-05-07T16:48:30Z

I can't reproduce the problem, I was testing against prod on the development branch which does the following:

install 0.6 packages # because I did not tell it to take the apt-test packages
install the process_submissions_today.sh script in /var/ossec/ which fooled me into thinking 0.7.0 packages were installed

The alerts are grouped into a single mail because the required ossec.conf + rules are not in the 0.6 packages. Back to square one.

ghost · 2018-05-07T19:12:28Z

For the record, @kushaldas & @redshiftzero managed to reproduce it as follows:

On the app server

edit var/ossec/etc/ossec.conf for email to journalists in every 3 minutes (so that I can see them).
echo 1 > /var/lib/securedrop/submissions_today.txt
rebooted the app server
and one case I also rebooted the mon again

@redshiftzero sent me the content of the ossec.log containing the alerts and despite injecting them in a mon I was not able to reproduce the problem.

ghost · 2018-05-07T19:13:25Z

it could be a race condition when writing the log file while reading is going on
which would explain why I'm not seeing it when writing wiht cat : too fast
and why it only happens at boot time: because the two alerts come in sequence
and why it does not always show: because the race has to be lost which is by definition not always
and src/shared/file-queue.c has no lock

ghost · 2018-05-07T19:17:16Z

Hum, reading read-alert.c I don't see how that theory would work. The file is append only.

redshiftzero · 2018-05-10T16:31:46Z

Note that myself and @kushaldas were only able to reproduce this (and only intermittently even then) when the journalist notification time was dramatically increased. We could not reproduce this issue with the notification time at 24 hours.

A commit was added in #3384 by @dachary to mitigate this issue - as such I'm closing this for now.

redshiftzero added the QA: Release label May 4, 2018

redshiftzero added this to the 0.7 milestone May 4, 2018

redshiftzero changed the title ~~SecureDrop submissions error sent to admin upon reboot~~ [0.7.0] SecureDrop submissions error sent to admin upon reboot May 4, 2018

redshiftzero added the bug label May 4, 2018

redshiftzero mentioned this issue May 4, 2018

[0.7.0] Journalist notification sends email every time the app server is manually restarted #3367

Closed

ghost self-assigned this May 4, 2018

redshiftzero changed the title ~~[0.7.0] SecureDrop submissions error sent to admin upon reboot~~ [0.7.0] Journalist and admin notifications can group May 4, 2018

redshiftzero changed the title ~~[0.7.0] Journalist and admin notifications can group~~ [0.7.0] Journalist and admin notifications can group and cause "SecureDrop Submissions Error" May 4, 2018

redshiftzero mentioned this issue May 6, 2018

ossec: resolve journalist notification racing with reboots #3374

Merged

1 task

redshiftzero added the unable to reproduce label May 7, 2018

ghost mentioned this issue May 9, 2018

[0.7.0] ossec: resolve journalist notification racing with reboots #3384

Merged

1 task

redshiftzero closed this as completed May 10, 2018

redshiftzero mentioned this issue Jun 22, 2018

journalist notification error #3557

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[0.7.0] Journalist and admin notifications can group and cause "SecureDrop Submissions Error" #3368

[0.7.0] Journalist and admin notifications can group and cause "SecureDrop Submissions Error" #3368

redshiftzero commented May 4, 2018

redshiftzero commented May 4, 2018

ghost commented May 4, 2018

kushaldas commented May 4, 2018 •

edited

Loading

redshiftzero commented May 4, 2018

redshiftzero commented May 4, 2018 •

edited

Loading

ghost commented May 5, 2018

ghost commented May 5, 2018 •

edited by ghost

Loading

ghost commented May 5, 2018

ghost commented May 5, 2018 •

edited by ghost

Loading

ghost commented May 5, 2018

ghost commented May 5, 2018 •

edited by ghost

Loading

ghost commented May 5, 2018

ghost commented May 5, 2018

redshiftzero commented May 6, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018 •

edited by ghost

Loading

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

redshiftzero commented May 10, 2018

[0.7.0] Journalist and admin notifications can group and cause "SecureDrop Submissions Error" #3368

[0.7.0] Journalist and admin notifications can group and cause "SecureDrop Submissions Error" #3368

Comments

redshiftzero commented May 4, 2018

Description

Steps to Reproduce

Expected Behavior

Actual Behavior

Comments

redshiftzero commented May 4, 2018

ghost commented May 4, 2018

kushaldas commented May 4, 2018 • edited Loading

Update

Update2

redshiftzero commented May 4, 2018

redshiftzero commented May 4, 2018 • edited Loading

ghost commented May 5, 2018

ghost commented May 5, 2018 • edited by ghost Loading

ghost commented May 5, 2018

ghost commented May 5, 2018 • edited by ghost Loading

ghost commented May 5, 2018

ghost commented May 5, 2018 • edited by ghost Loading

ghost commented May 5, 2018

ghost commented May 5, 2018

redshiftzero commented May 6, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018 • edited by ghost Loading

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

ghost commented May 7, 2018

redshiftzero commented May 10, 2018

kushaldas commented May 4, 2018 •

edited

Loading

redshiftzero commented May 4, 2018 •

edited

Loading

ghost commented May 5, 2018 •

edited by ghost

Loading

ghost commented May 5, 2018 •

edited by ghost

Loading

ghost commented May 5, 2018 •

edited by ghost

Loading

ghost commented May 7, 2018 •

edited by ghost

Loading