Closed Bug 1013004 Opened 10 years ago Closed 9 years ago

Intermittent testANRReporter | Exception caught - org.json.JSONException: Unterminated string at character 2638 of {JSON}

Categories

(Firefox for Android Graveyard :: General, defect)

ARM
Android
defect
Not set
normal

Tracking

(firefox32 wontfix, firefox33 wontfix, firefox34 wontfix, firefox35 wontfix, firefox36 fixed, firefox-esr24 unaffected, firefox-esr31 unaffected)

RESOLVED FIXED
Firefox 36
Tracking Status
firefox32 --- wontfix
firefox33 --- wontfix
firefox34 --- wontfix
firefox35 --- wontfix
firefox36 --- fixed
firefox-esr24 --- unaffected
firefox-esr31 --- unaffected

People

(Reporter: KWierso, Assigned: jchen)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

https://tbpl.mozilla.org/php/getParsedLog.php?id=39952945&tree=Mozilla-Aurora
Android 4.0 Panda mozilla-aurora opt test robocop-1 on 2014-05-19 08:15:31 PDT for push 42d103fc8993

slave: panda-0133



08:33:10     INFO -  1 INFO TEST-START | testANRReporter
08:33:10     INFO -  2 INFO TEST-PASS | testANRReporter | Given message occurred for registered event: {"type":"Gecko:Ready"} - Gecko:Ready should equal Gecko:Ready
08:33:10     INFO -  EventExpecter: no longer listening for Gecko:Ready
08:33:10     INFO -  3 INFO TEST-PASS | testANRReporter | Ping directory is empty
08:33:10     INFO -  4 INFO TEST-PASS | testANRReporter | Successfully set package name - org.mozilla.fennec_aurora should equal org.mozilla.fennec_aurora
08:33:10     INFO -  5 INFO TEST-PASS | testANRReporter | testContext should not be null - android.app.ContextImpl@412584b0 should not equal null
08:33:10     INFO -  6 INFO TEST-INFO | testANRReporter | Triggering ANR
08:33:10     INFO -  7 INFO TEST-INFO | testANRReporter | Triggering second ANR
08:33:10     INFO -  8 INFO TEST-INFO | testANRReporter | Waiting for ping
08:33:10     INFO -  waitForCondition timeout after 10000 ms.
08:33:10     INFO -  9 INFO TEST-PASS | testANRReporter | Ping directory exists
08:33:10     INFO -  10 INFO TEST-PASS | testANRReporter | Ping directory is a directory
08:33:10     INFO -  11 INFO TEST-PASS | testANRReporter | Ping directory is not empty - [Ljava.io.File;@412c8898 should not equal null
08:33:10     INFO -  12 INFO TEST-PASS | testANRReporter | ANR reporter wrote one ping - 1 should equal 1
08:33:10     INFO -  13 INFO TEST-PASS | testANRReporter | Ping exists
08:33:10     INFO -  14 INFO TEST-PASS | testANRReporter | Ping is a file
08:33:10     INFO -  15 INFO TEST-PASS | testANRReporter | Ping is readable
08:33:10     INFO -  16 INFO TEST-INFO | testANRReporter | Found ping file - /mnt/sdcard/tests/profile/saved-telemetry-pings/0d0e8fa0-e13b-4674-949e-3528d87f06ae
08:33:10     INFO -  Exception caught during test!
08:33:10     INFO -  org.json.JSONException: Unterminated string at character 2638 of {"reason":"android-anr-report","slug":"0d0e8fa0-e13b-4674-949e-3528d87f06ae","payload":{"ver":1,"simpleMeasurements":{"uptime":0},"info":{"reason":"android-anr-report","OS":"Android","version":"15","appID":"{aa3c5121-dab2-40e2-81ca-7ea25febc110}","appVersion":"31.0a2","appName":"Fennec","appBuildID":"20140519065232","appUpdateChannel":"default","platformBuildID":"20140519065232","locale":"en-US","cpucount":2,"memsize":899,"arch":"armeabi-v7a","kernel_version":"3.2.0+","device":"pandaboard","manufacturer":"unknown","hardware":"omap4pandaboard"},"androidANR":"----- pid 1 at 2014-01-15 18:55:51 -----\nCmd line: org.mozilla.fennec_aurora\n\nJNI: CheckJNI is off; workarounds are off; pins=0; globals=397\n\nDALVIK THREADS:\n(mutexes: tll=0 tsl=0 tscl=0 ghl=0)\n\n\"main\" prio=5 tid=1 WAIT\n  | group=\"main\" sCount=1 dsCount=0 obj=0x41d6bc90 self=0x41d5a3c8\n  | sysTid=3485 nice=0 sched=0\/0 cgrp=apps handle=1074852180\n  | state=S schedstat=( 0 0 0 ) utm=1065 stm=152 core=0\n  at java.lang.Object.wait(Native Method)\n  - waiting on <0x427ab340> (a org.mozilla.gecko.GeckoEditable$5)\n  at java.lang.Object.wait(Object.java:364)\n  at org.mozilla.gecko.GeckoEditable$5.run(GeckoEditable.java:746)\n  at android.os.Handler.handleCallback(Handler.java:733)\n  at android.os.Handler.dispatchMessage(Handler.java:95)\n  at android.os.Looper.loop(Looper.java:137)\n  at android.app.ActivityThread.main(ActivityThread.java:4998)\n  at java.lang.reflect.Method.invokeNative(Native Method)\n  at java.lang.reflect.Method.invoke(Method.java:515)\n  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:777)\n  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:593)\n  at dalvik.system.NativeStart.main(Native Method)\n\n\"Gecko\" prio=5 tid=16 SUSPENDED\n  | group=\"main\" sCount=1 dsCount=0 obj=0x426e2b28 self=0x76ae92e8\n  | sysTid=3541 nice=0 sched=0\/0 cgrp=apps handle=1991153472\n  | state=S schedstat=( 0 0 0 ) utm=1118 stm=145 core=0\n  #00  pc 00000904  \/system\/lib\/libc.so (__futex_syscall3+4294832136)\n  #01  pc 0000eec4  \/system\/lib\/libc.so (__pthread_cond_timedwait_relative+48)\n  #02  pc 0000ef24  \/system\/lib\/libc.so (__pthread_cond_timedwait+64)\n  #03  pc 000536b7  \/system\/lib\/libdvm.so\n  #04  pc 00053c79  \/system\/lib\/libdvm.so (dvmChangeStatus(Thread*, ThreadStatus)+34)\n  #05  pc 00049507  \/system\/lib\/libdvm.so\n  #06  pc 0004d84b  \/system\/lib\/libdvm.so\n  #07  pc 0003f1df  \/dev\/ashmem\/libxul.so (deleted)\n  at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)\n  at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:384)\n  a
08:33:10     INFO -  	at org.json.JSONTokener.syntaxError(JSONTokener.java:450)
08:33:10     INFO -  	at org.json.JSONTokener.nextString(JSONTokener.java:230)
08:33:10     INFO -  	at org.json.JSONTokener.nextValue(JSONTokener.java:107)
08:33:10     INFO -  	at org.json.JSONTokener.readObject(JSONTokener.java:385)
08:33:10     INFO -  	at org.json.JSONTokener.nextValue(JSONTokener.java:100)
08:33:10     INFO -  	at org.json.JSONTokener.readObject(JSONTokener.java:385)
08:33:10     INFO -  	at org.json.JSONTokener.nextValue(JSONTokener.java:100)
08:33:10     INFO -  	at org.json.JSONObject.<init>(JSONObject.java:154)
08:33:10     INFO -  	at org.json.JSONObject.<init>(JSONObject.java:171)
08:33:10     INFO -  	at org.mozilla.gecko.tests.testANRReporter.readPingFile(testANRReporter.java:93)
08:33:10     INFO -  	at org.mozilla.gecko.tests.testANRReporter.testANRReporter(testANRReporter.java:195)
08:33:10     INFO -  	at java.lang.reflect.Method.invokeNative(Native Method)
08:33:10     INFO -  	at java.lang.reflect.Method.invoke(Method.java:511)
08:33:10     INFO -  	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:214)
08:33:10     INFO -  	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:199)
08:33:10     INFO -  	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:192)
08:33:10     INFO -  	at org.mozilla.gecko.tests.BaseTest.runTest(BaseTest.java:125)
08:33:10     INFO -  	at junit.framework.TestCase.runBare(TestCase.java:127)
08:33:10     INFO -  	at junit.framework.TestResult$1.protect(TestResult.java:106)
08:33:10     INFO -  	at junit.framework.TestResult.runProtected(TestResult.java:124)
08:33:10     INFO -  	at junit.framework.TestResult.run(TestResult.java:109)
08:33:10     INFO -  	at junit.framework.TestCase.run(TestCase.java:118)
08:33:10     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
08:33:10     INFO -  	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
08:33:10     INFO -  	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:545)
08:33:10     INFO -  	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1551)
08:33:10     INFO -  17 INFO TEST-UNEXPECTED-FAIL | testANRReporter | Exception caught - org.json.JSONException: Unterminated string at character 2638 of {"reason":"android-anr-report","slug":"0d0e8fa0-e13b-4674-949e-3528d87f06ae","payload":{"ver":1,"simpleMeasurements":{"uptime":0},"info":{"reason":"android-anr-report","OS":"Android","version":"15","appID":"{aa3c5121-dab2-40e2-81ca-7ea25febc110}","appVersion":"31.0a2","appName":"Fennec","appBuildID":"20140519065232","appUpdateChannel":"default","platformBuildID":"20140519065232","locale":"en-US","cpucount":2,"memsize":899,"arch":"armeabi-v7a","kernel_version":"3.2.0+","device":"pandaboard","manufacturer":"unknown","hardware":"omap4pandaboard"},"androidANR":"----- pid 1 at 2014-01-15 18:55:51 -----\nCmd line: org.mozilla.fennec_aurora\n\nJNI: CheckJNI is off; workarounds are off; pins=0; globals=397\n\nDALVIK THREADS:\n(mutexes: tll=0 tsl=0 tscl=0 ghl=0)\n\n\"main\" prio=5 tid=1 WAIT\n  | group=\"main\" sCount=1 dsCount=0 obj=0x41d6bc90 self=0x41d5a3c8\n  | sysTid=3485 nice=0 sched=0\/0 cgrp=apps handle=1074852180\n  | state=S schedstat=( 0 0 0 ) utm=1065 stm=152 core=0\n  at java.lang.Object.wait(Native Method)\n  - waiting on <0x427ab340> (a org.mozilla.gecko.GeckoEditable$5)\n  at java.lang.Object.wait(Object.java:364)\n  at org.mozilla.gecko.GeckoEditable$5.run(GeckoEditable.java:746)\n  at android.os.Handler.handleCallback(Handler.java:733)\n  at android.os.Handler.dispatchMessage(Handler.java:95)\n  at android.os.Looper.loop(Looper.java:137)\n  at android.app.ActivityThread.main(ActivityThread.java:4998)\n  at java.lang.reflect.Method.invokeNative(Native Method)\n  at java.lang.reflect.Method.invoke(Method.java:515)\n  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:777)\n  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:593)\n  at dalvik.system.NativeStart.main(Native Method)\n\n\"Gecko\" prio=5 tid=16 SUSPENDED\n  | group=\"main\" sCount=1 dsCount=0 obj=0x426e2b28 self=0x76ae92e8\n  | sysTid=3541 nice=0 sched=0\/0 cgrp=apps handle=1991153472\n  | state=S schedstat=( 0 0 0 ) utm=1118 stm=145 core=0\n  #00  pc 00000904  \/system\/lib\/libc.so (__futex_syscall3+4294832136)\n  #01  pc 0000eec4  \/system\/lib\/libc.so (__pthread_cond_timedwait_relative+48)\n  #02  pc 0000ef24  \/system\/lib\/libc.so (__pthread_cond_timedwait+64)\n  #03  pc 000536b7  \/system\/lib\/libdvm.so\n  #04  pc 00053c79  \/system\/lib\/libdvm.so (dvmChangeStatus(Thread*, ThreadStatus)+34)\n  #05  pc 00049507  \/system\/lib\/libdvm.so\n  #06  pc 0004d84b  \/system\/lib\/libdvm.so\n  #07  pc 0003f1df  \/dev\/ashmem\/libxul.so (deleted)\n  at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)\n  at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:384)\n  a
08:33:10     INFO -  18 INFO TEST-END | testANRReporter | finished in 14814ms
08:33:10     INFO -  19 INFO TEST-START | Shutdown
RyanVM just pointed this one out too, which is a little different: https://tbpl.mozilla.org/php/getParsedLog.php?id=44038006&full=1&branch=mozilla-central

Android 4.2 x86 Emulator mozilla-central opt test androidx86-set-4 on 2014-07-17 08:45:18 PDT

09:14:00     INFO -  15 INFO TEST-PASS | testANRReporter | Ping is readable
09:14:00     INFO -  16 INFO TEST-INFO | testANRReporter | Found ping file - /mnt/sdcard/tests/profile/saved-telemetry-pings/5e99c087-ebb5-4091-b5c8-75bd0889509c
09:14:00     INFO -  Exception caught during test!
09:14:00     INFO -  org.json.JSONException: Unterminated string at character 23963 of {"reason":"android-anr-report","slug":"5e99c087-ebb5-4091-b5c8-75bd0889509c","payload":{"ver":1,"simpleMeasurements":{"uptime":0},"info":{"reason":"android-anr-report","OS":"Android","version":"17","appID":"{aa3c5121-dab2-40e2-81ca-7ea25febc110}","appVersion":"33.0a1","appName":"Fennec","appBuildID":"20140717073317","appUpdateChannel":"default","platformBuildID":"20140717073317","locale":"en-US","cpucount":1,"memsize":882,"arch":"x86","kernel_version":"2.6.29","device":"Full Android on Emulator","manufacturer":"unknown","hardware":"goldfish"},"androidANR":"----- pid 1 at 2014-01-15 18:55:51 -----\nCmd line: org.mozilla.fennec\n\nJNI: CheckJNI is off; workarounds are off; pins=0; globals=397\n\nDALVIK THREADS:\n(mutexes: tll=0 tsl=0 tscl=0 ghl=0)\n\n\"main\" prio=5 tid=1 WAIT\n  | group=\"main\" sCount=1 dsCount=0 obj=0x41d6bc90 self=0x41d5a3c8\n  | sysTid=3485 nice=0 sched=0\/0 cgrp=apps handle=1074852180\n  | state=S schedstat=( 0 0 0 ) utm=1065 stm=152 core=0\n  at java.lang.Object.wait(Native Method)\n  - waiting on <0x427ab340> (a org.mozilla.gecko.GeckoEditable$5)\n  at java.lang.Object.wait(Object.java:364)\n  at org.mozilla.gecko.GeckoEditable$5.run(GeckoEditable.java:746)\n  at android.os.Handler.handleCallback(Handler.java:733)\n  at android.os.Handler.dispatchMessage(Handler.java:95)\n  at android.os.Looper.loop(Looper.java:137)\n  at android.app.ActivityThread.main(ActivityThread.java:4998)\n  at java.lang.reflect.Method.invokeNative(Native Method)\n  at java.lang.reflect.Method.invoke(Method.java:515)\n  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:777)\n  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:593)\n  at dalvik.system.NativeStart.main(Native Method)\n\n\"Gecko\" prio=5 tid=16 SUSPENDED\n  | group=\"main\" sCount=1 dsCount=0 obj=0x426e2b28 self=0x76ae92e8\n  | sysTid=3541 nice=0 sched=0\/0 cgrp=apps handle=1991153472\n  | state=S schedstat=( 0 0 0 ) utm=1118 stm=145 core=0\n  #00  pc 00000904  \/system\/lib\/libc.so (__futex_syscall3+4294832136)\n  #01  pc 0000eec4  \/system\/lib\/libc.so (__pthread_cond_timedwait_relative+48)\n  #02  pc 0000ef24  \/system\/lib\/libc.so (__pthread_cond_timedwait+64)\n  #03  pc 000536b7  \/system\/lib\/libdvm.so\n  #04  pc 00053c79  \/system\/lib\/libdvm.so (dvmChangeStatus(Thread*, ThreadStatus)+34)\n  #05  pc 00049507  \/system\/lib\/libdvm.so\n  #06  pc 0004d84b  \/system\/lib\/libdvm.so\n  #07  pc 0003f1df  \/dev\/ashmem\/libxul.so (deleted)\n  at org.mozilla.gecko.mozglue.GeckoLoader.nativeRun(Native Method)\n  at org.mozilla.gecko.GeckoAppShell.runGecko(GeckoAppShell.java:384)\n  at org.mozilla.gecko.GeckoThread.run(GeckoThread.java:177)\n\n----- end","androidLogcat":"07-17 15:53:32.846  2446  2446 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.846  2446  2446 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  1203  1203 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  1203  1203 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856   803  1481 E SurfaceFlinger: ro.sf.lcd_density must be defined as a build property\n07-17 15:53:32.856  1203  1341 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  1203  1341 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  2446  2446 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  2446  2446 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  1203  1519 W Trace   : Unexpected value from nativeGetEnabledTags: 0\n07-17 15:53:32.856  1203  1519 W Trace   : Unexpected value 

...

Gecko:Ready\n07-17 15:53:34.176  2446  2461 I Robocop : 3 INFO TEST-PASS | testANRReporter | Ping directory is empty\n07-17 15:53:34.176  2446  2461 I Robocop : 4 INFO TEST-PASS | testANRReporter | Successfully set package name - org.mozilla.fennec should equal org.mozilla.fennec\n07-17 15:53:34.176  2446  2461 I Robocop : 5 INFO TEST-PASS | testANRReporter | testContext should not be null - android.app.ContextImpl@b3202568 should not equal null\n
09:14:00     INFO -  18 INFO TEST-END | testANRReporter | finished in 11938ms
Do you think increasing WAIT_FOR_PING_TIMEOUT might help?
Flags: needinfo?(nchen)
(In reply to Geoff Brown [:gbrown] from comment #16)
> Do you think increasing WAIT_FOR_PING_TIMEOUT might help?

I tend to think it's long enough because other emulator environments (i.e. 2.3 emulator) don't seem to be affected. Maybe we should crash when time out happens, so we can find out what the other threads are doing?
Flags: needinfo?(nchen)
(In reply to Geoff Brown [:gbrown] from comment #45)
> We are not returning from the call to getNativeStack() at
> http://hg.mozilla.org/mozilla-central/annotate/1d6500527f66/mobile/android/
> base/ANRReporter.java#l442.

...and that's because mozilla_sampler_get_profile() hangs calling t->ToStreamAsJSON(stream):

https://tbpl.mozilla.org/?tree=Try&rev=9769e71b9f2e
https://tbpl.mozilla.org/php/getParsedLog.php?id=45669037&tree=Try&full=1

:nchen -- do you understand what's happening here?
Flags: needinfo?(nchen)
Hmm I'm not sure. You'd have to check it with a debugger. I can do it too if you have a loaner around.
Flags: needinfo?(nchen)
I tried debugging locally but could not repro. Borrowing a test slave is probably the way to go, but I don't have one currently. Mind if I leave it to you?
No problem. I'll borrow one.
Depends on: 1051996
ANR reporter uses a 10 second sampling interval in order to only take one sample. This patch fixes OS::SleepMicro for inervals > 1 second.
Attachment #8475255 - Flags: review?(bgirard)
Assignee: nobody → nchen
Status: NEW → ASSIGNED
Attachment #8475255 - Flags: review?(bgirard) → review+
https://hg.mozilla.org/mozilla-central/rev/7e5735c7a767
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 34
Can we get this nominated for Aurora/Beta uplift as well? :)
Comment on attachment 8475255 [details] [diff] [review]
Fix support for sampling intervals > 1 second (v1)

Approval Request Comment
[Feature/regressing bug #]: Bug 979566
[User impact if declined]: Possible hangs and annoyed sheriffs :)
[Describe test coverage new/current, TBPL]: Locally, m-c
[Risks and why]: Very small; patch only fixes existing bug
[String/UUID change made/needed]: None
Attachment #8475255 - Flags: approval-mozilla-beta?
Attachment #8475255 - Flags: approval-mozilla-aurora?
Flags: needinfo?(nchen)
Attachment #8475255 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Attachment #8475255 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
This test continues to be plagued with multiple different failures. I'm thinking it's disabling time until it can be made to run reliably.
Status: RESOLVED → REOPENED
Flags: needinfo?(nchen)
Resolution: FIXED → ---
Target Milestone: Firefox 34 → ---
I'm looking at it as soon as I have time to get a Panda loaner. Promise! :)
Flags: needinfo?(nchen)
I've lost track of the number of intermittents this test has now. I plan to disable it by the end of the week.
Flags: needinfo?(nchen)
I've been looking at it these last few days.
Flags: needinfo?(nchen)
Okay let's try this. Basically the ANR reporter is slow on testing hardware (especially with 2.3 in the emulator), so this patch makes the test wait longer, and tries to give the ANR reporter more CPU time.
Attachment #8506271 - Flags: review?(snorp)
Attachment #8506271 - Flags: review?(snorp) → review+
Looks like it did.
Status: REOPENED → RESOLVED
Closed: 10 years ago9 years ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → Firefox 36
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.