From 4bb2a0e0d0f6209b40385196bdb7c99196db67c3 Mon Sep 17 00:00:00 2001 From: Peter Serwylo Date: Fri, 11 Sep 2015 07:13:30 +1000 Subject: [PATCH 1/4] Added massive amounts of logging to pin down problem. Trying to pin down why the UI takes one or two seconds to catch up after performing the "Enable WiFi" toggle. This is best done via logging rather than using the debugger. Also changed to Utils.DebugLog instead of Log.d, and removed some comments and fixed a typo in one comment. --- .../fdroid/fdroid/localrepo/SwapService.java | 28 ++++++++++------- .../fdroid/localrepo/type/SwapType.java | 5 +++ .../fdroid/localrepo/type/WifiSwap.java | 9 +++--- .../fdroid/views/swap/StartSwapView.java | 31 ++++++++++++------- 4 files changed, 45 insertions(+), 28 deletions(-) diff --git a/F-Droid/src/org/fdroid/fdroid/localrepo/SwapService.java b/F-Droid/src/org/fdroid/fdroid/localrepo/SwapService.java index 0512273d6..1e5f9b708 100644 --- a/F-Droid/src/org/fdroid/fdroid/localrepo/SwapService.java +++ b/F-Droid/src/org/fdroid/fdroid/localrepo/SwapService.java @@ -106,7 +106,7 @@ public class SwapService extends Service { // ========================================================== public void scanForPeers() { - Log.d(TAG, "Scanning for nearby devices to swap with..."); + Utils.debugLog(TAG, "Scanning for nearby devices to swap with..."); bonjourFinder.scan(); bluetoothFinder.scan(); } @@ -209,7 +209,7 @@ public class SwapService extends Service { HttpHost host = new HttpHost(repoUri.getHost(), repoUri.getPort(), repoUri.getScheme()); try { - Log.d(TAG, "Asking server at " + address + " to swap with us in return (by POSTing to \"/request-swap\" with repo \"" + swapBackUri + "\")..."); + Utils.debugLog(TAG, "Asking server at " + address + " to swap with us in return (by POSTing to \"/request-swap\" with repo \"" + swapBackUri + "\")..."); populatePostParams(swapBackUri, request); client.execute(host, request); } catch (IOException e) { @@ -377,6 +377,8 @@ public class SwapService extends Service { // ============================================================= private void persistPreferredSwapTypes() { + Utils.debugLog(TAG, "Remembering that Bluetooth swap " + ( bluetoothSwap.isConnected() ? "IS" : "is NOT" ) + + " connected and WiFi swap " + (wifiSwap.isConnected() ? "IS" : "is NOT" ) + " connected."); persistence().edit() .putBoolean(KEY_BLUETOOTH_ENABLED, bluetoothSwap.isConnected()) .putBoolean(KEY_WIFI_ENABLED, wifiSwap.isConnected()) @@ -399,7 +401,7 @@ public class SwapService extends Service { * Moves the service to the forground and [re]starts the timeout timer. */ private void attachService() { - Log.d(TAG, "Moving SwapService to foreground so that it hangs around even when F-Droid is closed."); + Utils.debugLog(TAG, "Moving SwapService to foreground so that it hangs around even when F-Droid is closed (may already be foregrounded)."); startForeground(NOTIFICATION, createNotification()); // Regardless of whether it was previously enabled, start the timer again. This ensures that @@ -413,7 +415,7 @@ public class SwapService extends Service { timer.cancel(); } - Log.d(TAG, "Moving SwapService to background so that it can be GC'ed if required."); + Utils.debugLog(TAG, "Moving SwapService to background so that it can be GC'ed if required."); stopForeground(true); } @@ -425,7 +427,7 @@ public class SwapService extends Service { new AsyncTask() { @Override protected Void doInBackground(Void... params) { - Log.d(TAG, "Restarting WiFi swap service"); + Utils.debugLog(TAG, "Restarting WiFi swap service"); wifiSwap.stop(); wifiSwap.start(); return null; @@ -511,7 +513,7 @@ public class SwapService extends Service { public void onCreate() { super.onCreate(); - Log.d(TAG, "Creating swap service."); + Utils.debugLog(TAG, "Creating swap service."); SharedPreferences preferences = getSharedPreferences(SHARED_PREFERENCES, Context.MODE_PRIVATE); @@ -531,13 +533,15 @@ public class SwapService extends Service { /** if (wasBluetoothEnabled()) { - Log.d(TAG, "Previously the user enabled Bluetooth swap, so enabling again automatically."); + Utils.debugLog(TAG, "Previously the user enabled Bluetooth swap, so enabling again automatically."); bluetoothSwap.startInBackground(); }*/ if (wasWifiEnabled()) { - Log.d(TAG, "Previously the user enabled Wifi swap, so enabling again automatically."); + Utils.debugLog(TAG, "Previously the user enabled WiFi swap, so enabling again automatically."); wifiSwap.startInBackground(); + } else { + Utils.debugLog(TAG, "WiFi was NOT enabled last time user swapped, so starting with WiFi not visible."); } } @@ -586,7 +590,7 @@ public class SwapService extends Service { @Override public void onDestroy() { super.onDestroy(); - Log.d(TAG, "Destroying service, will disable swapping if required, and unregister listeners."); + Utils.debugLog(TAG, "Destroying service, will disable swapping if required, and unregister listeners."); disableAllSwapping(); Preferences.get().unregisterLocalRepoHttpsListeners(httpsEnabledListener); LocalBroadcastManager.getInstance(this).unregisterReceiver(onWifiChange); @@ -607,16 +611,16 @@ public class SwapService extends Service { private void initTimer() { if (timer != null) { - Log.d(TAG, "Cancelling existing timeout timer so timeout can be reset."); + Utils.debugLog(TAG, "Cancelling existing timeout timer so timeout can be reset."); timer.cancel(); } - Log.d(TAG, "Initializing swap timeout to " + TIMEOUT + "ms minutes"); + Utils.debugLog(TAG, "Initializing swap timeout to " + TIMEOUT + "ms minutes"); timer = new Timer(); timer.schedule(new TimerTask() { @Override public void run() { - Log.d(TAG, "Disabling swap because " + TIMEOUT + "ms passed."); + Utils.debugLog(TAG, "Disabling swap because " + TIMEOUT + "ms passed."); disableAllSwapping(); } }, TIMEOUT); diff --git a/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java b/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java index 7b4a11fe3..e3a7f6a33 100644 --- a/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java +++ b/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java @@ -5,7 +5,9 @@ import android.content.Intent; import android.os.AsyncTask; import android.support.annotation.NonNull; import android.support.v4.content.LocalBroadcastManager; +import android.util.Log; +import org.fdroid.fdroid.Utils; import org.fdroid.fdroid.localrepo.SwapService; /** @@ -17,6 +19,8 @@ import org.fdroid.fdroid.localrepo.SwapService; */ public abstract class SwapType { + private final static String TAG = "SwapType"; + private boolean isConnected; @NonNull @@ -58,6 +62,7 @@ public abstract class SwapType { if (getBroadcastAction() != null) { Intent intent = new Intent(getBroadcastAction()); intent.putExtra(extra, true); + Utils.debugLog(TAG, "Sending broadcast " + extra + " from " + getClass().getSimpleName()); LocalBroadcastManager.getInstance(context).sendBroadcast(intent); } } diff --git a/F-Droid/src/org/fdroid/fdroid/localrepo/type/WifiSwap.java b/F-Droid/src/org/fdroid/fdroid/localrepo/type/WifiSwap.java index 3409ff939..2d6bd629e 100644 --- a/F-Droid/src/org/fdroid/fdroid/localrepo/type/WifiSwap.java +++ b/F-Droid/src/org/fdroid/fdroid/localrepo/type/WifiSwap.java @@ -10,6 +10,7 @@ import android.util.Log; import org.fdroid.fdroid.FDroidApp; import org.fdroid.fdroid.Preferences; +import org.fdroid.fdroid.Utils; import org.fdroid.fdroid.localrepo.SwapService; import org.fdroid.fdroid.net.LocalHTTPD; import org.fdroid.fdroid.net.WifiStateChangeService; @@ -42,7 +43,7 @@ public class WifiSwap extends SwapType { @Override public void start() { - Log.d(TAG, "Preparing swap webserver."); + Utils.debugLog(TAG, "Preparing swap webserver."); sendBroadcast(SwapService.EXTRA_STARTING); Runnable webServer = new Runnable() { @@ -67,10 +68,10 @@ public class WifiSwap extends SwapType { } }; try { - Log.d(TAG, "Starting swap webserver..."); + Utils.debugLog(TAG, "Starting swap webserver..."); localHttpd.start(); setConnected(true); - Log.d(TAG, "Swap webserver started."); + Utils.debugLog(TAG, "Swap webserver started."); } catch (BindException e) { int prev = FDroidApp.port; FDroidApp.port = FDroidApp.port + new Random().nextInt(1111); @@ -93,7 +94,7 @@ public class WifiSwap extends SwapType { if (webServerThreadHandler == null) { Log.i(TAG, "null handler in stopWebServer"); } else { - Log.d(TAG, "Sending message to swap webserver to stop it."); + Utils.debugLog(TAG, "Sending message to swap webserver to stop it."); Message msg = webServerThreadHandler.obtainMessage(); msg.obj = webServerThreadHandler.getLooper().getThread().getName() + " says stop"; webServerThreadHandler.sendMessage(msg); diff --git a/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java b/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java index a91a980c9..e59104af1 100644 --- a/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java +++ b/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java @@ -32,6 +32,7 @@ import android.widget.TextView; import org.fdroid.fdroid.FDroidApp; import org.fdroid.fdroid.R; +import org.fdroid.fdroid.Utils; import org.fdroid.fdroid.localrepo.SwapService; import org.fdroid.fdroid.localrepo.peers.Peer; import org.fdroid.fdroid.net.WifiStateChangeService; @@ -44,10 +45,10 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In private static final String TAG = "StartSwapView"; - // TODO: Is there a way to guarangee which of these constructors the inflater will call? + // TODO: Is there a way to guarantee which of these constructors the inflater will call? // Especially on different API levels? It would be nice to only have the one which accepts // a Context, but I'm not sure if that is correct or not. As it stands, this class provides - // constructurs which match each of the ones available in the parent class. + // constructors which match each of the ones available in the parent class. // The same is true for the other views in the swap process too. public StartSwapView(Context context) { @@ -87,11 +88,9 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In return convertView; } - } private SwapWorkflowActivity getActivity() { - // TODO: Try and find a better way to get to the SwapActivity, which makes less asumptions. return (SwapWorkflowActivity)getContext(); } @@ -177,9 +176,9 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In public void onReceive(Context context, Intent intent) { Peer peer = intent.getParcelableExtra(SwapService.EXTRA_PEER); if (adapter.getPosition(peer) >= 0) { - Log.d(TAG, "Found peer: " + peer + ", ignoring though, because it is already in our list."); + Utils.debugLog(TAG, "Found peer: " + peer + ", ignoring though, because it is already in our list."); } else { - Log.d(TAG, "Found peer: " + peer + ", adding to list of peers in UI."); + Utils.debugLog(TAG, "Found peer: " + peer + ", adding to list of peers in UI."); adapter.add(peer); uiUpdatePeersInfo(); } @@ -216,21 +215,26 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In textBluetoothVisible.setText(textResource); final SwitchCompat bluetoothSwitch = ((SwitchCompat) findViewById(R.id.switch_bluetooth)); + Utils.debugLog(TAG, getManager().isBluetoothDiscoverable() ? "Initially marking switch as checked, because Bluetooth is discoverable." : "Initially marking switch as not-checked, because Bluetooth is not discoverable."); bluetoothSwitch.setChecked(getManager().isBluetoothDiscoverable()); bluetoothSwitch.setOnCheckedChangeListener(new CompoundButton.OnCheckedChangeListener() { @Override public void onCheckedChanged(CompoundButton buttonView, boolean isChecked) { if (isChecked) { + Utils.debugLog(TAG, "Received onCheckChanged(true) for Bluetooth swap, prompting user as to whether they want to enable Bluetooth."); getActivity().startBluetoothSwap(); textBluetoothVisible.setText(R.string.swap_visible_bluetooth); viewBluetoothId.setVisibility(View.VISIBLE); uiUpdatePeersInfo(); + Utils.debugLog(TAG, "Received onCheckChanged(true) for Bluetooth swap (prompting user or setup Bluetooth complete)"); // TODO: When they deny the request for enabling bluetooth, we need to disable this switch... } else { + Utils.debugLog(TAG, "Received onCheckChanged(false) for Bluetooth swap, disabling Bluetooth swap."); getManager().getBluetoothSwap().stop(); textBluetoothVisible.setText(R.string.swap_not_visible_bluetooth); viewBluetoothId.setVisibility(View.GONE); uiUpdatePeersInfo(); + Utils.debugLog(TAG, "Received onCheckChanged(false) for Bluetooth swap, Bluetooth swap disabled successfully."); } } }); @@ -240,18 +244,18 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In @Override public void onReceive(Context context, Intent intent) { if (intent.hasExtra(SwapService.EXTRA_STARTING)) { - Log.d(TAG, "Bluetooth service is starting..."); + Utils.debugLog(TAG, "Bluetooth service is starting (setting toggle to disabled, not checking because we will wait for an intent that bluetooth is actually enabled)"); bluetoothSwitch.setEnabled(false); textBluetoothVisible.setText(R.string.swap_setting_up_bluetooth); // bluetoothSwitch.setChecked(true); } else { bluetoothSwitch.setEnabled(true); if (intent.hasExtra(SwapService.EXTRA_STARTED)) { - Log.d(TAG, "Bluetooth service has started."); + Utils.debugLog(TAG, "Bluetooth service has started (updating text to visible, but not marking as checked)."); textBluetoothVisible.setText(R.string.swap_visible_bluetooth); // bluetoothSwitch.setChecked(true); } else { - Log.d(TAG, "Bluetooth service has stopped."); + Utils.debugLog(TAG, "Bluetooth service has stopped (setting switch to not-visible)."); textBluetoothVisible.setText(R.string.swap_not_visible_bluetooth); bluetoothSwitch.setChecked(false); } @@ -275,9 +279,12 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In @Override public void onCheckedChanged(CompoundButton buttonView, boolean isChecked) { if (isChecked) { + Utils.debugLog(TAG, "Received onCheckChanged(true) for WiFi swap, asking in background thread to ensure WiFi swap is running."); getManager().getWifiSwap().ensureRunningInBackground(); } else { + Utils.debugLog(TAG, "Received onCheckChanged(false) for WiFi swap, disabling WiFi swap."); getManager().getWifiSwap().stop(); + Utils.debugLog(TAG, "Received onCheckChanged(false) for WiFi swap, WiFi swap disabled successfully."); } uiUpdatePeersInfo(); uiUpdateWifiNetwork(); @@ -293,18 +300,18 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In @Override public void onReceive(Context context, Intent intent) { if (intent.hasExtra(SwapService.EXTRA_STARTING)) { - Log.d(TAG, "Bonjour/WiFi service is starting..."); + Utils.debugLog(TAG, "WiFi service is starting (setting toggle to visible, but disabled)."); textWifiVisible.setText(R.string.swap_setting_up_wifi); wifiSwitch.setEnabled(false); wifiSwitch.setChecked(true); } else { wifiSwitch.setEnabled(true); if (intent.hasExtra(SwapService.EXTRA_STARTED)) { - Log.d(TAG, "Bonjour/WiFi service has started."); + Utils.debugLog(TAG, "WiFi service has started (setting toggle to visible)."); textWifiVisible.setText(R.string.swap_visible_wifi); wifiSwitch.setChecked(true); } else { - Log.d(TAG, "Bonjour/WiFi service has stopped."); + Utils.debugLog(TAG, "WiFi service has stopped (setting toggle to not-visible)."); textWifiVisible.setText(R.string.swap_not_visible_wifi); wifiSwitch.setChecked(false); } From 828cc272ee5235f868104b009349cc7e835e144f Mon Sep 17 00:00:00 2001 From: Peter Serwylo Date: Sat, 12 Sep 2015 20:25:20 +1000 Subject: [PATCH 2/4] Only start Bluetooth in UI thread, WiFi needs background. While we're at it, use `Thread`s rather than `AsyncTask`s because they are more concise. Not 100% sure, but I think `AsyncTask`s need to wait for the UI event loop to get to them in order kick off. --- .../fdroid/localrepo/type/BluetoothSwap.java | 8 ++++++ .../fdroid/localrepo/type/SwapType.java | 27 ++++++++----------- 2 files changed, 19 insertions(+), 16 deletions(-) diff --git a/F-Droid/src/org/fdroid/fdroid/localrepo/type/BluetoothSwap.java b/F-Droid/src/org/fdroid/fdroid/localrepo/type/BluetoothSwap.java index 8310e41ea..57563250a 100644 --- a/F-Droid/src/org/fdroid/fdroid/localrepo/type/BluetoothSwap.java +++ b/F-Droid/src/org/fdroid/fdroid/localrepo/type/BluetoothSwap.java @@ -127,6 +127,14 @@ public class BluetoothSwap extends SwapType { } } + /** + * Don't try to start BT in the background. you can only start/stop a BT server once, else new connections don't work. + */ + @Override + public void stopInBackground() { + stop(); + } + @Override public void stop() { if (server != null && server.isAlive()) { diff --git a/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java b/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java index e3a7f6a33..47ad2c55f 100644 --- a/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java +++ b/F-Droid/src/org/fdroid/fdroid/localrepo/type/SwapType.java @@ -72,15 +72,12 @@ public abstract class SwapType { } public void startInBackground() { - start(); - /** - new AsyncTask() { + new Thread() { @Override - protected Void doInBackground(Void... params) { - start(); - return null; + public void run() { + SwapType.this.start(); } - }.execute();*/ + }.start(); } public void ensureRunning() { @@ -90,23 +87,21 @@ public abstract class SwapType { } public void ensureRunningInBackground() { - new AsyncTask() { + new Thread() { @Override - protected Void doInBackground(Void... params) { + public void run() { ensureRunning(); - return null; } - }.execute(); + }.start(); } public void stopInBackground() { - new AsyncTask() { + new Thread() { @Override - protected Void doInBackground(Void... params) { - stop(); - return null; + public void run() { + SwapType.this.stop(); } - }.execute(); + }.run(); } } From 90ede44790d317c123880e0041a0c715a76a099f Mon Sep 17 00:00:00 2001 From: Peter Serwylo Date: Sat, 12 Sep 2015 20:30:07 +1000 Subject: [PATCH 3/4] Check for null `netmask` variable to prevent NPE. Not sure if this is the correct course of action to prevent the problem, but it prevents the crash documented in Issue #413. --- F-Droid/src/org/fdroid/fdroid/net/WifiStateChangeService.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/F-Droid/src/org/fdroid/fdroid/net/WifiStateChangeService.java b/F-Droid/src/org/fdroid/fdroid/net/WifiStateChangeService.java index c3eedfd0f..860371ec8 100644 --- a/F-Droid/src/org/fdroid/fdroid/net/WifiStateChangeService.java +++ b/F-Droid/src/org/fdroid/fdroid/net/WifiStateChangeService.java @@ -86,7 +86,7 @@ public class WifiStateChangeService extends Service { wifiInfo = wifiManager.getConnectionInfo(); FDroidApp.ipAddressString = formatIpAddress(wifiInfo.getIpAddress()); String netmask = formatIpAddress(wifiManager.getDhcpInfo().netmask); - if (!TextUtils.isEmpty(FDroidApp.ipAddressString)) + if (!TextUtils.isEmpty(FDroidApp.ipAddressString) && netmask != null) FDroidApp.subnetInfo = new SubnetUtils(FDroidApp.ipAddressString, netmask).getInfo(); } else if (wifiState == WifiManager.WIFI_STATE_DISABLED || wifiState == WifiManager.WIFI_STATE_DISABLING) { From 198cc7357ca4869d62f6ee1f032f146a79629cf8 Mon Sep 17 00:00:00 2001 From: Peter Serwylo Date: Sat, 12 Sep 2015 20:32:43 +1000 Subject: [PATCH 4/4] Update UI in response to WiFi enabling, not Bonjour discovery enabling. The Bonjour stuff takes a while to start, and isn't strictly neccesary in order to swap over WiFi. Rather, it is more of a convenience. Also, it was causing the UI to appear to lag quite a lot. This way, the WiFi swap gets setup almost instantly, and is available to swap - therefore the UI seems much more responsive. --- F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java b/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java index e59104af1..5f931458f 100644 --- a/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java +++ b/F-Droid/src/org/fdroid/fdroid/views/swap/StartSwapView.java @@ -295,6 +295,10 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In int textResource = getManager().isBonjourDiscoverable() ? R.string.swap_visible_wifi : R.string.swap_not_visible_wifi; textWifiVisible.setText(textResource); + // Note that this is only listening for the WifiSwap, whereas we start both the WifiSwap + // and the Bonjour service at the same time. Technically swap will work fine without + // Bonjour, and that is more of a convenience. Thus, we should show feedback once wifi + // is ready, even if Bonjour is not yet. // TODO: Unregister receiver correctly... LocalBroadcastManager.getInstance(getContext()).registerReceiver(new BroadcastReceiver() { @Override @@ -318,7 +322,7 @@ public class StartSwapView extends ScrollView implements SwapWorkflowActivity.In } uiUpdateWifiNetwork(); } - }, new IntentFilter(SwapService.BONJOUR_STATE_CHANGE)); + }, new IntentFilter(SwapService.WIFI_STATE_CHANGE)); viewWifiNetwork.setOnClickListener(new OnClickListener() { @Override