Facebook login with Android SDK 3.0 causing ANRs or not working at all

Question

In order to log a user in to Facebook in an Android app, I'm trying to use the following code. After the user has been logged in, all their friends' locations should fetched.

Unfortunately, this code causes ANRs sometimes (as reported in the Google Play developer console) and sometimes it just doesn't work. If I remove the app inside Facebook (revoke permissions), the permission dialog is shown again on the next launch of the Android app. But if the app has the permissions already, it causes those ANRs or just quits without success.

Seems like parts are working and parts are wrong, doesn't it? Is the following code a correct way of logging in and fetching data?

package com.my.application;

import java.util.Arrays;
import java.util.List;
import org.json.JSONArray;
import org.json.JSONObject;
import android.app.Activity;
import android.app.ProgressDialog;
import android.content.Intent;
import android.os.Bundle;
import android.preference.PreferenceManager;
import com.facebook.*;
import com.facebook.Session.OpenRequest;
import com.facebook.Session.StatusCallback;

public class FBLocations extends Activity {

    private Session.StatusCallback fbStatusCallback = new Session.StatusCallback() {
        @Override
        public void call(Session session, SessionState state, Exception exception) { // callback for session state changes
            if (state.isOpened()) {
                Request.executeGraphPathRequestAsync(session, "me/friends/?access_token="+session.getAccessToken()+"&fields=id,name,location&limit=500", new Request.Callback() {
                    @Override
                    public void onCompleted(Response response) {
                        if (response != null) {
                            // do something with <response> now
                        }
                    }
                });
            }
        }
    };

    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        try {
            openActiveSession(this, true, fbStatusCallback, Arrays.asList("friends_location"));
        }
        catch (Exception e) {
            e.printStackTrace();
        }
    }

    private static Session openActiveSession(Activity activity, boolean allowLoginUI, StatusCallback callback, List<String> permissions) {
        OpenRequest openRequest = new OpenRequest(activity).setPermissions(permissions).setLoginBehavior(SessionLoginBehavior.SSO_WITH_FALLBACK).setCallback(callback).setDefaultAudience(SessionDefaultAudience.FRIENDS);
        Session session = new Session.Builder(activity).build();
        if (SessionState.CREATED_TOKEN_LOADED.equals(session.getState()) || allowLoginUI) {
            Session.setActiveSession(session);
            session.openForRead(openRequest);
            return session;
        }
        return null;
    }

    @Override
    public void onActivityResult(int requestCode, int resultCode, Intent data) {
        super.onActivityResult(requestCode, resultCode, data);
        Session.getActiveSession().onActivityResult(this, requestCode, resultCode, data);
    }

}

I've also added the app's key hashes to Facebook, both debug and production. Wasn't sure if the padding = has to be written as well.

I couldn't follow Facebook's official tutorial as I won't use the SDK's login button nor do I use fragments in Android.

Edit (7th January 2013):

After Hartok suggested to replace session.isOpened() by state.isOpened() in the callback's call() method, things work in 50% of all test runs now. Nevertheless, there are some problems. In some cases, everything works fine, in some other cases (without me doing anything differently), there is the following error in LogCat:

01-07 01:55:29.882: W/System.err(30572): com.facebook.FacebookException: Log in attempt aborted.
at com.facebook.Session.close(Session.java:572)
at com.facebook.Session.setActiveSession(Session.java:755)
at my.app.package.FBImport.openActiveSession(FBImport.java:145) // this is: Session.setActiveSession(session);
at my.app.package.FBImport.access$5(FBImport.java:139)
at my.app.package.FBImport$4.run(FBImport.java:124)

What causes this error? Client problem or server problem? App seems to freeze (ANR) after that, by the way.

And if I try to connect twice in sequence, I see the following LogCat output:

java.lang.IllegalStateException: Cannot execute task: the task is already running.
at android.os.AsyncTask.executeOnExecutor(AsyncTask.java:550)
at android.os.AsyncTask.execute(AsyncTask.java:511)
at com.facebook.RequestAsyncTask.executeOnSettingsExecutor(RequestAsyncTask.java:186)
at com.facebook.Request.executeBatchAsync(Request.java:1094)
at com.facebook.Request.executeBatchAsync(Request.java:1073)
at com.facebook.Request.executeBatchAsync(Request.java:1055)
at com.facebook.Request.executeAsync(Request.java:852)

Why is that? Why is the task still running?

ANR description (ANR keyDispatchingTimedOut):

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x4184e9a0 self=0x40011010
  | sysTid=19301 nice=0 sched=0/0 cgrp=apps handle=1074414556
  | state=S schedstat=( 906984000 397085000 2526 ) utm=66 stm=24 core=0
  #00 pc 00017ee4 /system/lib/libc.so (epoll_wait+12)
  #01 pc 00014b09 /system/lib/libutils.so (android::Looper::pollInner(int)+96)
  #02 pc 00014d71 /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+104)
  #03 pc 0005ed53 /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)
  #04 pc 0001e290 /system/lib/libdvm.so (dvmPlatformInvoke+112)
  #05 pc 0004d411 /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+396)
  #06 pc 000276a0 /system/lib/libdvm.so
  #07 pc 0002b57c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #08 pc 0005ff07 /system/lib/libdvm.so (dvmInvokeMethod(Object*, Method const*, ArrayObject*, ArrayObject*, ClassObject*, bool)+374)
  #09 pc 000677e1 /system/lib/libdvm.so
  #10 pc 000276a0 /system/lib/libdvm.so
  #11 pc 0002b57c /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+184)
  #12 pc 0005fc31 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+272)
  #13 pc 000499fb /system/lib/libdvm.so
  #14 pc 00046871 /system/lib/libandroid_runtime.so
  #15 pc 00047533 /system/lib/libandroid_runtime.so (android::AndroidRuntime::start(char const*, char const*)+390)
  #16 pc 00000db7 /system/bin/app_process
  #17 pc 0001271f /system/lib/libc.so (__libc_init+38)
  #18 pc 00000ae8 /system/bin/app_process
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:125)
  at android.os.Looper.loop(Looper.java:124)
  at android.app.ActivityThread.main(ActivityThread.java:5039)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:511)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
  at dalvik.system.NativeStart.main(Native Method)

"AsyncTask #2" prio=5 tid=17 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4205f6d0 self=0x6742f940
  | sysTid=19354 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1732251672
  | state=S schedstat=( 82839000 103493000 646 ) utm=5 stm=3 core=0
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4205f7f0> (a java.lang.VMThread) held by tid=17 (AsyncTask #2)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
  at java.lang.Thread.run(Thread.java:856)

"Binder_3" prio=5 tid=16 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41fed668 self=0x41838008
  | sysTid=19330 nice=0 sched=0/0 cgrp=apps handle=1742766600
  | state=S schedstat=( 1078000 818000 10 ) utm=0 stm=0 core=0
  #00 pc 00016fe4 /system/lib/libc.so (__ioctl+8)
  #01 pc 0002a97d /system/lib/libc.so (ioctl+16)
  #02 pc 00016ba1 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+132)
  #03 pc 00017363 /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
  #04 pc 0001b15d /system/lib/libbinder.so
  #05 pc 00011267 /system/lib/libutils.so (android::Thread::_threadLoop(void*)+114)
  #06 pc 0004679f /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+66)
  #07 pc 00010dcd /system/lib/libutils.so
  #08 pc 0000e3d8 /system/lib/libc.so (__thread_entry+72)
  #09 pc 0000dac4 /system/lib/libc.so (pthread_create+160)
  at dalvik.system.NativeStart.run(Native Method)

"pool-1-thread-5" prio=5 tid=15 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x420423d0 self=0x673d8ab8
  | sysTid=19329 nice=0 sched=0/0 cgrp=apps handle=1732087560
  | state=S schedstat=( 6292000 7083000 36 ) utm=0 stm=0 core=2
  at java.lang.Object.wait(Native Method)
  - waiting on <0x42042528> (a java.lang.VMThread) held by tid=15 (pool-1-thread-5)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
  at java.lang.Thread.run(Thread.java:856)

"pool-1-thread-4" prio=5 tid=14 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x42039040 self=0x673cb248
  | sysTid=19328 nice=0 sched=0/0 cgrp=apps handle=1732032152
  | state=S schedstat=( 8178000 7047000 32 ) utm=0 stm=0 core=3
  at java.lang.Object.wait(Native Method)
  - waiting on <0x42039160> (a java.lang.VMThread) held by tid=14 (pool-1-thread-4)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
  at java.lang.Thread.run(Thread.java:856)

"pool-1-thread-3" prio=5 tid=13 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x42027140 self=0x673c95f8
  | sysTid=19327 nice=0 sched=0/0 cgrp=apps handle=1698808232
  | state=S schedstat=( 10642000 19156000 34 ) utm=1 stm=0 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x42027260> (a java.lang.VMThread) held by tid=13 (pool-1-thread-3)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
  at java.lang.Thread.run(Thread.java:856)

"pool-1-thread-2" prio=5 tid=12 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x4201d958 self=0x672cd008
  | sysTid=19326 nice=0 sched=0/0 cgrp=apps handle=1731988480
  | state=S schedstat=( 17725000 16571000 59 ) utm=1 stm=0 core=3
  at java.lang.Object.wait(Native Method)
  - waiting on <0x4201da78> (a java.lang.VMThread) held by tid=12 (pool-1-thread-2)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
  at java.lang.Thread.run(Thread.java:856)

"pool-1-thread-1" prio=5 tid=11 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x420156c8 self=0x65dc8818
  | sysTid=19325 nice=0 sched=0/0 cgrp=apps handle=1728232912
  | state=S schedstat=( 11166000 9311000 77 ) utm=0 stm=1 core=2
  at java.lang.Object.wait(Native Method)
  - waiting on <0x42015810> (a java.lang.VMThread) held by tid=11 (pool-1-thread-1)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1013)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1073)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:573)
  at java.lang.Thread.run(Thread.java:856)

"AsyncTask #1" prio=5 tid=10 WAIT
  | group="main" sCount=1 dsCount=0 obj=0x41fb5990 self=0x63bd3008
  | sysTid=19318 nice=10 sched=0/0 cgrp=apps/bg_non_interactive handle=1748684416
  | state=S schedstat=( 24263000 18668000 33 ) utm=1 stm=1 core=1
  at java.lang.Object.wait(Native Method)
  - waiting on <0x41fd07d0> (a java.lang.VMThread) held by tid=10 (AsyncTask #1)
  at java.lang.Thread.parkFor(Thread.java:1231)
  at sun.misc.Unsafe.park(Unsafe.java:323)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:159)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2019)
  at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:413)
  at java.util.concurrent.ThreadPoolExecutor...

Answer 1

Log in attempt aborted is fired because Session.setActiveSession() is called while a previous Session was currently opening.

Is it possible that you call Session.setActiveSession() two times?

You could try this code. It was not tested, but it partly comes from SessionLoginSample.

private static Session openActiveSession(Activity activity, boolean allowLoginUI, StatusCallback callback, List<String> permissions, Bundle savedInstanceState) {

    OpenRequest openRequest = new OpenRequest(activity).setPermissions(permissions).setLoginBehavior(SessionLoginBehavior.SSO_WITH_FALLBACK).setCallback(callback).setDefaultAudience(SessionDefaultAudience.FRIENDS);

    Session session = Session.getActiveSession();
    if (session == null) {
        if (savedInstanceState != null) {
            session = Session.restoreSession(this, null, fbStatusCallback, savedInstanceState);
        }
        if (session == null) {
            session = new Session(this);
        }
        Session.setActiveSession(session);
        if (session.getState().equals(SessionState.CREATED_TOKEN_LOADED) || allowLoginUI) {
            session.openForRead(openRequest);
            return session;
        }
    }

    return null;
}

Answer 2

If it's hanging up when the user has already authorized the permissions, try checking for the permissions and excluding code based on if the permissions exist. Something like:

if(!session.getReadPermissions.contains("friends_location"){
    //restore or start the session and ask for the permission
}
else{
    //do stuff that would happen after the permission is already granted
}

I'm not at my workstation so the method might be a little off but that's the general idea I would try.