Merge lp:~javier.collado/utah/bug1162862 into lp:utah

[Javier Collado]

This change is intended to write to log:
- The pattern that matched (to make sure about what pattern of all the possible
  ones matched)
- The error message when a timeout happens (to get the timestamp of when that
  happened)

This is expected to make easier to troubleshoot timeout problems.

[Andy Doan (doanac)]

> === modified file 'utah/provisioning/rsyslog.py'
> --- utah/provisioning/rsyslog.py 2013-03-29 17:00:50 +0000
> +++ utah/provisioning/rsyslog.py 2013-04-01 16:25:27 +0000
> @@ -154,6 +154,9 @@
> msg = 'Expected pattern missed, matched future pattern: %s'
> self.logger.warn(msg, match)
> x = self._fast_forward(steps, match, callbacks)
> + else:
> + self.logger.info('Matched pattern {!r} for {!r} message'
> + .format(match, message))

make this:
  + self.logger.info('Matched pattern %s for %s message',
                                        match, message)

[Javier Collado (javier.collado)]

Is there any reason why you prefer string interpolation over `format`? I find
easier to use curly braces and forget about the type of what I want to print.

[Andy Doan (doanac)]

On 04/02/2013 06:09 AM, Javier Collado wrote:
> Is there any reason why you prefer string interpolation over `format`? I find
> easier to use curly braces and forget about the type of what I want to print.

more for the logging.debug case. when you do .format it always builds
the string to write, even if that level of debug isn't enabled.

[lp:~javier.collado/utah/bug1162862]

853. By Javier Collado on 2013-04-03

Avoid creating log message string depending on loglevel

[Javier Collado (javier.collado)]

I've never used that feature of the logging module, but indeed it makes sense.
Thanks for the explanation.

review: Needs Resubmitting

[Andy Doan (doanac)]

review: Approve

=== modified file 'debian/changelog'
--- debian/changelog	2013-04-02 12:35:07 +0000
+++ debian/changelog	2013-04-03 09:40:31 +0000
@@ -3,8 +3,12 @@
   * Return error code on unhandled error (LP: #1160857)
   * Remove temporary files downloaded based on URL (LP: #1101186)
   * Stop server on installation failure (LP: #1161855)
+<<<<<<< TREE
   * Check group after command line argument parsing (LP: #1126219)
   * Added INVALID_USER return code (LP: #1160032)
+=======
+  * Write syslog pattern matched and timeouts timestamps (LP: #1162862)
+>>>>>>> MERGE-SOURCE
 
  -- Javier Collado <[e-mail]>  Wed, 27 Mar 2013 13:00:47 +0100
 
 
=== modified file 'utah/provisioning/rsyslog.py'
--- utah/provisioning/rsyslog.py	2013-03-29 17:00:50 +0000
+++ utah/provisioning/rsyslog.py	2013-04-03 09:40:31 +0000
@@ -154,6 +154,9 @@
                     msg = 'Expected pattern missed, matched future pattern: %s'
                     self.logger.warn(msg, match)
                     x = self._fast_forward(steps, match, callbacks)
+                else:
+                    self.logger.info('Matched pattern %r for %r message',
+                                     match, message)
 
                 self._do_callback(steps[x], callbacks)
                 x += 1
@@ -213,7 +216,11 @@
                 for pat in pats:
                     if pat.match(data):
                         return pat.pattern
-        raise UTAHException('Timeout occurred for {}'.format(message))
+        log_message = ('Timeout ({}) occurred for {!r} message'
+                       .format(timeout, message))
+        # Log error message to write the timestamp when the timeout happened
+        self.logger.error(log_message)
+        raise UTAHException(log_message)
 
     def _read_udp(self):
         data = None