Merge pull request #3374 from dachary/wip-journalist-submission-frequ…

…ency

ossec: resolve journalist notification racing with reboots

docs/install.rst

@@ -75,6 +75,9 @@ worth checking the *Journalist Interface*. For this you will need:
           the GPG private key, it is not possible to specify multiple
           GPG keys.
 
+.. note:: The journalist notification is sent after the daily reboot
+          of the *Application Server*.
+
 You will have to copy the following required files to
 ``install_files/ansible-base``:
 

install_files/ansible-base/roles/ossec/files/process_submissions_today.sh

@@ -1,17 +1,35 @@
 #!/bin/bash
 
+SENT_STAMP=/var/ossec/logs/journalist_notification_sent.stamp
+
 function send_encrypted_alarm() {
     /var/ossec/send_encrypted_alarm.sh "$1"
 }
 
 function main() {
+    if modified_in_the_past_24h "${SENT_STAMP}" ; then
+        logger "$0 journalist notification suppressed"
+    else
+        handle_notification "$@"
+    fi
+}
+
+function modified_in_the_past_24h() {
+    local stamp
+    stamp="$1"
+    test -f "${stamp}" && \
+        find "${stamp}" -mtime -1 | \
+            grep --quiet "${stamp}"
+}
+
+function handle_notification() {
     local sender
     local stdin
     sender=${1:-send_encrypted_alarm}
     stdin="$(< /dev/stdin)"
 
     local count
-    count=$(echo "$stdin" | perl -ne 'print scalar(<>) and exit if(/ossec: output/);')
+    count=$(echo "$stdin" | perl -ne "print scalar(<>) and exit if(m|ossec: output: 'head -1 /var/lib/securedrop/submissions_today.txt|);")
     if [[ "$count" =~ ^[0-9]+$ ]] ; then
         export SUBJECT="Submissions in the past 24h"
         #
@@ -24,6 +42,7 @@ function main() {
             echo "There has been no submission activity in the past 24 hours."
             echo "You do not need to login to SecureDrop."
         fi | $sender journalist
+        touch "${SENT_STAMP}"
     else
         export SUBJECT="SecureDrop Submissions Error"
         (
@@ -34,33 +53,50 @@ function main() {
     fi
 }
 
+function forget() {
+    rm -f "${1:-$SENT_STAMP}"
+}
+
+function test_modified_in_the_past_24h() {
+    local stamp
+    stamp=$(mktemp)
+
+    modified_in_the_past_24h "${stamp}" || exit 1
+
+    touch --date '-2 days' "${stamp}"
+    ! modified_in_the_past_24h "${stamp}" || exit 1
+
+    forget "${stamp}"
+    ! modified_in_the_past_24h "${stamp}" || exit 1
+}
+
 function test_send_encrypted_alarm() {
     echo "$1"
     cat
 }
 
-function test_main() {
+function test_handle_notification() {
     shopt -s -o xtrace
     PS4='${BASH_SOURCE[0]}:$LINENO: ${FUNCNAME[0]}:  '
 
-    echo BUGOUS | main test_send_encrypted_alarm | \
+    echo BUGOUS | handle_notification test_send_encrypted_alarm | \
         tee /dev/stderr | \
         grep -q 'failed to find 0/1 submissions boolean' || exit 1
 
     (
         echo 'ossec: output'
         echo 'NOTANUMBER'
-    ) | main test_send_encrypted_alarm | tee /dev/stderr | grep -q 'failed to find 0/1 submissions boolean' || exit 1
+    ) | handle_notification test_send_encrypted_alarm | tee /dev/stderr | grep -q 'failed to find 0/1 submissions boolean' || exit 1
 
     (
         echo 'ossec: output'
         echo '1'
-    ) | main test_send_encrypted_alarm | tee /tmp/submission-yes.txt | grep -q 'There has been submission activity' || exit 1
+    ) | handle_notification test_send_encrypted_alarm | tee /tmp/submission-yes.txt | grep -q 'There has been submission activity' || exit 1
 
     (
         echo 'ossec: output'
         echo '0'
-    ) | main test_send_encrypted_alarm | tee /tmp/submission-no.txt | grep -q 'There has been no submission activity' || exit 1
+    ) | handle_notification test_send_encrypted_alarm | tee /tmp/submission-no.txt | grep -q 'There has been no submission activity' || exit 1
 
     if test "$(stat --format=%s /tmp/submission-no.txt)" != "$(stat --format=%s /tmp/submission-yes.txt)" ; then
         echo both files are expected to have exactly the same size, padding must be missing

install_files/securedrop-ossec-agent/var/ossec/etc/ossec.conf

@@ -108,7 +108,7 @@
   <localfile>
     <log_format>full_command</log_format>
     <command>head -1 /var/lib/securedrop/submissions_today.txt | grep '^[0-9]*$'</command>
-    <frequency>86400</frequency>
+    <frequency>90000</frequency> <!-- 25 hours -->
   </localfile>
 
   <localfile>

testinfra/ossec/alert-journalist-one.txt

@@ -0,0 +1,14 @@
+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
+

testinfra/ossec/alert-journalist-two.txt

@@ -0,0 +1,39 @@
+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
+

testinfra/ossec/alert-ossec.txt

@@ -0,0 +1,22 @@
+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

testinfra/ossec/test_journalist_mail.py

@@ -64,25 +64,31 @@ class TestJournalistMail(TestBase):
 
     def test_procmail(self, host):
         self.service_started(host, "postfix")
-        today_payload = (
-            'ossec: output: head -1 /var/lib/securedrop/submissions_today.txt'
-            '\n1234')
-        for (destination, payload) in (
-                ('journalist', today_payload),
-                ('ossec', 'MYGREATPAYLOAD')):
+        for (destination, f) in (
+                ('journalist', 'alert-journalist-one.txt'),
+                ('journalist', 'alert-journalist-two.txt'),
+                ('ossec', 'alert-ossec.txt')):
+            self.ansible(host, "copy",
+                         "dest=/tmp/{f} src=testinfra/ossec/{f}".format(f=f))
+            assert self.run(host,
+                            "/var/ossec/process_submissions_today.sh forget")
             assert self.run(host, "postsuper -d ALL")
             assert self.run(
                 host,
-                "echo -e '{payload}' | "
-                "mail -s 'abc' root@localhost".format(payload=payload))
+                "cat /tmp/{f} | mail -s 'abc' root@localhost".format(f=f))
             assert self.wait_for_command(
                 host,
                 "mailq | grep -q {destination}@ossec.test".format(
                     destination=destination))
         self.service_stopped(host, "postfix")
 
     def test_process_submissions_today(self, host):
-        self.run(host, "/var/ossec/process_submissions_today.sh test_main")
+        assert self.run(host,
+                        "/var/ossec/process_submissions_today.sh "
+                        "test_handle_notification")
+        assert self.run(host,
+                        "/var/ossec/process_submissions_today.sh "
+                        "test_modified_in_the_past_24h")
 
     def test_send_encrypted_alert(self, host):
         self.service_started(host, "postfix")
@@ -109,8 +115,8 @@ def trigger(who, payload):
         # encrypted mail to journalist or ossec contact
         #
         for (who, payload, expected) in (
-                ('journalist', 'ossec: output\n1', '1'),
-                ('ossec', 'MYGREATPAYLOAD', 'MYGREATPAYLOAD')):
+                ('journalist', 'JOURNALISTPAYLOAD', 'JOURNALISTPAYLOAD'),
+                ('ossec', 'OSSECPAYLOAD', 'OSSECPAYLOAD')):
             assert self.run(host, "postsuper -d ALL")
             trigger(who, payload)
             assert self.run(
@@ -185,10 +191,15 @@ def test_journalist_mail_notification(self, host):
         # empty the mailq on mon in case there were leftovers
         #
         assert self.run(mon, "postsuper -d ALL")
+        #
+        # forget about past notifications in case there were leftovers
+        #
+        assert self.run(mon, "/var/ossec/process_submissions_today.sh forget")
 
         #
         # the command fires every time ossec starts,
         # regardless of the frequency
+        # https://github.com/ossec/ossec-hids/issues/1415
         #
         with app.sudo():
             self.service_restarted(app, "ossec")
@@ -203,6 +214,21 @@ def test_journalist_mail_notification(self, host):
             mon,
             "test 1 = $(mailq | grep [email protected] | wc -l)")
 
+        assert self.run(
+            mon,
+            "grep --count 'notification suppressed' /var/log/syslog "
+            "> /tmp/before")
+
+        #
+        # The second notification within less than 24h is suppressed
+        #
+        with app.sudo():
+            self.service_restarted(app, "ossec")
+        assert self.wait_for_command(mon, """
+        grep --count 'notification suppressed' /var/log/syslog > /tmp/after
+        test $(cat /tmp/before) -lt $(cat /tmp/after)
+        """)
+
         #
         # teardown the ossec and postfix on mon and app
         #