Bug 69585

Summary: MC regression in 5.15.1: account-manager/connectivity.py fails
Product: Telepathy Reporter: Simon McVittie <smcv>
Component: mission-controlAssignee: Simon McVittie <smcv>
Status: RESOLVED FIXED QA Contact: Telepathy bugs list <telepathy-bugs>
Severity: major    
Priority: medium CC: rishi.is
Version: git masterKeywords: patch
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Attachments: 1/5] run-test.sh.in: now that we run under 'set -e', catch failures
2/5] run-test.sh.in: dump logfiles to stdout on failure
3/5] Log verbose test output and give it the same treatment as MC's log
4/5] connectivity_monitor_nm_state_change_cb: if NM says DISCONNECTED, believe it
5/5] connectivity test: make sure we've caught up on GDBus messages
Document the new test logging arrangement

Description Simon McVittie 2013-09-19 18:24:22 UTC
Here's a fun regression in the new GNetworkMonitor-based connectivity monitoring.

1. We're connected to the Internet. MC has a live Connection.
   The connectivity state is (awake, up, stable, running), all of which
   are needed.

2. We go to an indeterminate state (DISCONNECTING).

(process:4081): mcd-DEBUG: connectivity_monitor_nm_state_change_cb: New NetworkManager network state 30 (unstable state)
(process:4081): mcd-DEBUG: connectivity_monitor_change_states: awake: 1 -> 1; up: 2 -> 2; stable: 4 -> 0; running: 8 -> 8

3. We finish disconnecting. MC tells us that it has disconnected before the GNetworkMonitor does.

(process:4081): mcd-DEBUG: connectivity_monitor_nm_state_change_cb: New NetworkManager network state 20 (stable state)
(process:4081): mcd-DEBUG: connectivity_monitor_change_states: awake: 1 -> 1; up: 2 -> 2; stable: 0 -> 4; running: 8 -> 8

... spot the error: we're back in a stable state, we haven't yet been told by the GNetworkMonitor that we've been disconnected (which would be indicated by "up: 0"), so we try to reconnect!

A moment later we're told by the GNetworkMonitor that the connection has gone down

(process:4081): mcd-DEBUG: connectivity_monitor_network_changed: GNetworkMonitor (FakeNetworkMonitor) says we are offline
(process:4081): mcd-DEBUG: connectivity_monitor_change_states: awake: 1 -> 1; up: 2 -> 0; stable: 4 -> 4; running: 8 -> 8

and try to disconnect the connection again.

Open question: can this happen in real life, or is it just a deficiency in our simulated connectivity? Will NM ever signal DISCONNECTED before netlink/etc. says this has happened? (I suspect the answer is "it depends who reads which sockets in which order")

Once the system has "settled", if NM says we are disconnected, but the GNetworkMonitor says we're OK, we do probably still want to give it a try, so ideally, we shouldn't treat DISCONNECTED as "definitely offline" - but I'm willing to compromise on that if necessary.
Comment 1 Simon McVittie 2013-09-19 18:39:31 UTC
This is compounded by the fact that libnm-glib uses dbus-glib, whereas the FakeNetworkMonitor uses GDBus; so it's entirely possible that when the test sends this:

• NM: connected (70)
• FakeNetworkMonitor: connected
…
• NM: disconnecting (30)
• NM: disconnected (20)
• FakeNetworkMonitor: disconnected
• NM: connected (70)
• FakeNetworkMonitor: connected

MC receives this:

• NM: connected (70)
• FakeNetworkMonitor: connected
…
• NM: disconnecting (30)
• NM: disconnected (20)
• NM: connected (70)
• FakeNetworkMonitor: disconnected
• FakeNetworkMonitor: connected

which makes MC disconnect! Not helpful.
Comment 2 Simon McVittie 2013-09-19 18:45:37 UTC
Created attachment 86158 [details] [review]
1/5] run-test.sh.in: now that we run under 'set -e', catch  failures

If we just let with-session-bus.sh exit nonzero, the script aborts.
We want to catch the nonzero exit status and do some more things
before failing.

---

Not particularly related to this, should be merged anyway
Comment 3 Simon McVittie 2013-09-19 18:45:52 UTC
Created attachment 86159 [details] [review]
2/5] run-test.sh.in: dump logfiles to stdout on failure

This is a lot of very spammy output, but the failures are basically
undebuggable without it, so...
Comment 4 Simon McVittie 2013-09-19 18:46:36 UTC
Created attachment 86160 [details] [review]
3/5] Log verbose test output and give it the same treatment as  MC's log

---

Rather than having strange runes to get verbose test output, let's just log it unconditionally, and cat it (along with MC's own logs) if it becomes necessary.
Comment 5 Simon McVittie 2013-09-19 18:47:29 UTC
Created attachment 86161 [details] [review]
4/5] connectivity_monitor_nm_state_change_cb: if NM says  DISCONNECTED, believe it

---

This does mean we lose the "if NM believes we are disconnected, but netlink says we're OK, then we're OK" feature, but I can't see how to avoid that.
Comment 6 Simon McVittie 2013-09-19 18:47:48 UTC
Created attachment 86162 [details] [review]
5/5] connectivity test: make sure we've caught up on GDBus  messages

Otherwise, the message from the FakeNetworkMonitor saying we've gone
offline might not be received until after the message from the fake NM
saying we've gone online - which would be a problem. There's no
side-effect we can wait for here, so we just have to make sure the
GDBus queue has been processed.
Comment 7 Guillaume Desmottes 2013-09-20 08:32:57 UTC
Comment on attachment 86158 [details] [review]
1/5] run-test.sh.in: now that we run under 'set -e', catch  failures

Review of attachment 86158 [details] [review]:
-----------------------------------------------------------------

++
Comment 8 Guillaume Desmottes 2013-09-20 08:33:20 UTC
Comment on attachment 86159 [details] [review]
2/5] run-test.sh.in: dump logfiles to stdout on failure

Review of attachment 86159 [details] [review]:
-----------------------------------------------------------------

++
Comment 9 Guillaume Desmottes 2013-09-20 08:34:06 UTC
Comment on attachment 86160 [details] [review]
3/5] Log verbose test output and give it the same treatment as  MC's log

Review of attachment 86160 [details] [review]:
-----------------------------------------------------------------

++

Shouldn't be update tests/README if this env variable is always set now?
Comment 10 Guillaume Desmottes 2013-09-20 08:34:23 UTC
Comment on attachment 86161 [details] [review]
4/5] connectivity_monitor_nm_state_change_cb: if NM says  DISCONNECTED, believe it

Review of attachment 86161 [details] [review]:
-----------------------------------------------------------------

++
Comment 11 Guillaume Desmottes 2013-09-20 08:34:53 UTC
Comment on attachment 86162 [details] [review]
5/5] connectivity test: make sure we've caught up on GDBus  messages

Review of attachment 86162 [details] [review]:
-----------------------------------------------------------------

++
Comment 12 Simon McVittie 2013-09-20 11:49:59 UTC
Created attachment 86176 [details] [review]
Document the new test logging arrangement
Comment 13 Simon McVittie 2013-09-20 11:52:48 UTC
I merged this lot. Hopefully Attachment #86176 [details] fixes your comment on Attachment #86160 [details] - let me know if you want it changed or reverted.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.