Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Distinguishes between TemplateVM & AppVM in log collection #487

Merged
merged 7 commits into from
Mar 11, 2020

Conversation

conorsch
Copy link
Contributor

@conorsch conorsch commented Mar 5, 2020

Status

Ready for review.

Description of Changes

Fixes #476

Changes proposed in this pull request:

  • Consolidates the log-aggregation logic into a single SLS file, to DRY out the config
  • Stores logs separately for AppVM and TemplateVM clients in sd-log:~/QubesIncomingLogs/
  • Adds additional config tests for logging config, and RPC policies

Testing

These changes require a patch to the securedrop-log package, so in order to test, you'll need to build a custom package. Details below.

You'll need to apply the workaround #485 (comment) in order to review effectively.

  • Check out Infers hostname for "localvm" setting securedrop-log#16 and create new tarball (python3 setup.py sdist)
  • Check out Updates securedrop-log to 0.1.1 securedrop-builder#150 and build new deb pkg (PKG_VERSION=0.1.1 make securedrop-log)
  • Copy new 0.1.1 securedrop-log deb package to sd-workstation/securedrop-log_0.1.1+buster_all.deb, so you can install it as part of testing without promoting to apt repo
  • make clone && make clean && make all && make test passes without error
  • Inspect sd-log:/home/user/QubesIncomingLogs/ and ensure that both TemplateVM names and AppVM names are present as subdirs
  • Drop the commit prefixed with "TEMPORARY" prior to merge. That commit exists solely to facilitate local testing.

Checklist

If you have made code changes

  • Linter (make flake8) passes in the development environment (this box may
    be left unchecked, as flake8 also runs in CI)

If you have made changes to the provisioning logic

  • All tests (make test) pass in dom0 of a Qubes install

  • This PR adds/removes files, and includes required updates to the packaging
    logic in MANIFEST.in and rpm-build/SPECS/securedrop-workstation-dom0-config.spec

^ haven't updated the spec, nor the version; local build passes successfully

@conorsch conorsch mentioned this pull request Mar 5, 2020
6 tasks
@emkll emkll self-requested a review March 5, 2020 16:20
@conorsch conorsch force-pushed the 476-simplify-logging-hostname-config branch from ea4aaf7 to 0775f06 Compare March 5, 2020 17:33
@conorsch
Copy link
Contributor Author

conorsch commented Mar 5, 2020

Rebased on top of latest master (8f60f29), including changes from #486.

@conorsch
Copy link
Contributor Author

conorsch commented Mar 5, 2020

Inspect sd-log:/home/user/QubesIncomingLogs/ and ensure that both TemplateVM names and AppVM names are present as subdirs

Come to think of it, that deserves a config test. Added a few service-related checks in this PR, but we should also guard against regressions.

Copy link
Contributor

@emkll emkll left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @conorsch , left some comments in freedomofpress/securedrop-log#16 (review) . for sd-app and sd-devices (and their templates), everything does seem to work as expected. However, I've observed a few regressions with other VMs:

  • Logging in whonix-based VMs does not go to the correct folder on sd-log due to HOSTNAME being set to host

  • There's also a regression in sd-viewer-dvm, sd-viewer and sd-viewer-buster-template where the rsyslog service start but appears to throw an error (see inline). The service is marked as running but it seems like logs are not flowing properly (not sure if this is due to local changes, but i also don't see where you are installing/configuring the sd-logging-setup for sd-viewer* in the diff introduced here.

@@ -38,15 +40,12 @@ base:
- sd-sys-firewall-files
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure if this is a regression, but getting an issue with any sd-viewer-* vm:


Mar 05 15:46:42 sd-viewer rsyslogd[465]: omprog: program '/usr/sbin/sd-rsyslog' (pid 5737) terminated; will be restarted [v8.1901.0 try https://www.rsyslog.com/e/2119 ]
Mar 05 15:46:42 sd-viewer rsyslogd[465]: action 'action-0-omprog' suspended (module 'omprog'), retry 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsysl
Mar 05 15:46:43 sd-viewer rsyslogd[465]: action 'action-0-omprog' resumed (module 'omprog') [v8.1901.0 try https://www.rsyslog.com/e/2359 ]
Mar 05 15:46:43 sd-viewer rsyslogd[465]: child process (pid 5738) exited with status 1 [v8.1901.0]
Mar 05 15:46:43 sd-viewer rsyslogd[465]: omprog: program '/usr/sbin/sd-rsyslog' (pid 5738) terminated; will be restarted [v8.1901.0 try https://www.rsyslog.com/e/2119 ]
Mar 05 15:46:43 sd-viewer rsyslogd[465]: action 'action-0-omprog' suspended (module 'omprog'), retry 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsysl
Mar 05 15:46:44 sd-viewer rsyslogd[465]: action 'action-0-omprog' resumed (module 'omprog') [v8.1901.0 try https://www.rsyslog.com/e/2359 ]
Mar 05 15:46:44 sd-viewer rsyslogd[465]: child process (pid 5745) exited with status 1 [v8.1901.0]
Mar 05 15:46:44 sd-viewer rsyslogd[465]: omprog: program '/usr/sbin/sd-rsyslog' (pid 5745) terminated; will be restarted [v8.1901.0 try https://www.rsyslog.com/e/2119 ]
Mar 05 15:46:44 sd-viewer rsyslogd[465]: action 'action-0-omprog' suspended (module 'omprog'), retry 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsysl

Copy link
Contributor Author

@conorsch conorsch Mar 6, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good idea. I've added a config test for this case, but it's failing, so commented it out. We weren't testing for this case before, so we should compare behavior on master and see if the log messages occur there.

On this branch, I see those messages, even though a given VM is shipping logs successfully to sd-log. So it doesn't appear to be a final indicator of failure.

@@ -0,0 +1,79 @@
# -*- coding: utf-8 -*-
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 .sls in dom0/ folder will be automatically picked up by manifest.in and the rpm spec

@conorsch conorsch force-pushed the 476-simplify-logging-hostname-config branch from c057de1 to 548a2ac Compare March 6, 2020 03:42
@conorsch
Copy link
Contributor Author

conorsch commented Mar 6, 2020

@emkll Great review, please take another look. Given the special case of the whonix VMs, it might be preferable to review #488 first, then drop the sd-proxy-related customizations in the logging config here.

@emkll
Copy link
Contributor

emkll commented Mar 6, 2020

I'm running into some issues when running make clean / make clone / make all / make test, are you seeing these? It might be due to changes in whonix-gw-template that were not reverted properly when i ran make clean. Do you think twe should review #488 first, as the perhaps it may have benefits for the issues i've observed

======================================================================
FAIL: test_logging_configured (test_proxy_vm.SD_Proxy_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/m/securedrop-workstation/tests/test_proxy_vm.py", line 44, in test_logging_configured
    self.logging_configured(vmname=True)
  File "/home/m/securedrop-workstation/tests/base.py", line 135, in logging_configured
    self.assertEqual(file_content, static_content)
AssertionError: '[sd-rsyslog]\nremotevm = sd-log\nlocalvm = sd-proxy' != '[sd-rsyslog]\nremotevm = sd-loglocalvm = sd-proxy'
  [sd-rsyslog]
+ remotevm = sd-loglocalvm = sd-proxy- remotevm = sd-log
- localvm = sd-proxy

======================================================================
FAIL: test_logging_configured (test_sd_whonix.SD_Whonix_Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/m/securedrop-workstation/tests/test_sd_whonix.py", line 62, in test_logging_configured
    self.logging_configured(vmname=True)
  File "/home/m/securedrop-workstation/tests/base.py", line 135, in logging_configured
    self.assertEqual(file_content, static_content)
AssertionError: '[sd-rsyslog]\nremotevm = sd-log\nlocalvm = sd-whonix' != '[sd-rsyslog]\nremotevm = sd-loglocalvm = sd-whonix'
  [sd-rsyslog]
+ remotevm = sd-loglocalvm = sd-whonix- remotevm = sd-log
- localvm = sd-whonix

----------------------------------------------------------------------
Ran 65 tests in 237.095s

Copy link
Contributor

@emkll emkll left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With the diff [1] below, tests are passing, and everything looks good. However, I observe errors in sd-gpg due to misconfiguration of the package, as it's installed in the base template. It might make sense to configure logging for sd-gpg, I tried applying the diff below it appears to work [2]. What do you think?

Not sure if this is a regression from the second diff, but sd-whonix doesn't have a netvm when the diff below is applied

[1]

diff --git a/tests/base.py b/tests/base.py
index cc3c89c8a..5bef47494 100644
--- a/tests/base.py
+++ b/tests/base.py
@@ -124,14 +124,14 @@ class SD_VM_Local_Test(unittest.TestCase):
         self.assertTrue(self._fileExists("/etc/rsyslog.d/sdlog.conf"))
         self.assertTrue(self._fileExists("/etc/sd-rsyslog.conf"))
         # Then we check the configuration inside of the file.
-        # Using .strip() so trailing whitespace doesn't cause failures
-        file_content = self._get_file_contents("/etc/sd-rsyslog.conf").strip()
+        file_content = self._get_file_contents("/etc/sd-rsyslog.conf")
         static_content = """[sd-rsyslog]
-remotevm = sd-log"""
+remotevm = sd-log
+"""
         # A hardcoded vmname should only be present if required,
         # since securedrop-log will default to value of `hostname`.
         if vmname:
-            static_content += "localvm = {}".format(self.vm_name)
+            static_content += "localvm = {}\n".format(self.vm_name)
         self.assertEqual(file_content, static_content)
         # Check for evidence of misconfigured logging in syslog,
         # fail if matching events found

[2]

diff --git a/dom0/sd-logging-setup.sls b/dom0/sd-logging-setup.sls
index ca628492e..29780df1f 100644
--- a/dom0/sd-logging-setup.sls
+++ b/dom0/sd-logging-setup.sls
@@ -43,9 +43,10 @@ sd-log-remove-rsyslog-qubes-plugin:
   cmd.run:
     - name: /rw/config/rc.local
 
-{% elif grains['id'] in ["sd-whonix", "sd-proxy", "sd-proxy-buster-template"] %}
+{% elif grains['id'] in ["sd-whonix", "sd-proxy", "sd-proxy-buster-template", "sd-gpg"] %}
 # We can not place the file on the template under /etc/rsyslog.d/ because of whonix
-# template. This sdlog.conf file is the same from the securedrop-log package, to
+# template, or because it's the base template.
+# This sdlog.conf file is the same from the securedrop-log package, to
 # make sure that rsyslogd use our logging plugin.
 sd-rsyslog-sdlog-conf-for-sd-whonix:
   file.managed:
diff --git a/dom0/sd-workstation.top b/dom0/sd-workstation.top
index afa613922..611dbe410 100644
--- a/dom0/sd-workstation.top
+++ b/dom0/sd-workstation.top
@@ -25,6 +25,7 @@ base:
   sd-devices-buster-template:
     - sd-devices-files
   sd-gpg:
+    - sd-logging-setup
     - sd-gpg-files
   sd-log:
     - sd-logging-setup
diff --git a/tests/test_gpg.py b/tests/test_gpg.py
index cb8df361d..3348d003d 100644
--- a/tests/test_gpg.py
+++ b/tests/test_gpg.py
@@ -50,6 +50,9 @@ class SD_GPG_Tests(SD_VM_Local_Test):
     def test_we_have_the_key(self):
         self.assertEqual(get_local_fp(), get_remote_fp())
 
+    def test_logging_configured(self):
+        self.logging_configured(vmname=True)
+
 

@@ -21,13 +21,17 @@ base:
- sd-remove-unused-templates

sd-log-buster-template:
- sd-log-template-files
- sd-logging-setup
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This implies that sd-gpg will have this package installed. We might want to configure logging in that VM, since syslog is getting a deluge of errors due to misconfigured sd-log:

Mar  6 15:07:49 localhost rsyslogd: child process (pid 8971) exited with status 1 [v8.1901.0]
Mar  6 15:07:49 localhost rsyslogd: omprog: program '/usr/sbin/sd-rsyslog' (pid 8971) terminated; will be restarted [v8.1901.0 try https://www.rsyslog.com/e/2119 ]
Mar  6 15:07:49 localhost rsyslogd: action 'action-0-omprog' suspended (module 'omprog'), retry 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsyslog.com/e/2007 ]
Mar  6 15:07:50 localhost rsyslogd: action 'action-0-omprog' resumed (module 'omprog') [v8.1901.0 try https://www.rsyslog.com/e/2359 ]
Mar  6 15:07:50 localhost rsyslogd: child process (pid 8972) exited with status 1 [v8.1901.0]
Mar  6 15:07:50 localhost rsyslogd: omprog: program '/usr/sbin/sd-rsyslog' (pid 8972) terminated; will be restarted [v8.1901.0 try https://www.rsyslog.com/e/2119 ]
Mar  6 15:07:50 localhost rsyslogd: action 'action-0-omprog' suspended (module 'omprog'), retry 0. There should be messages before this one giving the reason for suspension. [v8.1901.0 try https://www.rsyslog.com/e/2007 ]

@conorsch
Copy link
Contributor Author

conorsch commented Mar 9, 2020

Addressing review comments now, will rebase to include changes from #487, then ping for re-review.

Conor Schaefer added 7 commits March 9, 2020 17:43
We were adding multiple tasks, customized per-VM, to several state
files. Let's instead intelligently handle all logging-related config
in a single state file, and include that in the various VM
configurations as necessary.

Requires a small change to the "securedrop-log" package (managed
separately), to infer the hostname from the logclient, rather than
hardcoding it in a config file on each VM. That way, we can reuse the
same config file for all machines.

There's still an exception
Ensures services are running in 'sd-log', since log aggregation can't
work if they're not. These checks are added to make the overall test
suite more durable.

In addition, updates some of the test logic to stop expecting a
hardcoded VM name in the config file. This way, we can reuse the same
config logic on all VMs.
We had the same task writing twice in dom0, so removing the duplicate as
unnecessary. Also updating the tests to ensure the right policy is
configured. In updating the config tests, discovered that we didn't have
any checks for the custom (i.e. `securedrop.*`) RPC policies, so added
those. Had to adjust the testing path assumptions somewhat in order to
accommodate.
The sd-viewer config didn't have the logging setup included, which was
an oversight. The Whonix-related VMs, sd-whonix, sd-proxy, and
corresponding templates, require special treatment that's now accounted
for in the single log-config state file.

Significantly expanded test coverage in order to verify the end state.
During the consolidation of the logging config, `sd-gpg` started trying
to log again, but it wasn't working correctly. Here we disable the
logging config explicitly, to match what's on master, and add a config test
to confirm.
The `sd-proxy` machine was previously based on a Whonix Workstation
template, which required special handling of the hostname, which is
"host" on all Whonix VMs. We've since ported the proxy to the SDW base
template, which returns accurate hostnames, so we can drop the custom
logic here.
A side-effect of consolidating the log collection logic is that all VMs,
even the TemplateVM for sd-log, begins shipping logs immediately upon
configuration. That's a problem for sd-log AppVM & TemplateVM because
the RPC calls to send logs will cause the AppVM to boot. If the AppVM
doesn't have the final config from the TemplateVM, because of an early
boot, log aggregation won't work. Let's configure both the TemplateVM &
AppVM, then shut down the TemplateVM (automatic as part of salt disp
mgmt vm logic), then reboot the AppVM. All tests passing on a clean
install.
@conorsch conorsch force-pushed the 476-simplify-logging-hostname-config branch from 548a2ac to c23da19 Compare March 10, 2020 06:06
@conorsch
Copy link
Contributor Author

Ready for re-review.

Addressed all comments. Opted to disable logging on sd-gpg explicitly, simply to match what's already on master, and to focus on the Template/App distinction. Config test suite is passing consistently, across multiple rebuilds, including the newly added tests.

@emkll
Copy link
Contributor

emkll commented Mar 11, 2020

Thanks @conorsch for the changes, and your patience, this looks good to merge from my perspective.

Functionally tested as follows:

  • Check out Infers hostname for "localvm" setting securedrop-log#16 and create new tarball (python3 setup.py sdist)
  • Check out Updates securedrop-log to 0.1.1 securedrop-builder#150 and build new deb pkg (PKG_VERSION=0.1.1 make securedrop-log)
  • Copy new 0.1.1 securedrop-log deb package to sd-workstation/securedrop-log_0.1.1+buster_all.deb, so you can install it as part of testing without promoting to apt repo
  • make clone && make clean && make all && make test passes without error
  • Inspect sd-log:/home/user/QubesIncomingLogs/ and ensure that both TemplateVM names and AppVM names are present as subdirs

Opted to disable logging on sd-gpg explicitly

Confirmed, however there is an sd-gpg folder and syslog that contains logs from provisioning-time. I think this is fine, but we should be aware of this

One new change introduced by this PR is that disposable VMs will now have their own folder in QubesIncomingLogs (eg. disp1234). This is good: We will be able to more easily debug specific errors without a massive sd-viewer log.

@conorsch if you want to drop the final commit, I think we can merge this alongside the securedrop-log and packaging changes. I do think that it might be good to capture this diff somewhere (wiki?) as it was extremely useful in the course of testing this pr.

kushaldas
kushaldas previously approved these changes Mar 11, 2020
Copy link
Contributor

@kushaldas kushaldas left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  • Check out Infers hostname for "localvm" setting securedrop-log#16 and create new tarball (python3 setup.py sdist)
  • Check out Updates securedrop-log to 0.1.1 securedrop-builder#150 and build new deb pkg (PKG_VERSION=0.1.1 make securedrop-log)
  • Copy new 0.1.1 securedrop-log deb package to sd-workstation/securedrop-log_0.1.1+buster_all.deb, so you can install it as part of testing without promoting to apt repo
  • make clone && make clean && make all && make test passes without error
  • Inspect sd-log:/home/user/QubesIncomingLogs/ and ensure that both TemplateVM names and AppVM names are present as subdirs

This is good, thank you @conorsch

@conorsch conorsch force-pushed the 476-simplify-logging-hostname-config branch from c23da19 to adc6dd4 Compare March 11, 2020 17:13
@conorsch
Copy link
Contributor Author

Thanks @emkll & @kushaldas for the detailed review.

if you want to drop the final commit, I think we can merge this alongside the securedrop-log and packaging changes.

Done: temporary commit referencing a locally built package has been dropped.

I do think that it might be good to capture this diff somewhere (wiki?) as it was extremely useful in the course of testing this pr.

Also done, see here: https://github.com/freedomofpress/securedrop-workstation/wiki/Evaluating-new-deb-package-behavior

Copy link
Contributor

@emkll emkll left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@emkll
Copy link
Contributor

emkll commented Mar 11, 2020

securedrop-log and packaging changes have been merged per #487 (review), merging this now

@emkll emkll merged commit 4236f5a into master Mar 11, 2020
@emkll emkll deleted the 476-simplify-logging-hostname-config branch March 11, 2020 20:56
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Template logs are their corresponding AppVMs
3 participants