search

cbitstech / Purple-Robot

Sensing and automation platform for Android.
Other
38 stars 19 forks source link

Purple Robot not uploading correctly #150

Closed JohnJ-Guiry closed 11 years ago

JohnJ-Guiry commented 11 years ago

Test Setup: A large amount of files (~11,000 => ~48 hours), are waiting to be uploaded on my device. I've disabled the probes, and re-enabled the HTTP Upload (simulating a user with no internet connection). Manually tap on Upload Data. Data appears to update fine for several minutes, before the status bar reverts to " Gathering Sensor Data", and uploads appear to cease, until another manual tap on the HTTP Upload button.

Expected Results: Tap HTTP Upload once, and all files should be uploaded, assuming an internet connection is present.

Actual outcome: Only a small amount of files are actually uploaded before uploads halt. Each upload occurs quite fast (~300kB in 10s on 3G connection). Issue occurs on both Wifi and 3G. No more data appears to be used according to Settings => Data Usage

Purple Robot Version: 1.0.22 Device: Nexus

audaciouscode commented 11 years ago

I'm seeing this on my device - investigating this afternoon.

JohnJ-Guiry commented 11 years ago

Does 1.0.23 fix this?

audaciouscode commented 11 years ago

It seems to have fixed this. I'm not able to replicate the problem any more. If the problem persists, please hook your device up to ADB and let me know what errors get logged from the HTTP upload plugin.

JohnJ-Guiry commented 11 years ago

Just spotted this bug again in 1.0.24. This time there's approx. 15MB of data left to be uploaded. Probes had just been turned off. Notification message said 'Gathering Sensor Data'. HTTP Uploads appeared to be functioning normally prior to disabling probes. LogCat doesn't seem to show anything too unusual:

1-31 16:46:45.018: E/PR-HTTP(11971): UPLOADING? true 01-31 16:46:49.119: E/PR-HTTP(11971): UPLOADING? false 01-31 16:46:49.119: E/PR-HTTP(11971): CONTINUE? 1359650809131 > 300000 01-31 16:46:49.119: E/PR-HTTP(11971): CONTINUING 01-31 16:46:49.119: E/PR-HTTP(11971): WIFI AVAILABLE: true 01-31 16:46:49.119: E/PR-HTTP(11971): WIFI AVAILABLE: true 01-31 16:46:49.346: D/dalvikvm(11971): GC_CONCURRENT freed 9084K, 41% free 17834K/30160K, paused 3ms+6ms, total 80ms 01-31 16:46:49.971: D/dalvikvm(11971): GC_CONCURRENT freed 2600K, 40% free 18228K/30160K, paused 1ms+4ms, total 50ms 01-31 16:46:49.971: D/dalvikvm(11971): WAIT_FOR_CONCURRENT_GC blocked 26ms 01-31 16:46:50.354: D/HockeyApp(11971): Current handler class = net.hockeyapp.android.internal.ExceptionHandler 01-31 16:46:50.854: D/dalvikvm(11971): GC_CONCURRENT freed 2920K, 39% free 18562K/30160K, paused 9ms+8ms, total 88ms 01-31 16:46:51.596: D/dalvikvm(11971): GC_CONCURRENT freed 3085K, 38% free 18713K/30160K, paused 3ms+10ms, total 55ms 01-31 16:46:51.596: D/dalvikvm(11971): WAIT_FOR_CONCURRENT_GC blocked 28ms 01-31 16:46:51.861: D/BluetoothAdapter(11971): 1114693400: getState() : mService = null. Returning STATE_OFF 01-31 16:46:52.385: D/dalvikvm(11971): GC_CONCURRENT freed 3325K, 26% free 18631K/24864K, paused 3ms+3ms, total 49ms 01-31 16:46:52.971: D/dalvikvm(11971): GC_CONCURRENT freed 3426K, 26% free 18464K/24864K, paused 3ms+2ms, total 42ms 01-31 16:46:52.971: D/dalvikvm(11971): WAIT_FOR_CONCURRENT_GC blocked 21ms 01-31 16:46:53.588: D/dalvikvm(11971): GC_CONCURRENT freed 3145K, 26% free 18521K/24864K, paused 3ms+4ms, total 44ms 01-31 16:46:54.150: D/dalvikvm(11971): GC_CONCURRENT freed 3268K, 26% free 18476K/24864K, paused 2ms+3ms, total 40ms 01-31 16:46:54.150: D/dalvikvm(11971): WAIT_FOR_CONCURRENT_GC blocked 16ms 01-31 16:46:54.721: D/dalvikvm(11971): GC_CONCURRENT freed 3197K, 26% free 18486K/24864K, paused 2ms+3ms, total 39ms 01-31 16:46:54.721: D/dalvikvm(11971): WAIT_FOR_CONCURRENT_GC blocked 17ms 01-31 16:46:55.174: D/dalvikvm(11971): GC_FOR_ALLOC freed 1722K, 25% free 18747K/24864K, paused 32ms, total 32ms 01-31 16:46:55.174: I/dalvikvm-heap(11971): Grow heap (frag case) to 18.791MB for 480202-byte allocation 01-31 16:46:55.205: D/dalvikvm(11971): GC_FOR_ALLOC freed 312K, 26% free 18903K/25336K, paused 29ms, total 29ms 01-31 16:46:55.440: D/dalvikvm(11971): GC_FOR_ALLOC freed 497K, 26% free 18903K/25336K, paused 29ms, total 29ms 01-31 16:46:55.447: I/dalvikvm-heap(11971): Grow heap (frag case) to 19.172MB for 720298-byte allocation 01-31 16:46:55.479: D/dalvikvm(11971): GC_FOR_ALLOC freed 468K, 27% free 19138K/26040K, paused 32ms, total 32ms 01-31 16:46:55.854: D/dalvikvm(11971): GC_FOR_ALLOC freed 717K, 27% free 19138K/26040K, paused 31ms, total 31ms 01-31 16:46:55.854: I/dalvikvm-heap(11971): Grow heap (frag case) to 19.745MB for 1080442-byte allocation 01-31 16:46:55.885: D/dalvikvm(11971): GC_FOR_ALLOC freed 703K, 29% free 19489K/27096K, paused 31ms, total 31ms 01-31 16:46:56.385: D/dalvikvm(11971): GC_FOR_ALLOC freed 2031K, 29% free 19458K/27096K, paused 32ms, total 32ms 01-31 16:46:56.416: D/dalvikvm(11971): GC_FOR_ALLOC freed 1023K, 29% free 19458K/27096K, paused 26ms, total 26ms 01-31 16:46:56.455: D/dalvikvm(11971): GC_FOR_ALLOC freed <1K, 25% free 20482K/27096K, paused 25ms, total 25ms 01-31 16:46:56.455: I/dalvikvm-heap(11971): Grow heap (frag case) to 21.027MB for 1048214-byte allocation 01-31 16:46:56.479: D/dalvikvm(11971): GC_FOR_ALLOC freed 1023K, 28% free 20482K/28120K, paused 26ms, total 26ms 01-31 16:46:56.525: D/dalvikvm(11971): GC_FOR_ALLOC freed <1K, 24% free 21506K/28120K, paused 28ms, total 28ms 01-31 16:46:56.525: I/dalvikvm-heap(11971): Grow heap (frag case) to 22.027MB for 1048302-byte allocation 01-31 16:46:56.557: D/dalvikvm(11971): GC_FOR_ALLOC freed 1023K, 27% free 21505K/29144K, paused 30ms, total 30ms 01-31 16:46:56.565: E/PR_HTTP(11971): SITE: http://165.124.171.122:8093/funfImporter 01-31 16:46:56.775: D/dalvikvm(11971): GC_FOR_ALLOC freed 2912K, 24% free 20405K/26584K, paused 26ms, total 26ms 01-31 16:46:56.775: I/dalvikvm-heap(11971): Grow heap (frag case) to 20.583MB for 662266-byte allocation 01-31 16:46:56.807: D/dalvikvm(11971): GC_FOR_ALLOC freed 431K, 25% free 20621K/27232K, paused 28ms, total 28ms 01-31 16:46:56.916: D/dalvikvm(11971): GC_FOR_ALLOC freed <1K, 25% free 20621K/27232K, paused 25ms, total 25ms 01-31 16:46:56.916: I/dalvikvm-heap(11971): Grow heap (frag case) to 21.110MB for 993394-byte allocation 01-31 16:46:56.947: D/dalvikvm(11971): GC_FOR_ALLOC freed 646K, 26% free 20944K/28204K, paused 33ms, total 33ms 01-31 16:46:57.096: D/dalvikvm(11971): GC_FOR_ALLOC freed <1K, 26% free 20944K/28204K, paused 26ms, total 26ms 01-31 16:46:57.096: I/dalvikvm-heap(11971): Grow heap (frag case) to 21.900MB for 1490086-byte allocation 01-31 16:46:57.127: D/dalvikvm(11971): GC_FOR_ALLOC freed 970K, 28% free 21429K/29660K, paused 31ms, total 31ms 01-31 16:46:57.190: D/dalvikvm(11971): GC_FOR_ALLOC freed 1455K, 30% free 21005K/29660K, paused 27ms, total 27ms 01-31 16:46:57.932: D/dalvikvm(11971): GC_CONCURRENT freed 3007K, 26% free 22039K/29660K, paused 2ms+3ms, total 56ms 01-31 16:46:58.049: I/PowerManagerService(390): Going to sleep by user request... 01-31 16:46:58.127: D/dalvikvm(11971): GC_FOR_ALLOC freed 550K, 26% free 22037K/29660K, paused 35ms, total 35ms 01-31 16:46:58.135: I/dalvikvm-heap(11971): Grow heap (frag case) to 23.056MB for 1583884-byte allocation 01-31 16:46:58.182: D/dalvikvm(11971): GC_FOR_ALLOC freed 1031K, 28% free 22552K/31208K, paused 47ms, total 47ms 01-31 16:46:58.377: D/dalvikvm(11971): GC_FOR_ALLOC freed 613K, 28% free 22552K/31208K, paused 40ms, total 40ms 01-31 16:46:58.377: I/dalvikvm-heap(11971): Grow heap (frag case) to 23.212MB for 1220686-byte allocation 01-31 16:46:58.416: D/dalvikvm(11971): GC_FOR_ALLOC freed 0K, 27% free 23744K/32404K, paused 39ms, total 39ms 01-31 16:46:58.447: D/dalvikvm(11971): GC_FOR_ALLOC freed 1546K, 32% free 22198K/32404K, paused 30ms, total 30ms 01-31 16:46:58.486: D/dalvikvm(464): GC_CONCURRENT freed 753K, 15% free 12631K/14712K, paused 2ms+4ms, total 26ms 01-31 16:46:58.729: V/TransportControlView(390): Create TCV com.android.internal.policy.impl.keyguard.KeyguardTransportControlView{42887b90 V.E..... ......I. 0,0-0,0 #1020308 android:id/keyguard_transport_control} 01-31 16:46:58.760: D/LightsService(390): Excessive delay setting light: 61ms 01-31 16:46:58.775: D/SurfaceFlinger(129): Screen released, type=0 flinger=0x41aee318 01-31 16:46:58.846: D/NfcService(597): NFC-C OFF, disconnect 01-31 16:46:58.861: D/YouTube(11500): youtube.app.prefetch.PrefetchStore$UserPresentReceiver.onReceive:364 Received: android.intent.action.SCREEN_OFF 01-31 16:46:58.908: D/PhoneStatusBar(464): disable: < expand icons alerts ticker system_info back home RECENT clock search > 01-31 16:46:59.041: D/dalvikvm(390): GC_FOR_ALLOC freed 1757K, 32% free 20874K/30516K, paused 72ms, total 72ms 01-31 16:46:59.049: I/dalvikvm-heap(390): Grow heap (frag case) to 23.667MB for 3409936-byte allocation 01-31 16:46:59.111: D/dalvikvm(390): GC_FOR_ALLOC freed 11K, 21% free 24192K/30516K, paused 66ms, total 66ms 01-31 16:46:59.119: D/PhoneStatusBar(464): disable: < expand icons alerts ticker system_info BACK* HOME* RECENT clock search > 01-31 16:46:59.213: D/dalvikvm(390): GC_CONCURRENT freed 82K, 21% free 24130K/30516K, paused 4ms+12ms, total 99ms 01-31 16:47:27.770: E/PR-HTTP(11971): UPLOADING? false 01-31 16:47:27.770: E/PR-HTTP(11971): CONTINUE? 1359650847780 > 300000 01-31 16:47:27.770: E/PR-HTTP(11971): CONTINUING 01-31 16:47:27.778: E/PR-HTTP(11971): WIFI AVAILABLE: true 01-31 16:47:27.778: E/PR-HTTP(11971): WIFI AVAILABLE: true 01-31 16:50:21.505: D/dalvikvm(11971): GC_CONCURRENT freed 9237K, 30% free 17281K/24536K, paused 6ms+4ms, total 123ms 01-31 16:53:20.841: W/ThrottleService(390): unable to find stats for iface rmnet0 01-31 16:58:33.910: I/PowerManagerService(390): Waking up from sleep... 01-31 16:58:33.965: I/WindowManager(390): Lock screen displayed! 01-31 16:58:34.277: D/PowerManagerService-JNI(390): Excessive delay in autosuspend_disable() while turning screen on: 349ms 01-31 16:58:34.277: D/SurfaceFlinger(129): Screen acquired, type=0 flinger=0x41aee318 01-31 16:58:34.363: D/LightsService(390): Excessive delay setting light: 84ms 01-31 16:58:35.191: D/PhoneStatusBar(464): disable: < expand icons alerts ticker system_info BACK HOME recent* clock search > 01-31 16:58:35.199: D/HockeyApp(11971): Current handler class = net.hockeyapp.android.internal.ExceptionHandler 01-31 16:58:35.199: D/NfcService(597): NFC-C ON 01-31 16:58:35.199: D/YouTube(11500): youtube.app.prefetch.PrefetchStore$UserPresentReceiver.onReceive:364 Received: android.intent.action.USER_PRESENT 01-31 16:58:35.277: D/PhoneStatusBar(464): disable: < expand icons alerts ticker system_info back* home\ recent clock search > 01-31 16:58:35.285: W/InputMethodManagerService(390): Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@436420d0 attribute=android.view.inputmethod.EditorInfo@436420e0, token = android.os.BinderProxy@427f2e88 01-31 16:58:38.004: D/dalvikvm(30656): GC_CONCURRENT freed 413K, 5% free 10167K/10672K, paused 5ms+3ms, total 35ms 01-31 16:58:45.043: I/ActivityManager(390): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.android.launcher/com.android.launcher2.Launcher} from pid 390 01-31 16:58:45.980: I/ActivityManager(390): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.android.settings/.Settings bnds=[200,785][360,985]} from pid 605 01-31 16:58:46.129: D/BluetoothAdapter(10522): 1112335056: getState() : mService = null. Returning STATE_OFF 01-31 16:58:46.215: W/System.err(10522): Removed 2131231194 01-31 16:58:46.215: W/System.err(10522): Removed 2131231203 01-31 16:58:49.558: I/ActivityManager(390): START u0 {act=android.intent.action.MAIN cmp=com.android.settings/.SubSettings (has extras)} from pid 10522 01-31 16:58:49.683: W/ApplicationContext(10522): Calling a method in the system process without a qualified user: android.app.ContextImpl.bindService:1406 android.content.ContextWrapper.bindService:473 com.android.settings.applications.ManageApplications.onCreate:849 01-31 16:58:49.886: W/System.err(10522): Removed 2131231194 01-31 16:58:49.886: W/System.err(10522): Removed 2131231203 01-31 16:58:50.027: I/ActivityManager(390): Displayed com.android.settings/.SubSettings: +408ms 01-31 16:58:50.121: W/System.err(10522): Removed 2131231194 01-31 16:58:50.121: W/System.err(10522): Removed 2131231203 01-31 16:58:51.426: I/ActivityManager(390): START u0 {act=android.intent.action.MAIN cmp=com.android.settings/.SubSettings (has extras)} from pid 10522 01-31 16:58:51.597: D/dalvikvm(390): GC_CONCURRENT freed 7028K, 24% free 20827K/27188K, paused 4ms+12ms, total 129ms 01-31 16:58:51.605: W/ResourceType(10522): getEntry failing because entryIndex 129 is beyond type entryCount 3 01-31 16:58:51.644: D/dalvikvm(11205): GC_CONCURRENT freed 367K, 5% free 8902K/9300K, paused 2ms+2ms, total 16ms 01-31 16:58:51.738: W/System.err(10522): Removed 2131231194 01-31 16:58:51.738: W/System.err(10522): Removed 2131231203 01-31 16:58:52.019: I/ActivityManager(390): Displayed com.android.settings/.SubSettings: +533ms 01-31 16:58:52.051: W/System.err(10522): Removed 2131231194 01-31 16:58:52.051: W/System.err(10522): Removed 2131231203 01-31 16:58:56.043: W/System.err(10522): Removed 2131231194 01-31 16:58:56.043: W/System.err(10522): Removed 2131231203 01-31 16:58:56.480: D/dalvikvm(11205): GC_CONCURRENT freed 390K, 5% free 8900K/9320K, paused 2ms+2ms, total 16ms 01-31 16:58:58.441: I/ActivityManager(390): START u0 {cmp=edu.northwestern.cbits.purple_robot_manager/.StartActivity bnds=[0,151][720,279]} from pid -1 01-31 16:58:58.441: W/ActivityManager(390): startActivity called from non-Activity context; forcing Intent.FLAG_ACTIVITY_NEW_TASK for: Intent { cmp=edu.northwestern.cbits.purple_robot_manager/.StartActivity bnds=[0,151][720,279] } 01-31 16:58:58.496: W/KeyguardViewMediator(390): verifyUnlock called when not externally disabled 01-31 16:58:58.511: D/HockeyApp(11971): Current handler class = net.hockeyapp.android.internal.ExceptionHandler 01-31 16:58:58.863: W/IInputConnectionWrapper(10522): showStatusIcon on inactive InputConnection 01-31 16:59:04.949: I/InputReader(390): Reconfiguring input devices. changes=0x00000004 01-31 16:59:04.949: I/InputReader(390): Device reconfigured: id=6, name='Melfas MMSxxx Touchscreen', size 720x1280, orientation 3, mode 1, display id 0 01-31 16:59:04.949: I/ActivityManager(390): Config changed: {1.0 999mcc?mnc en_GB ldltr sw360dp w598dp h335dp 320dpi nrml land finger -keyb/v/h -nav/h s.14} 01-31 16:59:05.066: D/HockeyApp(11971): Current handler class = net.hockeyapp.android.internal.ExceptionHandler 01-31 16:59:07.324: D/dalvikvm(390): JIT code cache reset in 10 ms (1048508 bytes 6/0) 01-31 16:59:07.347: D/dalvikvm(390): GC_EXPLICIT freed 2455K, 24% free 20731K/27188K, paused 7ms+20ms, total 120ms 01-31 16:59:13.902: I/EventLogService(769): Aggregate from 1359649753796 (log), 1359649753796 (data) 01-31 16:59:13.949: I/ServiceDumpSys(769): dumping service [account] 01-31 16:59:22.652: D/MtpService(523): updating state; isCurrentUser=true, mMtpLocked=false 01-31 16:59:22.652: D/MtpService(523): addStorageLocked 65537 /storage/emulated/0 01-31 16:59:22.660: D/MtpService(523): updating state; isCurrentUser=true, mMtpLocked=false 01-31 16:59:22.660: D/MtpService(523): starting MTP server in MTP mode 01-31 16:59:22.660: D/MtpService(523): addStorageLocked 65537 /storage/emulated/0 01-31 16:59:22.996: D/PicasaSyncManager(4299): battery info: true 01-31 16:59:23.004: W/PowerUI(464): unknown intent: Intent { act=android.intent.action.ACTION_POWER_CONNECTED flg=0x8000010 } 01-31 16:59:23.019: D/PicasaUploaderSyncManager(11488): battery info: true 01-31 16:59:23.043: D/YouTube(11500): youtube.app.prefetch.PrefetchService$DeviceStateReceiver.onReceive:551 Got device state change intent: android.intent.action.ACTION_POWER_CONNECTED 01-31 16:59:23.051: D/YouTube(11500): youtube.app.prefetch.PrefetchService.run:176 PrefetchService started at 31 Jan 2013 16:59:23 GMT 01-31 16:59:23.058: D/YouTube(11500): youtube.app.prefetch.PrefetchService.onRestored:251 Download snapshot restored 01-31 16:59:23.066: D/YouTube(11500): youtube.app.prefetch.PrefetchService.onDestroy:222 PrefetchService destroyed at 31 Jan 2013 16:59:23 GMT

audaciouscode commented 11 years ago

I've accumulated several gigs of data for testing this and I'm running though the upload test right now. My current working theory is that the issue isn't with the delay, but instead with the throttling of the payload sizes. Given the "Only upload via WiFi" setting, if my test goes through successfully, I'll deprecate that feature and go with a straight 512 KB or 1 MB upload size for payloads.

audaciouscode commented 11 years ago

So, here's the update:

  1. I've been unable to replicate your issue. My current working hypothesis is that you've managed to collect a larger data object than the 512 KB limit allows.
  2. In light of this hypothesis, I've made a few changes that may fix issues standing in the way in the code. I don't have a lot of faith that these fixes in the code itself will solve the "big packet" issue...
  3. ... so I've implemented user-configurable upload intervals and max payload sizes in the app's preferences. In the "HTTP Upload Settings", look for "HTTP Upload Interval" and "HTTP Upload Size". These are configured to use the adaptive behavior by default, so set a manual value to see if changing those parameters addresses your issues. A word of warning - making the upload size has the potential to run the app out of memory, so keep an eye open for that.

These changes will be released shortly in 1.0.26.

I'm leaving this issue open until you confirm that your issue is addressed.

JohnJ-Guiry commented 11 years ago

Alas, I collected that with this version on Saturday. Uploaded on Sunday and upload exceptions occurred twice. Again, the logs seemed to first hint at the WiFi being disconnected before the upload exception was thrown. I waited 11 minutes in both cases to see if uploads would resume automatically (Internet browser etc. was working fine), but they never did, so I manually intervened (something I'm trying to avoid)

Before uploading, I'd set the Upload Interval to 5 minutes, and the Upload Size to 2MB. Didn't seem to run out of memory. I'd assumed the upload interval would have dictated the time to reattempt an upload, should the last upload have failed, but perhaps I misunderstand what that parameter is for?