NullPointerException in background thread when attempting to call messenger

I'm testing a simple Android app that uses a Service, Thread, and Mes开发者_如何学Gosenger. I noticed when I quickly start and stop the Service I sometimes get a NullPointerException and FORCE CLOSE. I debugged it and found out my Messenger instance is sometimes null and thus my handler does not get called. What am I doing wrong? Do I need to wait before restarting the Service?

OK it just now happened without the quick stop/start of the Service. So I am not sure how to reproduce this problem. It may occur randomly.

I can catch the exception and get rid of the FORCE CLOSE, but that does not solve my problem of my handler not getting called when the Messenger instance is null. I looked at the Services documentation section on Managing the Lifecycle of a Service, and I did not see any mention of having to wait before restarting a Service.

This is how I start my Service:

    Intent backgroundService = new Intent(PlayAudio.this, com.marie.mp3player.BackgroundService.class);
    backgroundService.putExtra(BackgroundService.EXTRA_MESSENGER, new Messenger(handler));
    backgroundService.putExtra(BackgroundService.EXTRA_SONG, song);
    startService(backgroundService);

This is how I stop my Service:

Intent backgroundService = new Intent(MP3Player.this, BackgroundService.class);
stopService(backgroundService);

And here is a logcat containing two NullPointerExceptions near the bottom:

D/AndroidRuntime(17736): 

D/AndroidRuntime(17736): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<<

D/AndroidRuntime(17736): CheckJNI is OFF

D/dalvikvm(17736): creating instr width table

D/AndroidRuntime(17736): Calling main entry com.android.commands.pm.Pm

I/ActivityManager(   96): Start proc com.android.defcontainer for service com.android.defcontainer/.DefaultContainerService: pid=17744 uid=10011 gids={1015, 2001}

D/dalvikvm(17744): GC_EXPLICIT freed 46K, 50% free 2720K/5379K, external 1625K/2137K, paused 34ms

W/ActivityManager(   96): No content provider found for: 

D/PackageParser(   96): Scanning package: /data/app/vmdl-1782488429.tmp

W/ActivityManager(   96): No content provider found for: 

I/PackageManager(   96): Removing non-system package:com.marie.mp3player

I/ActivityManager(   96): Force stopping package com.marie.mp3player uid=10091

D/PackageManager(   96): Scanning package com.marie.mp3player

I/PackageManager(   96): Package com.marie.mp3player codePath changed from /data/app/com.marie.mp3player-2.apk to /data/app/com.marie.mp3player-1.apk; Retaining data and using new

I/PackageManager(   96): Unpacking native libraries for /data/app/com.marie.mp3player-1.apk

D/installd(   70): DexInv: --- BEGIN '/data/app/com.marie.mp3player-1.apk' ---

D/dalvikvm(17752): creating instr width table

D/dalvikvm(17752): DexOpt: load 5ms, verify+opt 18ms

D/installd(   70): DexInv: --- END '/data/app/com.marie.mp3player-1.apk' (success) ---

D/PackageManager(   96):   Services: com.marie.mp3player.BackgroundService

D/PackageManager(   96):   Activities: com.marie.mp3player.MP3Player com.marie.mp3player.PlayAudio

I/ActivityManager(   96): Force stopping package com.marie.mp3player uid=10091

W/PackageManager(   96): Code path for pkg : com.marie.mp3player changing from /data/app/com.marie.mp3player-2.apk to /data/app/com.marie.mp3player-1.apk

W/PackageManager(   96): Resource path for pkg : com.marie.mp3player changing from /data/app/com.marie.mp3player-2.apk to /data/app/com.marie.mp3player-1.apk

I/installd(   70): move /data/dalvik-cache/data@app@com.marie.mp3player-1.apk@classes.dex -> /data/dalvik-cache/data@app@com.marie.mp3player-1.apk@classes.dex

D/PackageManager(   96): New package installed in /data/app/com.marie.mp3player-1.apk

I/ActivityManager(   96): Force stopping package com.marie.mp3player uid=10091

D/dalvikvm(   96): GC_EXPLICIT freed 842K, 41% free 6421K/10759K, external 2424K/3027K, paused 106ms

D/dalvikvm(  192): GC_EXPLICIT freed 16K, 45% free 4617K/8327K, external 15977K/17649K, paused 67ms

D/dalvikvm(  158): GC_EXPLICIT freed 525K, 54% free 3151K/6791K, external 2480K/3071K, paused 49ms

I/ActivityManager(   96): Start proc com.appspot.swisscodemonkeys.apps for broadcast com.appspot.swisscodemonkeys.apps/.PackageReceiver: pid=17753 uid=10084 gids={3003}

I/ActivityThread(17753): Pub appbrain.SuggestionProvider: com.appspot.swisscodemonkeys.apps.search.SearchSuggestionSampleProvider

D/dalvikvm(11468): GC_EXPLICIT freed 2K, 49% free 2965K/5767K, external 1625K/2137K, paused 314ms

I/ActivityManager(   96): Start proc com.noshufou.android.su for broadcast com.noshufou.android.su/.UninstallReceiver: pid=17761 uid=10056 gids={1015, 3003}

D/dalvikvm(   96): GC_EXPLICIT freed 273K, 41% free 6367K/10759K, external 2424K/3027K, paused 101ms

I/installd(   70): unlink /data/dalvik-cache/data@app@com.marie.mp3player-2.apk@classes.dex

D/AndroidRuntime(17736): Shutting down VM

D/dalvikvm(17736): GC_CONCURRENT freed 101K, 72% free 296K/1024K, external 0K/0K, paused 0ms+1ms

D/jdwp    (17736): Got wake-up signal, bailing out of select

D/dalvikvm(17736): Debugger has detached; object registry had 1 entries

I/ActivityManager(   96): Start proc com.android.voicedialer for broadcast com.android.voicedialer/.VoiceDialerReceiver: pid=17770 uid=10048 gids={3002}

D/VoiceDialerReceiver(17770): onReceive Intent { act=android.intent.action.PACKAGE_REMOVED dat=package:com.marie.mp3player flg=0x10000000 cmp=com.android.voicedialer/.VoiceDialerReceiver (has extras) }

V/RecognizerEngine(17770): deleteCachedGrammarFiles /data/data/com.android.voicedialer/files/openentries.txt

I/ActivityManager(   96): Start proc com.android.vending for broadcast com.android.vending/.PackageMonitorReceiver: pid=17779 uid=10046 gids={1015, 3003}

D/dalvikvm(   67): GC_EXPLICIT freed 11K, 50% free 2717K/5379K, external 1625K/2137K, paused 94ms

D/dalvikvm(   67): GC_EXPLICIT freed <1K, 50% free 2717K/5379K, external 1625K/2137K, paused 81ms

I/ActivityThread(17779): Pub com.android.vending.SuggestionsProvider: com.android.vending.SuggestionsProvider

D/vending (17779): [1] VendingApplication.onCreate(): Resetting ServiceLocator from app

D/dalvikvm(   67): GC_EXPLICIT freed <1K, 50% free 2717K/5379K, external 1625K/2137K, paused 93ms

D/InstallReceiver(17761): com.marie.mp3player

I/ActivityManager(   96): Start proc com.google.android.partnersetup for broadcast com.google.android.partnersetup/.AppInstalledReceiver: pid=17791 uid=10021 gids={}

D/AndroidRuntime(17783): 

D/AndroidRuntime(17783): >>>>>> AndroidRuntime START com.android.internal.os.RuntimeInit <<<<<<

D/AndroidRuntime(17783): CheckJNI is OFF

D/dalvikvm(17783): creating instr width table

D/GTalkService(  211): handlePackageInstalled: re-initialize providers

D/GTalkService(  211): [RawStanzaProvidersMgr] ##### searchProvidersFromIntent

D/GTalkService(  211): [RawStanzaProvidersMgr] no intent receivers found

D/VoiceDialerReceiver(17770): onReceive Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.marie.mp3player flg=0x10000000 cmp=com.android.voicedialer/.VoiceDialerReceiver (has extras) }

V/RecognizerEngine(17770): deleteCachedGrammarFiles /data/data/com.android.voicedialer/files/openentries.txt

I/ActivityManager(   96): Start proc com.google.android.googlequicksearchbox for broadcast com.google.android.googlequicksearchbox/.CorporaUpdateReceiver: pid=17798 uid=10022 gids={3003}

I/ActivityThread(17798): Pub com.google.android.googlequicksearchbox.shortcuts: com.google.android.googlequicksearchbox.ShortcutsProvider

I/ActivityThread(17798): Pub com.google.android.googlequicksearchbox.google: com.google.android.googlequicksearchbox.google.GoogleSuggestionProvider

I/ActivityManager(   96): Start proc com.google.android.apps.maps:FriendService for broadcast com.google.android.apps.maps/com.google.googlenav.friend.android.ServiceReceiver: pid=17812 uid=10033 gids={3003, 1015}

D/AndroidRuntime(17783): Calling main entry com.android.commands.am.Am

I/ActivityManager(   96): Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10000000 cmp=com.marie.mp3player/.MP3Player } from pid 17783

D/AndroidRuntime(17783): Shutting down VM

D/dalvikvm(17783): GC_CONCURRENT freed 102K, 69% free 320K/1024K, external 0K/0K, paused 0ms+0ms

D/jdwp    (17783): Got wake-up signal, bailing out of select

D/dalvikvm(17783): Debugger has detached; object registry had 1 entries

I/ActivityManager(   96): Start proc com.marie.mp3player for activity com.marie.mp3player/.MP3Player: pid=17822 uid=10091 gids={}

I/AndroidRuntime(17783): NOTE: attach of thread 'Binder Thread #3' failed

I/ActivityManager(   96): Start proc com.google.android.apps.maps:NetworkLocationService for service com.google.android.apps.maps/com.google.android.location.internal.server.NetworkLocationService: pid=17830 uid=10033 gids={3003, 1015}

I/ActivityManager(   96): Displayed com.marie.mp3player/.MP3Player: +429ms

I/ActivityManager(   96): Start proc com.noinnion.android.greader.readerpro for broadcast com.noinnion.android.greader.readerpro/.OnUpgradeReceiver: pid=17831 uid=10070 gids={3003, 1015}

V/RenderScript_jni(  192): surfaceDestroyed

I/ActivityThread(17831): Pub com.noinnion.android.greader.readerpro: com.noinnion.android.greader.readerpro.ReaderProvider

D/InternalNlpService(17830): onCreate

D/NetworkLocationServiceThread(17830): start monitoring enabled

D/NetworkLocationServiceThread(17830): updateState

D/NetworkLocationServiceThread(17830): Creating RealOs

D/vending (17779): [11] LocalAssetCache.updateOnePackage(): No local info for com.marie.mp3player

D/szipinf (17830): Initializing inflate state

D/szipinf (17830): Initializing zlib to inflate

D/vending (17779): [12] LocalAssetCache.updateOnePackage(): No local info for com.marie.mp3player

D/dalvikvm(17830): GC_CONCURRENT freed 460K, 43% free 3851K/6727K, external 1625K/2137K, paused 2ms+3ms

D/WifiLocator(17830): Too many cache  misses. Need server request. hasLocation=0 noLocation=1 cacheMiss=2

I/System.out(17830): [INFO:1747]: f: Running flush

I/System.out(17830): [INFO:1761]: f: Sending payload [bytes=300]

I/System.out(17830): [INFO:6772]: f: Running flush

I/System.out(17830): [INFO:6761]: f: Running delayed flush

I/ActivityManager(   96): Start proc org.my_pod.mypod for service org.my_pod.mypod/net.robmunro.mypod.UpdateFeedsService: pid=17853 uid=10080 gids={3003, 1015}

I/ActivityThread(17853): Pub org.my_pod.mypod: net.robmunro.mypod.util.MyPodContentProvider

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +297ms

W/KeyCharacterMap(17822): No keyboard for id 131074

W/KeyCharacterMap(17822): Using default keymap: /system/usr/keychars/qwerty.kcm.bin

D/MP3Player(17822): Stop the background Service

D/WifiLocator(17830): Too many cache  misses. Need server request. hasLocation=0 noLocation=1 cacheMiss=2

E/GlsClient-query(17830): requestFailed

E/GlsClient-query(17830): ay.g

E/GlsClient-query(17830):   at ay.d.t(Unknown Source)

E/GlsClient-query(17830):   at ay.b.a(Unknown Source)

E/GlsClient-query(17830):   at Z.b.g(Unknown Source)

E/GlsClient-query(17830):   at Z.a.g(Unknown Source)

E/GlsClient-query(17830):   at Z.d.run(Unknown Source)

E/GlsClient-query(17830):   at aE.d.run(Unknown Source)

D/dalvikvm(13124): GC_EXPLICIT freed 2K, 50% free 2715K/5379K, external 1625K/2137K, paused 56ms

D/dalvikvm(  192): GC_EXPLICIT freed 88K, 44% free 4690K/8327K, external 16026K/17649K, paused 85ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +305ms

D/MP3Player(17822): Stop the background Service

D/dalvikvm(17830): GC_CONCURRENT freed 1201K, 51% free 3612K/7239K, external 1625K/2137K, paused 3ms+3ms

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/System.out(17830): [INFO:50519]: f: Response [http=200,length=147]

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +307ms

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +255ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +302ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +296ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +294ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

E/(Messenger)messenger: (17822): NullPointerException

W/System.err(17822): java.lang.NullPointerException

W/System.err(17822):    at com.marie.mp3player.BackgroundService$ServiceWorker.run(BackgroundService.java:65)

W/System.err(17822):    at java.lang.Thread.run(Thread.java:1019)

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +278ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

E/(Messenger)messenger: (17822): NullPointerException

W/System.err(17822): java.lang.NullPointerException

W/System.err(17822):    at com.marie.mp3player.BackgroundService$ServiceWorker.run(BackgroundService.java:65)

W/System.err(17822):    at java.lang.Thread.run(Thread.java:1019)

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +282ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +307ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +284ms

D/MP3Player(17822): Stop the background Service

I/ActivityManager(   96): Starting: Intent { cmp=com.marie.mp3player/.PlayAudio (has extras) } from pid 17822

I/handleMessge(17822): songNum: 10

I/ActivityManager(   96): Displayed com.marie.mp3player/.PlayAudio: +291ms

It was suggested that I add the code where the NullPointerException occurs. Very important. In fact here's the whole thread where the exception occurs marked with an arrow and stars:

/*
 * This is the ServiceWorker thread that calls messenger to pass messages
 * and data to the PlayAudio activity.
 */
class ServiceWorker implements Runnable
{
    public void run() {
        // do background processing here... a simple message for now

        // send a message to the handler defined in the PlayAudio
        try {
            Message msg1 = Message.obtain();
            msg1.obj = "Song";
            msg1.arg1 = song;
            if (messenger == null) Log.e("(Messenger)messenger: ", "NullPointerException");
            messenger.send(msg1);   // <== *** EXCEPTION OCCURS HERE ***
        } catch (RemoteException e) {
            e.printStackTrace();
        } catch (NullPointerException e) {
            e.printStackTrace();
        }

        // stop the service when done...
        // BackgroundService.this.stopSelf();
        // Or use the unbindBtn in the MP3Player activity.
    }
}

If anyone sees a mistake here that would sometimes cause my Message instance to be null I sure would appreciate an answer.

Marie, assuming that the rest of your service is as in your other question. Here is what happens and causes your NPE.

• In onCreate you create and start your thread, but you extract messenger in onStart method. If your worker method executes before onStart, you get NPE. The order of them is random, so sometimes you get NPE and sometimes not.