UTAH

Merge lp:~doanac/utah/rsyslog-v4 into lp:utah

  1. rsyslog-v4
  2. Merge into dev
Proposed by Andy Doan
Status: Merged
Merged at revision: 831
Proposed branch: lp:~doanac/utah/rsyslog-v4
Merge into: lp:utah
Diff against target: 959 lines (+593/-45) (has conflicts)
15 files modified
examples/run_install_test.py (+7/-0)
examples/run_test_bamboo_feeder.py (+6/-0)
examples/run_test_cobbler.py (+6/-0)
examples/run_test_vm.py (+7/-0)
examples/run_utah_tests.py (+7/-0)
templates/50-utahdefault.conf.jinja2 (+1/-0)
templates/utah-latecommand.jinja2 (+9/-0)
tests/test_rsyslog.py (+212/-0)
utah/config.py (+49/-1)
utah/provisioning/baremetal/bamboofeeder.py (+6/-11)
utah/provisioning/baremetal/cobbler.py (+17/-18)
utah/provisioning/provisioning.py (+55/-9)
utah/provisioning/rsyslog.py (+195/-0)
utah/provisioning/vm/vm.py (+15/-5)
utah_howto.txt (+1/-1)
Text conflict in examples/run_install_test.py
Text conflict in examples/run_test_bamboo_feeder.py
Text conflict in examples/run_test_cobbler.py
Text conflict in examples/run_test_vm.py
Text conflict in examples/run_utah_tests.py
To merge this branch: bzr merge lp:~doanac/utah/rsyslog-v4
Reviewer Review Type Date Requested Status
UTAH Dev Pending
Review via email: mp+151840@code.launchpad.net

Description of the change

yet another attempt to try and get BZR to not screw up my diffs:

This has finally been tested fairly well and should be ready to review. This patch set allows UTAH to read syslog messages from the target test device to understand what's going on (ie is install working, did the system boot).

Since the messages you'll need to queue on will likely change over time, I've made this configurable via our JSON config. The current configuration that seems to be working looks like:

    "install_steps": [
      {
        "message": "system started",
        "pattern": ".*",
        "booted": true,
        "timeout": 360
      },
      {
        "message": "install started",
        "pattern": [
          ".*ubiquity\\[\\d+\\]: Ubiquity \\d",
          ".*anna-install"
        ],
        "timeout": 120
      },
      {
        "message": "install complete",
        "comment": "the finish-install pattern was needed for server bootspeed job",
        "pattern": [
          ".*ubiquity reboot",
          ".*log-output -t ubiquity umount /target$",
          ".*finish-install.d/94save-logs",
          ".*finish-install: umount"
        ],
        "timeout": 3600
      }
    ],
    "boot_steps": [
      {
        "message": "system booted",
        "pattern": ".*Linux version \\d",
        "timeout": 180
      },
      {
        "message": "disk mounted",
        "pattern": ".*mounted filesystem with ordered data",
        "timeout": 180
      },
      {
        "message": "network active",
        "pattern": ".*NetworkManager",
        "timeout": 180
      }
    ]
}

I'm thinking this might be a good thing to include as a conf.d/10_syslog-messages file and be installed by default. let me know if that makes sense.

To post a comment you must log in.
Revision history for this message
Andy Doan (doanac) wrote :

some original comments from max:

So, it looks like you've added some generic exception logging to run_test_vm.py, but not any of the other test scripts. I forgot that script even exists; it used to be the script to run the vm-tools integration, but that integration has been deprecated for a while. I think if we're changing one run script, we should probably be changing them all or changing run.py. I think we should also consider whether changing them at all makes sense, given the likelihood that we'll be removing most of them soon in a separate merge.

On lines 270 and 401, I'd consider using a generic hostname, like ubuntu. I'd also consider picking a weird specific date, like the beginning of the unix epoch, or the date and time I was born, or when ubuntu was first released, but I'm weird like that.

On 468 and 532 we're still checking for SSH in a retry loop with a long timeout, even though we know the machine is installed and booted. I think this is reasonable behavior, at least for now, but I think a comment in there will help us remember that we may want to revise that at some point. Similarly, notes on lines 938 and 960 might make sense.

Since you've taken out the removal of the serial device on line 945, have you verified that the log correctly appends after a reboot and doesn't just overwrite the old one? I think I've had problems with that before.

I haven't actually reviewed the new rsyslog.py yet, but those are my thoughts on everything else.

lp:~doanac/utah/rsyslog-v4 updated
841. By Andy Doan

review comments from max

Revision history for this message
Andy Doan (doanac) wrote :

and my comments to his comments:

On 03/05/2013 10:41 AM, Max Brustkern wrote:
> So, it looks like you've added some generic exception logging to
> run_test_vm.py, but not any of the other test scripts. I forgot that
> script even exists; it used to be the script to run the vm-tools
> integration, but that integration has been deprecated for a while. I
> think if we're changing one run script, we should probably be
> changing them all or changing run.py. I think we should also
> consider whether changing them at all makes sense, given the
> likelihood that we'll be removing most of them soon in a separate
> merge.

I fixed the one because it happened to be swallowing a syntax error I
discovered while testing my code. I don't mind updating the others - it
might save someone else 20 minutes in the future.

> On lines 270 and 401, I'd consider using a generic hostname, like
> ubuntu. I'd also consider picking a weird specific date, like the
> beginning of the unix epoch, or the date and time I was born, or when
> ubuntu was first released, but I'm weird like that.

sure.

> On 468 and 532 we're still checking for SSH in a retry loop with a
> long timeout, even though we know the machine is installed and
> booted. I think this is reasonable behavior, at least for now, but I
> think a comment in there will help us remember that we may want to
> revise that at some point. Similarly, notes on lines 938 and 960
> might make sense.

I suppose we should just update our default config now, but I wasn't
sure if this would play nice with reboot support changes?

> Since you've taken out the removal of the serial device on line 945,
> have you verified that the log correctly appends after a reboot and
> doesn't just overwrite the old one? I think I've had problems with
> that before.

It does not append to the file. However, the rsyslog.py code creates a
-install.log file that has all of that.

> I haven't actually reviewed the new rsyslog.py yet, but those are my
> thoughts on everything else.

Cool - i'll make some updates ASAP

Revision history for this message
Max Brustkern (nuclearbob) wrote :

I've got two thoughts on the configuration.

1. I'm still seeing ubiquity (such as precise desktop amd64) installs where the last line is like:
Mar 11 14:44:37 utah-1657-precise-amd64 rsyslogd: [origin software="rsyslogd" swVersion="5.8.6" x-pid="1652" x-info="http://www.rsyslog.com"] exiting on signal 15.
I think that should be one of the options.
2. I think the configuration should be in the package. Since all installs will now be assuming it exists, I think it should be in config.py. The reason everything is in config.py is so that if a user has an empty utah config file, we can still theoretically have some defaults and work. I think that design decision is something we want to evaluate, per some email discussions, but for now, I think we should continue doing things in that manner until we actually move away from it.

Finally, I'm seeing some weird things on mini installs like this:
...
Test logs copied to the following files:
 /var/log/utah/utah-1670-quantal-mini-amd64_pass.run_2013-03-11_16-03-59.yaml
Exception in thread Thread-1 (most likely raised during interpreter shutdown):
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
  File "/usr/lib/python2.7/dist-packages/paramiko/transport.py", line 1571, in run
  File "/usr/lib/python2.7/dist-packages/paramiko/transport.py", line 1386, in _log
  File "/usr/lib/python2.7/logging/__init__.py", line 1203, in log
  File "/usr/lib/python2.7/logging/__init__.py", line 1257, in _log
  File "/usr/lib/python2.7/logging/__init__.py", line 1231, in makeRecord
<type 'exceptions.TypeError'>: 'NoneType' object is not callable
Exception in thread Thread-3 (most likely raised during interpreter shutdown):
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 551, in __bootstrap_inner
  File "/usr/lib/python2.7/dist-packages/paramiko/transport.py", line 1571, in run
  File "/usr/lib/python2.7/dist-packages/paramiko/transport.py", line 1386, in _log
  File "/usr/lib/python2.7/logging/__init__.py", line 1203, in log
  File "/usr/lib/python2.7/logging/__init__.py", line 1257, in _log
  File "/usr/lib/python2.7/logging/__init__.py", line 1231, in makeRecord
<type 'exceptions.TypeError'>: 'NoneType' object is not callable
0

This was a run of
run_utah_tests.py --lots-of-arguments ; echo $?
It looks like utah ran fine and exited with status 0, but dumped some weird stuff? It's confusing, and intermittent. It may not even be related to this change, but I wanted to mention it somewhere so we didn't lose sight of it completely.

Revision history for this message
Andy Doan (doanac) wrote :

On 03/11/2013 01:26 PM, Max Brustkern wrote:
> 1. I'm still seeing ubiquity (such as precise desktop amd64) installs where the last line is like:
> Mar 11 14:44:37 utah-1657-precise-amd64 rsyslogd: [origin software="rsyslogd" swVersion="5.8.6" x-pid="1652" x-info="http://www.rsyslog.com"] exiting on signal 15.
> I think that should be one of the options.

I left that one out because one we always hit one of the other current
regex's before this ever shows. However, its still a good safe-guard to
keep us from waiting forever.

> 2. I think the configuration should be in the package. Since all installs will now be assuming it exists, I think it should be in config.py. The reason everything is in config.py is so that if a user has an empty utah config file, we can still theoretically have some defaults and work. I think that design decision is something we want to evaluate, per some email discussions, but for now, I think we should continue doing things in that manner until we actually move away from it.

I agree. I wasn't sure if we wanted to start putting new fields like
this in conf.d instead of config.py so that things don't break when we
update the package. However, I guess apt will warn us, right?

> Finally, I'm seeing some weird things on mini installs like this:

That's interesting. I wonder if this happens on trunk?

Revision history for this message
Max Brustkern (nuclearbob) wrote :

> I agree. I wasn't sure if we wanted to start putting new fields like
> this in conf.d instead of config.py so that things don't break when we
> update the package. However, I guess apt will warn us, right?

Currently, most things are config.something, so if we refer to config.something and it's not in config.py and it's not in any config file, we'll have an Exception. This means that if the user blanks out their config file, and the item isn't in config.py, there's the possibility of an exception, so we put everything in config.py to avoid the possibility of the user creating a situation which is likely to generate an exception. I don't think this design is scaling well, but I'd like to have an agreed-upon new design before we move away from it.

>
> > Finally, I'm seeing some weird things on mini installs like this:
>
> That's interesting. I wonder if this happens on trunk?

I'm looking into that now.

Revision history for this message
Andy Doan (doanac) wrote :

On 03/11/2013 01:51 PM, Max Brustkern wrote:
> Currently, most things are config.something, so if we refer to config.something and it's not in config.py and it's not in any config file, we'll have an Exception. This means that if the user blanks out their config file, and the item isn't in config.py, there's the possibility of an exception, so we put everything in config.py to avoid the possibility of the user creating a situation which is likely to generate an exception. I don't think this design is scaling well, but I'd like to have an agreed-upon new design before we move away from it.

I mis-read your initial comment and was thinking you were suggesting
putting it in /etc/utah/config. config.py is a good place for this, not
sure why I didn't do it that way from the start.

Revision history for this message
Max Brustkern (nuclearbob) wrote :

I've got one last thing. Should rsyslog.py be held to the new standard for external exceptions that we've been discussing in code reviews, or should we come back to that file and implement that later?

Revision history for this message
Andy Doan (doanac) wrote :

On 03/11/2013 04:06 PM, Max Brustkern wrote:
> I've got one last thing. Should rsyslog.py be held to the new standard for external exceptions that we've been discussing in code reviews, or should we come back to that file and implement that later?

I wondered about that. I finally decided to keep this targeted at one
thing and we could go back later and clean stuff up.

lp:~doanac/utah/rsyslog-v4 updated
842. By Andy Doan

add default install/booted steps to config

These have been tested by Max and I on all the different permutations
we could come up with and they seem to work.

Revision history for this message
Andy Doan (doanac) wrote :

@max - I've added the config.py change as requested and tested locally.

Revision history for this message
Max Brustkern (nuclearbob) wrote :

I see merge conflicts again. Assuming we can resolve those before the final commit, I think we're good to go.

Revision history for this message
Andy Doan (doanac) wrote :

something must be broke in my copy of bzr. all i did for the last change was:

http://bazaar.launchpad.net/~doanac/utah/rsyslog-v4/revision/842

i'll do the merge from a pristine machine.

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'examples/run_install_test.py'
2--- examples/run_install_test.py 2013-03-11 09:15:18 +0000
3+++ examples/run_install_test.py 2013-03-12 16:15:29 +0000
4@@ -16,6 +16,7 @@
5 # with this program. If not, see <http://www.gnu.org/licenses/>.
6
7 import argparse
8+import logging
9 import sys
10
11 from utah.exceptions import UTAHException
12@@ -79,8 +80,14 @@
13
14 except UTAHException as error:
15 sys.stderr.write('Exception: ' + str(error))
16+<<<<<<< TREE
17 exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
18
19+=======
20+ exitstatus = 2
21+ except:
22+ logging.exception('Unhandled error in UTAH')
23+>>>>>>> MERGE-SOURCE
24 finally:
25 if not args.no_destroy and machine is not None:
26 try:
27
28=== modified file 'examples/run_test_bamboo_feeder.py'
29--- examples/run_test_bamboo_feeder.py 2013-03-11 09:15:18 +0000
30+++ examples/run_test_bamboo_feeder.py 2013-03-12 16:15:29 +0000
31@@ -87,8 +87,14 @@
32 logging.error(mesg)
33 except (AttributeError, NameError):
34 sys.stderr.write(mesg)
35+<<<<<<< TREE
36 exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
37
38+=======
39+ exitstatus = 2
40+ except:
41+ logging.exception('Unhandled error in UTAH')
42+>>>>>>> MERGE-SOURCE
43 finally:
44 if machine is not None:
45 try:
46
47=== modified file 'examples/run_test_cobbler.py'
48--- examples/run_test_cobbler.py 2013-03-11 09:15:18 +0000
49+++ examples/run_test_cobbler.py 2013-03-12 16:15:29 +0000
50@@ -92,8 +92,14 @@
51 logging.error(mesg)
52 except (AttributeError, NameError):
53 sys.stderr.write(mesg)
54+<<<<<<< TREE
55 exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
56
57+=======
58+ exitstatus = 2
59+ except:
60+ logging.exception('Unhandled error in UTAH')
61+>>>>>>> MERGE-SOURCE
62 finally:
63 if machine is not None:
64 try:
65
66=== modified file 'examples/run_test_vm.py'
67--- examples/run_test_vm.py 2013-03-11 09:15:18 +0000
68+++ examples/run_test_vm.py 2013-03-12 16:15:29 +0000
69@@ -16,6 +16,7 @@
70 # with this program. If not, see <http://www.gnu.org/licenses/>.
71
72 import argparse
73+import logging
74 import sys
75
76 from utah.exceptions import UTAHException
77@@ -73,8 +74,14 @@
78
79 except UTAHException as error:
80 sys.stderr.write('Exception: ' + str(error))
81+<<<<<<< TREE
82 exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
83
84+=======
85+ exitstatus = 2
86+ except:
87+ logging.exception('Unhandled error in UTAH')
88+>>>>>>> MERGE-SOURCE
89 finally:
90 if not args.no_destroy and machine is not None:
91 try:
92
93=== modified file 'examples/run_utah_tests.py'
94--- examples/run_utah_tests.py 2013-03-11 09:15:18 +0000
95+++ examples/run_utah_tests.py 2013-03-12 16:15:29 +0000
96@@ -16,6 +16,7 @@
97 # with this program. If not, see <http://www.gnu.org/licenses/>.
98
99 import argparse
100+import logging
101 import sys
102
103 from utah import config
104@@ -95,7 +96,13 @@
105 exitstatus, locallogs = run_tests(args, machine)
106 except UTAHException as error:
107 sys.stderr.write('Exception: ' + str(error))
108+<<<<<<< TREE
109 exitstatus = ReturnCodes.UTAH_EXCEPTION_ERROR
110+=======
111+ exitstatus = 2
112+ except:
113+ logging.exception('Unhandled error in UTAH')
114+>>>>>>> MERGE-SOURCE
115 finally:
116 if len(locallogs) != 0:
117 print('Test logs copied to the following files:')
118
119=== modified file 'templates/50-utahdefault.conf.jinja2'
120--- templates/50-utahdefault.conf.jinja2 2013-02-21 08:45:09 +0000
121+++ templates/50-utahdefault.conf.jinja2 2013-03-12 16:15:29 +0000
122@@ -11,3 +11,4 @@
123 news.err /var/log/news/news.err
124 news.notice -/var/log/news/news.notice
125 *.emerg *
126+*.* {{dest}}
127
128=== modified file 'templates/utah-latecommand.jinja2'
129--- templates/utah-latecommand.jinja2 2013-02-25 23:53:25 +0000
130+++ templates/utah-latecommand.jinja2 2013-03-12 16:15:29 +0000
131@@ -26,8 +26,17 @@
132 echo "{{user}}" >> /target/etc/utah/users
133 }
134
135+copy_rsyslog_cfg() {
136+ # ubiquity installs have this under /etc/rsyslog.d
137+ # d-i installs have it under /
138+ syslogcfg=/etc/rsyslog.d/50-utahdefault.conf
139+ [ -f $syslogcfg ] || syslogcfg=/$(basename $syslogcfg)
140+ cp $syslogcfg /target/etc/rsyslog.d/
141+}
142+
143 copy_ssh_keys
144 write_utah_data
145+copy_rsyslog_cfg
146
147 log "Copying UTAH latecommmand in-target script..."
148 cp utah-latecommand-in-target /target/tmp
149
150=== added file 'tests/test_rsyslog.py'
151--- tests/test_rsyslog.py 1970-01-01 00:00:00 +0000
152+++ tests/test_rsyslog.py 2013-03-12 16:15:29 +0000
153@@ -0,0 +1,212 @@
154+# Ubuntu Testing Automation Harness
155+# Copyright 2013 Canonical Ltd.
156+
157+# This program is free software: you can redistribute it and/or modify it
158+# under the terms of the GNU General Public License version 3, as published
159+# by the Free Software Foundation.
160+
161+# This program is distributed in the hope that it will be useful, but
162+# WITHOUT ANY WARRANTY; without even the implied warranties of
163+# MERCHANTABILITY, SATISFACTORY QUALITY, or FITNESS FOR A PARTICULAR
164+# PURPOSE. See the GNU General Public License for more details.
165+
166+# You should have received a copy of the GNU General Public License along
167+# with this program. If not, see <http://www.gnu.org/licenses/>.
168+
169+import logging
170+import socket
171+import time
172+import tempfile
173+import threading
174+import unittest
175+
176+from utah.provisioning.rsyslog import RSyslog
177+
178+
179+class TestRsyslog(unittest.TestCase):
180+ logger = logging.getLogger()
181+ logger.setLevel(logging.DEBUG)
182+ logging.getLogger('rsyslog').addHandler(logging.StreamHandler())
183+
184+ @staticmethod
185+ def producer(port, messages):
186+ print 'sending fake messages to port: %d' % port
187+ s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
188+ s.connect(('localhost', port))
189+ for m in messages:
190+ time.sleep(.5)
191+ s.send(m)
192+
193+ @staticmethod
194+ def file_producer(f, messages, truncate=False):
195+ for m in messages:
196+ f.write(m)
197+ f.write('\n')
198+ f.flush()
199+ time.sleep(1)
200+ if truncate:
201+ f.truncate(0)
202+ f.flush()
203+ time.sleep(1)
204+ truncate = False
205+
206+ def test_easy(self):
207+ """
208+ minimal test to make sure we can match a typical first message
209+ """
210+ steps = [
211+ {
212+ "message": "test_easy",
213+ "pattern": ".*log source = /proc/kmsg started",
214+ "timeout": 120,
215+ "booted": False,
216+ },
217+ ]
218+
219+ messages = [
220+ 'test 1',
221+ '<13>Feb 20 13:38:55 host user: log source = /proc/kmsg started',
222+ ]
223+ r = RSyslog("utah-test", '/tmp')
224+ threading.Thread(target=self.producer, args=(r.port, messages)).start()
225+ r.wait_for_install(steps)
226+
227+ def test_future(self):
228+ """
229+ test to make sure we can handle missing a message and understanding
230+ where things are in the future
231+ """
232+ steps = [
233+ {
234+ "message": "test_future",
235+ "pattern": ".*log source = /proc/kmsg started",
236+ "timeout": 120,
237+ "booted": True,
238+ },
239+ {
240+ "message": "hit skipped",
241+ "pattern": "hit skipped",
242+ "timeout": 120,
243+ },
244+ {
245+ "message": "message 3",
246+ "pattern": "message 3",
247+ "timeout": 120,
248+ },
249+ ]
250+
251+ messages = [
252+ 'test 1',
253+ 'hit skipped',
254+ 'message 3',
255+ ]
256+
257+ r = RSyslog("utah-test", '/tmp')
258+ threading.Thread(target=self.producer, args=(r.port, messages)).start()
259+
260+ def booted_cb():
261+ self.test_future_booted = True
262+
263+ self.test_future_booted = False
264+ r.wait_for_install(steps, booted_cb)
265+ self.assertTrue(self.test_future_booted, 'booted callback not made')
266+
267+ def test_callbacks(self):
268+ """
269+ minimal test to make sure wait_for_steps works
270+ """
271+ steps = [
272+ {
273+ "message": "test callbacks",
274+ "pattern": ".*log source = /proc/kmsg started",
275+ "timeout": 120,
276+ "booted": True,
277+ },
278+ {
279+ "message": "hit skipped",
280+ "pattern": "hit skipped",
281+ "timeout": 120,
282+ },
283+ {
284+ "message": "message 3",
285+ "pattern": "message 3",
286+ "timeout": 120,
287+ "blah": True,
288+ },
289+ ]
290+
291+ messages = [
292+ 'test 1',
293+ 'hit skipped',
294+ 'message 3',
295+ ]
296+
297+ r = RSyslog("utah-test", '/tmp')
298+ threading.Thread(target=self.producer, args=(r.port, messages)).start()
299+
300+ def booted_cb():
301+ self.test_callbacks_booted = True
302+
303+ def blah_cb():
304+ self.test_callbacks_blah = True
305+
306+ self.test_callbacks_booted = self.test_callbacks_blah = False
307+ callbacks = {
308+ 'booted': booted_cb,
309+ 'blah': blah_cb,
310+ }
311+ r._wait_for_steps(steps, "/dev/null", callbacks)
312+ self.assertTrue(self.test_callbacks_booted, 'booted callback not made')
313+ self.assertTrue(self.test_callbacks_blah, 'blah callback not made')
314+
315+ def test_booted(self):
316+ """
317+ minimal test to make sure wait_for_booted works
318+ """
319+ steps = [
320+ {
321+ "message": "test booted",
322+ "pattern": ".*log source = /proc/kmsg started",
323+ "timeout": 120,
324+ },
325+ ]
326+
327+ messages = [
328+ 'test 1',
329+ '<13>Feb 20 13:38:55 host user: log source = /proc/kmsg started',
330+ ]
331+
332+ r = RSyslog("utah-test", '/tmp')
333+ threading.Thread(target=self.producer, args=(r.port, messages)).start()
334+ r.wait_for_booted(steps)
335+
336+ def usefile(self, truncate):
337+ """
338+ minimal test to make sure wait_for_booted works when tailing a file
339+ """
340+ steps = [
341+ {
342+ "message": "truncate test",
343+ "pattern": ".*log source = /proc/kmsg started",
344+ "timeout": 60,
345+ },
346+ ]
347+
348+ messages = [
349+ 'test 1',
350+ 'lllllllllllllllllllllllllllllllllllllll',
351+ 'aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa',
352+ '<13>Feb 20 13:38:55 host user: log source = /proc/kmsg started',
353+ ]
354+
355+ with tempfile.NamedTemporaryFile() as f:
356+ r = RSyslog("utah-test", '/tmp', f.name)
357+ threading.Thread(
358+ target=self.file_producer, args=(f, messages, truncate)).start()
359+ r.wait_for_booted(steps)
360+
361+ def test_usefile(self):
362+ self.usefile(False)
363+
364+ def test_usefile_truncation(self):
365+ self.usefile(True)
366
367=== modified file 'utah/config.py'
368--- utah/config.py 2013-02-20 18:22:37 +0000
369+++ utah/config.py 2013-03-12 16:15:29 +0000
370@@ -141,7 +141,52 @@
371 # a value higher than the default is used to avoid db locking problems
372 sqlite3_db_connection_timeout=30,
373 # location of the jinja2 templates used by the provisionig module
374- template_dir=os.path.join('/', 'usr', 'share', 'utah', 'templates')
375+ template_dir=os.path.join('/', 'usr', 'share', 'utah', 'templates'),
376+
377+ install_steps=[
378+ {
379+ 'message': 'system started',
380+ 'pattern': '.*',
381+ 'booted': True,
382+ 'timeout': 360,
383+ },
384+ {
385+ 'message': 'install started',
386+ 'pattern': [
387+ '.*ubiquity\\[\\d+\\]: Ubiquity \\d',
388+ '.*anna-install', # needed for non-ubiquity installs
389+ ],
390+ 'timeout': 120,
391+ },
392+ {
393+ 'message': 'install complete',
394+ 'pattern': [
395+ '.*ubiquity reboot',
396+ '.*log-output -t ubiquity umount /target$',
397+ '.*finish-install.d/94save-logs', # needed for server bootspeed
398+ '.*finish-install: umount',
399+ '.*rsyslogd:.*exiting on signal 15.',
400+ ],
401+ "timeout": 3600
402+ },
403+ ],
404+ boot_steps=[
405+ {
406+ 'message': 'system booted',
407+ 'pattern': '.*Linux version \\d',
408+ 'timeout': 180,
409+ },
410+ {
411+ 'message': 'disk mounted',
412+ 'pattern': '.*mounted filesystem with ordered data',
413+ 'timeout': 180,
414+ },
415+ {
416+ 'message': 'network active',
417+ 'pattern': '.*NetworkManager',
418+ 'timeout': 180,
419+ }
420+ ]
421 )
422
423 # These depend on the local user/path, and need to be filtered out
424@@ -163,6 +208,9 @@
425 vmpath=os.path.join('~', 'vm'),
426 )
427
428+LOCALDEFAULTS['nfsiface'] = LOCALDEFAULTS['bridge']
429+LOCALDEFAULTS['wwwiface'] = LOCALDEFAULTS['bridge']
430+
431 # These depend on other config options, so they're added last.
432 # Default logfile is /var/log/utah/{hostname}.log
433 LOCALDEFAULTS['logfile'] = os.path.join(DEFAULTS['logpath'],
434
435=== modified file 'utah/provisioning/baremetal/bamboofeeder.py'
436--- utah/provisioning/baremetal/bamboofeeder.py 2013-01-24 16:31:58 +0000
437+++ utah/provisioning/baremetal/bamboofeeder.py 2013-03-12 16:15:29 +0000
438@@ -17,7 +17,6 @@
439 Support bare-metal provisioning of bamboo-feeder-based systems.
440 """
441
442-import netifaces
443 import os
444 import pipes
445 import shutil
446@@ -60,12 +59,9 @@
447 if self.image is None:
448 raise UTAHBMProvisioningException(
449 'Image file required for bamboo-feeder installation')
450- try:
451- iface = config.wwwiface
452- except AttributeError:
453- iface = config.bridge
454- self.ip = netifaces.ifaddresses(iface)[netifaces.AF_INET][0]['addr']
455- self.logger.debug('Configuring for ' + iface + ' with IP ' + self.ip)
456+ self.ip = self._ipaddr(config.wwwiface)
457+ self.logger.debug('Configuring for %s with IP %s',
458+ config.wwwiface, self.ip)
459 self._cmdlinesetup()
460 imageurl = 'http://' + self.ip + '/utah/' + self.name + '.img'
461 preenvurl = 'http://' + self.ip + '/utah/' + self.name + '.preEnv'
462@@ -276,10 +272,9 @@
463 self._umountimage()
464 self.restart()
465 self.logger.info('System installing')
466- self.logger.info('Checking every ' + str(config.checktimeout) +
467- ' seconds until system is installed')
468- self.logger.info('Will time out after ' + str(config.installtimeout)
469- + ' seconds')
470+
471+ self.rsyslog.wait_for_install(config.install_steps)
472+ self.rsyslog.wait_for_booted(config.boot_steps)
473 retry(self.sshcheck, config.checktimeout, logmethod=self.logger.info)
474
475 self.provisioned = True
476
477=== modified file 'utah/provisioning/baremetal/cobbler.py'
478--- utah/provisioning/baremetal/cobbler.py 2013-02-14 10:31:33 +0000
479+++ utah/provisioning/baremetal/cobbler.py 2013-03-12 16:15:29 +0000
480@@ -17,7 +17,6 @@
481 Support bare metal provisioning through cobbler.
482 """
483
484-import netifaces
485 import os
486 import pipes
487 import subprocess
488@@ -133,6 +132,13 @@
489 """)
490 myfile.close()
491 self._setuppreseed()
492+
493+ if self.rewrite == 'all':
494+ self._setuplogging(tmpdir=self.tmpdir)
495+ else:
496+ self.logger.debug('Skipping logging setup because rewrite is' +
497+ self.rewrite)
498+
499 initrd = self._repackinitrd()
500
501 self.logger.info('Setting up system with cobbler')
502@@ -165,11 +171,7 @@
503 self.logger.debug('Reloading NFS config')
504 self._runargs(config.nfscommand + ['reload'])
505 self.logger.debug('Adding NFS boot options')
506- try:
507- iface = config.nfsiface
508- except AttributeError:
509- iface = config.bridge
510- ip = netifaces.ifaddresses(iface)[netifaces.AF_INET][0]['addr']
511+ ip = self._ipaddr(config.nfsiface)
512 self.cmdline += (' root=/dev/nfs netboot=nfs nfsroot=' +
513 ip + ':' + self.isodir)
514 self.cmdline = self.cmdline.strip()
515@@ -190,28 +192,25 @@
516 for arg in self.machineinfo])
517
518 self.restart()
519-
520- self.logger.info('Waiting for installation to begin')
521- time.sleep(self.boottimeout)
522- self._cobble(['system', 'edit', '--name=' + self.name,
523- '--netboot-enabled=N'])
524-
525- self.logger.info('System installing')
526- self.logger.info('Checking every ' + str(checktimeout) +
527- ' seconds until system is installed')
528- self.logger.info('Will time out after ' + str(installtimeout)
529- + ' seconds')
530- retry(self.sshcheck, checktimeout, logmethod=self.logger.info)
531+ self.rsyslog.wait_for_install(config.install_steps, self._disable_netboot)
532+ self.rsyslog.wait_for_booted(config.boot_steps)
533
534 if self.installtype == 'desktop':
535 self._removenfs()
536
537+ retry(self.sshcheck, config.checktimeout, logmethod=self.logger.info)
538+
539 self.provisioned = True
540 self.active = True
541 self._uuid_check()
542 self.logger.info('System installed')
543 return True
544
545+ def _disable_netboot(self):
546+ self.logger.info('install seems to have booted, disabling netboot')
547+ self._cobble(['system', 'edit', '--name=' + self.name,
548+ '--netboot-enabled=N'])
549+
550 def _cobble(self, cmd, failok=False):
551 """
552 Pull out all cobbler commands so that we can later support changing
553
554=== modified file 'utah/provisioning/provisioning.py'
555--- utah/provisioning/provisioning.py 2013-02-28 16:44:17 +0000
556+++ utah/provisioning/provisioning.py 2013-03-12 16:15:29 +0000
557@@ -21,6 +21,7 @@
558 import apt.cache
559 import logging
560 import logging.handlers
561+import netifaces
562 import os
563 import pipes
564 import re
565@@ -45,6 +46,7 @@
566 OrderedSet,
567 )
568 from utah.preseed import Preseed
569+from utah.provisioning.rsyslog import RSyslog
570 from utah.provisioning.exceptions import UTAHProvisioningException
571 from utah.retry import retry
572
573@@ -217,6 +219,12 @@
574
575 self.logger.debug('Machine init finished')
576
577+ @property
578+ def rsyslog(self):
579+ if not getattr(self, '_rsyslog', None):
580+ self._rsyslog = RSyslog(self.name, config.logpath)
581+ return self._rsyslog
582+
583 def _namesetup(self, name=None):
584 """
585 Name the machine, automatically or using a specified name.
586@@ -955,11 +963,24 @@
587 '[ -e /conf/param.conf ] && . /conf/param.conf',
588 orderfilename])
589
590+ casper_file = os.path.join(tmpdir, 'initrd.d', 'etc', 'casper.conf')
591+ tmpfilename = casper_file + '.tmp'
592+ with open(casper_file, 'r') as i:
593+ with open(tmpfilename, 'w') as o:
594+ for line in i:
595+ if 'export HOST' in line:
596+ o.write('export HOST="{}"\n'.format(self.name))
597+ elif 'export FLAVOUR' in line:
598+ o.write('export FLAVOUR="Ubuntu"\n')
599+ else:
600+ o.write(line)
601+ o.flush()
602+ os.rename(tmpfilename, casper_file)
603+
604 def _setuplogging(self, tmpdir=None):
605 """
606 Send the installer syslog to a console.
607 """
608- # TODO: move this into CustomVM
609 if tmpdir is None:
610 tmpdir = self.tmpdir
611 inittab = os.path.join(tmpdir, 'initrd.d', 'etc', 'inittab')
612@@ -970,14 +991,18 @@
613 "# logging to serial\n"
614 "ttyS0::respawn:/usr/bin/tail -n 1200 "
615 "-f /var/log/syslog \n")
616- else:
617- self.logger.info('No inittab found, creating rsyslog config file')
618- template = self.template_env.get_template(
619- '50-utahdefault.conf.jinja2')
620- conffilename = os.path.join(tmpdir, 'initrd.d',
621- '50-utahdefault.conf')
622- with open(conffilename, 'w') as f:
623- f.write(template.render())
624+
625+ self.logger.info('Creating rsyslog config file')
626+ template = self.template_env.get_template('50-utahdefault.conf.jinja2')
627+ conffilename = os.path.join(tmpdir, 'initrd.d', '50-utahdefault.conf')
628+ with open(conffilename, 'w') as f:
629+ if self.rsyslog.port:
630+ ip = self._ipaddr(config.bridge)
631+ dest = '@{}:{}'.format(ip, self.rsyslog.port)
632+ else:
633+ self.logger.debug('setting up logging to go to serial console')
634+ dest = '|/dev/ttyS0'
635+ f.write(template.render(dest=dest))
636
637 def _repackinitrd(self, tmpdir=None):
638 """
639@@ -1044,6 +1069,19 @@
640 self.logger.info('Adding debconf/priority=critical option '
641 'since installtype is not desktop')
642 self.cmdline += ' debconf/priority=critical'
643+ if 'netcfg/get_hostname=' not in self.cmdline:
644+ self.logger.info('Adding netcfg/get_hostname option')
645+ self.cmdline += (' netcfg/get_hostname={}'.format(self.name))
646+ if 'log_host' not in self.cmdline:
647+ option = 'log_host={}'.format(self._ipaddr(config.bridge))
648+ self.logger.info('Adding {} option for rsyslog'
649+ .format(option))
650+ self.cmdline += ' ' + option
651+ if 'log_port' not in self.cmdline:
652+ option = 'log_port={}'.format(self.rsyslog.port)
653+ self.logger.info('Adding {} option for rsyslog'
654+ .format(option))
655+ self.cmdline += ' ' + option
656 else:
657 self.logger.info('Not altering command line since rewrite is ' +
658 self.rewrite)
659@@ -1065,3 +1103,11 @@
660 if series is None:
661 self.series = self.image.series
662 self._cmdlinesetup(boot=boot)
663+
664+ @staticmethod
665+ def _ipaddr(ifname):
666+ """
667+ Returns the first IP address found for the given interface name
668+ """
669+ iface = netifaces.ifaddresses(ifname)
670+ return iface[netifaces.AF_INET][0]['addr']
671
672=== added file 'utah/provisioning/rsyslog.py'
673--- utah/provisioning/rsyslog.py 1970-01-01 00:00:00 +0000
674+++ utah/provisioning/rsyslog.py 2013-03-12 16:15:29 +0000
675@@ -0,0 +1,195 @@
676+# Ubuntu Testing Automation Harness
677+# Copyright 2013 Canonical Ltd.
678+
679+# This program is free software: you can redistribute it and/or modify it
680+# under the terms of the GNU General Public License version 3, as published
681+# by the Free Software Foundation.
682+
683+# This program is distributed in the hope that it will be useful, but
684+# WITHOUT ANY WARRANTY; without even the implied warranties of
685+# MERCHANTABILITY, SATISFACTORY QUALITY, or FITNESS FOR A PARTICULAR
686+# PURPOSE. See the GNU General Public License for more details.
687+
688+# You should have received a copy of the GNU General Public License along
689+# with this program. If not, see <http://www.gnu.org/licenses/>.
690+
691+import logging
692+import os
693+import re
694+import select
695+import socket
696+import sys
697+import time
698+
699+from utah.exceptions import UTAHException
700+
701+
702+class RSyslog(object):
703+ def __init__(self, hostname, logpath, usefile=None):
704+ """
705+ :param usefile: allows class to "tail" a file rather than act as an
706+ rsyslogd server
707+ """
708+ self._host = hostname
709+ self._logpath = logpath
710+
711+ self.logger = logging.getLogger('rsyslog')
712+
713+ if usefile:
714+ if not os.path.exists(usefile):
715+ self.logger.debug('creating syslog file')
716+ with open(usefile, 'w') as f:
717+ os.fchmod(f.fileno(), 0660)
718+ self._file = open(usefile, 'r')
719+ self._where = 0
720+ self._read_line = self._read_file
721+ self._port = 0
722+ else:
723+ # start listening on an ephemeral UDP port
724+ self._sock = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
725+ self._sock.bind(('', 0))
726+ self._port = self._sock.getsockname()[1]
727+ self._read_line = self._read_udp
728+ self.logger.info('rsylogd port(%d) opened', self._port)
729+
730+ @property
731+ def port(self):
732+ return self._port
733+
734+ def wait_for_install(self, steps, booted_callback=None):
735+ """
736+ Works through each step in the steps array to find messages in the
737+ syslog indicating what part of the install we are in. Steps is an
738+ array of:
739+ {
740+ "message": "system started",
741+ "pattern": ".*log source = /proc/kmsg started",
742+ "timeout": 1000,
743+ "booted": false
744+ },
745+ {
746+ "message": "system started",
747+ "pattern": [
748+ ".*log source = /proc/kmsg started"
749+ ],
750+ "timeout": 1000,
751+ "booted": false
752+ }
753+ "pattern" can an array or string
754+ "booted" is optional, but can be used to indicate that the system is
755+ fully operational. This can be used in conjunction with the
756+ "booted_callback" function.
757+ """
758+ logfile = '{}/{}-install.log'.format(self._logpath, self._host)
759+ callbacks = {'booted': booted_callback}
760+ self._wait_for_steps(steps, logfile, callbacks)
761+
762+ def wait_for_booted(self, steps):
763+ """
764+ Works the same as the wait_for_install function but takes in steps
765+ that determine a system has booted after the install has completed.
766+ """
767+ logfile = '{}/{}-boot.log'.format(self._logpath, self._host)
768+ callbacks = {}
769+ self._wait_for_steps(steps, logfile, callbacks)
770+
771+ def _wait_for_steps(self, steps, logfile, callbacks):
772+ with open(logfile, 'w') as f:
773+ x = 0
774+ while x < len(steps):
775+ message = steps[x]['message']
776+ pattern = steps[x]['pattern']
777+ timeout = steps[x]['timeout']
778+
779+ if not isinstance(pattern, list):
780+ pattern = [pattern]
781+ future_pats = self._future_patterns(steps, x)
782+ pattern.extend(future_pats)
783+ self.logger.info('Waiting %ds for: %s', timeout, message)
784+ match = self._wait_for(f, pattern, message, timeout)
785+ if match in future_pats:
786+ msg = 'Expected pattern missed, matched future pattern: %s'
787+ self.logger.warn(msg, match)
788+ x = self._fast_forward(steps, match, callbacks)
789+
790+ self._do_callback(steps[x], callbacks)
791+ x += 1
792+
793+ @staticmethod
794+ def _do_callback(step, callbacks):
795+ for name, func in callbacks.iteritems():
796+ if func and step.get(name, False):
797+ func()
798+
799+ @staticmethod
800+ def _future_patterns(steps, index):
801+ patterns = []
802+ index += 1
803+ for step in steps[index:]:
804+ pattern = step['pattern']
805+ if not isinstance(pattern, list):
806+ patterns.append(pattern)
807+ else:
808+ patterns.extend(pattern)
809+ return patterns
810+
811+ @staticmethod
812+ def _fast_forward(steps, pattern, callbacks):
813+ """
814+ Looks through each item in the steps array to find the index of the
815+ given pattern. It will return that index so that the wait_for code
816+ knows where to continue from. It will also alert the booted_callback
817+ function if that was one of the steps that was missed.
818+ """
819+ x = 0
820+ while x < len(steps):
821+ # make sure we don't skip a callback
822+ RSyslog._do_callback(steps[x], callbacks)
823+
824+ patterns = steps[x]['pattern']
825+ if not isinstance(patterns, list):
826+ patterns = [patterns]
827+ if pattern in patterns:
828+ return x
829+
830+ x += 1
831+
832+ def _wait_for(self, writer, patterns, message, timeout):
833+ pats = [re.compile(x) for x in patterns]
834+
835+ endtime = time.time() + timeout
836+ while(time.time() < endtime):
837+ data = self._read_line()
838+ if data:
839+ if self.logger.level <= logging.DEBUG:
840+ sys.stderr.write(data)
841+ writer.write(data)
842+ for pat in pats:
843+ if pat.match(data):
844+ return pat.pattern
845+ raise UTAHException('Timeout occurred for {}'.format(message))
846+
847+ def _read_udp(self):
848+ data = None
849+ (rd, _, _) = select.select([self._sock], [], [], 5)
850+ if self._sock in rd:
851+ data = self._sock.recv(1024)
852+ if data[-1] != '\n':
853+ data += '\n'
854+ return data
855+
856+ def _read_file(self):
857+ # try for up to 5 seconds
858+ for _ in xrange(5):
859+ line = self._file.readline()
860+ if line:
861+ self._where = self._file.tell()
862+ return line
863+
864+ if os.fstat(self._file.fileno()).st_size < self._where:
865+ self.logger.warn('file truncation detected')
866+ self._file.seek(0)
867+ self._where = 0
868+ elif not line:
869+ time.sleep(1)
870+ return None
871
872=== modified file 'utah/provisioning/vm/vm.py'
873--- utah/provisioning/vm/vm.py 2013-01-24 16:31:58 +0000
874+++ utah/provisioning/vm/vm.py 2013-03-12 16:15:29 +0000
875@@ -31,6 +31,7 @@
876 from utah.process import ProcessChecker
877 from utah.provisioning.inventory.sqlite import SQLiteInventory
878 from utah.provisioning.provisioning import CustomInstallMixin, Machine
879+from utah.provisioning.rsyslog import RSyslog
880 from utah.provisioning.ssh import SSHMixin
881 from utah.provisioning.vm.exceptions import UTAHVMProvisioningException
882 from utah.timeout import UTAHTimeout
883@@ -59,8 +60,15 @@
884 self.lv = libvirt.open(config.qemupath)
885 if self.lv is None:
886 raise UTAHVMProvisioningException('Cannot connect to libvirt')
887+ self.syslog = os.path.join(config.logpath, self.name + '.syslog.log')
888 self.logger.debug('LibvirtVM init finished')
889
890+ @property
891+ def rsyslog(self):
892+ if not getattr(self, '_rsyslog', None):
893+ self._rsyslog = RSyslog(self.name, config.logpath, self.syslog)
894+ return self._rsyslog
895+
896 def _load(self):
897 """
898 Load an existing VM.
899@@ -215,6 +223,7 @@
900 self._loggerunsetup()
901 self._loggersetup()
902 self._dirsetup()
903+ self._cmdlinesetup()
904 if emulator is None:
905 emulator = config.emulator
906 if emulator is None:
907@@ -401,8 +410,7 @@
908 serial = ElementTree.Element('serial')
909 serial.set('type', 'file')
910 source = ElementTree.Element('source')
911- log_filename = os.path.join(config.logpath, self.name + '.syslog.log')
912- source.set('path', log_filename)
913+ source.set('path', self.syslog)
914 serial.append(source)
915 target = ElementTree.Element('target')
916 target.set('port', '0')
917@@ -429,6 +437,7 @@
918 log_filename = os.path.join(config.logpath, self.name + '.syslog.log')
919 self.logger.info('Logs will be written to ' + log_filename)
920
921+ self.rsyslog.wait_for_install(config.install_steps)
922 while vm.isActive() is not 0:
923 pass
924
925@@ -458,7 +467,6 @@
926 for cmdline in ose.iterfind('cmdline'):
927 ose.remove(cmdline)
928 devices = xml.find('devices')
929- devices.remove(devices.find('serial'))
930 for disk in list(devices.iterfind('disk')):
931 if disk.get('device') == 'cdrom':
932 disk.remove(disk.find('source'))
933@@ -541,9 +549,11 @@
934 self.vm.create()
935 else:
936 raise UTAHVMProvisioningException('Failed to provision VM')
937- self.logger.info('Waiting ' + str(self.boottimeout) +
938- ' seconds to allow machine to boot')
939+
940+ self.rsyslog.wait_for_booted(config.boot_steps)
941 try:
942+ self.logger.info(
943+ 'Waiting %d seconds for ping response', self.boottimeout)
944 self.pingpoll(timeout=self.boottimeout)
945 except UTAHTimeout:
946 # Ignore timeout for ping, since depending on the network
947
948=== modified file 'utah_howto.txt'
949--- utah_howto.txt 2012-08-22 16:42:35 +0000
950+++ utah_howto.txt 2013-03-12 16:15:29 +0000
951@@ -48,7 +48,7 @@
952 ######################################################################
953
954 # needed to run the self tests
955-sudo apt-get install python-nose
956+sudo apt-get install python-nose python-mock
957
958 # run the self tests
959 cd utah/client

Subscribers

People subscribed via source and target branches

to all changes: