[TIMOB-4706] Android: Cannot debug an application while using require('some_js_module')

Problem

Cannot debug an application in the Android emulator while using a require('some_js_module') in the application

Steps to reproduce

Step 1: Run the code below. Step 2: Run Indie bug mode and watch it crash.

Console log when debugging (Crash)

The following is logged when debugging (trace level): {noformat} D/Zygote ( 33): Process 503 terminated by signal (15) I/ActivityManager( 97): Process com.appcelerator.pushtest (pid 503) has died. I/WindowManager( 97): WIN DEATH: Window{43ebe460 com.appcelerator.pushtest/com.appcelerator.pushtest.Test1Activity paused=false} I/UsageStats( 97): Unexpected resume of com.android.launcher while already resumed in com.appcelerator.pushtest W/InputManagerService( 97): Got RemoteException sending setActive(false) notification to pid 503 uid 10040 D/AndroidRuntime( 532): D/AndroidRuntime( 532): >>>>>>>>>>>>>> AndroidRuntime START <<<<<<<<<<<<<< D/AndroidRuntime( 532): CheckJNI is ON D/AndroidRuntime( 532): --- registering native functions --- I/ActivityManager( 97): Starting activity: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10000000 cmp=com.appcelerator.pushtest/.Test1Activity } D/AndroidRuntime( 532): Shutting down VM D/jdwp ( 532): adbd disconnected I/AndroidRuntime( 532): NOTE: attach of thread 'Binder Thread #3' failed I/ActivityManager( 97): Start proc com.appcelerator.pushtest for activity com.appcelerator.pushtest/.Test1Activity: pid=538 uid=10040 gids={1015, 3003} D/dalvikvm( 33): GC_EXPLICIT freed 285 objects / 10816 bytes in 348ms D/dalvikvm( 33): GC_EXPLICIT freed 47 objects / 2080 bytes in 106ms D/dalvikvm( 33): GC_EXPLICIT freed 2 objects / 64 bytes in 83ms I/TiApplication( 538): (main) [0,0] checkpoint, app created. I/TiApplication( 538): (main) [217,217] Titanium 1.7.0 (2011/06/06 18:05 4155ee) D/TiDeployData( 538): (main) [70,287] Read deploy data: {"debuggerPort":63442,"debuggerEnabled":true,"fastdevPort":63444} E/TiPlatformHelper( 538): (main) [112,399] renaming ID D/dalvikvm( 538): GC_FOR_MALLOC freed 3593 objects / 341760 bytes in 83ms I/TiRootActivity( 538): (main) [0,0] checkpoint, on root activity create, savedInstanceState: null E/TiApplication( 538): (main) [288,288] APP PROXY: [Ti.App] D/TiCommonContactsApi( 538): (main) [24,312] Using newer contacts api. Android SDK level: 8 D/dalvikvm( 538): GC_FOR_MALLOC freed 5768 objects / 398176 bytes in 67ms D/TiDebugClient( 538): (Thread-10) [236,548] debugger connected D/TiDebugSession( 538): (Thread-10) [4,552] debug session started with /10.0.2.2 I/global ( 538): Default buffer size used in BufferedInputStream constructor. It would be better to be explicit if an 8k buffer is required. D/TiDebugSession( 538): (Thread-11) [9,561] session started D/TiDebugSession( 538): (Thread-11) [200,761] rcvd request: 21*1311010379851*version D/TiDebugSession( 538): (Thread-11) [5,766] write packet: 21*1311010379851*2*0.0.1 D/TiDebugSession( 538): (Thread-11) [11,777] rcvd request: 20*1311010379852*update D/TiDebugSession( 538): (Thread-11) [2,779] write packet: 19*1311010379852*0.0.1 D/TiDebugSession( 538): (Thread-11) [8,787] rcvd request: 45*1311010379853*option*stepFiltersEnabled*false D/TiDebugClient( 538): (Thread-11) [3,790] setting server property: stepFiltersEnabled = false D/TiDebugSession( 538): (Thread-11) [3,793] write packet: 13*1311010379853 D/TiDebugSession( 538): (Thread-11) [5,798] rcvd request: 36*1311010379854*option*monitorXHR*true D/TiDebugClient( 538): (Thread-11) [3,801] setting server property: monitorXHR = true D/TiDebugSession( 538): (Thread-11) [2,803] write packet: 13*1311010379854 D/TiDebugSession( 538): (Thread-11) [12,815] rcvd request: 45*1311010379855*option*suspendOnFirstLine*false D/TiDebugClient( 538): (Thread-11) [3,818] setting server property: suspendOnFirstLine = false D/TiDebugSession( 538): (Thread-11) [1,819] write packet: 13*1311010379855 D/TiDebugSession( 538): (Thread-11) [6,825] rcvd request: 46*1311010379856*option*suspendOnExceptions*false D/TiDebugClient( 538): (Thread-11) [3,828] setting server property: suspendOnExceptions = false D/TiDebugSession( 538): (Thread-11) [2,830] write packet: 13*1311010379856 D/TiDebugSession( 538): (Thread-11) [5,835] rcvd request: 41*1311010379857*option*suspendOnErrors*true D/TiDebugClient( 538): (Thread-11) [3,838] setting server property: suspendOnErrors = true D/TiDebugSession( 538): (Thread-11) [2,840] write packet: 13*1311010379857 D/TiDebugSession( 538): (Thread-11) [5,845] rcvd request: 43*1311010379858*option*suspendOnKeywords*true D/TiDebugClient( 538): (Thread-11) [6,851] setting server property: suspendOnKeywords = true D/TiDebugSession( 538): (Thread-11) [5,856] write packet: 13*1311010379858 D/TiDebugSession( 538): (Thread-11) [5,861] rcvd request: 45*1311010379859*option*bypassConstructors*false D/TiDebugClient( 538): (Thread-11) [7,868] setting server property: bypassConstructors = false D/TiDebugSession( 538): (Thread-11) [1,869] write packet: 13*1311010379859 D/TiDebugSession( 538): (Thread-11) [5,874] rcvd request: 45*1311010379860*option*stepFiltersEnabled*false D/TiDebugClient( 538): (Thread-11) [3,877] setting server property: stepFiltersEnabled = false D/TiDebugSession( 538): (Thread-11) [1,878] write packet: 13*1311010379860 D/TiDebugSession( 538): (Thread-11) [4,882] rcvd request: 30*1311010379861*detailFormatters D/TiDebugSession( 538): (Thread-11) [3,885] write packet: 13*1311010379861 D/TiDebugSession( 538): (Thread-11) [8,893] rcvd request: 53*1311010379862*breakpoint*create*app:/app.js*13*1*0**1 D/TiFastDev( 538): (Thread-11) [6,899] Enabling Fastdev on port 63444 D/TiFastDev( 538): (Thread-11) [15,914] sent tokens successfully D/TiFastDev( 538): (Thread-11) [3,917] Fastdev session handshake succesful. D/TiFastDev( 538): (Thread-11) [21,938] sent tokens successfully D/TiDebugSession( 538): (Thread-11) [144,1082] write packet: 21*1311010379862*created D/TiDebugSession( 538): (Thread-11) [6,1088] rcvd request: 20*1311010379863*enable D/TiDebugSession( 538): (Thread-11) [16,1104] write packet: 13*1311010379863 D/dalvikvm( 538): GC_FOR_MALLOC freed 2894 objects / 343128 bytes in 63ms I/global ( 538): 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 0x19f28 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/TiDebugClient( 538): (kroll$1: app://app.js) [177,1281] debugger evalFile: file:///android_asset/Resources/app.js D/TiDebugSession( 538): (kroll$1: app://app.js) [1,1282] write packet: 40*threads*created*9*kroll$1: [app:/app.js] D/TiDebugSession( 538): (kroll$1: app://app.js) [53,1335] write packet: 47*scripts*created*9|app:/app.js|app:/app.js|1|715 D/TitaniumModule( 538): (kroll$1: app://app.js) [116,1451] Attempting to include native module: ui D/TiFastDev( 538): (kroll$1: app://app.js) [10,1461] sent tokens successfully E/TitaniumModule( 538): (kroll$1: app://app.js) [113,1574] Error loading module named: ui E/TitaniumModule( 538): java.lang.ClassCastException: org.mozilla.javascript.Undefined E/TitaniumModule( 538): at ti.modules.titanium.TitaniumModule.require(TitaniumModule.java:434) E/TitaniumModule( 538): at ti.modules.titanium.TitaniumModuleBindingGen$23.invoke(TitaniumModuleBindingGen.java:875) E/TitaniumModule( 538): at org.appcelerator.kroll.KrollProxy$ThisMethod.invoke(KrollProxy.java:397) E/TitaniumModule( 538): at org.appcelerator.kroll.KrollMethod.call(KrollMethod.java:51) E/TitaniumModule( 538): at org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:1701) E/TitaniumModule( 538): at org.mozilla.javascript.Interpreter.interpret(Interpreter.java:854) E/TitaniumModule( 538): at org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:164) E/TitaniumModule( 538): at org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:426) E/TitaniumModule( 538): at org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3177) E/TitaniumModule( 538): at org.mozilla.javascript.InterpretedFunction.exec(InterpretedFunction.java:175) E/TitaniumModule( 538): at org.mozilla.javascript.Context.evaluateString(Context.java:1111) E/TitaniumModule( 538): at org.mozilla.javascript.tools.debugger.Dim$DimIProxy.run(Dim.java:1039) E/TitaniumModule( 538): at org.mozilla.javascript.Context.call(Context.java:521) E/TitaniumModule( 538): at org.mozilla.javascript.ContextFactory.call(ContextFactory.java:535) E/TitaniumModule( 538): at org.mozilla.javascript.tools.debugger.Dim$DimIProxy.withContext(Dim.java:1078) E/TitaniumModule( 538): at org.mozilla.javascript.tools.debugger.Dim$DimIProxy.access$3(Dim.java:1077) E/TitaniumModule( 538): at org.mozilla.javascript.tools.debugger.Dim.evalScript(Dim.java:677) E/TitaniumModule( 538): at ti.modules.titanium.debug.g.evaluateFile(Unknown Source) E/TitaniumModule( 538): at org.appcelerator.titanium.kroll.KrollContext.evaluateScript(KrollContext.java:306) E/TitaniumModule( 538): at org.appcelerator.titanium.kroll.KrollContext.handleEvalFile(KrollContext.java:318) E/TitaniumModule( 538): at org.appcelerator.titanium.kroll.KrollContext.handleMessage(KrollContext.java:217) E/TitaniumModule( 538): at org.appcelerator.titanium.TiMessageQueue.handleMessage(TiMessageQueue.java:223) E/TitaniumModule( 538): at android.os.Handler.dispatchMessage(Handler.java:95) E/TitaniumModule( 538): at android.os.Looper.loop(Looper.java:123) E/TitaniumModule( 538): at org.appcelerator.titanium.kroll.KrollHandlerThread.run(KrollHandlerThread.java:86) E/KrollMethod( 538): (kroll$1: app://app.js) [39,1613] Exception calling kroll method require, invocation: null ] E/KrollMethod( 538): org.mozilla.javascript.WrappedException: Wrapped java.lang.ClassCastException: org.mozilla.javascript.Undefined (file:///android_asset/Resources/app.js#5) E/KrollMethod( 538): at org.mozilla.javascript.Context.throwAsScriptRuntimeEx(Context.java:1786) E/KrollMethod( 538): at ti.modules.titanium.TitaniumModule.require(TitaniumModule.java:453) E/KrollMethod( 538): at ti.modules.titanium.TitaniumModuleBindingGen$23.invoke(TitaniumModuleBindingGen.java:875) E/KrollMethod( 538): at org.appcelerator.kroll.KrollProxy$ThisMethod.invoke(KrollProxy.java:397) E/KrollMethod( 538): at org.appcelerator.kroll.KrollMethod.call(KrollMethod.java:51) E/KrollMethod( 538): at org.mozilla.javascript.Interpreter.interpretLoop(Interpreter.java:1701) E/KrollMethod( 538): at script(file:///android_asset/Resources/app.js:5) E/KrollMethod( 538): at org.mozilla.javascript.Interpreter.interpret(Interpreter.java:854) E/KrollMethod( 538): at org.mozilla.javascript.InterpretedFunction.call(InterpretedFunction.java:164) E/KrollMethod( 538): at org.mozilla.javascript.ContextFactory.doTopCall(ContextFactory.java:426) E/KrollMethod( 538): at org.mozilla.javascript.ScriptRuntime.doTopCall(ScriptRuntime.java:3177) E/KrollMethod( 538): at org.mozilla.javascript.InterpretedFunction.exec(InterpretedFunction.java:175) E/KrollMethod( 538): at org.mozilla.javascript.Context.evaluateString(Context.java:1111) E/KrollMethod( 538): at org.mozilla.javascript.tools.debugger.Dim$DimIProxy.run(Dim.java:1039) E/KrollMethod( 538): at org.mozilla.javascript.Context.call(Context.java:521) E/KrollMethod( 538): at org.mozilla.javascript.ContextFactory.call(ContextFactory.java:535) E/KrollMethod( 538): at org.mozilla.javascript.tools.debugger.Dim$DimIProxy.withContext(Dim.java:1078) E/KrollMethod( 538): at org.mozilla.javascript.tools.debugger.Dim$DimIProxy.access$3(Dim.java:1077) E/KrollMethod( 538): at org.mozilla.javascript.tools.debugger.Dim.evalScript(Dim.java:677) E/KrollMethod( 538): at ti.modules.titanium.debug.g.evaluateFile(Unknown Source) E/KrollMethod( 538): at org.appcelerator.titanium.kroll.KrollContext.evaluateScript(KrollContext.java:306) E/KrollMethod( 538): at org.appcelerator.titanium.kroll.KrollContext.handleEvalFile(KrollContext.java:318) E/KrollMethod( 538): at org.appcelerator.titanium.kroll.KrollContext.handleMessage(KrollContext.java:217) E/KrollMethod( 538): at org.appcelerator.titanium.TiMessageQueue.handleMessage(TiMessageQueue.java:223) E/KrollMethod( 538): at android.os.Handler.dispatchMessage(Handler.java:95) E/KrollMethod( 538): at android.os.Looper.loop(Looper.java:123) E/KrollMethod( 538): at org.appcelerator.titanium.kroll.KrollHandlerThread.run(KrollHandlerThread.java:86) E/KrollMethod( 538): Caused by: java.lang.ClassCastException: org.mozilla.javascript.Undefined E/KrollMethod( 538): at ti.modules.titanium.TitaniumModule.require(TitaniumModule.java:434) E/KrollMethod( 538): ... 24 more I/System.out( 538): onExceptionThrown, cx:org.mozilla.javascript.Context@43e85600, exception:org.mozilla.javascript.WrappedException: Wrapped java.lang.ClassCastException: org.mozilla.javascript.Undefined (file:///android_asset/Resources/app.js#5) D/TiDebugSession( 538): (kroll$1: app://app.js) [24,1637] write packet: 130*log*err*[ERROR] Wrapped java.lang.ClassCastException: org.mozilla.javascript.Undefined (file:///android_asset/Resources/app.js#05) D/TiDebugSession( 538): (kroll$1: app://app.js) [4,1641] write packet: 35*suspended*9*exception*app:/app.js*5 D/TiDebugSession( 538): (Thread-11) [9,1650] rcvd request: 22*1311010379864*frames*9 D/FramesHandler( 538): Frame 0 scope: [object Object] D/TiDebugSession( 538): (Thread-11) [7,1657] write packet: 61*1311010379864*0|||app:/app.js|5|false|1311010380161|333894860 W/ActivityManager( 97): Activity idle timeout for HistoryRecord{43e80318 com.appcelerator.pushtest/.Test1Activity} D/TiDebugSession( 538): (Thread-11) [11141,12798] rcvd request: 34*1311010379865*variables*9*frame[0] D/VariablesHandler( 538): expr: frame[0], scope: [object Object], value: [object Object], name: null D/VariablesHandler( 538): o1: button, o1Class: class java.lang.String, o2: ui, o2Class: class java.lang.String D/VariablesHandler( 538): o1: win, o1Class: class java.lang.String, o2: button, o2Class: class java.lang.String D/VariablesHandler( 538): o1: win, o1Class: class java.lang.String, o2: ui, o2Class: class java.lang.String D/TiDebugSession( 538): (Thread-11) [24,12822] write packet: 114*1311010379865*button|Object|vwlpn|undefined*ui|Object|vwlpn|undefined*win|Ti.UI.Window|volpn|[object Ti.UI.Window] D/dalvikvm( 296): GC_EXPLICIT freed 168 objects / 8784 bytes in 67ms W/ActivityManager( 97): Timeout executing service: ServiceRecord{441ac5a0 com.appcelerator.pushtest/org.appcelerator.titanium.analytics.TiAnalyticsService} I/Process ( 97): Sending signal. PID: 538 SIG: 3 I/dalvikvm( 538): threadid=3: reacting to signal 3 I/dalvikvm( 538): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 97 SIG: 3 I/dalvikvm( 97): threadid=3: reacting to signal 3 I/dalvikvm( 97): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 228 SIG: 3 I/dalvikvm( 228): threadid=3: reacting to signal 3 I/dalvikvm( 228): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 296 SIG: 3 I/dalvikvm( 296): threadid=3: reacting to signal 3 I/dalvikvm( 296): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 331 SIG: 3 I/dalvikvm( 331): threadid=3: reacting to signal 3 I/dalvikvm( 331): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 486 SIG: 3 I/dalvikvm( 486): threadid=3: reacting to signal 3 I/dalvikvm( 486): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 464 SIG: 3 I/dalvikvm( 464): threadid=3: reacting to signal 3 I/dalvikvm( 464): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 314 SIG: 3 I/dalvikvm( 314): threadid=3: reacting to signal 3 I/dalvikvm( 314): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 358 SIG: 3 I/dalvikvm( 358): threadid=3: reacting to signal 3 I/dalvikvm( 358): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 409 SIG: 3 I/dalvikvm( 409): threadid=3: reacting to signal 3 I/dalvikvm( 409): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 389 SIG: 3 I/dalvikvm( 389): threadid=3: reacting to signal 3 I/dalvikvm( 389): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 375 SIG: 3 I/dalvikvm( 375): threadid=3: reacting to signal 3 I/dalvikvm( 375): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 442 SIG: 3 I/dalvikvm( 442): threadid=3: reacting to signal 3 I/dalvikvm( 442): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 232 SIG: 3 I/dalvikvm( 232): threadid=3: reacting to signal 3 I/dalvikvm( 232): Wrote stack traces to '/data/anr/traces.txt' I/Process ( 97): Sending signal. PID: 434 SIG: 3 I/dalvikvm( 434): threadid=3: reacting to signal 3 I/dalvikvm( 434): Wrote stack traces to '/data/anr/traces.txt' E/ActivityManager( 97): ANR in com.appcelerator.pushtest E/ActivityManager( 97): Reason: Executing service com.appcelerator.pushtest/org.appcelerator.titanium.analytics.TiAnalyticsService E/ActivityManager( 97): Load: 0.13 / 0.04 / 0.02 E/ActivityManager( 97): CPU usage from 19435ms to 39ms ago: E/ActivityManager( 97): erator.pushtest: 13% = 9% user + 3% kernel / faults: 5605 minor 65 major E/ActivityManager( 97): system_server: 1% = 0% user + 1% kernel / faults: 324 minor 8 major E/ActivityManager( 97): ndroid.launcher: 0% = 0% user + 0% kernel / faults: 310 minor E/ActivityManager( 97): logcat: 0% = 0% user + 0% kernel / faults: 13 minor E/ActivityManager( 97): m.android.phone: 0% = 0% user + 0% kernel / faults: 227 minor E/ActivityManager( 97): e.process.gapps: 0% = 0% user + 0% kernel / faults: 218 minor 4 major E/ActivityManager( 97): m.android.email: 0% = 0% user + 0% kernel / faults: 283 minor 4 major E/ActivityManager( 97): id.defcontainer: 0% = 0% user + 0% kernel / faults: 162 minor E/ActivityManager( 97): putmethod.latin: 0% = 0% user + 0% kernel / faults: 221 minor E/ActivityManager( 97): roid.alarmclock: 0% = 0% user + 0% kernel / faults: 177 minor E/ActivityManager( 97): d.process.media: 0% = 0% user + 0% kernel / faults: 152 minor E/ActivityManager( 97): m.android.music: 0% = 0% user + 0% kernel / faults: 160 minor E/ActivityManager( 97): com.svox.pico: 0% = 0% user + 0% kernel / faults: 158 minor E/ActivityManager( 97): qemud: 0% = 0% user + 0% kernel / faults: 21 minor E/ActivityManager( 97): .quicksearchbox: 0% = 0% user + 0% kernel / faults: 179 minor E/ActivityManager( 97): android.protips: 0% = 0% user + 0% kernel / faults: 167 minor E/ActivityManager( 97): s:FriendService: 0% = 0% user + 0% kernel / faults: 162 minor E/ActivityManager( 97): kswapd0: 0% = 0% user + 0% kernel E/ActivityManager( 97): TOTAL: 9% = 2% user + 4% kernel + 2% iowait I/ARMAssembler( 97): generated scanline__00000077:03515104_00000000_00000000 [ 33 ipp] (47 ins) at [0x2c1318:0x2c13d4] in 6439001 ns D/TiDebugSession( 538): (Thread-11) [9000,21822] rcvd request: 35*1311010379866*details*9*frame[0].ui D/dalvikvm( 538): GC_FOR_MALLOC freed 5467 objects / 426040 bytes in 72ms D/SntpClient( 97): request time failed: java.net.SocketException: Address family not supported by protocol D/SntpClient( 97): request time failed: java.net.SocketException: Address family not supported {noformat}

Reproduction code

// app.js
var win = Ti.UI.createWindow({
  backgroundColor: 'blue'
});

var ui = require('ui'); 
var button = Ti.UI.createButton({
  title: 'Test',
  top: 20,
  height: 50,
  width: 200
});
button.addEventListener('click', function(e){
  ui.alertIt('hi');
});
win.add(button);
win.open();

// ui.js
exports.alertIt = function(e) {
  alert(e);
};

Customer describing the problem

"I love Titanium Studio if it wasn't for the fact that I can NEVER debug an application in the Android emulator if I am using a require('some_js_module') in the application. If I take the default application and add at the top of app.js I add

Titanium.UI.setBackgroundColor('#000');
var ui = require('ui'); 
// create tab group
var tabGroup = Titanium.UI.createTabGroup();

...then create a ui.js file and put the following inside

exports.alertIt = function(e) {
  alert(e);
};

... then try to debug the application on Android ...the debugger throws an exception as soon as it reaches var ui = require('ui'); and the application stops there.