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.
This commit is contained in:
Peter Serwylo 2015-09-11 07:13:30 +10:00
parent 9e410662ea
commit 4bb2a0e0d0
4 changed files with 45 additions and 28 deletions

View File

@ -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<Void, Void, Void>() {
@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);

View File

@ -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);
}
}

View File

@ -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);

View File

@ -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);
}