summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorGeorgy Redkozubov <georgy.redkozubov@linaro.org>2015-03-25 11:09:11 (GMT)
committerNeil Williams <neil.williams@linaro.org>2015-03-25 11:36:43 (GMT)
commitb710079672ae480bcbf36d6c237c8d06770fde92 (patch)
tree3453cdf3d88c2426bcaedbc28d6da184fa417961
parent0364e0a6008fdc5f0271273ea8ed9fe6c3a9933f (diff)
downloadlava-dispatcher-b710079672ae480bcbf36d6c237c8d06770fde92.tar.gz
lava-dispatcher-b710079672ae480bcbf36d6c237c8d06770fde92.tar.xz
Use different logging levels for messages from Pipeline.
Implements LAVA-1930 (https://cards.linaro.org/browse/LAVA-1930) Change-Id: I6c23f25e08bf5f1a5a07762c50e8a14af27fa597
-rw-r--r--lava_dispatcher/pipeline/action.py18
-rw-r--r--lava_dispatcher/pipeline/actions/boot/qemu.py2
-rw-r--r--lava_dispatcher/pipeline/actions/deploy/download.py12
-rw-r--r--lava_dispatcher/pipeline/actions/deploy/overlay.py2
-rw-r--r--lava_dispatcher/pipeline/actions/deploy/removable.py2
-rw-r--r--lava_dispatcher/pipeline/actions/deploy/testdef.py4
-rw-r--r--lava_dispatcher/pipeline/actions/test/multinode.py2
-rw-r--r--lava_dispatcher/pipeline/actions/test/shell.py12
-rw-r--r--lava_dispatcher/pipeline/logical.py4
-rw-r--r--lava_dispatcher/pipeline/power.py7
-rw-r--r--lava_dispatcher/pipeline/protocols/multinode.py6
-rw-r--r--lava_dispatcher/pipeline/shell.py2
-rw-r--r--lava_dispatcher/pipeline/utils/shell.py2
-rw-r--r--lava_dispatcher/pipeline/utils/vcs.py4
14 files changed, 44 insertions, 35 deletions
diff --git a/lava_dispatcher/pipeline/action.py b/lava_dispatcher/pipeline/action.py
index eca842a..5bc5a72 100644
--- a/lava_dispatcher/pipeline/action.py
+++ b/lava_dispatcher/pipeline/action.py
@@ -259,7 +259,7 @@ class Pipeline(object): # pylint: disable=too-many-instance-attributes
pipeline and allow cleanup actions to happen on all actions,
not just the ones directly related to the currently running action.
"""
- self.logger.debug("Cancelled")
+ self.logger.info("Cancelled")
self.cleanup_actions(None, "Cancelled")
signal.signal(signal.SIGINT, signal.default_int_handler)
raise KeyboardInterrupt
@@ -284,7 +284,11 @@ class Pipeline(object): # pylint: disable=too-many-instance-attributes
# The ci-test does not set the default logging class
if isinstance(action.logger, YAMLLogger):
action.logger.setMetadata(action.level, action.name)
- action.logger.debug('start: %s %s (max %ds)' % (action.level, action.name, action.timeout.duration))
+ msg = 'start: %s %s (max %ds)' % (action.level, action.name, action.timeout.duration)
+ if self.parent is None:
+ action.logger.info(msg)
+ else:
+ action.logger.debug(msg)
try:
if not self.parent:
signal.signal(signal.SIGINT, cancelling_handler)
@@ -300,7 +304,11 @@ class Pipeline(object): # pylint: disable=too-many-instance-attributes
action.logger.exception(exc)
raise RuntimeError(exc)
action.elapsed_time = time.time() - start
- action.logger.debug("%s duration: %.02f" % (action.name, action.elapsed_time))
+ msg = "%s duration: %.02f" % (action.name, action.elapsed_time)
+ if self.parent is None:
+ action.logger.info(msg)
+ else:
+ action.logger.debug(msg)
if action.results:
action.logger.debug({"results": action.results})
if new_connection:
@@ -548,10 +556,10 @@ class Action(object): # pylint: disable=too-many-instance-attributes
try:
log = subprocess.check_output(command_list, stderr=subprocess.STDOUT)
except OSError as exc:
- self.logger.debug({exc.strerror: exc.child_traceback.split('\n')})
+ self.logger.exception({exc.strerror: exc.child_traceback.split('\n')})
except subprocess.CalledProcessError as exc:
self.errors = exc.message
- self.logger.debug({
+ self.logger.exception({
'command': [i.strip() for i in exc.cmd],
'message': [i.strip() for i in exc.message],
'output': exc.output.split('\n')})
diff --git a/lava_dispatcher/pipeline/actions/boot/qemu.py b/lava_dispatcher/pipeline/actions/boot/qemu.py
index f05ea45..51b66d1 100644
--- a/lava_dispatcher/pipeline/actions/boot/qemu.py
+++ b/lava_dispatcher/pipeline/actions/boot/qemu.py
@@ -134,7 +134,7 @@ class CallQemuAction(Action):
raise RuntimeError("No image file setting from the download_action")
command = self.get_common_data('qemu-command', 'command')
command.extend(["-hda", self.data['download_action']['image']['file']])
- self.logger.debug("Boot command: %s" % ' '.join(command))
+ self.logger.info("Boot command: %s" % ' '.join(command))
# initialise the first Connection object, a command line shell into the running QEMU.
shell = ShellCommand(' '.join(command), self.timeout)
diff --git a/lava_dispatcher/pipeline/actions/deploy/download.py b/lava_dispatcher/pipeline/actions/deploy/download.py
index 6136a56..e525f0f 100644
--- a/lava_dispatcher/pipeline/actions/deploy/download.py
+++ b/lava_dispatcher/pipeline/actions/deploy/download.py
@@ -181,7 +181,7 @@ class DownloadHandler(Action): # pylint: disable=too-many-instance-attributes
md5 = hashlib.md5()
sha256 = hashlib.sha256()
with self._decompressor_stream() as (writer, fname):
- self.logger.debug("downloading %s as %s" % (self.parameters[self.key], fname))
+ self.logger.info("downloading %s as %s" % (self.parameters[self.key], fname))
downloaded_size = 0
beginning = time.time()
@@ -208,9 +208,9 @@ class DownloadHandler(Action): # pylint: disable=too-many-instance-attributes
# Log the download speed
ending = time.time()
- self.logger.debug("%dMB downloaded in %0.2fs (%0.2fMB/s)" %
- (downloaded_size / (1024 * 1024), round(ending - beginning, 2),
- round(downloaded_size / (1024 * 1024 * (ending - beginning)), 2)))
+ self.logger.info("%dMB downloaded in %0.2fs (%0.2fMB/s)" %
+ (downloaded_size / (1024 * 1024), round(ending - beginning, 2),
+ round(downloaded_size / (1024 * 1024 * (ending - beginning)), 2)))
# set the dynamic data into the context
self.data['download_action'][self.key] = {
@@ -224,8 +224,8 @@ class DownloadHandler(Action): # pylint: disable=too-many-instance-attributes
self.set_common_data('file', self.key, os.path.join(suffix, os.path.basename(fname)))
else:
self.set_common_data('file', self.key, fname)
- self.logger.debug("md5sum of downloaded content: %s" % (md5.hexdigest()))
- self.logger.debug("sha256sum of downloaded content: %s" % (sha256.hexdigest()))
+ self.logger.info("md5sum of downloaded content: %s" % (md5.hexdigest()))
+ self.logger.info("sha256sum of downloaded content: %s" % (sha256.hexdigest()))
return connection
diff --git a/lava_dispatcher/pipeline/actions/deploy/overlay.py b/lava_dispatcher/pipeline/actions/deploy/overlay.py
index a68c3e8..467185e 100644
--- a/lava_dispatcher/pipeline/actions/deploy/overlay.py
+++ b/lava_dispatcher/pipeline/actions/deploy/overlay.py
@@ -221,7 +221,7 @@ class CompressOverlay(Action):
if not os.path.exists(self.data['lava-overlay']['location']):
raise RuntimeError("Unable to find overlay location")
if not self.valid:
- self.logger.debug(self.errors)
+ self.logger.error(self.errors)
return connection
connection = super(CompressOverlay, self).run(connection, args)
location = self.data['lava-overlay']['location']
diff --git a/lava_dispatcher/pipeline/actions/deploy/removable.py b/lava_dispatcher/pipeline/actions/deploy/removable.py
index 82af4f0..23603ca 100644
--- a/lava_dispatcher/pipeline/actions/deploy/removable.py
+++ b/lava_dispatcher/pipeline/actions/deploy/removable.py
@@ -156,7 +156,7 @@ class DDAction(Action):
# connection.wait() # long command lines can echo back
# connection.wait()
if not self.valid:
- self.logger.debug(self.errors)
+ self.logger.error(self.errors)
return connection
diff --git a/lava_dispatcher/pipeline/actions/deploy/testdef.py b/lava_dispatcher/pipeline/actions/deploy/testdef.py
index 53b94dc..9a8be1a 100644
--- a/lava_dispatcher/pipeline/actions/deploy/testdef.py
+++ b/lava_dispatcher/pipeline/actions/deploy/testdef.py
@@ -480,7 +480,7 @@ class UrlRepoAction(RepoAction): # pylint: disable=too-many-public-methods
except OSError as exc:
raise JobError('Unable to get test definition from url\n' + str(exc))
finally:
- self.logger.debug("Downloaded test definition file to %s." % runner_path)
+ self.logger.info("Downloaded test definition file to %s." % runner_path)
i = []
for elem in " $&()\"'<>/\\|;`":
@@ -600,7 +600,7 @@ class TestDefinitionAction(TestAction):
"""
if 'location' not in self.data['lava-overlay']:
raise RuntimeError("Missing lava overlay location")
- self.logger.debug("Loading test definitions")
+ self.logger.info("Loading test definitions")
# overlay_path is the location of the files before boot
self.data[self.name]['overlay_dir'] = os.path.abspath(
diff --git a/lava_dispatcher/pipeline/actions/test/multinode.py b/lava_dispatcher/pipeline/actions/test/multinode.py
index 017d910..c3fed95 100644
--- a/lava_dispatcher/pipeline/actions/test/multinode.py
+++ b/lava_dispatcher/pipeline/actions/test/multinode.py
@@ -88,7 +88,7 @@ class MultinodeTestAction(TestShellAction):
try:
ret = self.signal_director.signal(name, params)
except JobError as exc:
- self.logger.debug("Job error in %s signal: %s %s" % (event, exc, name))
+ self.logger.exception("Job error in %s signal: %s %s" % (event, exc, name))
return False
return ret
return ret
diff --git a/lava_dispatcher/pipeline/actions/test/shell.py b/lava_dispatcher/pipeline/actions/test/shell.py
index 7000ca9..1b7019f 100644
--- a/lava_dispatcher/pipeline/actions/test/shell.py
+++ b/lava_dispatcher/pipeline/actions/test/shell.py
@@ -105,7 +105,7 @@ class TestShellAction(TestAction):
self.signal_director.connection = connection
- self.logger.debug("Executing test definitions using %s" % connection.name)
+ self.logger.info("Executing test definitions using %s" % connection.name)
self.logger.debug("Setting default test shell prompt")
connection.prompt_str = self.job.device['test_image_prompts']
self.logger.debug("Setting default timeout: %s" % self.timeout.duration)
@@ -148,18 +148,18 @@ class TestShellAction(TestAction):
Call from subclasses before checking subclass-specific events.
"""
if event == 'exit':
- self.logger.debug('ok: lava_test_shell seems to have completed')
+ self.logger.info('ok: lava_test_shell seems to have completed')
return False
elif event == 'eof':
- self.logger.debug('err: lava_test_shell connection dropped')
+ self.logger.warning('err: lava_test_shell connection dropped')
self.errors = 'lava_test_shell connection dropped'
return False
elif event == 'timeout':
# if target.is_booted():
# target.reset_boot()
- self.logger.debug('err: lava_test_shell has timed out')
+ self.logger.warning('err: lava_test_shell has timed out')
self.errors = 'lava_test_shell has timed out'
return False
@@ -197,7 +197,7 @@ class TestShellAction(TestAction):
if match is pexpect.TIMEOUT:
# if target.is_booted():
# target.reset_boot()
- self.logger.debug('err: lava_test_shell has timed out (test_case)')
+ self.logger.warning('err: lava_test_shell has timed out (test_case)')
else:
res = self.match.match(match.groupdict()) # FIXME: rename!
self.logger.debug('result: %s' % res)
@@ -247,7 +247,7 @@ class TestShellAction(TestAction):
except KeyboardInterrupt:
raise KeyboardInterrupt
except JobError:
- self.logger.debug("err: handling signal %s failed" % name)
+ self.logger.error("err: handling signal %s failed" % name)
return False
return True
diff --git a/lava_dispatcher/pipeline/logical.py b/lava_dispatcher/pipeline/logical.py
index 79004af..b8235bf 100644
--- a/lava_dispatcher/pipeline/logical.py
+++ b/lava_dispatcher/pipeline/logical.py
@@ -63,7 +63,7 @@ class RetryAction(Action):
self.retries += 1
self.errors = "%s failed: %d of %d attempts. '%s'" % (self.name, self.retries, self.max_retries, exc)
if self.timeout:
- self.logger.debug(" %s: timeout. %s seconds" % (self.timeout.name, int(self.timeout.duration)))
+ self.logger.warning(" %s: timeout. %s seconds" % (self.timeout.name, int(self.timeout.duration)))
time.sleep(self.sleep)
if not self.valid:
self.errors = "%s retries failed for %s" % (self.retries, self.name)
@@ -132,7 +132,7 @@ class AdjuvantAction(Action): # pylint: disable=abstract-class-not-used
return connection
if self.data[self.key()]:
self.adjuvant = True
- self.logger.debug("Adjuvant %s required" % self.name)
+ self.logger.warning("Adjuvant %s required" % self.name)
else:
self.logger.debug("Adjuvant %s skipped" % self.name)
return connection
diff --git a/lava_dispatcher/pipeline/power.py b/lava_dispatcher/pipeline/power.py
index c639b3f..d13ed07 100644
--- a/lava_dispatcher/pipeline/power.py
+++ b/lava_dispatcher/pipeline/power.py
@@ -79,7 +79,7 @@ class RebootDevice(Action):
try:
self.wait(connection)
except TestError:
- self.logger.debug("Wait for prompt after soft reboot failed")
+ self.logger.info("Wait for prompt after soft reboot failed")
self.results = {'status': "failed"}
self.data[PDUReboot.key()] = True
connection.prompt_str = self.reboot_prompt
@@ -203,8 +203,9 @@ class FinalizeAction(Action):
elif self.job.pipeline.errors:
self.results = {'status': "Incomplete"}
self.errors = "Incomplete"
- self.logger.debug("Status: Incomplete")
- self.logger.debug(self.job.pipeline.errors)
+ self.logger.error({
+ 'Status': 'Incomplete',
+ 'Errors': self.job.pipeline.errors})
else:
self.results = {'status': "Complete"}
self.logger.debug("Status: Complete")
diff --git a/lava_dispatcher/pipeline/protocols/multinode.py b/lava_dispatcher/pipeline/protocols/multinode.py
index cbc371d..2110b82 100644
--- a/lava_dispatcher/pipeline/protocols/multinode.py
+++ b/lava_dispatcher/pipeline/protocols/multinode.py
@@ -111,7 +111,7 @@ class MultinodeProtocol(Protocol):
self.sock.connect((self.settings['coordinator_hostname'], self.settings['port']))
return True
except socket.error as exc:
- self.logger.debug(
+ self.logger.exception(
"socket error on connect: %d %s %s" % (
exc.errno, self.settings['coordinator_hostname'], self.settings['port']))
time.sleep(delay)
@@ -131,7 +131,7 @@ class MultinodeProtocol(Protocol):
self.logger.debug("zero bytes sent for message - connection closed?")
return False
except socket.error as exc:
- self.logger.debug("socket error '%d' on send" % exc.message)
+ self.logger.exception("socket error '%d' on send" % exc.message)
self.sock.close()
return False
return True
@@ -149,7 +149,7 @@ class MultinodeProtocol(Protocol):
response += self.sock.recv(self.blocks)
recv_count += self.blocks
except socket.error as exc:
- self.logger.debug("socket error '%d' on response" % exc.errno)
+ self.logger.exception("socket error '%d' on response" % exc.errno)
self.sock.close()
return json.dumps({"response": "wait"})
return response
diff --git a/lava_dispatcher/pipeline/shell.py b/lava_dispatcher/pipeline/shell.py
index 8aa52ac..a8f7860 100644
--- a/lava_dispatcher/pipeline/shell.py
+++ b/lava_dispatcher/pipeline/shell.py
@@ -276,7 +276,7 @@ class ConnectDevice(Action):
connection.prompt_str = self.job.device['test_image_prompts']
return connection
command = self.job.device['commands']['connect']
- self.logger.debug("connecting to device using '%s'" % command)
+ self.logger.info("connecting to device using '%s'" % command)
signal.alarm(0) # clear the timeouts used without connections.
shell = ShellCommand("%s\n" % command, self.timeout)
if shell.exitstatus:
diff --git a/lava_dispatcher/pipeline/utils/shell.py b/lava_dispatcher/pipeline/utils/shell.py
index 41eefba..04db63b 100644
--- a/lava_dispatcher/pipeline/utils/shell.py
+++ b/lava_dispatcher/pipeline/utils/shell.py
@@ -57,7 +57,7 @@ def wait_for_prompt(connection, prompt_pattern, timeout):
except pexpect.TIMEOUT:
if prompt_wait_count < 6:
logger = logging.getLogger('dispatcher')
- logger.debug('Sending newline in case of corruption.')
+ logger.warning('Sending newline in case of corruption.')
prompt_wait_count += 1
partial_timeout = timeout / 10
connection.sendline('')
diff --git a/lava_dispatcher/pipeline/utils/vcs.py b/lava_dispatcher/pipeline/utils/vcs.py
index f4d17a0..1e66347 100644
--- a/lava_dispatcher/pipeline/utils/vcs.py
+++ b/lava_dispatcher/pipeline/utils/vcs.py
@@ -66,7 +66,7 @@ class BzrHelper(VCSHelper):
except subprocess.CalledProcessError as exc:
logger = logging.getLogger('dispatcher')
- logger.debug({
+ logger.exception({
'command': [i.strip() for i in exc.cmd],
'message': [i.strip() for i in exc.message],
'output': exc.output.split('\n')})
@@ -111,7 +111,7 @@ class GitHelper(VCSHelper):
stderr=subprocess.STDOUT).strip()
except subprocess.CalledProcessError as exc:
logger = logging.getLogger('dispatcher')
- logger.debug({
+ logger.exception({
'command': [i.strip() for i in exc.cmd],
'message': [i.strip() for i in exc.message],
'output': exc.output.split('\n')})