Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

P2: Teacher App failure in tag: 0.9.9b2-jamsj - loses data #43

Open
truedat101 opened this issue Jun 8, 2014 · 20 comments
Open

P2: Teacher App failure in tag: 0.9.9b2-jamsj - loses data #43

truedat101 opened this issue Jun 8, 2014 · 20 comments
Assignees
Labels

Comments

@truedat101
Copy link
Member

After some point, perhaps if the screen lock goes on and puts the app into pause state, the data in memory is lost and there is no way to recover it, other than to kill the app and restart. I can create this by leaving screen lock on for about 5 minutes, at which point something happens and the app, when returning to it, doesn't have any data in the student or question view.

@yukoyuko
Copy link
Member

After a screen rotation and losing the data on the screen, I did:
Start Solving Questions -> Finish Show Result -> terminate the app with error -> Recovering Session -> Exit

02-12 12:18:31.754 8245-8245/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 46K, 1% free 10910K/10992K, paused 11ms, total 11ms
02-12 12:18:31.964 8245-8299/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 244K, 3% free 11310K/11588K, paused 14ms, total 14ms
02-12 12:18:35.707 8245-8245/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 275K, 3% free 11799K/12112K, paused 14ms, total 14ms
02-12 12:18:35.787 8245-8245/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 844K, 9% free 11670K/12760K, paused 14ms, total 14ms
02-12 12:18:36.989 8245-8245/org.smilec.smile I/Choreographer﹕ Skipped 68 frames! The application may be doing too much work on its main thread.
02-12 12:18:37.089 8245-8245/org.smilec.smile I/System.out﹕ Mon Feb 02 00:00:00 PST 2015
02-12 12:18:37.119 8245-8245/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 114K, 3% free 12451K/12760K, paused 15ms, total 15ms
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.199 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:37.219 8245-8245/org.smilec.smile I/System.out﹕ Fri Jan 30 00:00:00 PST 2015
02-12 12:18:42.134 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:42.134 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:42.134 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:42.134 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:42.134 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:42.134 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:42.144 8245-8245/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.346 8245-8299/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-12 12:18:44.366 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"An Issei living in California","O2":"A person from outer space","O3":"A non-citizen","O4":"A first generation Japanese (Issei) who came to the U.S.A.","Q":"When referring to Japanese Americans, who was NOT an Alien?","SessionID":"1423772324359","A":2}
02-12 12:18:45.397 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"Arkansas and Arizona","O2":"California and Colorado","O3":"Idaho, Utah and Wyoming","O4":"Hawaii and Texas","Q":"What States DID NOT HAVE War Relocation Authority (WRA) camps for Japanese and Japanese-Americans?","SessionID":"1423772325403","A":4}
02-12 12:18:45.437 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"They were resort like and had comfortable climates","O2":"Located in isolated rural areas","O3":"Extreme temperatures in summer (120 degrees F) and winter (32 degrees F)","O4":"Frequent sandstorms","Q":"What environmental and/or geographical characteristics did MOST of the internment camps NOT share?","SessionID":"1423772325441","A":1}
02-12 12:18:45.477 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"They had bigger windows to let the air cool the rooms","O2":"Basements for keeping their sake cold","O3":"Mosquito netting for malaria control","O4":"Double roofs for insulation during hot summers","Q":"How and why were the barracks at Gila River and Poston built differently from the barracks in other camps?","SessionID":"1423772325481","A":4}
02-12 12:18:45.517 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"They brought them with them from California","O2":"Shells were found in ponds and creeks running through the camps","O3":"Internees requested imports of shells and other supplies from friends in California coastal towns","O4":"They ordered the seashells from catalogs","Q":"Why was much of the hand-crafted internee jewelry created from seashells?","SessionID":"1423772325525","A":2}
02-12 12:18:45.547 8245-8299/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 689K, 6% free 12921K/13644K, paused 20ms, total 21ms
02-12 12:18:45.647 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"Coal","O2":"Wood","O3":"Oil","O4":"Gas","Q":"How were the rooms in the tarpaper barracks NOT heated during cold weather?","SessionID":"1423772325653","A":4}
02-12 12:18:45.677 8245-8299/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"Truck farming vegetables (like broccoli, carrots, cucumber, tomatoes, etc.)","O2":"Gourd-type crops (like pumpkins, cantaloupes, winter squash, watermelon)","O3":"Tropical crops (Like: Cocoa, coconuts, coffee, pineapple)","O4":"Japanese vegetables (like Daikon, gobo, nasu, napa)","Q":"What crops were NOT grown by the internees?","SessionID":"1423772325688","A":3}
02-12 12:18:46.037 8245-8301/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1338K, 10% free 12900K/14272K, paused 18ms, total 18ms
02-12 12:18:46.178 8245-8245/org.smilec.smile I/System.out﹕ *_Number of students in session =0
02-12 12:18:51.363 8245-8302/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1473K, 11% free 12732K/14272K, paused 15ms, total 15ms
02-12 12:18:51.433 8245-8245/org.smilec.smile I/System.out﹕ *_Number of students in session =1
02-12 12:18:51.433 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:18:53.335 8245-8245/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 2286K, 19% free 11698K/14272K, paused 16ms, total 16ms
02-12 12:19:16.828 8245-8245/org.smilec.smile D/SMILEPLUG﹕ loadItems is true
02-12 12:19:16.828 8245-8245/org.smilec.smile D/SMILEPLUG﹕ loadSelections()
02-12 12:19:20.511 8245-8245/org.smilec.smile I/System.out﹕ *_Number of students in session =1
02-12 12:19:20.511 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:21.973 8245-8300/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 524K, 16% free 12081K/14272K, paused 20ms, total 20ms
02-12 12:19:22.063 8245-8300/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1298K, 18% free 11814K/14272K, paused 15ms, total 15ms
02-12 12:19:22.063 8245-8245/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:19:22.063 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:22.063 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:22.063 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:25.726 8245-8303/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 746K, 16% free 12014K/14272K, paused 15ms, total 15ms
02-12 12:19:25.766 8245-8245/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:19:25.766 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:25.766 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:25.766 8245-8245/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:19:30.801 8245-8300/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1052K, 17% free 11967K/14272K, paused 24ms, total 24ms
02-12 12:19:31.001 8245-8300/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 749K, 15% free 12214K/14272K, paused 15ms, total 15ms
02-12 12:19:33.254 8245-8301/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1115K, 15% free 12177K/14272K, paused 16ms, total 17ms
02-12 12:19:35.125 8245-8245/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1017K, 15% free 12225K/14272K, paused 17ms, total 17ms
02-12 12:19:36.266 8245-8302/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1128K, 15% free 12179K/14272K, paused 16ms, total 16ms
02-12 12:19:38.779 8245-8303/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1052K, 15% free 12192K/14272K, paused 16ms, total 16ms
02-12 12:19:41.482 8245-8299/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1084K, 15% free 12179K/14272K, paused 15ms, total 16ms
02-12 12:19:46.597 8245-8301/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1061K, 15% free 12185K/14272K, paused 22ms, total 22ms
02-12 12:19:46.717 8245-8301/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1013K, 15% free 12238K/14272K, paused 16ms, total 16ms
02-12 12:19:53.693 8245-8300/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 551K, 11% free 12770K/14272K, paused 16ms, total 16ms
02-12 12:19:55.555 8245-8303/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1850K, 15% free 12179K/14272K, paused 16ms, total 16ms
02-12 12:19:55.665 8245-8303/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1124K, 16% free 12119K/14272K, paused 15ms, total 15ms
02-12 12:19:57.707 8245-8245/org.smilec.smile D/AndroidRuntime﹕ Shutting down VM
02-12 12:19:57.707 8245-8245/org.smilec.smile W/dalvikvm﹕ threadid=1: thread exiting with uncaught exception (group=0x41a5dba8)
02-12 12:19:57.707 8245-8245/org.smilec.smile E/AndroidRuntime﹕ FATAL EXCEPTION: main
Process: org.smilec.smile, PID: 8245
java.lang.NullPointerException
at org.smilec.smile.ui.fragment.StudentsFragment.updatePercentCorrect(StudentsFragment.java:314)
at org.smilec.smile.ui.GeneralActivity$10.onItemSelected(GeneralActivity.java:655)
at android.widget.AdapterView.fireOnSelected(AdapterView.java:893)
at android.widget.AdapterView.access$200(AdapterView.java:48)
at android.widget.AdapterView$SelectionNotifier.run(AdapterView.java:861)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5001)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:785)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:601)
at dalvik.system.NativeStart.main(Native Method)
02-12 12:20:03.563 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 123K, 2% free 9263K/9420K, paused 12ms, total 12ms
02-12 12:20:03.593 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 10K, 2% free 9631K/9796K, paused 10ms, total 10ms
02-12 12:20:03.763 8608-8624/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 218K, 3% free 9926K/10180K, paused 14ms, total 14ms
02-12 12:20:06.446 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 238K, 3% free 10198K/10472K, paused 18ms, total 18ms
02-12 12:20:06.556 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 339K, 4% free 10364K/10744K, paused 13ms, total 14ms
02-12 12:20:06.676 8608-8626/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 288K, 3% free 10585K/10912K, paused 17ms, total 17ms
02-12 12:20:06.736 8608-8626/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 535K, 6% free 10577K/11148K, paused 15ms, total 15ms
02-12 12:20:06.806 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 570K, 6% free 10540K/11148K, paused 13ms, total 13ms
02-12 12:20:06.856 8608-8608/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:20:06.856 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:06.856 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:06.856 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:11.951 8608-8624/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 242K, 3% free 10817K/11148K, paused 14ms, total 14ms
02-12 12:20:11.991 8608-8608/org.smilec.smile D/SMILEPLUG﹕ loadItems is true
02-12 12:20:11.991 8608-8608/org.smilec.smile D/SMILEPLUG﹕ loadSelections()
02-12 12:20:12.051 8608-8624/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1227K, 12% free 10195K/11460K, paused 14ms, total 14ms
02-12 12:20:12.131 8608-8624/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 416K, 11% free 10286K/11460K, paused 13ms, total 13ms
02-12 12:20:15.925 8608-8608/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:20:15.925 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:15.925 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:15.925 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:15.945 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 380K, 10% free 10418K/11460K, paused 17ms, total 17ms
02-12 12:20:17.116 8608-8623/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 411K, 9% free 10516K/11460K, paused 18ms, total 18ms
02-12 12:20:17.176 8608-8623/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 659K, 10% free 10369K/11460K, paused 13ms, total 13ms
02-12 12:20:17.206 8608-8608/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:20:17.206 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:17.206 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:17.206 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:17.226 8608-8624/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 534K, 10% free 10343K/11460K, paused 15ms, total 15ms
02-12 12:20:20.440 8608-8622/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 207K, 8% free 10647K/11460K, paused 18ms, total 18ms
02-12 12:20:20.490 8608-8622/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 780K, 10% free 10420K/11460K, paused 14ms, total 14ms
02-12 12:20:20.540 8608-8622/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 508K, 10% free 10420K/11460K, paused 13ms, total 13ms
02-12 12:20:20.540 8608-8608/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:20:20.540 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:20.540 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:20.540 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:21.040 8608-8623/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 362K, 8% free 10567K/11460K, paused 20ms, total 20ms
02-12 12:20:21.080 8608-8623/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 673K, 10% free 10420K/11460K, paused 13ms, total 13ms
02-12 12:20:21.130 8608-8623/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 509K, 10% free 10420K/11460K, paused 13ms, total 14ms
02-12 12:20:21.130 8608-8608/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:20:21.130 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:21.130 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:21.130 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:22.341 8608-8625/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 361K, 8% free 10567K/11460K, paused 22ms, total 22ms
02-12 12:20:22.401 8608-8625/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 677K, 10% free 10420K/11460K, paused 14ms, total 14ms
02-12 12:20:22.452 8608-8625/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 510K, 10% free 10421K/11460K, paused 13ms, total 13ms
02-12 12:20:22.452 8608-8608/org.smilec.smile I/System.out﹕ *_Number of students in session =3
02-12 12:20:22.452 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:22.452 8608-8608/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-12 12:20:22.452 8608-8608/org.smilec.smile I/System.out﹕ **The student 'i' already solved the questions =false
02-12 12:20:23.112 8608-8608/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 182K, 9% free 10495K/11460K, paused 19ms, total 19ms
02-12 12:20:23.112 8608-8608/org.smilec.smile I/dalvikvm-heap﹕ Grow heap (frag case) to 10.546MB for 279056-byte allocation
02-12 12:20:23.122 8608-8618/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed <1K, 9% free 10767K/11736K, paused 14ms, total 14ms
02-12 12:20:31.050 8608-8608/org.smilec.smile I/Choreographer﹕ Skipped 383 frames! The application may be doing too much work on its main thread.
02-12 12:20:46.425 8608-8625/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 266K, 6% free 11092K/11736K, paused 45ms, total 46ms

@truedat101
Copy link
Member Author

Great, this was useful. Seems like this is the error after rotating the screen? Can you confirm when the FATAL Exception occurs?

exception (group=0x41a5dba8)
02-12 12:19:57.707 8245-8245/org.smilec.smile E/AndroidRuntime﹕ FATAL EXCEPTION: main
Process: org.smilec.smile, PID: 8245
java.lang.NullPointerException
at org.smilec.smile.ui.fragment.StudentsFragment.updatePercentCorrect(StudentsFragment.java:314)
at org.smilec.smile.ui.GeneralActivity$10.onItemSelected(GeneralActivity.java:655)
at android.widget.AdapterView.fireOnSelected(AdapterView.java:893)
at android.widget.AdapterView.access$200(AdapterView.java:48)
at android.widget.AdapterView$SelectionNotifier.run(AdapterView.java:861)
at android.os.Handler.handleCallback(Handler.java:733)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5001)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:785)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:601)
at dalvik.system.NativeStart.main(Native Method)

@yukoyuko
Copy link
Member

Yes it occurs after rotating the screen but not right after. 'Start Solving Questions' works even thought students/question set data doesn't display. The FATAL EXCEPTION comes up when hitting 'Finish Show Result.' The app gets terminated but the right result is shown on the student side screen.

@truedat101
Copy link
Member Author

Ok, well the problem must be happening before hitting "Finish", as the questions don't show up, so there is a problem. Can you get a complete log trace of the entire output on the teacher tablet, up to the point where you rotate sideways, and then rejoin the teacher session.

@yukoyuko
Copy link
Member

I am not understanding 'a complete log trace of the entire output' yet. Am I supposed to create a trace file? Traceview? Or else?

@truedat101
Copy link
Member Author

I'd start with capturing all of the logging output.‎ If we can pinpoint the are of failure we can watch the variables in the debugger and step through. I'm guessing the application is not resuming from being paused or recreated when rotation occurs. Sent from my BlackBerry Passport. From: yukoyukoSent: Thursday, February 19, 2015 9:13 PMTo: RazortoothRTC/smile_teacher_androidReply To: RazortoothRTC/smile_teacher_androidCc: David J. KordsmeierSubject: Re: [smile_teacher_android] P2: Teacher App failure in tag: 0.9.9b2-jamsj - loses data (#43)I am not understanding 'a complete log trace of the entire output' yet. Am I supposed to create a trace file? Traceview? Or else?

—Reply to this email directly or view it on GitHub.

@yukoyuko
Copy link
Member

Below is the logging output starting from running the app and adding two students, until getting back to the app after rotating the device. After the rotation, the logcat stopped updating the output:

02-21 13:09:18.157 27255-27255/org.smilec.smile I/dalvikvm﹕ Enabling JNI app bug workarounds for target SDK version 7...
02-21 13:09:18.217 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 77K, 2% free 9023K/9132K, paused 12ms, total 12ms
02-21 13:09:18.217 27255-27255/org.smilec.smile I/dalvikvm-heap﹕ Grow heap (frag case) to 9.523MB for 717456-byte allocation
02-21 13:09:18.227 27255-27264/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed <1K, 2% free 9723K/9836K, paused 10ms, total 10ms
02-21 13:09:18.267 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 17K, 1% free 9996K/10068K, paused 9ms, total 9ms
02-21 13:09:20.669 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 25K, 1% free 10481K/10540K, paused 13ms, total 13ms
02-21 13:09:31.970 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 37K, 1% free 10945K/11016K, paused 9ms, total 9ms
02-21 13:09:32.241 27255-27319/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 258K, 3% free 11339K/11628K, paused 13ms, total 13ms
02-21 13:09:35.384 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 290K, 3% free 11812K/12140K, paused 13ms, total 13ms
02-21 13:09:35.584 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 412K, 4% free 12293K/12784K, paused 13ms, total 13ms
02-21 13:09:35.664 27255-27255/org.smilec.smile I/System.out﹕ Mon Feb 02 00:00:00 PST 2015
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.724 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.764 27255-27255/org.smilec.smile I/System.out﹕ Fri Jan 30 00:00:00 PST 2015
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:35.824 27255-27255/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.526 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.526 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.526 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.536 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.536 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.536 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.536 27255-27319/org.smilec.smile D/SMILE IQSetJSONParser﹕ Failed parsing JSON, reason: No value for PIC
02-21 13:09:37.566 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"An Issei living in California","O2":"A person from outer space","O3":"A non-citizen","O4":"A first generation Japanese (Issei) who came to the U.S.A.","Q":"When referring to Japanese Americans, who was NOT an Alien?","SessionID":"1424552977539","A":2}
02-21 13:09:37.616 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"Arkansas and Arizona","O2":"California and Colorado","O3":"Idaho, Utah and Wyoming","O4":"Hawaii and Texas","Q":"What States DID NOT HAVE War Relocation Authority (WRA) camps for Japanese and Japanese-Americans?","SessionID":"1424552977616","A":4}
02-21 13:09:37.626 27255-27319/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 549K, 5% free 12849K/13428K, paused 16ms, total 16ms
02-21 13:09:37.686 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"They were resort like and had comfortable climates","O2":"Located in isolated rural areas","O3":"Extreme temperatures in summer (120 degrees F) and winter (32 degrees F)","O4":"Frequent sandstorms","Q":"What environmental and/or geographical characteristics did MOST of the internment camps NOT share?","SessionID":"1424552977686","A":1}
02-21 13:09:37.716 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"They had bigger windows to let the air cool the rooms","O2":"Basements for keeping their sake cold","O3":"Mosquito netting for malaria control","O4":"Double roofs for insulation during hot summers","Q":"How and why were the barracks at Gila River and Poston built differently from the barracks in other camps?","SessionID":"1424552977725","A":4}
02-21 13:09:37.746 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"They brought them with them from California","O2":"Shells were found in ponds and creeks running through the camps","O3":"Internees requested imports of shells and other supplies from friends in California coastal towns","O4":"They ordered the seashells from catalogs","Q":"Why was much of the hand-crafted internee jewelry created from seashells?","SessionID":"1424552977751","A":2}
02-21 13:09:37.786 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"Coal","O2":"Wood","O3":"Oil","O4":"Gas","Q":"How were the rooms in the tarpaper barracks NOT heated during cold weather?","SessionID":"1424552977788","A":4}
02-21 13:09:37.806 27255-27319/org.smilec.smile D/SmilePlugServerManager﹕ serialized question as JSON, use prepared: {"TYPE":"QUESTION","IP":"127.0.0.1","NAME":"teacher","O1":"Truck farming vegetables (like broccoli, carrots, cucumber, tomatoes, etc.)","O2":"Gourd-type crops (like pumpkins, cantaloupes, winter squash, watermelon)","O3":"Tropical crops (Like: Cocoa, coconuts, coffee, pineapple)","O4":"Japanese vegetables (like Daikon, gobo, nasu, napa)","Q":"What crops were NOT grown by the internees?","SessionID":"1424552977812","A":3}
02-21 13:09:38.096 27255-27327/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1102K, 8% free 13040K/14172K, paused 19ms, total 19ms
02-21 13:09:38.257 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =0
02-21 13:09:43.422 27255-27326/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1672K, 12% free 12714K/14420K, paused 34ms, total 36ms
02-21 13:09:43.532 27255-27326/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 2360K, 20% free 11599K/14420K, paused 17ms, total 17ms
02-21 13:09:43.532 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =0
02-21 13:09:56.434 27255-27255/org.smilec.smile D/SMILEPLUG﹕ loadItems is true
02-21 13:09:56.434 27255-27255/org.smilec.smile D/SMILEPLUG﹕ loadSelections()
02-21 13:09:57.475 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =0
02-21 13:09:57.525 27255-27327/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 441K, 17% free 12027K/14420K, paused 15ms, total 15ms
02-21 13:10:01.599 27255-27328/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1139K, 18% free 11905K/14420K, paused 14ms, total 14ms
02-21 13:10:01.629 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =2
02-21 13:10:01.629 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:01.629 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:02.620 27255-27329/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 908K, 17% free 11970K/14420K, paused 15ms, total 15ms
02-21 13:10:02.690 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =2
02-21 13:10:02.690 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:02.690 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:02.730 27255-27255/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1156K, 19% free 11811K/14420K, paused 14ms, total 14ms
02-21 13:10:06.884 27255-27327/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 775K, 17% free 11978K/14420K, paused 14ms, total 14ms
02-21 13:10:06.914 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =2
02-21 13:10:06.914 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:06.914 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:07.785 27255-27326/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1006K, 17% free 11969K/14420K, paused 14ms, total 14ms
02-21 13:10:07.885 27255-27326/org.smilec.smile D/dalvikvm﹕ GC_FOR_ALLOC freed 1141K, 19% free 11821K/14420K, paused 16ms, total 16ms
02-21 13:10:07.895 27255-27255/org.smilec.smile I/System.out﹕ *_Number of students in session =2
02-21 13:10:07.895 27255-27255/org.smilec.smile I/System.out﹕ *_The student 'i' already solved the questions =false
02-21 13:10:07.895 27255-27255/org.smilec.smile I/System.out﹕ **The student 'i' already solved the questions =false

@truedat101
Copy link
Member Author

Yuko, one of the problems I see is that the developer on this didn't use Android logging facilities. They used system.out.println. While this is ok (doesn't cause any problems with the code), it makes debugging difficult. We don't really know how to find our application in all of the output. Normally logging is done by severity and by category (name) of the programming doing the logging.

@truedat101
Copy link
Member Author

Secondly, I can see that in my own testing, I can cause the data to be "lost" after locking the screen. I can't figure out what happens based on this output. I may need to modify this to improve logging.

@truedat101
Copy link
Member Author

Looks like here is one thing that happens when the screen locks:

I/ActivityManager( 567): Activity reported stop, but no longer stopping: ActivityRecord{65b3b660 u0 org.smilec.smile/.ui.GeneralActivity t14}

@truedat101
Copy link
Member Author

Bingo:

I/ActivityManager( 567): START u0 {cmp=org.smilec.smile/.ui.ChooseActivityFlowDialog (has extras)} from pid 14492
W/InputMethodManagerService( 567): Focus gain on non-focused client com.android.internal.view.IInputMethodClient$Stub$Proxy@65996248 (uid=10176 pid=14492)
V/PhoneStatusBar( 636): setLightsOn(true)
I/ActivityManager( 567): Displayed org.smilec.smile/.ui.ChooseActivityFlowDialog: +117ms
I/ActivityManager( 567): START u0 {cmp=org.smilec.smile/.ui.GeneralActivity (has extras)} from pid 14492
W/InputMethodManagerService( 567): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@6562bc38 attribute=null, token = android.os.BinderProxy@659f1dc8
V/PhoneStatusBar( 636): setLightsOn(true)
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/ActivityManager( 567): Displayed org.smilec.smile/.ui.GeneralActivity: +268ms
W/WindowManager( 567): Rebuild removed 14 windows but added 13
W/WindowManager( 567): java.lang.RuntimeException: here
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.rebuildAppWindowListLocked(WindowManagerService.java:8027)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.rebuildAppWindowListLocked(WindowManagerService.java:7963)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.handleAnimatingStoppedAndTransitionLocked(WindowManagerService.java:8707)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedInner(WindowManagerService.java:9221)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLockedLoop(WindowManagerService.java:8179)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.performLayoutAndPlaceSurfacesLocked(WindowManagerService.java:8121)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService.access$300(WindowManagerService.java:157)
W/WindowManager( 567): at com.android.server.wm.WindowManagerService$H.handleMessage(WindowManagerService.java:7155)
W/WindowManager( 567): at android.os.Handler.dispatchMessage(Handler.java:102)
W/WindowManager( 567): at android.os.Looper.loop(Looper.java:136)
W/WindowManager( 567): at android.os.HandlerThread.run(HandlerThread.java:61)
w{65614228 u0 org.smilec.smile/org.smilec.smile.ui.ChooseActivityFlowDialog}
W/WindowManager( 567): mDisplayId=0 mSession=Session{659f7620 14492:u0a10176} mClient=android.os.BinderProxy@659f1dc8
W/WindowManager( 567): mOwnerUid=10176 mShowToOwnerOnly=true package=org.smilec.smile appop=NONE

@truedat101
Copy link
Member Author

Here are a few more things from the output:

D/SMILEPLUG(14492): loadItems is true
D/SMILEPLUG(14492): loadSelections()
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
E/CheckinTask( 962): Checkin failed: https://android.clients.google.com/checkin (request #0): java.net.UnknownHostException: Unable to resolve host "android.clients.google.com": No address associated with hostname
I/GoogleURLConnFactory( 962): unbinding HttpService
I/CheckinService( 962): Checking schedule, now: 1424584558435 next: 1424584593418
I/CheckinService( 962): active receiver: disabled
D/GCM ( 914): GcmService start Intent { act=com.google.android.checkin.CHECKIN_COMPLETE flg=0x10 cmp=com.google.android.gms/.gcm.GcmService (has extras) } com.google.android.checkin.CHECKIN_COMPLETE
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false
I/System.out(14492): *_Number of students in session =1
I/System.out(14492): *_The student 'i' already solved the questions =false

@truedat101
Copy link
Member Author

It would appear that several things happen:

  • The application gets stopped when the screen is locked and possibly turned
  • on start, the UI isn't properly initialized, seems there is at least one crash in the activity, but the UsePreparedQuestionsActivity or StudentSTatusDetailsActivity is presented without being initialized with data.
  • Either the crash has lost the data, or the resume invocation doesn't resume with the right state
  • saveInstancestate is never called and restore from instance state is never called

@truedat101
Copy link
Member Author

I'd need to run this in the debugger to know for sure.

@truedat101
Copy link
Member Author

The work around might be to turn off screen lock.

@truedat101
Copy link
Member Author

There is a "recover" state that works sometimes, but only if the app is killed and restarted.

@truedat101
Copy link
Member Author

I will propose a work around to see if this fixes things for JAMsj:

  • Turn Off Screen Timeout - Set to 30 minutes
  • Recommend DO NOT screen dim (hit power)
  • User can "kill" a running instance easily if it loses the session data, and rejoin to recover the session

Future work should focus on the Web Version of the Teacher App. This android version is a horribly complex code base. If we choose to fix it, someone will need to go through with a fine tooth comb in the debugger and track down the problem.

@glureau
Copy link

glureau commented Sep 19, 2016

Hi @truedat101 . Do you have any feedback about this workaround? I've similar issues with the WindowManager in my app.

@truedat101
Copy link
Member Author

@glureau what version of the Android app and android os are you using?

@glureau
Copy link

glureau commented Sep 21, 2016

Android 4.2/4.4/5.1 (customized ROM and private apps)
I'm just experienced similar logs WindowManagerService.rebuild... but the source of this rebuild is not really clear to me :/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants