Merge ~raharper/cloud-init:feature/cloudinit-clean-from-write-log into cloud-init:master

Proposed by Ryan Harper on 2019-09-18
Status: Work in progress
Proposed branch: ~raharper/cloud-init:feature/cloudinit-clean-from-write-log
Merge into: cloud-init:master
Diff against target: 328 lines (+154/-7)
5 files modified
cloudinit/cmd/clean.py (+27/-4)
cloudinit/cmd/tests/test_clean.py (+28/-3)
cloudinit/tests/helpers.py (+2/-0)
cloudinit/util.py (+52/-0)
tests/unittests/test_util.py (+45/-0)
Reviewer Review Type Date Requested Status
Server Team CI bot continuous-integration Approve on 2019-09-18
cloud-init Commiters 2019-09-18 Pending
Review via email: mp+372946@code.launchpad.net

Commit message

clean: add a write_file audit log and use it to clean artifacts

Cloud-init uses util.write_file() in many places to write files
during cloud-init execution. This branch will create an audit log
in /var/lib/cloud/instance/write_file.log which contains JSON entries
which captures information about each write.

As a user of this newly created log, cloud-init clean subcommand
reads this data (if present) and augments the list of artifacts to
clean.

To post a comment you must log in.

FAILED: Continuous integration, rev:6b005ae905b5666a9bcd10865ea95c599a5d7e99
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1163/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    FAILED: Ubuntu LTS: Build

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1163//rebuild

review: Needs Fixing (continuous-integration)
65b8808... by Ryan Harper on 2019-09-18

Handle write_file_log_append failures

PASSED: Continuous integration, rev:65b88088e1a5f83b41511dfdf57ef3a2315ad59f
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1165/
Executed test runs:
    SUCCESS: Checkout
    SUCCESS: Unit & Style Tests
    SUCCESS: Ubuntu LTS: Build
    SUCCESS: Ubuntu LTS: Integration
    IN_PROGRESS: Declarative: Post Actions

Click here to trigger a rebuild:
https://jenkins.ubuntu.com/server/job/cloud-init-ci/1165//rebuild

review: Approve (continuous-integration)
Scott Moser (smoser) wrote :

Some thoughts:
a.) Why? Why do two writes for every write?
b.) currently atomic write_file is not covered.

Ryan Harper (raharper) wrote :

For (a) what would you suggest instead?

I'll look at (b).

Scott Moser (smoser) wrote :

For (a), I suggest maybe writing exactly one write for every write?
Why do you need a log of files' you've written? Should we have a separate log for:
 - files opened?
 - files checked for existence?
 - commands run?
 - log files written?

What is motivating you to have this list of files that cloud-init wrote? Realize that in regard to usefulness, it will likely be incomplete. For example, /var/log/cloud-init-output.log won't be in there, and neither would files written by commands cloud-init executes.

We already have a log file which I find to be way too verbose, and a "reporting" mechanism. Do we really need more logging?

I suspect that you're after something here, but what?

Ryan Harper (raharper) wrote :

We're looking to have cloud-init clean remove as many of the artifacts that cloud-init is responsible for creating. Since clean already removes things in cloud paths, like /var/lib/cloud but we do touch other files outside of those paths and logging what files we wrote makes clean-up of those files easy.

Scott Moser (smoser) wrote :

I think that this will not really get you what you're after.
Having a list of the files that cloud-init created or appended to or truncated isn't going to get you to your goal. The partial solution comes at the cost of 2 open and writes for every write. Additionally, we're already writing messages with the same information to the log. You could just parse the log to get the same information, possibly making it more machine friendly if you need to.

I think I'd prefer a solution that could at least get us to the goal.

Unmerged commits

65b8808... by Ryan Harper on 2019-09-18

Handle write_file_log_append failures

6b005ae... by Ryan Harper on 2019-09-16

cmd/clean: leverage write_file log to clean additional files

4837140... by Ryan Harper on 2019-09-13

Switch to json format for records, add unittests

46f3fe9... by Ryan Harper on 2019-09-13

Write file log intial commit

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1diff --git a/cloudinit/cmd/clean.py b/cloudinit/cmd/clean.py
2index 30e49de..06f7daa 100644
3--- a/cloudinit/cmd/clean.py
4+++ b/cloudinit/cmd/clean.py
5@@ -12,7 +12,7 @@ import sys
6 from cloudinit.stages import Init
7 from cloudinit.util import (
8 ProcessExecutionError, del_dir, del_file, get_config_logfiles,
9- is_link, subp)
10+ is_link, subp, write_file_log_read)
11
12
13 def error(msg):
14@@ -45,7 +45,20 @@ def get_parser(parser=None):
15 return parser
16
17
18-def remove_artifacts(remove_logs, remove_seed=False):
19+def get_written_files(filterfn=None):
20+ if filterfn is None:
21+ def _exists(fn):
22+ return os.path.exists(fn)
23+ filterfn = _exists
24+
25+ for wf in write_file_log_read():
26+ fn = wf.get('filename')
27+ if fn:
28+ if filterfn(fn):
29+ yield fn
30+
31+
32+def remove_artifacts(remove_logs=False, remove_seed=False):
33 """Helper which removes artifacts dir and optionally log files.
34
35 @param: remove_logs: Boolean. Set True to delete the cloud_dir path. False
36@@ -56,14 +69,24 @@ def remove_artifacts(remove_logs, remove_seed=False):
37 """
38 init = Init(ds_deps=[])
39 init.read_cfg()
40+
41+ logfiles = get_config_logfiles(init.cfg)
42 if remove_logs:
43- for log_file in get_config_logfiles(init.cfg):
44+ for log_file in logfiles:
45 del_file(log_file)
46
47 if not os.path.isdir(init.paths.cloud_dir):
48 return 0 # Artifacts dir already cleaned
49 seed_path = os.path.join(init.paths.cloud_dir, 'seed')
50- for path in glob.glob('%s/*' % init.paths.cloud_dir):
51+
52+ def _written_filter(fn):
53+ if fn not in logfiles:
54+ if not fn.startswith(init.paths.cloud_dir):
55+ if os.path.exists(fn):
56+ return fn
57+
58+ files_written = list(get_written_files(filterfn=_written_filter))
59+ for path in glob.glob('%s/*' % init.paths.cloud_dir) + files_written:
60 if path == seed_path and not remove_seed:
61 continue
62 try:
63diff --git a/cloudinit/cmd/tests/test_clean.py b/cloudinit/cmd/tests/test_clean.py
64index f092ab3..143d955 100644
65--- a/cloudinit/cmd/tests/test_clean.py
66+++ b/cloudinit/cmd/tests/test_clean.py
67@@ -2,6 +2,7 @@
68
69 from cloudinit.cmd import clean
70 from cloudinit.util import ensure_dir, sym_link, write_file
71+from cloudinit import util
72 from cloudinit.tests.helpers import CiTestCase, wrap_and_call, mock
73 from collections import namedtuple
74 import os
75@@ -18,6 +19,10 @@ class TestClean(CiTestCase):
76 self.artifact_dir = self.tmp_path('artifacts', self.new_root)
77 self.log1 = self.tmp_path('cloud-init.log', self.new_root)
78 self.log2 = self.tmp_path('cloud-init-output.log', self.new_root)
79+ self.wflog = self.tmp_path('write_file.log', self.artifact_dir)
80+ os.makedirs(os.path.dirname(self.wflog))
81+ util.WRITE_FILE_LOG = self.wflog
82+ util._ENABLE_WRITE_FILE_LOG = True
83
84 class FakeInit(object):
85 cfg = {'def_log_file': self.log1,
86@@ -37,21 +42,31 @@ class TestClean(CiTestCase):
87 """remove_artifacts removes logs when remove_logs is True."""
88 write_file(self.log1, 'cloud-init-log')
89 write_file(self.log2, 'cloud-init-output-log')
90+ netplan = self.tmp_path('50-cloud-init.yaml', self.artifact_dir)
91+ write_file(netplan, 'netplan content')
92+ # read the write log before it gets cleaned
93+ with open(self.wflog) as fh:
94+ contents = fh.readlines()
95+ self.assertEqual(3, len(contents))
96
97- self.assertFalse(
98- os.path.exists(self.artifact_dir), 'Unexpected artifacts dir')
99 retcode = wrap_and_call(
100 'cloudinit.cmd.clean',
101 {'Init': {'side_effect': self.init_class}},
102 clean.remove_artifacts, remove_logs=True)
103 self.assertFalse(os.path.exists(self.log1), 'Unexpected file')
104 self.assertFalse(os.path.exists(self.log2), 'Unexpected file')
105+ self.assertFalse(os.path.exists(netplan), 'Unexpected file')
106 self.assertEqual(0, retcode)
107+ self.assertFalse(os.path.exists(self.wflog))
108
109 def test_remove_artifacts_preserves_logs(self):
110 """remove_artifacts leaves logs when remove_logs is False."""
111 write_file(self.log1, 'cloud-init-log')
112 write_file(self.log2, 'cloud-init-output-log')
113+ # read the write log before it gets cleaned
114+ with open(self.wflog) as fh:
115+ contents = fh.readlines()
116+ self.assertEqual(2, len(contents))
117
118 retcode = wrap_and_call(
119 'cloudinit.cmd.clean',
120@@ -60,6 +75,7 @@ class TestClean(CiTestCase):
121 self.assertTrue(os.path.exists(self.log1), 'Missing expected file')
122 self.assertTrue(os.path.exists(self.log2), 'Missing expected file')
123 self.assertEqual(0, retcode)
124+ self.assertFalse(os.path.exists(self.wflog))
125
126 def test_remove_artifacts_removes_unlinks_symlinks(self):
127 """remove_artifacts cleans artifacts dir unlinking any symlinks."""
128@@ -77,6 +93,7 @@ class TestClean(CiTestCase):
129 self.assertFalse(
130 os.path.exists(path),
131 'Unexpected {0} dir'.format(path))
132+ self.assertFalse(os.path.exists(self.wflog))
133
134 def test_remove_artifacts_removes_artifacts_skipping_seed(self):
135 """remove_artifacts cleans artifacts dir with exception of seed dir."""
136@@ -101,6 +118,7 @@ class TestClean(CiTestCase):
137 self.assertFalse(
138 os.path.exists(deleted_dir),
139 'Unexpected {0} dir'.format(deleted_dir))
140+ self.assertFalse(os.path.exists(self.wflog))
141
142 def test_remove_artifacts_removes_artifacts_removes_seed(self):
143 """remove_artifacts removes seed dir when remove_seed is True."""
144@@ -124,6 +142,8 @@ class TestClean(CiTestCase):
145 os.path.exists(deleted_dir),
146 'Unexpected {0} dir'.format(deleted_dir))
147
148+ self.assertFalse(os.path.exists(self.wflog))
149+
150 def test_remove_artifacts_returns_one_on_errors(self):
151 """remove_artifacts returns non-zero on failure and prints an error."""
152 ensure_dir(self.artifact_dir)
153@@ -139,6 +159,7 @@ class TestClean(CiTestCase):
154 self.assertEqual(
155 'ERROR: Could not remove %s/dir1: oops\n' % self.artifact_dir,
156 m_stderr.getvalue())
157+ self.assertFalse(os.path.exists(self.wflog))
158
159 def test_handle_clean_args_reboots(self):
160 """handle_clean_args_reboots when reboot arg is provided."""
161@@ -159,10 +180,15 @@ class TestClean(CiTestCase):
162 self.assertEqual(0, retcode)
163 self.assertEqual(
164 [(['shutdown', '-r', 'now'], False)], called_cmds)
165+ self.assertFalse(os.path.exists(self.wflog))
166
167 def test_status_main(self):
168 '''clean.main can be run as a standalone script.'''
169 write_file(self.log1, 'cloud-init-log')
170+ # read the write log before it gets cleaned
171+ with open(self.wflog) as fh:
172+ contents = fh.readlines()
173+ self.assertEqual(1, len(contents))
174 with self.assertRaises(SystemExit) as context_manager:
175 wrap_and_call(
176 'cloudinit.cmd.clean',
177@@ -175,5 +201,4 @@ class TestClean(CiTestCase):
178 self.assertFalse(
179 os.path.exists(self.log1), 'Unexpected log {0}'.format(self.log1))
180
181-
182 # vi: ts=4 expandtab syntax=python
183diff --git a/cloudinit/tests/helpers.py b/cloudinit/tests/helpers.py
184index 4dad2af..c994a3b 100644
185--- a/cloudinit/tests/helpers.py
186+++ b/cloudinit/tests/helpers.py
187@@ -96,6 +96,8 @@ class TestCase(unittest2.TestCase):
188 util.PROC_CMDLINE = None
189 util._DNS_REDIRECT_IP = None
190 util._LSB_RELEASE = {}
191+ util._ENABLE_WRITE_FILE_LOG = False
192+ util.WRITE_LOG_FILE = '/var/lib/cloud/instance/write_file.log'
193
194 def setUp(self):
195 super(TestCase, self).setUp()
196diff --git a/cloudinit/util.py b/cloudinit/util.py
197index aa23b3f..950921c 100644
198--- a/cloudinit/util.py
199+++ b/cloudinit/util.py
200@@ -70,6 +70,8 @@ CONTAINER_TESTS = (['systemd-detect-virt', '--quiet', '--container'],
201 ['lxc-is-container'])
202
203 PROC_CMDLINE = None
204+WRITE_FILE_LOG = '/var/lib/cloud/instance/write_file.log'
205+_ENABLE_WRITE_FILE_LOG = True
206
207 _LSB_RELEASE = {}
208
209@@ -1841,6 +1843,55 @@ def chmod(path, mode):
210 os.chmod(path, real_mode)
211
212
213+def write_file_log_append(filename, omode, target=None):
214+ """ Create an audit log of files that cloud-init has written.
215+
216+ The log is located at: /var/lib/cloud/instance/write_file.log
217+
218+ The format is JSON dict, one per line
219+ {'timestamp': time.time(), 'path': filename, 'mode': omode}
220+
221+ Example entries:
222+ {'filename': '/etc/apt/sources.list', 'mode': 'wb', 'timestamp': ts}
223+
224+ """
225+ global WRITE_FILE_LOG
226+ global _ENABLE_WRITE_FILE_LOG
227+
228+ if not _ENABLE_WRITE_FILE_LOG:
229+ return
230+
231+ log_file = target_path(target, path=WRITE_FILE_LOG)
232+ if not os.path.exists(os.path.dirname(log_file)):
233+ return
234+
235+ record = {'timestamp': time.time(), 'filename': filename, 'mode': omode}
236+ content = json.dumps(record, default=json_serialize_default)
237+ try:
238+ with open(log_file, "ab") as wfl:
239+ wfl.write((content + '\n').encode('utf-8'))
240+ wfl.flush()
241+ except IOError as e:
242+ LOG.debug('Failed to append to write file log (%s): %s', log_file, e)
243+
244+
245+def write_file_log_read(target=None):
246+ """ Read the WRITE_FILE_LOG and yield the contents.
247+
248+ :returns a list of record dicts
249+ """
250+ global WRITE_FILE_LOG
251+
252+ log_file = target_path(target, path=WRITE_FILE_LOG)
253+ if os.path.exists(log_file):
254+ with open(log_file, "rb") as wfl:
255+ contents = wfl.read()
256+ for line in contents.splitlines():
257+ record = load_json(line)
258+ if record:
259+ yield record
260+
261+
262 def write_file(filename, content, mode=0o644, omode="wb", copy_mode=False):
263 """
264 Writes a file with the given content and sets the file mode as specified.
265@@ -1872,6 +1923,7 @@ def write_file(filename, content, mode=0o644, omode="wb", copy_mode=False):
266 mode_r = "%r" % mode
267 LOG.debug("Writing to %s - %s: [%s] %s %s",
268 filename, omode, mode_r, len(content), write_type)
269+ write_file_log_append(filename, omode)
270 with SeLinuxGuard(path=filename):
271 with open(filename, omode) as fh:
272 fh.write(content)
273diff --git a/tests/unittests/test_util.py b/tests/unittests/test_util.py
274index 0e71db8..82909a7 100644
275--- a/tests/unittests/test_util.py
276+++ b/tests/unittests/test_util.py
277@@ -186,6 +186,51 @@ class TestWriteFile(helpers.TestCase):
278 mockobj.assert_called_once_with('selinux')
279
280
281+class TestWriteFileLogAppend(helpers.CiTestCase):
282+
283+ idir = 'var/lib/cloud/instance'
284+
285+ def test_write_file_log_append(self):
286+ root_d = self.tmp_dir()
287+ log_path = os.path.join(root_d, self.idir, 'write_file.log')
288+ util._ENABLE_WRITE_FILE_LOG = True
289+ util.WRITE_FILE_LOG = log_path
290+ helpers.populate_dir(root_d,
291+ {os.path.join(self.idir, 'dummy'): 'i-foobar'})
292+
293+ content = self.random_string()
294+ fname = os.path.join(root_d, self.random_string())
295+ util.write_file(fname, content, omode='wb')
296+
297+ self.assertTrue(os.path.exists(log_path))
298+ contents = util.load_file(log_path)
299+ self.assertEqual(1, len(contents.splitlines()))
300+ for line in contents.splitlines():
301+ record = util.load_json(line)
302+ self.assertEqual(fname, record['filename'])
303+ self.assertEqual('wb', record['mode'])
304+ self.assertIn('timestamp', record)
305+
306+ def test_write_file_log_read(self):
307+ root_d = self.tmp_dir()
308+ log_path = os.path.join(root_d, self.idir, 'write_file.log')
309+ util.WRITE_FILE_LOG = log_path
310+ helpers.populate_dir(root_d,
311+ {os.path.join(self.idir, 'dummy'): 'i-foobar'})
312+
313+ fname = os.path.join(root_d, self.random_string())
314+
315+ expected_record = {'timestamp': 0, 'filename': fname, 'mode': 'wb'}
316+ with open(log_path, 'ab') as wfl:
317+ record = (json.dumps(expected_record) + '\n').encode('utf-8')
318+ wfl.write(record)
319+ wfl.flush()
320+
321+ records = list(util.write_file_log_read())
322+ self.assertEqual(1, len(records))
323+ self.assertEqual(expected_record, records[0])
324+
325+
326 class TestDeleteDirContents(helpers.TestCase):
327 def setUp(self):
328 super(TestDeleteDirContents, self).setUp()

Subscribers

People subscribed via source and target branches