From: Ben Pfaff Date: Fri, 4 Jun 2010 20:49:25 +0000 (-0700) Subject: discovery: Include datapath name in log messages. X-Git-Tag: v1.1.0pre1~311 X-Git-Url: http://git.onelab.eu/?a=commitdiff_plain;h=c2e01f64e7ed6c0c0ae0a160daf3f2704f43bad8;p=sliver-openvswitch.git discovery: Include datapath name in log messages. This commit adds the datapath name to discovery and DHCP-related messages, so that it is obvious to the user where discovery is taking place. Previously, messages looked like: Jun 04 13:41:29|00010|dhcp_client|INFO|sending DHCPDISCOVER With this commit, they look like this: Jun 04 13:41:29|00010|dhcp_client|INFO|br0: sending DHCPDISCOVER I may be the only person in the world who regularly uses controller discovery. --- diff --git a/lib/dhcp-client.c b/lib/dhcp-client.c index 709d7a368..7168361f0 100644 --- a/lib/dhcp-client.c +++ b/lib/dhcp-client.c @@ -164,14 +164,14 @@ dhclient_create(const char *netdev_name, error = netdev_open(&netdev_options, &netdev); /* XXX install socket filter to catch only DHCP packets. */ if (error) { - VLOG_ERR("could not open %s network device: %s", + VLOG_ERR("%s: could not open network device: %s", netdev_name, strerror(error)); return error; } error = netdev_turn_flags_on(netdev, NETDEV_UP, false); if (error) { - VLOG_ERR("could not bring %s device up: %s", + VLOG_ERR("%s: could not bring device up: %s", netdev_name, strerror(error)); netdev_close(netdev); return error; @@ -226,6 +226,14 @@ dhclient_get_netdev(struct dhclient *cli) return cli->netdev; } +/* Returns the name of the network device in use by 'cli'. The caller must + * not modify or destroy the returned string. */ +const char * +dhclient_get_name(const struct dhclient *cli) +{ + return netdev_get_name(cli->netdev); +} + /* Forces 'cli' into a (re)initialization state, in which no address is bound * but the client is advertising to obtain one. If 'requested_ip' is nonzero, * then the client will attempt to re-bind to that IP address; otherwise, it @@ -402,6 +410,7 @@ dhclient_get_config(const struct dhclient *cli) int dhclient_configure_netdev(struct dhclient *cli) { + const char *cli_name = dhclient_get_name(cli); struct in_addr addr = { dhclient_get_ip(cli) }; struct in_addr mask = { dhclient_get_netmask(cli) }; struct in_addr router = { dhclient_get_router(cli) }; @@ -409,18 +418,16 @@ dhclient_configure_netdev(struct dhclient *cli) error = netdev_set_in4(cli->netdev, addr, mask); if (error) { - VLOG_ERR("could not set %s address "IP_FMT"/"IP_FMT": %s", - netdev_get_name(cli->netdev), - IP_ARGS(&addr.s_addr), IP_ARGS(&mask.s_addr), + VLOG_ERR("%s: could not set address "IP_FMT"/"IP_FMT" (%s)", + cli_name, IP_ARGS(&addr.s_addr), IP_ARGS(&mask.s_addr), strerror(error)); } if (!error && router.s_addr) { error = netdev_add_router(cli->netdev, router); if (error) { - VLOG_ERR("failed to add default route to "IP_FMT" on %s: %s", - IP_ARGS(&router), netdev_get_name(cli->netdev), - strerror(error)); + VLOG_ERR("%s: failed to add default route to "IP_FMT" (%s)", + cli_name, IP_ARGS(&router), strerror(error)); } } @@ -433,6 +440,7 @@ dhclient_configure_netdev(struct dhclient *cli) int dhclient_update_resolv_conf(struct dhclient *cli) { + const char *cli_name = dhclient_get_name(cli); uint32_t dns_server; char *domain_name; bool has_domain_name; @@ -444,14 +452,15 @@ dhclient_update_resolv_conf(struct dhclient *cli) return 0; } if (!dhcp_msg_get_ip(cli->binding, DHCP_CODE_DNS_SERVER, 0, &dns_server)) { - VLOG_DBG("binding does not include any DNS servers"); + VLOG_DBG("%s: binding does not include any DNS servers", cli_name); return 0; } sprintf(new_name, "/etc/resolv.conf.tmp%ld", (long int) getpid()); new = fopen(new_name, "w"); if (!new) { - VLOG_WARN("%s: create: %s", new_name, strerror(errno)); + VLOG_WARN("%s: could not create %s (%s)", + cli_name, new_name, strerror(errno)); return errno; } @@ -462,11 +471,12 @@ dhclient_update_resolv_conf(struct dhclient *cli) "ABCDEFGHIJKLMNOPQRSTUVWXYZ") == strlen(domain_name)) { fprintf(new, "domain %s\n", domain_name); } else { - VLOG_WARN("ignoring invalid domain name %s", domain_name); + VLOG_WARN("%s: ignoring invalid domain name %s", + cli_name, domain_name); has_domain_name = false; } } else { - VLOG_DBG("binding does not include domain name"); + VLOG_DBG("%s: binding does not include domain name", cli_name); } free(domain_name); @@ -490,17 +500,19 @@ dhclient_update_resolv_conf(struct dhclient *cli) } fclose(old); } else { - VLOG_DBG("/etc/resolv.conf: open: %s", strerror(errno)); + VLOG_DBG("%s: failed to open /etc/resolv.conf (%s)", + cli_name, strerror(errno)); } if (fclose(new) < 0) { - VLOG_WARN("%s: close: %s", new_name, strerror(errno)); + VLOG_WARN("%s: closing %s failed (%s)", + cli_name, new_name, strerror(errno)); return errno; } if (rename(new_name, "/etc/resolv.conf") < 0) { - VLOG_WARN("failed to rename %s to /etc/resolv.conf: %s", - new_name, strerror(errno)); + VLOG_WARN("%s: failed to rename %s to /etc/resolv.conf (%s)", + cli_name, new_name, strerror(errno)); return errno; } @@ -566,13 +578,16 @@ static bool dhcp_receive(struct dhclient *cli, unsigned int msgs, struct dhcp_msg *msg) { while (do_receive_msg(cli, msg)) { + const char *cli_name = dhclient_get_name(cli); + if (msg->type > 31 || !((1u << msg->type) & msgs)) { - VLOG_DBG_RL(&rl, "received unexpected %s in %s state: %s", + VLOG_DBG_RL(&rl, "%s: received unexpected %s in %s state: %s", + cli_name, dhcp_type_name(msg->type), state_name(cli->state), dhcp_msg_to_string(msg, false, &cli->s)); } else if (msg->xid != cli->xid) { - VLOG_DBG_RL(&rl, - "ignoring %s with xid != %08"PRIx32" in %s state: %s", + VLOG_DBG_RL(&rl, "%s: ignoring %s with xid != %08"PRIx32" " + "in %s state: %s", cli_name, dhcp_type_name(msg->type), msg->xid, state_name(cli->state), dhcp_msg_to_string(msg, false, &cli->s)); @@ -587,20 +602,25 @@ dhcp_receive(struct dhclient *cli, unsigned int msgs, struct dhcp_msg *msg) static bool validate_offered_options(struct dhclient *cli, const struct dhcp_msg *msg) { + const char *cli_name = dhclient_get_name(cli); uint32_t lease, netmask; + if (!dhcp_msg_get_secs(msg, DHCP_CODE_LEASE_TIME, 0, &lease)) { - VLOG_WARN_RL(&rl, "%s lacks lease time: %s", dhcp_type_name(msg->type), + VLOG_WARN_RL(&rl, "%s: %s lacks lease time (%s)", + cli_name, dhcp_type_name(msg->type), dhcp_msg_to_string(msg, false, &cli->s)); } else if (!dhcp_msg_get_ip(msg, DHCP_CODE_SUBNET_MASK, 0, &netmask)) { - VLOG_WARN_RL(&rl, "%s lacks netmask: %s", dhcp_type_name(msg->type), + VLOG_WARN_RL(&rl, "%s: %s lacks netmask (%s)", + cli_name, dhcp_type_name(msg->type), dhcp_msg_to_string(msg, false, &cli->s)); } else if (lease < MIN_ACCEPTABLE_LEASE) { - VLOG_WARN_RL(&rl, "Ignoring %s with %"PRIu32"-second lease time: %s", + VLOG_WARN_RL(&rl, "%s: ignoring %s with %"PRIu32"-second " + "lease time (%s)", cli_name, dhcp_type_name(msg->type), lease, dhcp_msg_to_string(msg, false, &cli->s)); } else if (cli->validate_offer && !cli->validate_offer(msg, cli->aux)) { - VLOG_DBG_RL(&rl, "client validation hook refused offer: %s", - dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_DBG_RL(&rl, "%s: client validation hook refused offer (%s)", + cli_name, dhcp_msg_to_string(msg, false, &cli->s)); } else { return true; } @@ -610,6 +630,7 @@ validate_offered_options(struct dhclient *cli, const struct dhcp_msg *msg) static void dhclient_run_SELECTING(struct dhclient *cli) { + const char *cli_name = dhclient_get_name(cli); struct dhcp_msg msg; send_reliably(cli, make_dhcpdiscover); @@ -623,13 +644,13 @@ dhclient_run_SELECTING(struct dhclient *cli) } if (!dhcp_msg_get_ip(&msg, DHCP_CODE_SERVER_IDENTIFIER, 0, &cli->server_ip)) { - VLOG_WARN_RL(&rl, "DHCPOFFER lacks server identifier: %s", - dhcp_msg_to_string(&msg, false, &cli->s)); + VLOG_WARN_RL(&rl, "%s: DHCPOFFER lacks server identifier (%s)", + cli_name, dhcp_msg_to_string(&msg, false, &cli->s)); continue; } - VLOG_DBG_RL(&rl, "accepting DHCPOFFER: %s", - dhcp_msg_to_string(&msg, false, &cli->s)); + VLOG_DBG_RL(&rl, "%s: accepting DHCPOFFER (%s)", + cli_name, dhcp_msg_to_string(&msg, false, &cli->s)); cli->ipaddr = msg.yiaddr; state_transition(cli, S_REQUESTING); break; @@ -637,7 +658,8 @@ dhclient_run_SELECTING(struct dhclient *cli) } static bool -same_binding(const struct dhcp_msg *old, const struct dhcp_msg *new) +same_binding(const char *cli_name, + const struct dhcp_msg *old, const struct dhcp_msg *new) { static const int codes[] = { DHCP_CODE_SUBNET_MASK, @@ -660,8 +682,9 @@ same_binding(const struct dhcp_msg *old, const struct dhcp_msg *new) bool same = true; if (old->yiaddr != new->yiaddr) { - VLOG_WARN("DHCP binding changed IP address from "IP_FMT" to "IP_FMT, - IP_ARGS(&old->yiaddr), IP_ARGS(&new->yiaddr)); + VLOG_WARN("%s: DHCP binding changed IP address " + "from "IP_FMT" to "IP_FMT, + cli_name, IP_ARGS(&old->yiaddr), IP_ARGS(&new->yiaddr)); same = false; } for (i = 0; i < ARRAY_SIZE(codes); i++) { @@ -671,7 +694,8 @@ same_binding(const struct dhcp_msg *old, const struct dhcp_msg *new) if (!dhcp_option_equals(old_opt, new_opt)) { struct ds old_string = DS_EMPTY_INITIALIZER; struct ds new_string = DS_EMPTY_INITIALIZER; - VLOG_WARN("DHCP binding changed option from %s to %s", + VLOG_WARN("%s: DHCP binding changed option from %s to %s", + cli_name, dhcp_option_to_string(old_opt, code, &old_string), dhcp_option_to_string(new_opt, code, &new_string)); ds_destroy(&old_string); @@ -700,7 +724,7 @@ receive_ack(struct dhclient *cli) uint32_t lease = 0, t1 = 0, t2 = 0; if (cli->binding) { - if (!same_binding(cli->binding, &msg)) { + if (!same_binding(dhclient_get_name(cli), cli->binding, &msg)) { cli->changed = true; } dhcp_msg_uninit(cli->binding); @@ -732,7 +756,8 @@ receive_ack(struct dhclient *cli) cli->router = INADDR_ANY; } state_transition(cli, S_BOUND); - VLOG_DBG("Bound: %s", dhcp_msg_to_string(&msg, false, &cli->s)); + VLOG_DBG("%s: bound (%s)", dhclient_get_name(cli), + dhcp_msg_to_string(&msg, false, &cli->s)); return true; } } @@ -821,10 +846,12 @@ dhclient_wait(struct dhclient *cli) static void state_transition(struct dhclient *cli, enum dhclient_state state) { + const char *cli_name = dhclient_get_name(cli); bool was_bound = dhclient_is_bound(cli); bool am_bound; + if (cli->state != state) { - VLOG_DBG("entering %s", state_name(state)); + VLOG_DBG("%s: entering %s", cli_name, state_name(state)); cli->state = state; } cli->state_entered = time_now(); @@ -835,19 +862,18 @@ state_transition(struct dhclient *cli, enum dhclient_state state) if (am_bound) { assert(cli->binding != NULL); VLOG_INFO("%s: obtained address "IP_FMT", netmask "IP_FMT, - netdev_get_name(cli->netdev), + cli_name, IP_ARGS(&cli->ipaddr), IP_ARGS(&cli->netmask)); if (cli->router) { VLOG_INFO("%s: obtained default gateway "IP_FMT, - netdev_get_name(cli->netdev), IP_ARGS(&cli->router)); + cli_name, IP_ARGS(&cli->router)); } } else { dhcp_msg_uninit(cli->binding); free(cli->binding); cli->binding = NULL; - VLOG_INFO("%s: network address unbound", - netdev_get_name(cli->netdev)); + VLOG_INFO("%s: network address unbound", cli_name); } } if (cli->state & (S_SELECTING | S_REQUESTING | S_REBOOTING)) { @@ -905,6 +931,7 @@ timeout(struct dhclient *cli, unsigned int secs) static bool do_receive_msg(struct dhclient *cli, struct dhcp_msg *msg) { + const char *cli_name = dhclient_get_name(cli); uint8_t cli_mac[ETH_ADDR_LEN]; struct ofpbuf b; int mtu; @@ -936,13 +963,15 @@ do_receive_msg(struct dhclient *cli, struct dhcp_msg *msg) ip = b.l3; if (IP_IS_FRAGMENT(ip->ip_frag_off)) { /* We don't do reassembly. */ - VLOG_WARN_RL(&rl, "ignoring fragmented DHCP datagram"); + VLOG_WARN_RL(&rl, "%s: ignoring fragmented DHCP datagram", + cli_name); continue; } dhcp = b.l7; if (!dhcp) { - VLOG_WARN_RL(&rl, "ignoring DHCP datagram with missing payload"); + VLOG_WARN_RL(&rl, "%s: ignoring DHCP datagram with missing " + "payload", cli_name); continue; } @@ -950,10 +979,11 @@ do_receive_msg(struct dhclient *cli, struct dhcp_msg *msg) error = dhcp_parse(msg, &b); if (!error) { if (VLOG_IS_DBG_ENABLED()) { - VLOG_DBG_RL(&rl, "received %s", + VLOG_DBG_RL(&rl, "%s: received %s", cli_name, dhcp_msg_to_string(msg, false, &cli->s)); } else { - VLOG_INFO_RL(&rl, "received %s", dhcp_type_name(msg->type)); + VLOG_INFO_RL(&rl, "%s: received %s", + cli_name, dhcp_type_name(msg->type)); } ofpbuf_uninit(&b); return true; @@ -968,6 +998,7 @@ drained: static void do_send_msg(struct dhclient *cli, const struct dhcp_msg *msg) { + const char *cli_name = dhclient_get_name(cli); struct ofpbuf b; struct eth_header eh; struct ip_header nh; @@ -1030,17 +1061,18 @@ do_send_msg(struct dhclient *cli, const struct dhcp_msg *msg) * Ethernet at some point. 1500 bytes should be enough for anyone. */ if (b.size <= ETH_TOTAL_MAX) { if (VLOG_IS_DBG_ENABLED()) { - VLOG_DBG("sending %s", dhcp_msg_to_string(msg, false, &cli->s)); + VLOG_DBG("%s: sending %s", + cli_name, dhcp_msg_to_string(msg, false, &cli->s)); } else { - VLOG_INFO("sending %s", dhcp_type_name(msg->type)); + VLOG_INFO("%s: sending %s", cli_name, dhcp_type_name(msg->type)); } error = netdev_send(cli->netdev, &b); if (error) { - VLOG_ERR("send failed on %s: %s", + VLOG_ERR("%s: send failed on %s (%s)", cli_name, netdev_get_name(cli->netdev), strerror(error)); } } else { - VLOG_ERR("cannot send %zu-byte Ethernet frame", b.size); + VLOG_ERR("%s: cannot send %zu-byte Ethernet frame", cli_name, b.size); } ofpbuf_uninit(&b); diff --git a/lib/dhcp-client.h b/lib/dhcp-client.h index 6872db6b9..b4c3065c0 100644 --- a/lib/dhcp-client.h +++ b/lib/dhcp-client.h @@ -1,5 +1,5 @@ /* - * Copyright (c) 2008 Nicira Networks. + * Copyright (c) 2008, 2010 Nicira Networks. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -31,6 +31,7 @@ void dhclient_set_max_timeout(struct dhclient *, unsigned int max_timeout); void dhclient_destroy(struct dhclient *); struct netdev *dhclient_get_netdev(struct dhclient *); +const char *dhclient_get_name(const struct dhclient *); void dhclient_init(struct dhclient *, uint32_t requested_ip); void dhclient_release(struct dhclient *); diff --git a/ofproto/discovery.c b/ofproto/discovery.c index b875890af..84f092e69 100644 --- a/ofproto/discovery.c +++ b/ofproto/discovery.c @@ -36,6 +36,7 @@ #include "vlog.h" struct discovery { + char *dpif_name; char *re; bool update_resolv_conf; regex_t *regex; @@ -105,6 +106,8 @@ discovery_create(const char *re, bool update_resolv_conf, d = xzalloc(sizeof *d); + d->dpif_name = xstrdup(dpif_base_name(dpif)); + /* Controller regular expression. */ error = discovery_set_accept_controller_re(d, re); if (error) { @@ -116,13 +119,15 @@ discovery_create(const char *re, bool update_resolv_conf, error = dpif_port_get_name(dpif, ODPP_LOCAL, local_name, sizeof local_name); if (error) { - VLOG_ERR("failed to query datapath local port: %s", strerror(error)); + VLOG_ERR("%s: failed to query datapath local port: %s", + d->dpif_name, strerror(error)); goto error_regfree; } error = dhclient_create(local_name, modify_dhcp_request, validate_dhcp_offer, d, &d->dhcp); if (error) { - VLOG_ERR("failed to initialize DHCP client: %s", strerror(error)); + VLOG_ERR("%s: failed to initialize DHCP client: %s", + d->dpif_name, strerror(error)); goto error_regfree; } dhclient_set_max_timeout(d->dhcp, 3); @@ -138,6 +143,7 @@ error_regfree: regfree(d->regex); free(d->regex); error_free: + free(d->dpif_name); free(d); *discoveryp = 0; return error; @@ -152,6 +158,7 @@ discovery_destroy(struct discovery *d) free(d->regex); dhclient_destroy(d->dhcp); switch_status_unregister(d->ss_cat); + free(d->dpif_name); free(d); } } @@ -190,7 +197,7 @@ discovery_set_accept_controller_re(struct discovery *d, const char *re_) size_t length = regerror(error, regex, NULL, 0); char *buffer = xmalloc(length); regerror(error, regex, buffer, length); - VLOG_WARN("%s: %s", re, buffer); + VLOG_WARN("%s: %s: %s", d->dpif_name, re, buffer); free(regex); free(re); return EINVAL; @@ -236,12 +243,14 @@ discovery_run(struct discovery *d, char **controller_name) if (dhclient_is_bound(d->dhcp)) { *controller_name = dhcp_msg_get_string(dhclient_get_config(d->dhcp), DHCP_CODE_OFP_CONTROLLER_VCONN); - VLOG_INFO("%s: discovered controller", *controller_name); + VLOG_INFO("%s: discovered controller %s", + d->dpif_name, *controller_name); d->n_changes++; } else { *controller_name = NULL; if (d->n_changes) { - VLOG_INFO("discovered controller no longer available"); + VLOG_INFO("%s: discovered controller no longer available", + d->dpif_name); d->n_changes++; } } @@ -271,13 +280,14 @@ validate_dhcp_offer(const struct dhcp_msg *msg, void *d_) vconn_name = dhcp_msg_get_string(msg, DHCP_CODE_OFP_CONTROLLER_VCONN); if (!vconn_name) { - VLOG_WARN_RL(&rl, "rejecting DHCP offer missing controller vconn"); + VLOG_WARN_RL(&rl, "%s: rejecting DHCP offer missing controller vconn", + d->dpif_name); return false; } accept = !regexec(d->regex, vconn_name, 0, NULL, 0); if (!accept) { - VLOG_WARN_RL(&rl, "rejecting controller vconn that fails to match %s", - d->re); + VLOG_WARN_RL(&rl, "%s: rejecting controller vconn that fails to " + "match %s", d->dpif_name, d->re); } free(vconn_name); return accept;