[TIMOB-4525] Android: Services Crash Debugger

GitHub Issue	n/a
Type	Bug
Priority	High
Status	Closed
Resolution	Fixed
Resolution Date	2011-08-26T15:05:43.000+0000
Affected Version/s	Release 1.7.0, Release 1.7.1, Release 1.8.0
Fix Version/s	Sprint 2011-33, Release 1.8.0
Components	Android
Labels	n/a
Reporter	Dawson Toth
Assignee	Vikramjeet Singh
Created	2011-06-29T13:27:13.000+0000
Updated	2011-09-13T10:59:44.000+0000

Description

Problem

Services crash the debugger in Ti Studio when you try to step over them.

Reproduction

Drop the following in an app.js, service.js, and tiapp.xml and follow the instructions in the code's comments. There are 3 steps to follow, after which the debugger will crash.

/* STEP 1: Place a breakpoint on the next line */
Titanium.UI.setBackgroundColor('#000');

/* STEP 2: Debug the app, and step over each line one at a time until you hit "STEP 3" */
var intent = Ti.Android.createServiceIntent({ url: 'service.js' });
intent.putExtra('interval', 6000);
intent.putExtra('message', 'Hi from bound service');

/* STEP 3: Step one more time over the next line, and the debugger should crash! */
var service = Ti.Android.createService(intent);
service.start();

var window = Ti.UI.createWindow({ backgroundColor: '#fff' });
window.add(Ti.UI.createLabel({ text: 'Debug this app to crash the debugger' }));
window.open();

Ti.API.info('in service');

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<ti:app xmlns:ti="http://ti.appcelerator.org">
    ...
    <android xmlns:android="http://schemas.android.com/apk/res/android">
        <services>
            <service type="interval" url="service.js"/>
        </services>
    </android>
    ...
</ti:app>

Workaround

Don't debug. Brilliant, eh?

Log When Debugging (Crash)

The following is logged when debugging (trace level):

I/ActivityManager(   60): Start proc com.dawson.playgroundmobile for activity com.dawson.playgroundmobile/.PlaygroundmobileActivity: pid=268 uid=10033 gids={1015, 3003}
D/MediaScannerService(  211): done scanning volume internal
D/MediaScannerService(  211): start scanning volume external
V/MediaProvider(  211): /mnt/sdcard volume ID: 266415125
I/TiApplication(  268): (main) [0,0] checkpoint, app created.
I/TiApplication(  268): (main) [353,353] Titanium 1.7.1 (2011/06/21 14:28 293a6d)
D/TiDeployData(  268): (main) [85,438] Read deploy data: {"debuggerPort":62892,"debuggerEnabled":true,"fastdevPort":62586}
E/TiPlatformHelper(  268): (main) [153,591] renaming ID
D/dalvikvm(  268): GC_FOR_MALLOC freed 3297 objects / 331768 bytes in 101ms
I/TiRootActivity(  268): (main) [1,1] checkpoint, on root activity create, savedInstanceState: null
E/TiApplication(  268): (main) [645,646] APP PROXY: [Ti.App]
D/TiCommonContactsApi(  268): (main) [47,693] Using newer contacts api.  Android SDK level: 8
D/dalvikvm(  268): GC_FOR_MALLOC freed 5815 objects / 395352 bytes in 83ms
D/TiDebugClient(  268): (Thread-10) [561,1254] debugger connected
D/TiDebugSession(  268): (Thread-10) [8,1262] debug session started with /10.0.2.2
I/global  (  268): Default buffer size used in BufferedInputStream constructor. It would be better to be explicit if an 8k buffer is required.
D/TiDebugSession(  268): (Thread-11) [12,1274] session started
D/TiDebugSession(  268): (Thread-11) [17,1291] rcvd request: 21*1309378982340*version
D/TiDebugSession(  268): (Thread-11) [6,1297] write packet: 21*1309378982340*2*0.0.1
D/TiDebugSession(  268): (Thread-11) [10,1307] rcvd request: 36*1309378982341*option*monitorXHR*true
D/TiDebugClient(  268): (Thread-11) [3,1310] setting server property: monitorXHR = true
D/TiDebugSession(  268): (Thread-11) [1,1311] write packet: 13*1309378982341
D/TiDebugSession(  268): (Thread-11) [11,1322] rcvd request: 45*1309378982342*option*suspendOnFirstLine*false
D/TiDebugClient(  268): (Thread-11) [5,1327] setting server property: suspendOnFirstLine = false
D/TiDebugSession(  268): (Thread-11) [4,1331] write packet: 13*1309378982342
D/TiDebugSession(  268): (Thread-11) [11,1342] rcvd request: 45*1309378982343*option*stepFiltersEnabled*false
D/TiDebugClient(  268): (Thread-11) [4,1346] setting server property: stepFiltersEnabled = false
D/TiDebugSession(  268): (Thread-11) [5,1351] write packet: 13*1309378982343
D/TiDebugSession(  268): (Thread-11) [9,1360] rcvd request: 46*1309378982344*option*suspendOnExceptions*false
D/TiDebugClient(  268): (Thread-11) [2,1362] setting server property: suspendOnExceptions = false
D/TiDebugSession(  268): (Thread-11) [1,1363] write packet: 13*1309378982344
D/TiDebugSession(  268): (Thread-11) [7,1370] rcvd request: 41*1309378982345*option*suspendOnErrors*true
D/TiDebugClient(  268): (Thread-11) [3,1373] setting server property: suspendOnErrors = true
D/TiDebugSession(  268): (Thread-11) [2,1375] write packet: 13*1309378982345
D/TiDebugSession(  268): (Thread-11) [16,1391] rcvd request: 43*1309378982346*option*suspendOnKeywords*true
D/TiDebugClient(  268): (Thread-11) [5,1396] setting server property: suspendOnKeywords = true
D/TiDebugSession(  268): (Thread-11) [9,1405] write packet: 13*1309378982346
D/TiDebugSession(  268): (Thread-11) [10,1415] rcvd request: 45*1309378982347*option*bypassConstructors*false
D/TiDebugClient(  268): (Thread-11) [3,1418] setting server property: bypassConstructors = false
D/TiDebugSession(  268): (Thread-11) [2,1420] write packet: 13*1309378982347
D/TiDebugSession(  268): (Thread-11) [10,1430] rcvd request: 45*1309378982348*option*stepFiltersEnabled*false
D/TiDebugClient(  268): (Thread-11) [3,1433] setting server property: stepFiltersEnabled = false
D/TiDebugSession(  268): (Thread-11) [0,1433] write packet: 13*1309378982348
D/TiDebugSession(  268): (Thread-11) [8,1441] rcvd request: 30*1309378982349*detailFormatters
D/TiDebugSession(  268): (Thread-11) [6,1447] write packet: 13*1309378982349
D/TiDebugSession(  268): (Thread-11) [10,1457] rcvd request: 20*1309378982350*enable
D/TiDebugSession(  268): (Thread-11) [21,1478] write packet: 13*1309378982350
I/global  (  268): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
D/qemud   (   38): fdhandler_accept_event: accepting on fd 10
D/qemud   (   38): created client 0x150b8 listening on fd 15
D/qemud   (   38): client_fd_receive: attempting registration for service 'sensors'
D/qemud   (   38): client_fd_receive:    -> received channel id 8
D/qemud   (   38): client_registration: registration succeeded for client 8
D/qemud   (   38): fdhandler_event: disconnect on fd 15
D/TiDebugClient(  268): (kroll$1: app://app.js) [214,1692] debugger evalFile: file:///android_asset/Resources/app.js
D/TiDebugSession(  268): (kroll$1: app://app.js) [2,1694] write packet: 40*threads*created*9*kroll$1: [app:/app.js]
D/TiFastDev(  268): (kroll$1: app://app.js) [13,1707] Enabling Fastdev on port 62586
D/TiFastDev(  268): (kroll$1: app://app.js) [29,1736] sent tokens successfully
D/TiFastDev(  268): (kroll$1: app://app.js) [1,1737] Fastdev session handshake succesful.
D/TiFastDev(  268): (kroll$1: app://app.js) [13,1750] sent tokens successfully
D/TiDebugSession(  268): (kroll$1: app://app.js) [116,1866] write packet: 46*scripts*created*9|app:/app.js|app:/app.js|1|15
W/dalvikvm(  268): threadid=11: thread exiting with uncaught exception (group=0x4001d800)
E/TiUncaughtHandler(  268): (kroll$2) [129,1995] Sending event: exception on thread: kroll$2 msg:java.lang.NullPointerException; Titanium 1.7.1,2011/06/21 14:28,293a6d
E/TiUncaughtHandler(  268): java.lang.NullPointerException
E/TiUncaughtHandler(  268): 	at ti.modules.titanium.debug.DebugServer.e(Unknown Source)
E/TiUncaughtHandler(  268): 	at ti.modules.titanium.debug.DebugServer.a(Unknown Source)
E/TiUncaughtHandler(  268): 	at ti.modules.titanium.debug.g.threadStarted(Unknown Source)
E/TiUncaughtHandler(  268): 	at org.appcelerator.titanium.kroll.KrollContext.initContext(KrollContext.java:178)
E/TiUncaughtHandler(  268): 	at org.appcelerator.titanium.kroll.KrollHandlerThread.onLooperPrepared(KrollHandlerThread.java:74)
E/TiUncaughtHandler(  268): 	at org.appcelerator.titanium.kroll.KrollHandlerThread.run(KrollHandlerThread.java:85)
E/AndroidRuntime(  268): FATAL EXCEPTION: kroll$2
E/AndroidRuntime(  268): java.lang.NullPointerException
E/AndroidRuntime(  268): 	at ti.modules.titanium.debug.DebugServer.e(Unknown Source)
E/AndroidRuntime(  268): 	at ti.modules.titanium.debug.DebugServer.a(Unknown Source)
E/AndroidRuntime(  268): 	at ti.modules.titanium.debug.g.threadStarted(Unknown Source)
E/AndroidRuntime(  268): 	at org.appcelerator.titanium.kroll.KrollContext.initContext(KrollContext.java:178)
E/AndroidRuntime(  268): 	at org.appcelerator.titanium.kroll.KrollHandlerThread.onLooperPrepared(KrollHandlerThread.java:74)
E/AndroidRuntime(  268): 	at org.appcelerator.titanium.kroll.KrollHandlerThread.run(KrollHandlerThread.java:85)
W/ActivityManager(   60):   Force finishing activity com.dawson.playgroundmobile/.PlaygroundmobileActivity
V/MediaProvider(  211): Attached volume: external
I/ARMAssembler(   60): generated scanline__00000077:03515104_00000000_00000000 [ 33 ipp] (47 ins) at [0x3551c8:0x355284] in 5386001 ns
W/ActivityManager(   60): Activity pause timeout for HistoryRecord{43fbdd68 com.dawson.playgroundmobile/.PlaygroundmobileActivity}
D/AlarmManagerService(   60): Kernel timezone updated to 240 minutes west of GMT
D/SystemClock(  114): Setting time of day to sec=1309378985
W/SystemClock(  114): Unable to set rtc to 1309378985: Invalid argument
I/Launcher.Model(  116): not binding apps: no Launcher activity
D/dalvikvm(  116): GC_EXPLICIT freed 3764 objects / 214272 bytes in 258ms
D/dalvikvm(  116): GC_EXPLICIT freed 5125 objects / 253072 bytes in 83ms
D/MediaScanner(  211):  prescan time: 1824ms
D/MediaScanner(  211):     scan time: 2360ms
D/MediaScanner(  211): postscan time: 1ms
D/MediaScanner(  211):    total time: 4185ms
D/MediaScannerService(  211): done scanning volume external
I/Process (  268): Sending signal. PID: 268 SIG: 9
I/ActivityManager(   60): Process com.dawson.playgroundmobile (pid 268) has died.
W/ActivityManager(   60): Scheduling restart of crashed service com.dawson.playgroundmobile/org.appcelerator.titanium.analytics.TiAnalyticsService in 12824ms
W/InputManagerService(   60): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@440161e8
W/ActivityManager(   60): Activity destroy timeout for HistoryRecord{43fbdd68 com.dawson.playgroundmobile/.PlaygroundmobileActivity}

Log When Running (Normal Run, No Crash)

The following is logged when you simply run the app in the emulator, without the debugger (trace level).

I/ActivityManager(   60): Start proc com.dawson.playgroundmobile for activity com.dawson.playgroundmobile/.PlaygroundmobileActivity: pid=312 uid=10033 gids={1015, 3003}
I/AndroidRuntime(  305): NOTE: attach of thread 'Binder Thread #3' failed
I/TiApplication(  312): (main) [0,0] checkpoint, app created.
I/TiApplication(  312): (main) [245,245] Titanium 1.7.1 (2011/06/21 14:28 293a6d)
D/TiDeployData(  312): (main) [74,319] Read deploy data: {"debuggerPort":-1,"debuggerEnabled":false,"fastdevPort":62586}
E/TiPlatformHelper(  312): (main) [120,439] renaming ID
D/dalvikvm(  312): GC_FOR_MALLOC freed 3349 objects / 333696 bytes in 92ms
I/TiRootActivity(  312): (main) [0,0] checkpoint, on root activity create, savedInstanceState: null
E/TiApplication(  312): (main) [311,311] APP PROXY: [Ti.App]
D/TiCommonContactsApi(  312): (main) [33,344] Using newer contacts api.  Android SDK level: 8
D/dalvikvm(  312): GC_FOR_MALLOC freed 5781 objects / 393616 bytes in 77ms
I/global  (  312): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
D/qemud   (   38): fdhandler_accept_event: accepting on fd 10
D/qemud   (   38): created client 0x16068 listening on fd 15
D/qemud   (   38): client_fd_receive: attempting registration for service 'sensors'
D/qemud   (   38): client_fd_receive:    -> received channel id 9
D/qemud   (   38): client_registration: registration succeeded for client 9
D/qemud   (   38): fdhandler_event: disconnect on fd 15
D/TiFastDev(  312): (kroll$1: app://app.js) [652,996] Enabling Fastdev on port 62586
D/TiFastDev(  312): (kroll$1: app://app.js) [18,1014] sent tokens successfully
D/TiFastDev(  312): (kroll$1: app://app.js) [2,1016] Fastdev session handshake succesful.
D/dalvikvm(  312): GC_FOR_MALLOC freed 7542 objects / 510416 bytes in 73ms
D/TiFastDev(  312): (kroll$1: app://app.js) [88,1104] sent tokens successfully
D/KrollContext(  312): (kroll$1: app://app.js) [3,1107] Running evaluated script: file:///android_asset/Resources/app.js
I/global  (  312): Default buffer size used in BufferedReader constructor. It would be better to be explicit if an 8k-char buffer is required.
D/dalvikvm(  312): GC_FOR_MALLOC freed 6459 objects / 464712 bytes in 80ms
I/TiRootActivity(  312): (main) [0,0] checkpoint, on root activity resume. context = org.appcelerator.titanium.TiContext@43e5daf0
D/dalvikvm(   60): GREF has increased to 301
W/TiAnalyticsSvc(  312): (Thread-12) [59,59] Analytics Service Started
D/TiFastDev(  312): (kroll$2) [224,283] sent tokens successfully
D/KrollContext(  312): (kroll$2) [2,285] Running evaluated script: app://service.js
I/TiAPI   (  312): (kroll$2) [5,290] in service
I/ActivityManager(   60): Displayed activity com.dawson.playgroundmobile/.PlaygroundmobileActivity: 3820 ms (total 157392 ms)
I/TiAnalyticsSvc(  312): (Thread-12) [492,782] Sending 1 analytics events.
D/dalvikvm(  312): GC_FOR_MALLOC freed 5919 objects / 373080 bytes in 91ms
D/dalvikvm(  312): GC_FOR_MALLOC freed 1391 objects / 70192 bytes in 70ms
W/TiAnalyticsSvc(  312): (Thread-12) [1072,1854] Stopping Analytics Service
D/dalvikvm(  116): GC_EXPLICIT freed 205 objects / 9392 bytes in 55ms
D/TiFastDev(  312): (kroll$2) [4427,6281] sent tokens successfully
D/KrollContext(  312): (kroll$2) [1,6282] Running evaluated script: app://service.js
I/TiAPI   (  312): (kroll$2) [5,6287] in service
D/TiFastDev(  312): (kroll$2) [5995,12282] sent tokens successfully
D/KrollContext(  312): (kroll$2) [2,12284] Running evaluated script: app://service.js
I/TiAPI   (  312): (kroll$2) [4,12288] in service

Associated Helpdesk Ticket

http://appc.me/c/APP-963284

Comments

Miguel Vizcaino 2011-07-12