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