From 3a656eafb96ab8a474e943baabdb2679d0a6b0ef Mon Sep 17 00:00:00 2001 From: Ethan Jackson Date: Sat, 24 Sep 2011 17:53:30 -0700 Subject: [PATCH] python: Upgrade to vlog. This patch upgrades the library code in the python/ovs directory to the new vlog module. --- python/ovs/daemon.py | 32 +++++++++-------- python/ovs/db/idl.py | 72 +++++++++++++++++++------------------- python/ovs/fatal_signal.py | 7 ++-- python/ovs/jsonrpc.py | 23 ++++++------ python/ovs/poller.py | 10 +++--- python/ovs/reconnect.py | 36 ++++++++++--------- python/ovs/socket_util.py | 13 +++---- python/ovs/stream.py | 8 +++-- tests/test-daemon.py | 1 - tests/test-reconnect.py | 3 -- 10 files changed, 106 insertions(+), 99 deletions(-) diff --git a/python/ovs/daemon.py b/python/ovs/daemon.py index 864a1633d..85db050ca 100644 --- a/python/ovs/daemon.py +++ b/python/ovs/daemon.py @@ -14,7 +14,6 @@ import errno import fcntl -import logging import os import resource import signal @@ -28,6 +27,9 @@ import ovs.process import ovs.socket_util import ovs.timeval import ovs.util +import ovs.vlog + +vlog = ovs.vlog.Vlog("daemon") # --detach: Should we run in the background? _detach = False @@ -121,7 +123,7 @@ def set_monitor(): def _fatal(msg): - logging.error(msg) + vlog.err(msg) sys.stderr.write("%s\n" % msg) sys.exit(1) @@ -306,13 +308,13 @@ def _monitor_daemon(daemon_pid): try: resource.setrlimit(resource.RLIMIT_CORE, (0, 0)) except resource.error: - logging.warning("failed to disable core dumps") + vlog.warn("failed to disable core dumps") # Throttle restarts to no more than once every 10 seconds. if (last_restart is not None and ovs.timeval.msec() < last_restart + 10000): - logging.warning("%s, waiting until 10 seconds since last " - "restart" % status_msg) + vlog.warn("%s, waiting until 10 seconds since last " + "restart" % status_msg) while True: now = ovs.timeval.msec() wakeup = last_restart + 10000 @@ -322,12 +324,12 @@ def _monitor_daemon(daemon_pid): time.sleep((wakeup - now) / 1000.0) last_restart = ovs.timeval.msec() - logging.error("%s, restarting" % status_msg) + vlog.err("%s, restarting" % status_msg) daemon_pid = _fork_and_wait_for_startup() if not daemon_pid: break else: - logging.info("%s, exiting" % status_msg) + vlog.info("%s, exiting" % status_msg) sys.exit(0) # Running in new daemon process. @@ -411,7 +413,7 @@ def __read_pidfile(pidfile, delete_if_stale): except IOError, e: if e.errno == errno.ENOENT and delete_if_stale: return 0 - logging.warning("%s: open: %s" % (pidfile, e.strerror)) + vlog.warn("%s: open: %s" % (pidfile, e.strerror)) return -e.errno # Python fcntl doesn't directly support F_GETLK so we have to just try @@ -422,7 +424,7 @@ def __read_pidfile(pidfile, delete_if_stale): # pidfile exists but wasn't locked by anyone. Now we have the lock. if not delete_if_stale: file_handle.close() - logging.warning("%s: pid file is stale" % pidfile) + vlog.warn("%s: pid file is stale" % pidfile) return -errno.ESRCH # Is the file we have locked still named 'pidfile'? @@ -435,23 +437,23 @@ def __read_pidfile(pidfile, delete_if_stale): except IOError: raced = True if raced: - logging.warning("%s: lost race to delete pidfile" % pidfile) + vlog.warn("%s: lost race to delete pidfile" % pidfile) return -errno.EALREADY # We won the right to delete the stale pidfile. try: os.unlink(pidfile) except IOError, e: - logging.warning("%s: failed to delete stale pidfile (%s)" + vlog.warn("%s: failed to delete stale pidfile (%s)" % (pidfile, e.strerror)) return -e.errno else: - logging.debug("%s: deleted stale pidfile" % pidfile) + vlog.dbg("%s: deleted stale pidfile" % pidfile) file_handle.close() return 0 except IOError, e: if e.errno not in [errno.EACCES, errno.EAGAIN]: - logging.warn("%s: fcntl: %s" % (pidfile, e.strerror)) + vlog.warn("%s: fcntl: %s" % (pidfile, e.strerror)) return -e.errno # Someone else has the pidfile locked. @@ -459,10 +461,10 @@ def __read_pidfile(pidfile, delete_if_stale): try: error = int(file_handle.readline()) except IOError, e: - logging.warning("%s: read: %s" % (pidfile, e.strerror)) + vlog.warn("%s: read: %s" % (pidfile, e.strerror)) error = -e.errno except ValueError: - logging.warning("%s does not contain a pid" % pidfile) + vlog.warn("%s does not contain a pid" % pidfile) error = -errno.EINVAL return error diff --git a/python/ovs/db/idl.py b/python/ovs/db/idl.py index a06e9ec12..cd72fe4de 100644 --- a/python/ovs/db/idl.py +++ b/python/ovs/db/idl.py @@ -12,7 +12,6 @@ # See the License for the specific language governing permissions and # limitations under the License. -import logging import uuid import ovs.jsonrpc @@ -21,6 +20,9 @@ import ovs.db.schema from ovs.db import error import ovs.ovsuuid import ovs.poller +import ovs.vlog + +vlog = ovs.vlog.Vlog("idl") __pychecker__ = 'no-classattr no-objattrs' @@ -173,8 +175,8 @@ class Idl: self.__clear() self.__parse_update(msg.result) except error.Error, e: - logging.error("%s: parse error in received schema: %s" - % (self._session.get_name(), e)) + vlog.err("%s: parse error in received schema: %s" + % (self._session.get_name(), e)) self.__error() elif (msg.type == ovs.jsonrpc.Message.T_REPLY and self._lock_request_id is not None @@ -200,9 +202,9 @@ class Idl: else: # This can happen if a transaction is destroyed before we # receive the reply, so keep the log level low. - logging.debug("%s: received unexpected %s message" - % (self._session.get_name(), - ovs.jsonrpc.Message.type_to_string(msg.type))) + vlog.dbg("%s: received unexpected %s message" + % (self._session.get_name(), + ovs.jsonrpc.Message.type_to_string(msg.type))) return initial_change_seqno != self.change_seqno @@ -319,8 +321,8 @@ class Idl: try: self.__do_parse_update(update) except error.Error, e: - logging.error("%s: error parsing update: %s" - % (self._session.get_name(), e)) + vlog.err("%s: error parsing update: %s" + % (self._session.get_name(), e)) def __do_parse_update(self, table_updates): if type(table_updates) != dict: @@ -374,8 +376,8 @@ class Idl: changed = True else: # XXX rate-limit - logging.warning("cannot delete missing row %s from table %s" - % (uuid, table.name)) + vlog.warn("cannot delete missing row %s from table %s" + % (uuid, table.name)) elif not old: # Insert row. if not row: @@ -383,8 +385,8 @@ class Idl: changed = True else: # XXX rate-limit - logging.warning("cannot add existing row %s to table %s" - % (uuid, table.name)) + vlog.warn("cannot add existing row %s to table %s" + % (uuid, table.name)) if self.__row_update(table, row, new): changed = True else: @@ -392,8 +394,8 @@ class Idl: row = self.__create_row(table, uuid) changed = True # XXX rate-limit - logging.warning("cannot modify missing row %s in table %s" - % (uuid, table.name)) + vlog.warn("cannot modify missing row %s in table %s" + % (uuid, table.name)) if self.__row_update(table, row, new): changed = True return changed @@ -404,16 +406,16 @@ class Idl: column = table.columns.get(column_name) if not column: # XXX rate-limit - logging.warning("unknown column %s updating table %s" - % (column_name, table.name)) + vlog.warn("unknown column %s updating table %s" + % (column_name, table.name)) continue try: datum = ovs.db.data.Datum.from_json(column.type, datum_json) except error.Error, e: # XXX rate-limit - logging.warning("error parsing column %s in table %s: %s" - % (column_name, table.name, e)) + vlog.warn("error parsing column %s in table %s: %s" + % (column_name, table.name, e)) continue if datum != row._data[column_name]: @@ -548,8 +550,8 @@ class Row(object): _row_to_uuid) except error.Error, e: # XXX rate-limit - logging.error("attempting to write bad value to column %s (%s)" - % (column_name, e)) + vlog.err("attempting to write bad value to column %s (%s)" + % (column_name, e)) return self._idl.txn._write(self, column, datum) @@ -936,7 +938,7 @@ class Transaction(object): self._status = Transaction.ERROR elif type(msg.result) not in (list, tuple): # XXX rate-limit - logging.warning('reply to "transact" is not JSON array') + vlog.warn('reply to "transact" is not JSON array') else: hard_errors = False soft_errors = False @@ -965,8 +967,7 @@ class Transaction(object): hard_errors = True self.__set_error_json(op) # XXX rate-limit - logging.warning("operation reply is not JSON null or " - "object") + vlog.warn("operation reply is not JSON null or object") if not soft_errors and not hard_errors and not lock_errors: if self._inc_table and not self.__process_inc_reply(ops): @@ -989,11 +990,11 @@ class Transaction(object): def __check_json_type(json, types, name): if not json: # XXX rate-limit - logging.warning("%s is missing" % name) + vlog.warn("%s is missing" % name) return False elif type(json) not in types: # XXX rate-limit - logging.warning("%s has unexpected type %s" % (name, type(json))) + vlog.warn("%s has unexpected type %s" % (name, type(json))) return False else: return True @@ -1001,9 +1002,9 @@ class Transaction(object): def __process_inc_reply(self, ops): if self._inc_index + 2 > len(ops): # XXX rate-limit - logging.warning("reply does not contain enough operations for " - "increment (has %d, needs %d)" % - (len(ops), self._inc_index + 2)) + vlog.warn("reply does not contain enough operations for " + "increment (has %d, needs %d)" % + (len(ops), self._inc_index + 2)) # We know that this is a JSON object because the loop in # __process_reply() already checked. @@ -1014,8 +1015,7 @@ class Transaction(object): return False if count != 1: # XXX rate-limit - logging.warning('"mutate" reply "count" is %d instead of 1' - % count) + vlog.warn('"mutate" reply "count" is %d instead of 1' % count) return False select = ops[self._inc_index + 1] @@ -1025,8 +1025,8 @@ class Transaction(object): return False if len(rows) != 1: # XXX rate-limit - logging.warning('"select" reply "rows" has %d elements ' - 'instead of 1' % len(rows)) + vlog.warn('"select" reply "rows" has %d elements ' + 'instead of 1' % len(rows)) return False row = rows[0] if not Transaction.__check_json_type(row, (dict,), @@ -1042,9 +1042,9 @@ class Transaction(object): def __process_insert_reply(self, insert, ops): if insert.op_index >= len(ops): # XXX rate-limit - logging.warning("reply does not contain enough operations " - "for insert (has %d, needs %d)" - % (len(ops), insert.op_index)) + vlog.warn("reply does not contain enough operations " + "for insert (has %d, needs %d)" + % (len(ops), insert.op_index)) return False # We know that this is a JSON object because the loop in @@ -1059,7 +1059,7 @@ class Transaction(object): uuid_ = ovs.ovsuuid.from_json(json_uuid) except error.Error: # XXX rate-limit - logging.warning('"insert" reply "uuid" is not a JSON UUID') + vlog.warn('"insert" reply "uuid" is not a JSON UUID') return False insert.real = uuid_ diff --git a/python/ovs/fatal_signal.py b/python/ovs/fatal_signal.py index f2edc8598..dd989a097 100644 --- a/python/ovs/fatal_signal.py +++ b/python/ovs/fatal_signal.py @@ -13,11 +13,13 @@ # limitations under the License. import atexit -import logging import os import signal +import ovs.vlog + _hooks = [] +vlog = ovs.vlog.Vlog("fatal-signal") def add_hook(hook, cancel, run_at_exit): @@ -67,8 +69,7 @@ def unlink_file_now(file): Returns 0 if successful, otherwise a positive errno value.""" error = _unlink(file) if error: - logging.warning("could not unlink \"%s\" (%s)" - % (file, os.strerror(error))) + vlog.warn("could not unlink \"%s\" (%s)" % (file, os.strerror(error))) remove_file_to_unlink(file) return error diff --git a/python/ovs/jsonrpc.py b/python/ovs/jsonrpc.py index a7b69c590..25b022918 100644 --- a/python/ovs/jsonrpc.py +++ b/python/ovs/jsonrpc.py @@ -13,7 +13,6 @@ # limitations under the License. import errno -import logging import os import ovs.json @@ -21,8 +20,10 @@ import ovs.poller import ovs.reconnect import ovs.stream import ovs.timeval +import ovs.vlog EOF = -1 +vlog = ovs.vlog.Vlog("jsonrpc") class Message(object): @@ -199,8 +200,8 @@ class Connection(object): self.output = self.output[retval:] else: if retval != -errno.EAGAIN: - logging.warn("%s: send error: %s" % (self.name, - os.strerror(-retval))) + vlog.warn("%s: send error: %s" % + (self.name, os.strerror(-retval))) self.error(-retval) break @@ -220,7 +221,7 @@ class Connection(object): return len(self.output) def __log_msg(self, title, msg): - logging.debug("%s: %s %s" % (self.name, title, msg)) + vlog.dbg("%s: %s %s" % (self.name, title, msg)) def send(self, msg): if self.status: @@ -260,8 +261,8 @@ class Connection(object): return error, None else: # XXX rate-limit - logging.warning("%s: receive error: %s" - % (self.name, os.strerror(error))) + vlog.warn("%s: receive error: %s" + % (self.name, os.strerror(error))) self.error(error) return self.status, None elif not data: @@ -309,15 +310,15 @@ class Connection(object): self.parser = None if type(json) in [str, unicode]: # XXX rate-limit - logging.warning("%s: error parsing stream: %s" % (self.name, json)) + vlog.warn("%s: error parsing stream: %s" % (self.name, json)) self.error(errno.EPROTO) return msg = Message.from_json(json) if not isinstance(msg, Message): # XXX rate-limit - logging.warning("%s: received bad JSON-RPC message: %s" - % (self.name, msg)) + vlog.warn("%s: received bad JSON-RPC message: %s" + % (self.name, msg)) self.error(errno.EPROTO) return @@ -425,8 +426,8 @@ class Session(object): if error == 0: if self.rpc or self.stream: # XXX rate-limit - logging.info("%s: new connection replacing active " - "connection" % self.reconnect.get_name()) + vlog.info("%s: new connection replacing active " + "connection" % self.reconnect.get_name()) self.__disconnect() self.reconnect.connected(ovs.timeval.msec()) self.rpc = Connection(stream) diff --git a/python/ovs/poller.py b/python/ovs/poller.py index aea35460a..8d52d32b2 100644 --- a/python/ovs/poller.py +++ b/python/ovs/poller.py @@ -13,9 +13,11 @@ # limitations under the License. import errno -import logging import select import ovs.timeval +import ovs.vlog + +vlog = ovs.vlog.Vlog("poller") class Poller(object): @@ -96,13 +98,13 @@ class Poller(object): # XXX rate-limit error, msg = e if error != errno.EINTR: - logging.error("poll: %s" % e[1]) + vlog.err("poll: %s" % e[1]) finally: self.__reset() def __log_wakeup(self, events): if not events: - logging.debug("%d-ms timeout" % self.timeout) + vlog.dbg("%d-ms timeout" % self.timeout) else: for fd, revents in events: if revents != 0: @@ -117,7 +119,7 @@ class Poller(object): s += "[POLLHUP]" if revents & select.POLLNVAL: s += "[POLLNVAL]" - logging.debug("%s on fd %d" % (s, fd)) + vlog.dbg("%s on fd %d" % (s, fd)) def __reset(self): self.poll = select.poll() diff --git a/python/ovs/reconnect.py b/python/ovs/reconnect.py index f34214381..a6ecc39b3 100644 --- a/python/ovs/reconnect.py +++ b/python/ovs/reconnect.py @@ -12,15 +12,17 @@ # See the License for the specific language governing permissions and # limitations under the License. -import logging import os +import ovs.vlog + # Values returned by Reconnect.run() CONNECT = 'connect' DISCONNECT = 'disconnect' PROBE = 'probe' EOF = -1 +vlog = ovs.vlog.Vlog("reconnect") class Reconnect(object): @@ -97,9 +99,9 @@ class Reconnect(object): @staticmethod def run(fsm, now): - logging.debug("%s: idle %d ms, sending inactivity probe" - % (fsm.name, - now - max(fsm.last_received, fsm.state_entered))) + vlog.dbg("%s: idle %d ms, sending inactivity probe" + % (fsm.name, + now - max(fsm.last_received, fsm.state_entered))) fsm._transition(now, Reconnect.Idle) return PROBE @@ -113,9 +115,9 @@ class Reconnect(object): @staticmethod def run(fsm, now): - logging.error("%s: no response to inactivity probe after %.3g " - "seconds, disconnecting" - % (fsm.name, (now - fsm.state_entered) / 1000.0)) + vlog.err("%s: no response to inactivity probe after %.3g " + "seconds, disconnecting" + % (fsm.name, (now - fsm.state_entered) / 1000.0)) return DISCONNECT class Reconnect(object): @@ -140,7 +142,7 @@ class Reconnect(object): self.max_backoff = 8000 self.probe_interval = 5000 self.passive = False - self.info_level = logging.info + self.info_level = vlog.info self.state = Reconnect.Void self.state_entered = now @@ -168,9 +170,9 @@ class Reconnect(object): This setting has no effect on the log level of debugging, warning, or error messages.""" if quiet: - self.info_level = logging.debug + self.info_level = vlog.dbg else: - self.info_level = logging.info + self.info_level = vlog.info def get_name(self): return self.name @@ -318,8 +320,8 @@ class Reconnect(object): # Report what happened if self.state in (Reconnect.Active, Reconnect.Idle): if error > 0: - logging.warning("%s: connection dropped (%s)" - % (self.name, os.strerror(error))) + vlog.warn("%s: connection dropped (%s)" + % (self.name, os.strerror(error))) elif error == EOF: self.info_level("%s: connection closed by peer" % self.name) @@ -327,8 +329,8 @@ class Reconnect(object): self.info_level("%s: connection dropped" % self.name) elif self.state == Reconnect.Listening: if error > 0: - logging.warning("%s: error listening for connections (%s)" - % (self.name, os.strerror(error))) + vlog.warn("%s: error listening for connections (%s)" + % (self.name, os.strerror(error))) else: self.info_level("%s: error listening for connections" % self.name) @@ -338,8 +340,8 @@ class Reconnect(object): else: type_ = "connection" if error > 0: - logging.warning("%s: %s attempt failed (%s)" - % (self.name, type_, os.strerror(error))) + vlog.warn("%s: %s attempt failed (%s)" + % (self.name, type_, os.strerror(error))) else: self.info_level("%s: %s attempt timed out" % (self.name, type_)) @@ -459,7 +461,7 @@ class Reconnect(object): self.total_connected_duration += now - self.last_connected self.seqno += 1 - logging.debug("%s: entering %s" % (self.name, state.name)) + vlog.dbg("%s: entering %s" % (self.name, state.name)) self.state = state self.state_entered = now diff --git a/python/ovs/socket_util.py b/python/ovs/socket_util.py index 65fe94d18..83c82046e 100644 --- a/python/ovs/socket_util.py +++ b/python/ovs/socket_util.py @@ -13,13 +13,15 @@ # limitations under the License. import errno -import logging import os import select import socket import sys import ovs.fatal_signal +import ovs.vlog + +vlog = ovs.vlog.Vlog("socket_util") def make_unix_socket(style, nonblock, bind_path, connect_path): @@ -114,8 +116,7 @@ def get_null_fd(): try: null_fd = os.open("/dev/null", os.O_RDWR) except OSError, e: - logging.error("could not open /dev/null: %s" - % os.strerror(e.errno)) + vlog.err("could not open /dev/null: %s" % os.strerror(e.errno)) return -e.errno return null_fd @@ -135,7 +136,7 @@ def write_fully(fd, buf): if retval == len(buf): return 0, bytes_written + len(buf) elif retval == 0: - logging.warning("write returned 0") + vlog.warn("write returned 0") return errno.EPROTO, bytes_written else: bytes_written += retval @@ -148,5 +149,5 @@ def set_nonblocking(sock): try: sock.setblocking(0) except socket.error, e: - logging.error("could not set nonblocking mode on socket: %s" - % os.strerror(get_socket_error(e))) + vlog.err("could not set nonblocking mode on socket: %s" + % os.strerror(get_socket_error(e))) diff --git a/python/ovs/stream.py b/python/ovs/stream.py index 3bb0c10fd..7ea9e46e8 100644 --- a/python/ovs/stream.py +++ b/python/ovs/stream.py @@ -13,13 +13,15 @@ # limitations under the License. import errno -import logging import os import select import socket import ovs.poller import ovs.socket_util +import ovs.vlog + +vlog = ovs.vlog.Vlog("stream") class Stream(object): @@ -260,7 +262,7 @@ class PassiveStream(object): try: sock.listen(10) except socket.error, e: - logging.error("%s: listen: %s" % (name, os.strerror(e.error))) + vlog.err("%s: listen: %s" % (name, os.strerror(e.error))) sock.close() return e.error, None @@ -291,7 +293,7 @@ class PassiveStream(object): error = ovs.socket_util.get_exception_errno(e) if error != errno.EAGAIN: # XXX rate-limit - logging.debug("accept: %s" % os.strerror(error)) + vlog.dbg("accept: %s" % os.strerror(error)) return error, None def wait(self, poller): diff --git a/tests/test-daemon.py b/tests/test-daemon.py index a15068dd2..4fa07eabf 100644 --- a/tests/test-daemon.py +++ b/tests/test-daemon.py @@ -27,7 +27,6 @@ def handler(signum, _): def main(): - logging.basicConfig(level=logging.DEBUG) signal.signal(signal.SIGHUP, handler) diff --git a/tests/test-reconnect.py b/tests/test-reconnect.py index 90d337af3..5556ceeec 100644 --- a/tests/test-reconnect.py +++ b/tests/test-reconnect.py @@ -13,7 +13,6 @@ # limitations under the License. import errno -import logging import sys import ovs.reconnect @@ -177,8 +176,6 @@ def main(): "listen-error": do_listen_error } - logging.basicConfig(level=logging.CRITICAL) - global now global r -- 2.43.0