Upload Errors

[JohnJ-Guiry]

There seems to be a number of issues uploading Purple Robot data for the past few days. Errors include: "General Error: org.apach ...", "Socket Error" etc. Can we revise the re-try timeouts on these? For example, the General Error currently on my device has been there for the past hour, and will seemingly make no further attempts to upload, until I manually intervene, at which point uploads work fine for another few minutes. Instead, it would be better if data was repackaged within X minutes, as I have seen with other error types. X would preferably be something small e.g. 5 or 10 minutes.

[audaciouscode]

Can you attach ADB to your device and let me know what error stack traces you see? I don't have enough information to replicate the issue and test a resolution.

[JohnJ-Guiry]

I'm taking a quick look at the code on this today, and am a little confused as to the purpose of the continueUpload flag. It is set to true only when a valid checksum is found in the response. So if an exception gets thrown upon execution of the HTTP Post request, is it fair to say that continueUpload remains false, meaning the subsequent runnable will not be executed? In the event where probes are disabled, surely this would mean all uploads will then stop until a manual Upload data request is made. I'm also assuming here that processIntent will only be called when a manual upload is requested, or the probes are enabled with data flowing down the pipeline.

In my head, uploads should take a break for a few minutes max, before resuming, but I can't see how this happens ... just yet!

I'm basing this on the latest code from GitHub (Commit ID: 2575349bf5b7a5d19000185de526ab1366d57c49)

I'm making several assumptions here, so feel free to correct them!

[JohnJ-Guiry]

Here's another LogCat from today showing the continueUpload flag is true, the wifi disconnect, a Socket Exception thrown from PR (understandably), and the continueUpload flag remaining false. HTTP Uploads stopped at this point without manually intervening. The Wifi disconnect lasted ~2 seconds. I waited about 40 minutes to see if the uploads recommenced.

02-08 13:54:08.146: E/PRM(3091): CONTINUE UPLOAD: true 02-08 13:54:08.146: I/PRM(3091): FAIL TALLY0 02-08 13:54:09.599: D/dalvikvm(3091): GC_CONCURRENT freed 10545K, 35% free 19937K/30428K, paused 3ms+4ms, total 57ms 02-08 13:54:10.419: D/dalvikvm(3091): GC_CONCURRENT freed 3758K, 35% free 19874K/30428K, paused 3ms+6ms, total 58ms 02-08 13:54:11.247: D/dalvikvm(3091): GC_CONCURRENT freed 3374K, 34% free 20173K/30428K, paused 1ms+4ms, total 55ms 02-08 13:54:11.247: D/dalvikvm(3091): WAIT_FOR_CONCURRENT_GC blocked 31ms 02-08 13:54:12.021: D/dalvikvm(3091): GC_CONCURRENT freed 3971K, 35% free 19964K/30428K, paused 3ms+4ms, total 59ms 02-08 13:54:12.021: D/dalvikvm(3091): WAIT_FOR_CONCURRENT_GC blocked 33ms 02-08 13:54:12.740: D/dalvikvm(3091): GC_CONCURRENT freed 3717K, 35% free 19951K/30428K, paused 2ms+5ms, total 59ms 02-08 13:54:12.740: D/dalvikvm(3091): WAIT_FOR_CONCURRENT_GC blocked 38ms 02-08 13:54:13.435: D/dalvikvm(3091): GC_CONCURRENT freed 3683K, 35% free 19967K/30428K, paused 3ms+5ms, total 56ms 02-08 13:54:13.435: D/dalvikvm(3091): WAIT_FOR_CONCURRENT_GC blocked 27ms 02-08 13:54:14.232: D/dalvikvm(3091): GC_FOR_ALLOC freed 2744K, 34% free 20368K/30428K, paused 44ms, total 44ms 02-08 13:54:15.083: D/dalvikvm(3091): GC_FOR_ALLOC freed 2788K, 32% free 20954K/30428K, paused 56ms, total 56ms 02-08 13:54:15.130: D/dalvikvm(3091): GC_FOR_ALLOC freed 1055K, 32% free 20900K/30428K, paused 35ms, total 35ms 02-08 13:54:15.169: D/dalvikvm(3091): GC_FOR_ALLOC freed 1001K, 32% free 20900K/30428K, paused 35ms, total 35ms 02-08 13:54:15.216: D/dalvikvm(3091): GC_FOR_ALLOC freed <1K, 29% free 21902K/30428K, paused 34ms, total 35ms 02-08 13:54:15.216: I/dalvikvm-heap(3091): Grow heap (frag case) to 22.391MB for 1025108-byte allocation 02-08 13:54:15.255: D/dalvikvm(3091): GC_FOR_ALLOC freed 1001K, 31% free 21901K/31432K, paused 40ms, total 40ms 02-08 13:54:15.310: D/dalvikvm(3091): GC_FOR_ALLOC freed <1K, 28% free 22903K/31432K, paused 37ms, total 37ms 02-08 13:54:15.310: I/dalvikvm-heap(3091): Grow heap (frag case) to 23.369MB for 1025196-byte allocation 02-08 13:54:15.349: D/dalvikvm(3091): GC_FOR_ALLOC freed 1001K, 30% free 22903K/32436K, paused 39ms, total 39ms 02-08 13:54:15.779: D/dalvikvm(3091): GC_FOR_ALLOC freed 3945K, 32% free 22376K/32436K, paused 35ms, total 35ms 02-08 13:54:15.833: D/dalvikvm(3091): GC_FOR_ALLOC freed 2425K, 24% free 22410K/29456K, paused 36ms, total 36ms 02-08 13:54:15.841: I/dalvikvm-heap(3091): Grow heap (frag case) to 22.890MB for 1028452-byte allocation 02-08 13:54:15.872: D/dalvikvm(3091): GC_FOR_ALLOC freed 0K, 24% free 23414K/30464K, paused 35ms, total 35ms 02-08 13:54:16.747: D/dalvikvm(3091): GC_FOR_ALLOC freed 3555K, 24% free 23414K/30464K, paused 53ms, total 53ms 02-08 13:54:16.755: I/dalvikvm-heap(3091): Grow heap (frag case) to 24.362MB for 1542674-byte allocation 02-08 13:54:16.794: D/dalvikvm(3091): GC_FOR_ALLOC freed 1004K, 26% free 23916K/31972K, paused 43ms, total 43ms 02-08 13:54:16.997: D/dalvikvm(3091): GC_FOR_ALLOC freed 533K, 26% free 23916K/31972K, paused 40ms, total 40ms 02-08 13:54:16.997: I/dalvikvm-heap(3091): Grow heap (frag case) to 24.508MB for 1182676-byte allocation 02-08 13:54:17.044: D/dalvikvm(3091): GC_FOR_ALLOC freed 0K, 25% free 25071K/33128K, paused 46ms, total 46ms 02-08 13:54:17.083: D/dalvikvm(3091): GC_FOR_ALLOC freed 1506K, 29% free 23565K/33128K, paused 41ms, total 41ms 02-08 13:54:27.537: E/DhcpStateMachine(389): DHCP failed on wlan0: Timed out waiting for DHCP Renew to finish 02-08 13:54:27.747: E/WifiStateMachine(389): IP configuration failed 02-08 13:54:27.763: I/wpa_supplicant(21635): wlan0: CTRL-EVENT-DISCONNECTED bssid=00:0b:0e:c9:13:42 reason=3 locally_generated=1 02-08 13:54:27.779: D/CommandListener(125): Clearing all IP addresses on wlan0 02-08 13:54:27.787: D/ConnectivityService(389): ConnectivityChange for WIFI: DISCONNECTED/DISCONNECTED 02-08 13:54:27.794: D/ConnectivityService(389): Attempting to switch to mobile 02-08 13:54:27.794: D/ConnectivityService(389): Attempting to switch to BLUETOOTH_TETHER 02-08 13:54:27.794: D/ConnectivityService(389): Attempting to switch to ETHERNET 02-08 13:54:27.802: D/NetUtils(389): android_net_utils_resetConnections in env=0x58240db0 clazz=0x44900001 iface=wlan0 mask=0x3 02-08 13:54:27.802: D/ConnectivityService(389): resetConnections(wlan0, 3) 02-08 13:54:27.810: W/System.err(3091): java.net.SocketException: recvfrom failed: ETIMEDOUT (Connection timed out) 02-08 13:54:27.833: D/ConnectivityService(389): ConnectivityChange for WIFI: DISCONNECTED/DISCONNECTED 02-08 13:54:27.841: D/ConnectivityService(389): Attempting to switch to mobile 02-08 13:54:27.841: D/ConnectivityService(389): Attempting to switch to BLUETOOTH_TETHER 02-08 13:54:27.841: D/ConnectivityService(389): Attempting to switch to ETHERNET 02-08 13:54:27.841: D/NetUtils(389): android_net_utils_resetConnections in env=0x58240db0 clazz=0x47800001 iface=wlan0 mask=0x3 02-08 13:54:27.841: W/Smack/Packet(809): notify conn break (IOEx), close connection 02-08 13:54:27.841: D/ConnectivityService(389): resetConnections(wlan0, 3) 02-08 13:54:27.857: W/System.err(3091): at libcore.io.IoBridge.maybeThrowAfterRecvfrom(IoBridge.java:552) 02-08 13:54:27.857: W/System.err(3091): at libcore.io.IoBridge.recvfrom(IoBridge.java:516) 02-08 13:54:27.857: W/System.err(3091): at java.net.PlainSocketImpl.read(PlainSocketImpl.java:488) 02-08 13:54:27.857: W/System.err(3091): at java.net.PlainSocketImpl.access$000(PlainSocketImpl.java:46) 02-08 13:54:27.857: W/System.err(3091): at java.net.PlainSocketImpl$PlainSocketInputStream.read(PlainSocketImpl.java:240) 02-08 13:54:27.857: W/System.err(3091): at org.apache.http.impl.io.AbstractSessionInputBuffer.fillBuffer(AbstractSessionInputBuffer.java:103) 02-08 13:54:27.857: W/System.err(3091): at org.apache.http.impl.io.AbstractSessionInputBuffer.readLine(AbstractSessionInputBuffer.java:191) 02-08 13:54:27.857: W/System.err(3091): at org.apache.http.impl.conn.DefaultResponseParser.parseHead(DefaultResponseParser.java:82) 02-08 13:54:27.857: W/System.err(3091): at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:174) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:180) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:235) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.conn.AbstractClientConnAdapter.receiveResponseHeader(AbstractClientConnAdapter.java:259) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:279) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:121) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:428) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:555) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:487) 02-08 13:54:27.865: W/System.err(3091): at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:465) 02-08 13:54:27.865: W/System.err(3091): at edu.northwestern.cbits.purple_robot_manager.plugins.HttpUploadPlugin$3.run(HttpUploadPlugin.java:607) 02-08 13:54:27.865: W/System.err(3091): at java.lang.Thread.run(Thread.java:856) 02-08 13:54:27.865: W/System.err(3091): Caused by: libcore.io.ErrnoException: recvfrom failed: ETIMEDOUT (Connection timed out) 02-08 13:54:27.872: W/System.err(3091): at libcore.io.Posix.recvfromBytes(Native Method) 02-08 13:54:27.872: W/System.err(3091): at libcore.io.Posix.recvfrom(Posix.java:136) 02-08 13:54:27.872: W/System.err(3091): at libcore.io.BlockGuardOs.recvfrom(BlockGuardOs.java:164) 02-08 13:54:27.880: W/System.err(3091): at libcore.io.IoBridge.recvfrom(IoBridge.java:513) 02-08 13:54:27.880: W/System.err(3091): ... 18 more 02-08 13:54:27.997: I/qtaguid(809): Failed write_ctrl(u 44) res=-1 errno=22 02-08 13:54:27.997: I/qtaguid(809): Untagging socket 44 failed errno=-22 02-08 13:54:27.997: W/NetworkManagementSocketTagger(809): untagSocket(44) failed with errno -22 02-08 13:54:27.997: D/ConnectivityService(389): handleInetConditionChange: no active default network - ignore 02-08 13:54:28.513: I/wpa_supplicant(21635): wlan0: Trying to associate with 00:0b:0e:c9:13:42 (SSID='ulwireless' freq=2437 MHz) 02-08 13:54:28.685: D/dalvikvm(3091): GC_FOR_ALLOC freed 6316K, 34% free 21902K/33124K, paused 45ms, total 45ms 02-08 13:54:28.779: I/wpa_supplicant(21635): wlan0: Associated with 00:0b:0e:c9:13:42 02-08 13:54:28.779: I/wpa_supplicant(21635): wlan0: CTRL-EVENT-CONNECTED - Connection to 00:0b:0e:c9:13:42 completed (reauth) [id=0 id_str=] 02-08 13:54:29.029: D/NetlinkEvent(125): Unexpected netlink message. type=0x0 02-08 13:54:29.044: D/ConnectivityService(389): ConnectivityChange for mobile: CONNECTED/CONNECTED 02-08 13:54:29.427: D/ConnectivityService(389): Captive portal check NetworkInfo: type: WIFI[], state: CONNECTING/CAPTIVE_PORTAL_CHECK, reason: (unspecified), extra: "ulwireless", roaming: false, failover: false, isAvailable: true 02-08 13:54:29.427: D/ConnectivityService(389): Captive check on WIFI 02-08 13:54:29.427: D/ConnectivityService(389): Captive portal check NetworkInfo: type: WIFI[], state: CONNECTING/CAPTIVE_PORTAL_CHECK, reason: (unspecified), extra: "ulwireless", roaming: false, failover: false, isAvailable: true 02-08 13:54:29.427: D/ConnectivityService(389): Captive check on WIFI 02-08 13:54:29.427: D/ConnectivityService(389): ConnectivityChange for WIFI: CONNECTED/CONNECTED 02-08 13:54:29.427: D/ConnectivityService(389): Policy requires mobile teardown 02-08 13:54:29.435: E/WifiStateMachine(389): Error! unhandled message{ what=131092 when=-3ms } 02-08 13:54:29.458: D/ConnectivityService(389): ConnectivityChange for WIFI: CONNECTED/CONNECTED 02-08 13:54:29.458: D/ConnectivityService(389): handleConnectivityChange: address are the same reset per doReset linkProperty[1]: resetMask=0 02-08 13:54:29.818: D/dalvikvm(3091): GC_FOR_ALLOC freed 2950K, 27% free 22487K/30512K, paused 54ms, total 54ms 02-08 13:54:29.826: I/dalvikvm-heap(3091): Grow heap (frag case) to 23.531MB for 1620658-byte allocation 02-08 13:54:29.865: D/dalvikvm(3091): GC_FOR_ALLOC freed 1055K, 29% free 23015K/32096K, paused 41ms, total 41ms 02-08 13:54:30.005: D/dalvikvm(3091): GC_FOR_ALLOC freed 225K, 29% free 23014K/32096K, paused 37ms, total 37ms 02-08 13:54:30.013: I/dalvikvm-heap(3091): Grow heap (frag case) to 23.599MB for 1152624-byte allocation 02-08 13:54:30.044: D/ConnectivityService(389): NetTransition Wakelock for WifiStateMachine released by timeout 02-08 13:54:30.052: D/dalvikvm(3091): GC_FOR_ALLOC freed 0K, 28% free 24140K/33224K, paused 43ms, total 43ms 02-08 13:54:30.076: E/PRM(3091): CONTINUE UPLOAD: false 02-08 13:54:30.076: I/PRM(3091): FAIL TALLY0

[JohnJ-Guiry]

I've replaced the LOC:

if (continueUpload || (me._failCount > 0 && me._failCount < MAX_RETRIES))

to ...

if ((me._failCount >= 0 && me._failCount < MAX_RETRIES))

I've not uploaded anything to Github, but maybe this could fix it?

[JohnJ-Guiry]

Just got this exception: org.apache.http.conn.HttpHostConnectException: Connection to http://165.124.171.122:8093 refused

With the modification, Purple Robot just waited on the Thread sleep for .5s before resuming uploads successfully. Not ideal if the server goes down, but exactly what I was looking for.

I would suggest, doubling up the failCount flag when catching the HTTP exceptions, so only X requests could be made before requiring user intervention.

Closing this for now.

[audaciouscode]

I've pulled continueUpload and we'll see how it goes.

[JohnJ-Guiry]

It seems v1.0.28 continually requires manual upload interventions. Probably caused by an off by one error on line 829 of HttpUploadPlugin.java. I should have highlighted the modification suggested in the earlier comment:

"I've replaced the LOC:

if (continueUpload || (me._failCount GREATER THAN 0 && me._failCount < MAX_RETRIES))

to ...

if ((me._failCount GREATER THAN OR EQUALS 0 && me._failCount < MAX_RETRIES))"

[audaciouscode]

I'm testing a fix now. If it works, I'll send out 1.0.30 and have you verify the fix on your end.

[JohnJ-Guiry]

Seems to work fine now, however there are still upload bugs that need to be fixed :-~