New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 817210 link

Starred by 1 user

Issue metadata

Status: Verified
Owner:
Last visit > 30 days ago
Closed: Dec 14
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Feature



Sign in to add a comment

Improve shill logging

Project Member Reported by cernekee@chromium.org, Feb 28 2018

Issue description

a) If `ff_debug --level -1` (or a higher verbosity level) is used, libchrome[0] fills up net.log with spammy messages that look like this every time a wifi scan completes:

2018-02-27T20:24:29.188038-08:00 DEBUG shill[28527]: [VERBOSE1:object_proxy.cc(500)] Signal received: message_type: MESSAGE_SIGNAL#012path: /fi/w1/wpa_supplicant1#012interface: fi.w1.wpa_supplicant1#012member: InterfaceRemoved#012sender: :1.1#012signature: o#012serial: 2530#012#012object_path "/fi/w1/wpa_supplicant1/Interfaces/13"#012

These lines can be 8000+ characters long.  We should disable them by default.

b) If `ff_debug +vpn` is enabled, it would be nice to tell the external VPN daemons to also increase their logging verbosity.  This can help in troubleshooting issues in verified mode.


[0] https://cs.chromium.org/chromium/src/dbus/object_proxy.cc?rcl=ff50dee02a4198907e13b66db33755404340d726&l=536
 
Project Member

Comment 1 by bugdroid1@chromium.org, Mar 16 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/connectivity/shill/+/d3c267b883a120397a7a09665d61729e02aeac75

commit d3c267b883a120397a7a09665d61729e02aeac75
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Fri Mar 16 04:23:29 2018

shill: Suppress dbus VLOGs by default

libchrome and libbrillo are unaware of shill's scoped logging setup.
If `ff_debug --level -1` is set, a log print in libchrome will spam
net.log with 8000+ character lines every time a wifi scan finishes.
Since this print doesn't impart much useful information but we don't
want to change it upstream, just set the default verbosity for
that module to 0.

Similarly, libbrillo's dbus_object.cc and bus.cc log all RPC calls
and object registrations at level -1.  Set their default verbosity back
to 0.

BUG= chromium:817210 
TEST=manually run with loglevel -1

Change-Id: I970e76378f81efc553058631379cd76354c4fb20
Reviewed-on: https://chromium-review.googlesource.com/944889
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>
Reviewed-by: Kevin Cernekee <cernekee@chromium.org>

[modify] https://crrev.com/d3c267b883a120397a7a09665d61729e02aeac75/init/shill.conf.in
[modify] https://crrev.com/d3c267b883a120397a7a09665d61729e02aeac75/init/shill.sh

Project Member

Comment 2 by bugdroid1@chromium.org, Mar 24 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/connectivity/shill/+/4f0d8e29bbc1acecfc00416ac65b1fb5f1d23a6b

commit 4f0d8e29bbc1acecfc00416ac65b1fb5f1d23a6b
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Sat Mar 24 00:29:27 2018

shill: Enable detailed VPN logging through ff_debug

Currently, `ff_debug +vpn` with any verbosity level enables:

 - `--verb 3` in the openvpn options
 - `debug` in pppd.conf
 - `charondebug="dmn 2, mgr 2, ike 2, net 2"` in strongswan.conf

If verbosity is increased to level -2, the shill/vpn/ code logs some
additional diagnostic information: primarily configuration key/value
parameters and function invocations.

Sometimes it is necessary to log more information:

 - To debug IPsec IKE negotiation and make sense of packet traces, the
   session keys must be logged and imported into wireshark.
 - To debug packet loss or key mismatches in OpenVPN, records of each
   (tunneled) data packet is often helpful.
 - To debug keepalives in OpenVPN, records of OpenVPN control messages
   may be necessary.

So, as a general guideline:

 - `ff_debug --level -2` and below will work the same way it does today
 - `ff_debug --level -3` will log more detail about control messages
 - `ff_debug --level -4` will enable per-data-packet logging
 - `ff_debug --level -5` will log keys and other sensitive data
 - `ff_debug --level -6` will turn debugging up to the max

BUG= chromium:817210 
TEST=manually set different loglevels and verify in net.log
CQ-DEPEND=CL:958289

Change-Id: I920fed0f3390203d053c5f1cf04b44d7245d8ab3
Reviewed-on: https://chromium-review.googlesource.com/944894
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>

[modify] https://crrev.com/4f0d8e29bbc1acecfc00416ac65b1fb5f1d23a6b/vpn/l2tp_ipsec_driver.cc
[modify] https://crrev.com/4f0d8e29bbc1acecfc00416ac65b1fb5f1d23a6b/scope_logger.h
[modify] https://crrev.com/4f0d8e29bbc1acecfc00416ac65b1fb5f1d23a6b/vpn/openvpn_driver.cc

Project Member

Comment 3 by bugdroid1@chromium.org, Mar 24 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/connectivity/shill/+/4721676f8b8e627545586cd8fe3527f8bc48c51a

commit 4721676f8b8e627545586cd8fe3527f8bc48c51a
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Sat Mar 24 00:29:29 2018

shill: Convert netlink code to use scoped logging

Currently this code uses VLOG(), so trying to debug a completely
different module will still fill up net.log with RTNL debug prints:

    ff_debug +vpn
    ff_debug --level -5

Change the net/ code to use SLOG() instead of VLOG(), with scope "rtnl".
This change will only take effect for the in-shill copy of the code;
libshill-net will continue to use VLOG() because library users do not
implement shill's scoped logging scheme.

BUG= chromium:817210 
TEST=manually try different loglevels

Change-Id: Iad5c0316a871a90a13705a8cfd42add9b61ab669
Reviewed-on: https://chromium-review.googlesource.com/947045
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Matthew Wang <matthewmwang@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>

[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/attribute_list.cc
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/netlink_message.cc
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/netlink_attribute.cc
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/netlink_socket.cc
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/rtnl_handler.cc
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/shill.gyp
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/logging.h
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/generic_netlink_message.cc
[modify] https://crrev.com/4721676f8b8e627545586cd8fe3527f8bc48c51a/net/netlink_manager.cc

Project Member

Comment 4 by bugdroid1@chromium.org, Mar 24 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/aosp/platform/system/connectivity/shill/+/6f7a8132cefbebe7456c1e5b7e04ee0fa06ef023

commit 6f7a8132cefbebe7456c1e5b7e04ee0fa06ef023
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Sat Mar 24 00:29:27 2018

shill: Compile libshill-net conditionally

Build the net/ directory twice.  The shared (reusable) version will be
built with different compilation flags than the version built into
shill.

BUG= chromium:817210 
TEST=unit tests

Change-Id: I332d5f913339a043afd055f7c5c2178bab826ea0
Reviewed-on: https://chromium-review.googlesource.com/947318
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Matthew Wang <matthewmwang@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>

[modify] https://crrev.com/6f7a8132cefbebe7456c1e5b7e04ee0fa06ef023/shill.gyp

Project Member

Comment 5 by bugdroid1@chromium.org, Mar 24 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/aef32231f97fd24ba92c8d1bad3898ab895cdaa1

commit aef32231f97fd24ba92c8d1bad3898ab895cdaa1
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Sat Mar 24 00:29:28 2018

vpn: Use numeric --log_level to enable debugging

Currently vpn_manager takes two bools: --debug and --ppp_debug.  This
is insufficiently granular for debugging some types of VPN problems;
it is desirable to enable more verbose charon output with e.g.
`ff_debug +vpn ; ff_debug --level -5`.

BUG= chromium:817210 
TEST=manually try different loglevels
CQ-DEPEND=CL:944894

Change-Id: I0a7d292346d5b58c05eee680203b80f3c069a110
Reviewed-on: https://chromium-review.googlesource.com/958289
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Matthew Wang <matthewmwang@chromium.org>
Reviewed-by: Ben Chan <benchan@chromium.org>

[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/service_manager.h
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/l2tp_manager_test.cc
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/l2tp_manager.h
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/ipsec_manager_test.cc
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/service_manager.cc
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/l2tp_manager.cc
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/ipsec_manager.cc
[modify] https://crrev.com/aef32231f97fd24ba92c8d1bad3898ab895cdaa1/vpn-manager/l2tpipsec_vpn.cc

Status: Assigned (was: Untriaged)
This bug has an owner, thus, it's been triaged. Changing status to "assigned".
Status: Verified (was: Assigned)
Bug doesn't have an active owner, and the description at the top is not relevant for future logging improvements. Closing this up.

Sign in to add a comment