I'm using scp to copy files to another company via our 4.3.3 server. I am having transfer problems right at the transfer point in scp. Below are 2 debug outputs showing the bottleneck. The lower level debug preceeds the higher level debug output. It just seems to stop and refuses to transfer the file from my server to the other server. It's an intermittent problem that seems to be worse on larger files. Can anyone give any suggestions on what might be causing this? Or does anyone know of any utilities I could you to look at the actual packets going out and back to see if there is a clue in those as to what is happening. I'm studying to be a unix system admin but I'm still a newbie in most things unix. This was set up by another programmer who is gone now and it has fallen into my lap to find a fix.

Any help would be greatly appreciated.

This is the command I am using:
scp -D4 -d --overwrite -p /share/ftpxfer/out/current/PELLPA_810_14740_16109 mikron@ecftp.adx.net:testin

I'm using Fsecure for IT for unix for the scp program.


scp:SshFSM/sshfsm.c:236: Entering the scheduler
scp:SshFSM/sshfsm.c:268: Thread continuing from state `20056254' (20056254)
scp:SshFSM/sshfsm.c:410: Starting a new thread starting from `fctc_start_transfer'
scp:SshFSM/sshfsm.c:351: Thread waiting for a thread to terminate in state `fct_set_attrs'
scp:SshFSM/sshfsm.c:268: Thread continuing from state `fctc_start_transfer' (Prepare everything for the actual transfer)
scp:SshFCTransferCore/sshfc_trcore.c:457: Starting transfer for file PELLPA_810_14740_16109, destination testin/PELLPA_810_14740_16109
scp:SshFSM/sshfsm.c:410: Starting a new thread starting from `fctc_shred'
scp:SshFSM/sshfsm.c:410: Starting a new thread starting from `fctc_write_out'
scp:SshEventLoop/sshunixeloop.c:443: timeout 45 at 1210629762:444503
scp:SshFSM/sshfsm.c:351: Thread waiting for a thread to terminate in state `fct_finish_thread'
scp:SshFSM/sshfsm.c:268: Thread continuing from state `fctc_shred' (Shred file to requests)
scp:SshFCTransferCore/sshfc_trcore.c:963: Reading 6265 bytes from offset 0.
scp:SshEventLoop/sshunixeloop.c:443: timeout 46 at 1210629761:444884
scp:SshEventLoop/sshunixeloop.c:443: timeout 47 at 1210629761:444991
scp:SshFCTransferCore/sshfc_trcore.c:897: No more requests at this time.
scp:SshFSM/sshfsm.c:343: Thread waiting for a condition variable in state `fctc_read_in'
scp:SshFSM/sshfsm.c:268: Thread continuing from state `fctc_write_out' (Try to write data to file)
scp:SshFCTransferCore/sshfc_trcore.c:1167: No more requests at this time.
scp:SshFSM/sshfsm.c:343: Thread waiting for a condition variable in state `fctc_write_out'
scp:SshFSM/sshfsm.c:252: No active threads so return from scheduler
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 46
scp:SshEventLoop/sshunixeloop.c:523: cancelled 46
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 47
scp:SshEventLoop/sshunixeloop.c:523: cancelled 47
scp:SshEventLoop/sshunixeloop.c:443: timeout 48 at 1210629761:446264
scp:SshPacketWrapper/sshpacketwrapper.c:137: Wrote 33 bytes of data.
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 48
scp:SshEventLoop/sshunixeloop.c:523: cancelled 48
scp:Ssh2SftpServer/sshfilexfers.c:542: Received SSH_FXP_READ.
scp:Ssh2SftpServer/sshfilexfers.c:928: SSH_FXP_READ: len 6265, offset 0
scp:SshEventLoop/sshunixeloop.c:443: timeout 49 at 1210629761:446945
scp:SshEventLoop/sshunixeloop.c:443: timeout 50 at 1210629761:447057
scp:SshEventLoop/sshunixeloop.c:443: timeout 51 at 1210629761:447195
scp:SshPacketWrapper/sshpacketwrapper.c:137: Wrote 6278 bytes of data.
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 49
scp:SshEventLoop/sshunixeloop.c:523: cancelled 49
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 50
scp:SshEventLoop/sshunixeloop.c:523: cancelled 50
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 51
scp:SshEventLoop/sshunixeloop.c:523: cancelled 51
scp:SshFCTransferCore/sshfc_trcore.c:719: Got 6265 bytes of data.
scp:SshFCTransferCore/sshfc_trcore.c:755: Adding a write request to writer's request queue.
scp:SshFSM/sshfsm.c:611: Signalling a condition variable
scp:SshFSM/sshfsm.c:621: Ok, activating one of the waiting threads
scp:SshEventLoop/sshunixeloop.c:443: timeout 52 at 1210629761:448424
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 52
scp:SshEventLoop/sshunixeloop.c:523: cancelled 52
scp:SshFSM/sshfsm.c:236: Entering the scheduler
scp:SshFSM/sshfsm.c:268: Thread continuing from state `fctc_write_out' (Try to write data to file)
scp:SshFCTransferCore/sshfc_trcore.c:1178: Writing 6265 bytes to offset 0.
scp:SshFCTransferCore/sshfc_trcore.c:1167: No more requests at this time.
scp:SshFSM/sshfsm.c:343: Thread waiting for a condition variable in state `fctc_write_out'
scp:SshFSM/sshfsm.c:252: No active threads so return from scheduler
scp:SshPacketWrapper/sshpacketwrapper.c:137: Wrote 6298 bytes of data.
debug: SshEventLoop/sshunixeloop.c:443: timeout 71 at 1210629761:449775
debug: SshEventLoop/sshunixeloop.c:443: timeout 72 at 1210629761:449903
debug: SshEventLoop/sshunixeloop.c:443: timeout 73 at 1210629761:450015
debug: SshEventLoop/sshunixeloop.c:443: timeout 74 at 1210629761:450127
debug: SshEventLoop/sshunixeloop.c:443: timeout 75 at 1210629761:450255
debug: SshEventLoop/sshunixeloop.c:443: timeout 76 at 1210629761:450368
debug: SshEventLoop/sshunixeloop.c:443: timeout 77 at 1210629761:450481
debug: SshEventLoop/sshunixeloop.c:443: timeout 78 at 1210629761:450593
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 71
debug: SshEventLoop/sshunixeloop.c:523: cancelled 71
debug: Ssh2Transport/trcommon.c:554: Outgoing empty, sending empty ignore packet.
debug: Ssh2Transport/trcommon.c:223: Running padding generator.
debug: Ssh2Transport/trcommon.c:554: Outgoing empty, sending empty ignore packet.
debug: Ssh2Transport/trcommon.c:223: Running padding generator.
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 72
debug: SshEventLoop/sshunixeloop.c:523: cancelled 72
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 73
debug: SshEventLoop/sshunixeloop.c:523: cancelled 73
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 74
debug: SshEventLoop/sshunixeloop.c:523: cancelled 74
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 75
debug: SshEventLoop/sshunixeloop.c:523: cancelled 75
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 76
debug: SshEventLoop/sshunixeloop.c:523: cancelled 76
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 77
debug: SshEventLoop/sshunixeloop.c:523: cancelled 77
debug: SshEventLoop/sshunixeloop.c:1004: firing timeout 78
debug: SshEventLoop/sshunixeloop.c:523: cancelled 78
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 45
scp:SshEventLoop/sshunixeloop.c:523: cancelled 45
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 53 at 1210629763:444872
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 53
scp:SshEventLoop/sshunixeloop.c:523: cancelled 53
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 54 at 1210629764:445143
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 54
scp:SshEventLoop/sshunixeloop.c:523: cancelled 54
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 55 at 1210629765:445415
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 55
scp:SshEventLoop/sshunixeloop.c:523: cancelled 55
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 56 at 1210629766:445686
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 56
scp:SshEventLoop/sshunixeloop.c:523: cancelled 56
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 57 at 1210629767:445964
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 57
scp:SshEventLoop/sshunixeloop.c:523: cancelled 57
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 58 at 1210629768:446236
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 58
scp:SshEventLoop/sshunixeloop.c:523: cancelled 58
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 59 at 1210629769:446512
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 59
scp:SshEventLoop/sshunixeloop.c:523: cancelled 59
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 60 at 1210629770:446784
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 60
scp:SshEventLoop/sshunixeloop.c:523: cancelled 60
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 61 at 1210629771:447063
scp:SshEventLoop/sshunixeloop.c:1004: firing timeout 61
scp:SshEventLoop/sshunixeloop.c:523: cancelled 61
PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%scp:SshEventLoop/sshunixeloop.c:443: timeout 62 at 1210629772:447345



Here's a higher level debug of the same point in the transfer:


scp:Scp2/scp2.c:1559: buffer: 'AUTHENTICATED YES
'
debug: Ssh2ChannelSession/sshchsession.c:2584: session channel established (but requests not yet sent)
debug: SshTtyFlags/sshttyflags.c:286: Not a tty. (fd = 0)
debug: Ssh2ChannelSession/sshchsession.c:2746: Requesting subsystem sftp
debug: SshConnection/sshconn.c:1655: Received reply for a channel request.
scp:SshFileXferClient/sshfilexferc.c:1436: ext_name `newline@vandyke.com', data:
scp:00000000: 0d0a ..
scp:SshFileXferClient/sshfilexferc.c:1461: Negotiated version: 3 (own version: 3, remote version: 3).
scp:SshFileCopy/sshfilecopy.c:620: Connection to remote host 'ecftp.adx.net', ready to serve requests.
scp:SshFCTransfer/sshfc_transfer.c:245: Fetching source newline convention extension data.
scp:SshFCTransfer/sshfc_transfer.c:259: Fetching dest newline convention extension data.
scp:SshFCTransfer/sshfc_transfer.c:276: source newline:
scp:00000000: 0a .
scp:SshFCTransfer/sshfc_transfer.c:281: destination newline:
scp:00000000: 0d0a ..
scp:SshFCTransfer/sshfc_transfer.c:309: Statting destination location ``testin'' before transfer...
scp:SshFCTransfer/sshfc_transfer.c:344: Setting next source file item...
scp:SshFCTransfer/sshfc_transfer.c:397: file name: ``/share/ftpxfer/out/current''
scp:SshFCTransfer/sshfc_transfer.c:453: basedir = /share/ftpxfer/out/current
scp:SshFCTransfer/sshfc_transfer.c:570: destination file: testin/PELLPA_810_14740_16109
scp:SshFCTransfer/sshfc_transfer.c:573: source file: /share/ftpxfer/out/current/PELLPA_810_14740_16109
scp:SshFCTransfer/sshfc_transfer.c:722: Statting source file ``/share/ftpxfer/out/current/PELLPA_810_14740_16109''...
scp:Ssh2SftpServer/sshfilexfers.c:1112: SSH_FXP_STAT /share/ftpxfer/out/current/PELLPA_810_14740_16109
scp:SshFCTransfer/sshfc_transfer.c:737: Statting destination file ``testin/PELLPA_810_14740_16109''...
scp:SshFCTransfer/sshfc_transfer.c:1132: Opening dest file testin/PELLPA_810_14740_16109...
scp:SshFCTransfer/sshfc_transfer.c:1115: File `testin/PELLPA_810_14740_16109' opened successfully.
scp:SshFCTransfer/sshfc_transfer.c:1148: Opening source file /share/ftpxfer/out/current/PELLPA_810_14740_16109...
scp:Ssh2SftpServer/sshfilexfers.c:783: SSH_FXP_OPEN /share/ftpxfer/out/current/PELLPA_810_14740_16109
scp:SshFCTransfer/sshfc_transfer.c:1115: File `PELLPA_810_14740_16109' opened successfully.
scp:SshFCTransfer/sshfc_transfer.c:1249: Setting permissions.
scp:SshFCTransferCore/sshfc_trcore.c:457: Starting transfer for file PELLPA_810_14740_16109, destination testin/PELLPA_810_14740_16109
scp:Ssh2SftpServer/sshfilexfers.c:542: Received SSH_FXP_READ.

This is the point where it stops above and keeps coming back with the firing timeouts in the lower level debug statement above.

PELLPA_810_14740_16109 | 0B | 0B/s | ETA: 01:44:25 | 0%^C
Interrupt.
$