Strange SocketExceptions: connection reset and Connection timed out
I have a Java TCP server and an Android TCP client. The server waits for requests and then sends 50MB of data to the Android client (who reads by looping an array and overwriting the data, so the data is not saved on the phone.) Everything works fine and dandy but at random times the client crashes with this:
java.net.SocketException: Connection timed out
and the server gets this:
java.net.SocketException: connection reset
The client reads in a loop until it has received all the data (the maximum I allow it to read in one call is 1.5MB.
The server sends like this:
connectionSocket.getOutputStream().write(new byte[1024*1024*10*5]);
I am looping the client and trying to do this transfer 5-10 times so I can take battery life measurements but I rarely get 3 successful completions of the 50MB transfer. I am really at a loss... the setup I have is really quite simple. I am willing to post code if it will help.
Here is what adb logcat says for android at the crash:
...transfering
D/WifiService( 109): got ACTION_DEVICE_IDLE
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
V/WifiMonitor( 109): Event [CTRL-EVENT-STATE-CHANGE id=1 state=8]
V/WifiStateTracker( 109): Changing supplicant state: COMPLETED ==> DORMANT
D/WifiStateTracker( 109): Reset connections and stopping DHCP
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
E/wpa_supplicant( 209): Set_key: Wrong Key
V/WifiMonitor( 109): Event [CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys]
V/WifiMonitor( 109): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=8]
D/WifiStateTracker( 109): Disabling interface
D/NetworkStateTracker( 109): setDetailed state, old =CONNECTED and new state=IDLE
V/WifiMonitor( 109): Event [CTRL-EVENT-DRIVER-STATE STOPPED]
V/WifiStateTracker( 109): New network state is DISCONNECTED
V/WifiStateTracker( 109): Changing supplicant state: DORMANT ==> DORMANT
D/ConnectivityService( 109): ConnectivityChange for WIFI: DISCONNECTED/IDLE
D/ConnectivityService( 109): getMobileDataEnabled returning false
D/ConnectivityService( 109): not failing over to mobile type 0 because Mobile Data Disabled
D/ConnectivityService( 109): not failing over to mobile type 2 because Mobile Data Disabled
D/ConnectivityService( 109): not failing over to mobile type 3 because Mobile Data Disabled
D/ConnectivityService( 109): not failing over to mobile type 4 because Mobile Data Disabled
D/ConnectivityService( 109): not failing over to mobile type 5 because Mobile Data Disabled
D/Tethering( 109): Tethering got CONNECTIVITY_ACTION
D/Tethering( 109): MasterInitialState.processMessage what=3
E/HierarchicalStateMachine( 109): TetherMaster - unhandledMessage: msg.what=3
I/ActivityManager( 109): Start proc android.process.media for broadcast com.android.providers.downloads/.DownloadReceiver: pid=793 uid=10004 gids={1015, 2001, 3003}
D/NetworkLocationProvider( 109): updateNetworkState(): Updating network state to 1
I/ActivityThread( 793): Publishing provider media: com.android.providers.media.MediaProvider
V/MediaProvider( 793): Attached volume: internal
V/MediaProvider( 793): /mnt/sdcard volume ID: 845505849
V/MediaProvider( 793): Attached volume: external
I/ActivityThread( 793): Publishing provider downloads: com.android.providers.downloads.DownloadProvider
I/ActivityThread( 793): Publishing provider drm: com.android.providers.drm.DrmProvider
I/GTalkService( 243): [ServiceAutoStarter] --- connectivity changed
I/GTalkService( 243): [ServiceAutoStarter] --- start GTalk service ---
I/ActivityManager( 109): Start proc com.google.android.apps.uploader for broadcast com.google.android.apps.uploader/.ConnectivityBroadcastReceiver: pid=801 uid=10027 gids={3003}
D/GTalkService( 243): [GTalkService.1] onStartCommand: found 0 connections, force audit connections...
D/GoogleLoginService( 243): onBind: Intent { act=android.accounts.AccountAuthenticator cmp=com.google.android.gsf/.loginservice.GoogleLoginService }
W/GoogleLoginService( 243): Device has no accounts: sending Intent { act=com.google.android.gsf.LOGIN_ACCOUNTS_MISSING }
D/GTalkService( 243): [GTalkService.25] account missing
I/ActivityThread( 801): Publishing provider com.google.android.apps.uploader: com.google.android.apps.uploader.UploadsContentProvider
I/ActivityThread( 801): Publishing provider com.google.photos.provider.Album: com.google.android.apps.uploader.clients.picasa.AlbumProvider
D/MediaUploader( 801): UploaderApplication.onCreate
D/MediaUploader( 801): nonWifiLimit=20971520, default=20971520
I/MediaUploader( 801): No need to wake up
I/ActivityManager( 109): Process com.google.android.apps.genie.geniewidget (pid 442) has died.
W/ActivityManager( 109): Scheduling restart of crashed service com.google.android.apps.genie.geniewidget/.GenieRefreshService in 5000ms
I/IO exception ( 766): ******************** Log Msg IOE java.net.SocketException: Connection timed out
**W/System.err( 766): java.net.SocketException: Connection timed out
W/System.err( 766): at org.apache.harmony.luni.platform.OSNetworkSystem.readSocketImpl(Native Method)
W/System.err( 766): at org.apache.harmony.luni.platform.OSNetworkSystem.read(OSNetworkSystem.java:358)
W/System.err( 766): at org.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:561)
W/System.err( 766): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:88)
W/System.err( 766): at com.mdog.datareceive.Receive$1.onReceive(Receive.java:71)
W/System.err( 766): at android.app.ActivityThread$PackageInfo$ReceiverDispatcher$Args.run(ActivityThread.java:892)
W/System.err( 766): at android.os.Handler.handleCallback(Handler.java:587)
W/System.err( 766): at android.os.Handler.dispatchMessage(Handler.java:92)
W/System.err( 766): at android.os.Looper.loop(Looper.java:123)
W/System.err( 766): at android.app.ActivityThread.main(ActivityThread.java:4627)
W/System.err( 766): at java.lang.reflect.Method.invokeNative(Native Method)
W/System.err( 766): at java.lang.reflect.Method.invoke(Method.java:521)
W/System.err( 766): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
W/System.err( 766): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
W/System.err( 766): at dalvik.system.NativeStart.main(Native Method)**
I/ActivityManager( 109): Start proc com.google.android.apps.genie.geniewidget for service com.google.android.apps.genie.geniewidget/.GenieRefreshService: pid=811 uid=10031 gids={3003, 1015}
Here is the server exception:
Exception in thread "main" java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:96)
at java.net.SocketOutputStream.write(SocketOutputStream.java:124)
at com.mdog.tcpserver.ServerDriver.main(ServerDriver.java:55)
Answer
There are various reasons why the connection drops, ranging from the infrastructure (as Dan pointed out) to the device going to sleep. You might want to try requesting a wakelock and see if this helps. Also, by randomly pressing the touch screen to keep the device from sleeping could see if this is sleep-related.
On the other hand, if you just catch the Exception and immediately reconnect and retry, your measurements shouldn't be off by too much. You might also want to try UDP instead of TCP (no timeouts possible). Be sure to monitor if the throughput drops though.