Android app Crashing with finalize() in SftpFileOutputStream

Question

Hi
I am using edtftpj-pro3.1 trial copy in my android app to make SFTP connection with the server.
After few connections with the server with 5-6 file transfers, my app is crashing with following exception.
I'm using Sqlite dbms. Is it causing the problem or what could be the problem??

04-03 15:06:35.663: ERROR/dalvikvm(12526): HeapWorker is wedged: 13056ms spent inside Lcom/enterprisedt/net/j2ssh/sftp/SftpFileOutputStream;.finalize()V
04-03 15:06:35.663: INFO/dalvikvm(12526): DALVIK THREADS:
04-03 15:06:35.694: INFO/dalvikvm(12526): "main" prio=5 tid=3 RUNNABLE
04-03 15:06:35.694: INFO/dalvikvm(12526): | group="main" sCount=1 dsCount=0 s=Y obj=0x4001b268 self=0xbd00
04-03 15:06:35.703: INFO/dalvikvm(12526): | sysTid=12526 nice=0 sched=0/0 cgrp=default handle=-1344001384
04-03 15:06:35.703: INFO/dalvikvm(12526): at com.corventis.gateway.hostcommunicator.HostCommunicator.workerIsFinished(HostCommunicator.java:~785)
04-03 15:06:35.703: INFO/dalvikvm(12526): at com.corventis.gateway.hostcommunicator.HostCommunicator.communicateWithHost(HostCommunicator.java:1258)
04-03 15:06:35.713: INFO/dalvikvm(12526): at com.corventis.gateway.hostcommunicator.HostCommunicator.doWork(HostCommunicator.java:1364)
04-03 15:06:35.723: INFO/dalvikvm(12526): at com.corventis.gateway.hf.HfGatewayApplication.onCreate(HfGatewayApplication.java:63)
04-03 15:06:35.743: INFO/dalvikvm(12526): at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1047)
04-03 15:06:35.743: INFO/dalvikvm(12526): at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2459)
04-03 15:06:35.753: INFO/dalvikvm(12526): at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2512)
04-03 15:06:35.753: INFO/dalvikvm(12526): at android.app.ActivityThread.access$2200(ActivityThread.java:119)
04-03 15:06:35.753: INFO/dalvikvm(12526): at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1863)
04-03 15:06:35.763: INFO/dalvikvm(12526): at android.os.Handler.dispatchMessage(Handler.java:99)
04-03 15:06:35.796: INFO/dalvikvm(12526): at android.os.Looper.loop(Looper.java:123)
04-03 15:06:35.796: INFO/dalvikvm(12526): at android.app.ActivityThread.main(ActivityThread.java:4363)
04-03 15:06:35.803: INFO/dalvikvm(12526): at java.lang.reflect.Method.invokeNative(Native Method)
04-03 15:06:35.833: INFO/dalvikvm(12526): at java.lang.reflect.Method.invoke(Method.java:521)
04-03 15:06:35.844: INFO/dalvikvm(12526): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:860)
04-03 15:06:35.844: INFO/dalvikvm(12526): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:618)
04-03 15:06:35.854: INFO/dalvikvm(12526): at dalvik.system.NativeStart.main(Native Method)
04-03 15:06:35.863: INFO/dalvikvm(12526): "ssh-connection 6" daemon prio=5 tid=27 TIMED_WAIT
04-03 15:06:35.863: INFO/dalvikvm(12526): | group="main" sCount=1 dsCount=0 s=N obj=0x43cd6a98 self=0x2f0d28
04-03 15:06:35.873: INFO/dalvikvm(12526): | sysTid=15530 nice=0 sched=0/0 cgrp=default handle=3097096
04-03 15:06:35.873: INFO/dalvikvm(12526): at java.lang.Object.wait(Native Method)
04-03 15:06:35.873: INFO/dalvikvm(12526): - waiting on <0x2f4a98> (a com.enterprisedt.net.j2ssh.transport.SshMessageStore)
04-03 15:06:35.873: INFO/dalvikvm(12526): at java.lang.Object.wait(Object.java:326)
04-03 15:06:35.873: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.SshMessageStore.getMessage((null):-1)
04-03 15:06:35.873: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.SshMessageStore.getMessage((null):-1)
04-03 15:06:35.873: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.AsyncService.run((null):-1)
04-03 15:06:35.883: INFO/dalvikvm(12526): at java.lang.Thread.run(Thread.java:1096)
04-03 15:06:35.903: INFO/dalvikvm(12526): "Transport protocol 6" daemon prio=5 tid=25 NATIVE
04-03 15:06:35.903: INFO/dalvikvm(12526): | group="main" sCount=1 dsCount=0 s=N obj=0x43c9f0c8 self=0x2ea620
04-03 15:06:35.913: INFO/dalvikvm(12526): | sysTid=15505 nice=0 sched=0/0 cgrp=default handle=3092536
04-03 15:06:35.913: INFO/dalvikvm(12526): at org.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(Native Method)
04-03 15:06:35.913: INFO/dalvikvm(12526): at org.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478)
04-03 15:06:35.913: INFO/dalvikvm(12526): at org.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565)
04-03 15:06:35.923: INFO/dalvikvm(12526): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87)
04-03 15:06:35.923: INFO/dalvikvm(12526): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:67)
04-03 15:06:35.943: INFO/dalvikvm(12526): at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:157)
04-03 15:06:35.953: INFO/dalvikvm(12526): at java.io.BufferedInputStream.read(BufferedInputStream.java:346)
04-03 15:06:35.953: INFO/dalvikvm(12526): at java.io.BufferedInputStream.read(BufferedInputStream.java:341)
04-03 15:06:35.953: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.A.A((null):-1)
04-03 15:06:35.953: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.A.B((null):-1)
04-03 15:06:35.963: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.processMessages((null):-1)
04-03 15:06:35.963: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.startBinaryPacketProtocol((null):-1)
04-03 15:06:35.974: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.run((null):-1)
04-03 15:06:35.974: INFO/dalvikvm(12526): at java.lang.Thread.run(Thread.java:1096)
04-03 15:06:35.983: INFO/dalvikvm(12526): "Transport protocol 5" daemon prio=5 tid=23 NATIVE
04-03 15:06:35.995: INFO/dalvikvm(12526): | group="main" sCount=1 dsCount=0 s=N obj=0x43b91ed8 self=0x2ecaa0
04-03 15:06:35.995: INFO/dalvikvm(12526): | sysTid=14937 nice=0 sched=0/0 cgrp=default handle=3045656
04-03 15:06:36.003: INFO/dalvikvm(12526): at org.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(Native Method)
04-03 15:06:36.003: INFO/dalvikvm(12526): at org.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478)
04-03 15:06:36.003: INFO/dalvikvm(12526): at org.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565)
04-03 15:06:36.003: INFO/dalvikvm(12526): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87)
04-03 15:06:36.003: INFO/dalvikvm(12526): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:67)
04-03 15:06:36.013: INFO/dalvikvm(12526): at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:157)
04-03 15:06:36.013: INFO/dalvikvm(12526): at java.io.BufferedInputStream.read(BufferedInputStream.java:346)
04-03 15:06:36.013: INFO/dalvikvm(12526): at java.io.BufferedInputStream.read(BufferedInputStream.java:341)
04-03 15:06:36.013: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.A.A((null):-1)
04-03 15:06:36.013: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.A.B((null):-1)
04-03 15:06:36.013: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.processMessages((null):-1)
04-03 15:06:36.013: INFO/dalvikvm(12526): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.startBinaryPacketProtocol((null):-1)
04-03 15

Answer 1

This could be happening because of parallel write mode.

In SSHFTPClient, before connecting try

setParallelMode(false);

Answer 2

Hi

Thanks for the reply. I have
Above solution is working for SftpFileOutputStream but not for SftpFileInputStream.
I have same problem in Android environment while downloading bulk of data.
What could be the reason??
I'm using edtftpj-pro-3.1.2 trial version.
Exception i'm getting is...
05-31 18:28:12.661: ERROR/dalvikvm(589): HeapWorker is wedged: 10173ms spent inside Lcom/enterprisedt/net/j2ssh/sftp/SftpFileInputStream;.finalize()V
05-31 18:28:12.661: INFO/dalvikvm(589): DALVIK THREADS:
05-31 18:28:12.661: INFO/dalvikvm(589): "main" prio=5 tid=3 WAIT
05-31 18:28:12.661: INFO/dalvikvm(589): | group="main" sCount=1 dsCount=0 s=N obj=0x4001b260 self=0xbd18
05-31 18:28:12.661: INFO/dalvikvm(589): | sysTid=589 nice=0 sched=0/0 cgrp=default handle=-1343993192
05-31 18:28:12.661: INFO/dalvikvm(589): at java.lang.Object.wait(Native Method)
05-31 18:28:12.661: INFO/dalvikvm(589): - waiting on <0x122d70> (a android.os.MessageQueue)
05-31 18:28:12.661: INFO/dalvikvm(589): at java.lang.Object.wait(Object.java:288)
05-31 18:28:12.661: INFO/dalvikvm(589): at android.os.MessageQueue.next(MessageQueue.java:148)
05-31 18:28:12.661: INFO/dalvikvm(589): at android.os.Looper.loop(Looper.java:110)
05-31 18:28:12.661: INFO/dalvikvm(589): at android.app.ActivityThread.main(ActivityThread.java:4363)
05-31 18:28:12.661: INFO/dalvikvm(589): at java.lang.reflect.Method.invokeNative(Native Method)
05-31 18:28:12.661: INFO/dalvikvm(589): at java.lang.reflect.Method.invoke(Method.java:521)
05-31 18:28:12.661: INFO/dalvikvm(589): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:860)
05-31 18:28:12.661: INFO/dalvikvm(589): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:618)
05-31 18:28:12.661: INFO/dalvikvm(589): at dalvik.system.NativeStart.main(Native Method)
05-31 18:28:12.671: INFO/dalvikvm(589): "Transport protocol 1" daemon prio=5 tid=29 NATIVE
05-31 18:28:12.671: INFO/dalvikvm(589): | group="main" sCount=1 dsCount=0 s=N obj=0x44774768 self=0x3a7938
05-31 18:28:12.671: INFO/dalvikvm(589): | sysTid=605 nice=0 sched=0/0 cgrp=default handle=3834600
05-31 18:28:12.671: INFO/dalvikvm(589): at org.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(Native Method)
05-31 18:28:12.671: INFO/dalvikvm(589): at org.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478)
05-31 18:28:12.671: INFO/dalvikvm(589): at org.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565)
05-31 18:28:12.671: INFO/dalvikvm(589): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87)
05-31 18:28:12.671: INFO/dalvikvm(589): at org.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:67)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.io.BufferedInputStream.fillbuf(BufferedInputStream.java:157)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.io.BufferedInputStream.read(BufferedInputStream.java:346)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.io.BufferedInputStream.read(BufferedInputStream.java:341)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.enterprisedt.net.j2ssh.transport.A.A((null):-1)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.enterprisedt.net.j2ssh.transport.A.B((null):-1)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.processMessages((null):-1)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.startBinaryPacketProtocol((null):-1)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.enterprisedt.net.j2ssh.transport.TransportProtocolCommon.run((null):-1)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Thread.run(Thread.java:1096)
05-31 18:28:12.671: INFO/dalvikvm(589): "StreamFrameSender" prio=5 tid=27 TIMED_WAIT
05-31 18:28:12.671: INFO/dalvikvm(589): | group="main" sCount=1 dsCount=0 s=N obj=0x44750a60 self=0x3964d8
05-31 18:28:12.671: INFO/dalvikvm(589): | sysTid=603 nice=0 sched=0/0 cgrp=default handle=3761648
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Object.wait(Native Method)
05-31 18:28:12.671: INFO/dalvikvm(589): - waiting on <0x399478> (a com.corventis.gateway.ppp.StreamFrameSender)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Object.wait(Object.java:326)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.corventis.gateway.ppp.StreamFrameSender.run(StreamFrameSender.java:154)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.corventis.gateway.util.MonitoredRunnable.run(MonitoredRunnable.java:41)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Thread.run(Thread.java:1096)
05-31 18:28:12.671: INFO/dalvikvm(589): "SftpActiveWorker" prio=5 tid=25 TIMED_WAIT
05-31 18:28:12.671: INFO/dalvikvm(589): | group="main" sCount=1 dsCount=0 s=N obj=0x447522b0 self=0x398e00
05-31 18:28:12.671: INFO/dalvikvm(589): | sysTid=604 nice=0 sched=0/0 cgrp=default handle=3762704
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Object.wait(Native Method)
05-31 18:28:12.671: INFO/dalvikvm(589): - waiting on <0x3962d8> (a com.corventis.gateway.hostcommunicator.SftpActiveWorker)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Object.wait(Object.java:326)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.corventis.gateway.hostcommunicator.SftpActiveWorker.run(SftpActiveWorker.java:151)
05-31 18:28:12.671: INFO/dalvikvm(589): at com.corventis.gateway.util.MonitoredRunnable.run(MonitoredRunnable.java:41)
05-31 18:28:12.671: INFO/dalvikvm(589): at java.lang.Thread.run(Thread.java:1096)
05-31 18:28:12.671: INFO/dalvikvm(589): "Thread-12" prio=5 tid=23 NATIVE
05-31 18:28:12.671: INFO/dalvikvm(589): | group="main" sCount=1 dsCount=0 s=N obj=0x4474aca8 self=0x115690
05-31 18:28:12.671: INFO/dalvikvm(589): | sysTid=602 nice=0 sched=0/0 cgrp=default handle=878120
05-31 18:28:12.671: INFO/dalvikvm(589): at android.bluetooth.BluetoothSocket.acceptNative(Native Method)
05-31 18:28:12.681: INFO/dalvikvm(589): at android.bluetooth.BluetoothSocket.accept(BluetoothSocket.java:287)
05-31 18:28:12.681: INFO/dalvikvm(589): at android.bluetooth.BluetoothServerSocket.accept(BluetoothServerSocket.java:105)
05-31 18:28:12.681: INFO/dalvikvm(589): at android.bluetooth.BluetoothServerSocket.accept(BluetoothServerSocket.java:91)
05-31 18:28:12.681: INFO/dalvikvm(589): at com.corventis.gateway.bluetooth.BluetoothManager.openPort(BluetoothManager.java:215)
05-31 18:28:12.681: INFO/dalvikvm(589): at com.corventis.gateway.bluetooth.BluetoothManager.open(BluetoothManager.java:84)
05-31 18:28:12.681: INFO/dalvikvm(589): at com.corventis.gateway.patchcommunicator.PatchCommunicator.open(PatchCommunicator.java:123)
05-31 18:28:12.681: INFO/dalvikvm(589): at com.corventis.gateway.patchcommunicator.PatchCommunicatorRunnable.run(PatchCommunicatorRunnable.java:134)
05-31 18:28:12.681: INFO/dalvikvm(589): at java.lang.Thread.run(Thread.java:1096)
05-31 18:28:12.681: INFO/dalvikvm(589): "HfGatewayApplication" prio=5 tid=21 RUNNABLE
05-31 18:28:12.681: INFO/dalvikvm(589): | group="main" sCount=0 dsCount=0 s=N obj=0x4472d9b0 self=0x120928
05-31 18:28:12.681: INFO/dalvikvm(589): | sysTid=601 nice=0 sched=0/0 cgrp=default handle=1264672
05-31 18:28:12.681: INFO/dalvikvm(589): at com.jcraft.jzlib.Deflate.deflateInit2(Deflate.java:~1361)
05-31 18:28:12.681: INFO/dalvikvm(589): at com.jcraft.jz

Answer 3

This has been solved, and the fix will appear in 3.4.0.

Answer 4

Hi Bruce

I appreciate your team for quick response and solving my problem.
Thanks alot.