Merge lp:~le-chi-thu/lava-dispatcher/improve-logging-2 into lp:lava-dispatcher
- improve-logging-2
- Merge into trunk
Status: | Merged |
---|---|
Approved by: | Zygmunt Krynicki |
Approved revision: | 207 |
Merged at revision: | 221 |
Proposed branch: | lp:~le-chi-thu/lava-dispatcher/improve-logging-2 |
Merge into: | lp:lava-dispatcher |
Diff against target: |
316 lines (+58/-17) 7 files modified
lava_dispatcher/actions/boot_control.py (+0/-2) lava_dispatcher/actions/launch_control.py (+4/-3) lava_dispatcher/client/base.py (+4/-1) lava_dispatcher/client/master.py (+13/-5) lava_dispatcher/connection.py (+1/-1) lava_dispatcher/job.py (+32/-1) lava_dispatcher/utils.py (+4/-4) |
To merge this branch: | bzr merge lp:~le-chi-thu/lava-dispatcher/improve-logging-2 |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
Le Chi Thu (community) | Needs Resubmitting | ||
Yongqin Liu | Approve | ||
Review via email: mp+90253@code.launchpad.net |
Commit message
Description of the change
make it easier to follow the flow and outcome of actions
Zygmunt Krynicki (zyga) wrote : | # |
Hi ChiThu
59 - rc = session.
60 + rc = session.
I understand this is not related to logging
294 + def _set_logging_
295 + # set logging level is optional
296 + try:
297 + logging.
298 + except :
299 + pass
I understand the intent was to ignore missing entries in the job file (and in that case accessing self.logging_level would raise KeyError). I think this is somewhat confusing and I'd suggest wrapping that inside the def logging_level(self) property method. To users of this class this should be a normal property, not something that may raise an unexpected KeyError. In addition, I think we should validate the values of logging level that are passed. Instead of using raw integers that few users will understand (is 0 more verbose than 100?) I would just use the standard set of logging.XXX names {DEBUG, INFO, WARNING, ERROR, CRITICAL}.
I can show you how to make code like that elegant and how to validate the input quickly.
Le Chi Thu (le-chi-thu) wrote : | # |
wait merging util I have updated according to the discussion below.
<zyga> ChiThu: so for that isuse: I was suggesting to use foo.set_
<zyga> ChiThu: you can convert a string to an integer (for logging) using...
<zyga> ChiThu: try logging.
<zyga> ChiThu: then I was hoping that we actually validate the dispatcher job file
<zyga> ChiThu: a simple schema could check if the log level is in the valid set ("INFO", "DEBUG", etc)
<zyga> ChiThu: for doing that I could point you to json-schema-
<zyga> ChiThu: and to json-document documentation (for better tutorial-like approach)
* antipov (~antipov@
<plars> zyga, ChiThu: Adding a schema for the dispatcher would also go a long way toward documenting the dispatcher
<ChiThu> zyga, yes, good idea about schema for dispatcher
Paul Larson (pwlars) wrote : | # |
I don't think adding a schema and validator should be part of this merge, though I do thing we should do it. I'll add a blueprint for it as I think it would improve reliability and documentation in the dispatcher. Is that something you'd like to work on ChiThu?
Le Chi Thu (le-chi-thu) wrote : | # |
I can update the log_level to string and let the let schema and validator feature be in an other patch.
Paul Larson (pwlars) wrote : | # |
You may want to take a look at logging.
Le Chi Thu (le-chi-thu) wrote : | # |
Updated according to the comments.
* Use string as logging level.
* Removed not logging related changes
* Sync with trunk
Zygmunt Krynicki (zyga) wrote : | # |
ChiThu: resubmit == submit another proposal I think
Preview Diff
1 | === modified file 'lava_dispatcher/actions/boot_control.py' |
2 | --- lava_dispatcher/actions/boot_control.py 2011-11-24 03:00:54 +0000 |
3 | +++ lava_dispatcher/actions/boot_control.py 2012-02-07 19:21:18 +0000 |
4 | @@ -43,7 +43,6 @@ |
5 | client = self.client |
6 | status = 'pass' |
7 | try: |
8 | - logging.info("Boot Linaro image") |
9 | client.boot_linaro_image() |
10 | except: |
11 | logging.exception("boot_linaro_image failed") |
12 | @@ -58,5 +57,4 @@ |
13 | """ |
14 | def run(self): |
15 | client = self.client |
16 | - logging.info("Boot master image") |
17 | client.boot_master_image() |
18 | |
19 | === modified file 'lava_dispatcher/actions/launch_control.py' |
20 | --- lava_dispatcher/actions/launch_control.py 2012-02-02 01:56:11 +0000 |
21 | +++ lava_dispatcher/actions/launch_control.py 2012-02-07 19:21:18 +0000 |
22 | @@ -62,8 +62,9 @@ |
23 | json_bundle = json.dumps(main_bundle) |
24 | job_name = self.context.job_data.get('job_name', "LAVA Results") |
25 | try: |
26 | - print >> self.context.oob_file, 'dashboard-put-result:', \ |
27 | - dashboard.put_ex(json_bundle, job_name, stream) |
28 | + result = dashboard.put_ex(json_bundle, job_name, stream) |
29 | + print >> self.context.oob_file, 'dashboard-put-result:', result |
30 | + logging.info("Dashboard : %s" %result) |
31 | except xmlrpclib.Fault, err: |
32 | logging.warning("xmlrpclib.Fault occurred") |
33 | logging.warning("Fault code: %d" % err.faultCode) |
34 | @@ -176,6 +177,6 @@ |
35 | logging.warn("The url seems not RPC2 or xml-rpc endpoints, please make sure it's a valid one!!!") |
36 | dashboard = srv.dashboard |
37 | |
38 | - logging.info("server RPC endpoint URL: %s" % server) |
39 | + logging.debug("server RPC endpoint URL: %s" % server) |
40 | return dashboard |
41 | |
42 | |
43 | === modified file 'lava_dispatcher/client/base.py' |
44 | --- lava_dispatcher/client/base.py 2012-02-07 18:42:14 +0000 |
45 | +++ lava_dispatcher/client/base.py 2012-02-07 19:21:18 +0000 |
46 | @@ -374,7 +374,6 @@ |
47 | timeout=timeout) |
48 | if match_id == 1: |
49 | raise OperationFailed |
50 | - logging.info("System is in test image now") |
51 | |
52 | def deploy_linaro(self, hwpack, rootfs, kernel_matrix=None, use_cache=True, rootfstype='ext3'): |
53 | raise NotImplementedError(self.deploy_linaro) |
54 | @@ -386,6 +385,8 @@ |
55 | """ |
56 | Reboot the system to the test image |
57 | """ |
58 | + logging.info("Boot the test image") |
59 | + |
60 | self.proc._boot(self.boot_cmds) |
61 | self.in_test_shell(300) |
62 | # set PS1 to include return value of last command |
63 | @@ -395,6 +396,8 @@ |
64 | self.proc.sendline('export PS1="$PS1 [rc=$(echo \$?)]: "') |
65 | self.proc.expect(self.tester_str, timeout=10) |
66 | |
67 | + logging.info("System is in test image now") |
68 | + |
69 | def get_seriallog(self): |
70 | return self.sio.getvalue() |
71 | |
72 | |
73 | === modified file 'lava_dispatcher/client/master.py' |
74 | --- lava_dispatcher/client/master.py 2012-01-27 03:23:09 +0000 |
75 | +++ lava_dispatcher/client/master.py 2012-02-07 19:21:18 +0000 |
76 | @@ -121,7 +121,7 @@ |
77 | session.run('umount /mnt/lava/boot') |
78 | |
79 | def _recreate_uInitrd(session): |
80 | - logging.info("Recreate uInitrd") |
81 | + logging.debug("Recreate uInitrd") |
82 | # Original android sdcard partition layout by l-a-m-c |
83 | sys_part_org = session._client.device_option("sys_part_android_org") |
84 | cache_part_org = session._client.device_option("cache_part_android_org") |
85 | @@ -245,9 +245,8 @@ |
86 | self.run( |
87 | cmd, [pattern1, pexpect.EOF, pexpect.TIMEOUT], timeout=5) |
88 | if self.match_id == 0: |
89 | - logging.info("\nmatching pattern is %s" % self.match_id) |
90 | ip = self.match.group(1) |
91 | - logging.info("Master IP is %s" % ip) |
92 | + logging.debug("Master image IP is %s" % ip) |
93 | return ip |
94 | return None |
95 | |
96 | @@ -269,9 +268,11 @@ |
97 | boot_tgz, root_tgz = self._generate_tarballs( |
98 | hwpack, rootfs, kernel_matrix, use_cache) |
99 | except: |
100 | + logging.error("Deployment tarballs preparation failed") |
101 | tb = traceback.format_exc() |
102 | self.sio.write(tb) |
103 | raise CriticalError("Deployment tarballs preparation failed") |
104 | + |
105 | logging.info("Booting master image") |
106 | try: |
107 | self.boot_master_image() |
108 | @@ -288,6 +289,7 @@ |
109 | try: |
110 | session.wait_network_up() |
111 | except: |
112 | + logging.error("Unable to reach LAVA server, check network") |
113 | tb = traceback.format_exc() |
114 | self.sio.write(tb) |
115 | raise CriticalError("Unable to reach LAVA server, check network") |
116 | @@ -296,6 +298,7 @@ |
117 | _deploy_linaro_rootfs(session, root_url) |
118 | _deploy_linaro_bootfs(session, boot_url) |
119 | except: |
120 | + logging.error("Deployment failed") |
121 | tb = traceback.format_exc() |
122 | self.sio.write(tb) |
123 | raise CriticalError("Deployment failed") |
124 | @@ -317,6 +320,7 @@ |
125 | try: |
126 | session.wait_network_up() |
127 | except: |
128 | + logging.error("Unable to reach LAVA server, check network") |
129 | tb = traceback.format_exc() |
130 | self.sio.write(tb) |
131 | raise CriticalError("Unable to reach LAVA server, check network") |
132 | @@ -325,6 +329,7 @@ |
133 | boot_tbz2, system_tbz2, data_tbz2, pkg_tbz2 = \ |
134 | self._download_tarballs(boot, system, data, pkg, use_cache) |
135 | except: |
136 | + logging.error("Unable to download artifacts for deployment") |
137 | tb = traceback.format_exc() |
138 | self.sio.write(tb) |
139 | raise CriticalError("Unable to download artifacts for deployment") |
140 | @@ -353,6 +358,7 @@ |
141 | # _purge_linaro_android_sdcard(session) |
142 | _deploy_linaro_android_data(session, data_url) |
143 | except: |
144 | + logging.error("Android deployment failed") |
145 | tb = traceback.format_exc() |
146 | self.sio.write(tb) |
147 | raise CriticalError("Android deployment failed") |
148 | @@ -400,6 +406,7 @@ |
149 | """ |
150 | reboot the system, and check that we are in a master shell |
151 | """ |
152 | + logging.info("Boot the system master image") |
153 | self.proc.soft_reboot() |
154 | try: |
155 | self.proc.expect("Starting kernel") |
156 | @@ -410,6 +417,7 @@ |
157 | self._in_master_shell(300) |
158 | self.proc.sendline('export PS1="$PS1 [rc=$(echo \$?)]: "') |
159 | self.proc.expect(self.master_str, timeout=10, lava_no_logging=1) |
160 | + logging.info("System is in master image now") |
161 | |
162 | def _format_testpartition(self, session, fstype): |
163 | logging.info("Format testboot and testrootfs partitions") |
164 | @@ -434,6 +442,7 @@ |
165 | _extract_partition(image_file, self.boot_part, boot_tgz) |
166 | _extract_partition(image_file, self.root_part, root_tgz) |
167 | except: |
168 | + logging.error("Failed to generate tarballs") |
169 | shutil.rmtree(tarball_dir) |
170 | tb = traceback.format_exc() |
171 | self.sio.write(tb) |
172 | @@ -553,8 +562,7 @@ |
173 | [self.master_str, pexpect.TIMEOUT], timeout=timeout, lava_no_logging=1) |
174 | if match_id == 1: |
175 | raise OperationFailed |
176 | - logging.info("System is in master image now") |
177 | - |
178 | + |
179 | @contextlib.contextmanager |
180 | def _master_session(self): |
181 | """A session that can be used to run commands in the master image. |
182 | |
183 | === modified file 'lava_dispatcher/connection.py' |
184 | --- lava_dispatcher/connection.py 2012-01-12 23:08:03 +0000 |
185 | +++ lava_dispatcher/connection.py 2012-02-07 19:21:18 +0000 |
186 | @@ -82,13 +82,13 @@ |
187 | self.sendline("") |
188 | |
189 | def soft_reboot(self): |
190 | + logging.info("Perform soft reboot the system") |
191 | cmd = self.device_option("soft_boot_cmd") |
192 | if cmd != "": |
193 | self.sendline(cmd) |
194 | else: |
195 | self.sendline("reboot") |
196 | # set soft reboot timeout 120s, or do a hard reset |
197 | - logging.info("Rebooting the system") |
198 | id = self.expect( |
199 | ['Restarting system.', 'The system is going down for reboot NOW', |
200 | 'Will now restart', pexpect.TIMEOUT], timeout=120) |
201 | |
202 | === modified file 'lava_dispatcher/job.py' |
203 | --- lava_dispatcher/job.py 2012-02-02 11:01:31 +0000 |
204 | +++ lava_dispatcher/job.py 2012-02-07 19:21:18 +0000 |
205 | @@ -67,6 +67,9 @@ |
206 | 'type': 'integer', |
207 | 'optional': False, |
208 | }, |
209 | + 'logging_level': { |
210 | + 'optional': True, |
211 | + }, |
212 | }, |
213 | } |
214 | |
215 | @@ -85,6 +88,13 @@ |
216 | return self.job_data['target'] |
217 | |
218 | @property |
219 | + def logging_level(self): |
220 | + try: |
221 | + return self.job_data['logging_level'] |
222 | + except : |
223 | + return None |
224 | + |
225 | + @property |
226 | def image_type(self): |
227 | return self.job_data.get('image_type') |
228 | |
229 | @@ -101,6 +111,7 @@ |
230 | |
231 | def run(self): |
232 | self.validate() |
233 | + self._set_logging_level() |
234 | lava_commands = get_all_cmds() |
235 | |
236 | if self.job_data['actions'][-1]['command'].startswith("submit_results"): |
237 | @@ -119,6 +130,7 @@ |
238 | try: |
239 | for cmd in self.job_data['actions']: |
240 | params = cmd.get('parameters', {}) |
241 | + logging.info("[ACTION-B] Command %s is started with parameters %s." % (cmd['command'],params)) |
242 | metadata = cmd.get('metadata', {}) |
243 | self.context.test_data.add_metadata(metadata) |
244 | action = lava_commands[cmd['command']](self.context) |
245 | @@ -135,8 +147,8 @@ |
246 | status = 'pass' |
247 | finally: |
248 | err_msg = "" |
249 | - logging.info("Action %s finished." % cmd['command']) |
250 | if status == 'fail': |
251 | + logging.warning("[ACTION-E] %s is finished with error (%s)." %(cmd['command'], err)) |
252 | err_msg = "Lava failed at action %s with error: %s\n" %\ |
253 | (cmd['command'], unicode(str(err), 'ascii', 'replace')) |
254 | if cmd['command'] == 'lava_test_run': |
255 | @@ -146,6 +158,7 @@ |
256 | # output to both serial log and logfile |
257 | self.context.client.sio.write(err_msg) |
258 | else: |
259 | + logging.info("[ACTION-E] %s is finished successfully." %cmd['command']) |
260 | err_msg = "" |
261 | self.context.test_data.add_result( |
262 | action.test_name(**params), status, err_msg) |
263 | @@ -159,3 +172,21 @@ |
264 | action = lava_commands[submit_results['command']]( |
265 | self.context) |
266 | action.run(**params) |
267 | + |
268 | + def _set_logging_level(self): |
269 | + # set logging level is optional |
270 | + level = self.logging_level |
271 | + # CRITICAL, ERROR, WARNING, INFO or DEBUG |
272 | + if level: |
273 | + if level == 'DEBUG': |
274 | + logging.root.setLevel(logging.DEBUG) |
275 | + elif level == 'INFO': |
276 | + logging.root.setLevel(logging.INFO) |
277 | + elif level == 'WARNING': |
278 | + logging.root.setLevel(logging.WARNING) |
279 | + elif level == 'ERROR': |
280 | + logging.root.setLevel(logging.ERROR) |
281 | + elif level == 'CRITICAL': |
282 | + logging.root.setLevel(logging.CRITICAL) |
283 | + else: |
284 | + logging.warning("Unknown logging level in the job '%s'. Allow level are : CRITICAL, ERROR, WARNING, INFO or DEBUG" %level) |
285 | |
286 | === modified file 'lava_dispatcher/utils.py' |
287 | --- lava_dispatcher/utils.py 2012-01-26 10:11:27 +0000 |
288 | +++ lava_dispatcher/utils.py 2012-02-07 19:21:18 +0000 |
289 | @@ -55,9 +55,9 @@ |
290 | if err.errno == errno.EXDEV: |
291 | shutil.copy(cache_loc, file_location) |
292 | if err.errno == errno.EEXIST: |
293 | - logging.info("Cached copy of %s already exists" % url) |
294 | + logging.debug("Cached copy of %s already exists" % url) |
295 | else: |
296 | - logging.exception("os.link failed") |
297 | + logging.exception("os.link '%s' with '%s' failed"%(cache_loc,file_location)) |
298 | else: |
299 | file_location = download(url, path) |
300 | try: |
301 | @@ -70,7 +70,7 @@ |
302 | if err.errno == errno.EXDEV: |
303 | shutil.copy(file_location, cache_loc) |
304 | if err.errno == errno.EEXIST: |
305 | - logging.info("Cached copy of %s already exists" % url) |
306 | + logging.debug("Cached copy of %s already exists" % url) |
307 | else: |
308 | logging.exception("os.link failed") |
309 | return file_location |
310 | @@ -90,6 +90,6 @@ |
311 | return map(strip_newlines, list(splitter)) |
312 | |
313 | def logging_system(cmd): |
314 | - logging.info('executing %r'%cmd) |
315 | + logging.debug("Executing on host : '%r'"%cmd) |
316 | return os.system(cmd) |
317 |
the logging level has been set in lava-dispatcher /lava-dispatch with the default value specified in lava-dispatcher .conf.
is it necessary that we change that to use the value specified in job file, and delete the _set_logging_level method?