Andrew Stuart
asked on
Issues with Scripted SFTP to Proftpd Server - Get command gets the file then drops connection when scripted
Hi
So if I manually connect using sftp from a centos box to my Proftpd server and issue a get command to grab a file, all's good.
If I do it in a script, it fails after getting the file (next step would be to delete the file which it never does)
It's driving me round the bend abit, so any help would be greatly appreciated.
on the sftp client side
Log from Scripted version
2018-03-15 12:34:35,029 [30711] <sftp:6>: received READ (5) SFTP request (request ID 11, channel ID 0)
2018-03-15 12:34:35,030 [30711] <sftp:7>: received request: READ 8fc9867310df242f 0 32768
2018-03-15 12:34:35,030 [30711] <sftp:8>: sending response: STATUS 1 'End of file' ('End of file' [-1])
2018-03-15 12:34:35,030 [30711] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 37 data bytes)
2018-03-15 12:34:35,030 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:34:35,030 [30711] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2018-03-15 12:34:35,031 [30711] <ssh2:11>: channel ID 0 remote window size currently at 2096633 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet len = 44 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet padding len = 5 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet payload len = 38 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:20>: SSH2 packet MAC len = 16 bytes
2018-03-15 12:34:35,032 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2018-03-15 12:34:35,032 [30711] <ssh2:17>: processing 29 bytes of data for channel ID 0
2018-03-15 12:34:35,032 [30711] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2018-03-15 12:34:35,032 [30711] <sftp:19>: using 29 bytes of SSH2 packet buffer data
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request packet len 25 from SSH2 packet buffer (25 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request type 4 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request payload size 24 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request ID 12 from SSH2 packet buffer (20 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: filling remaining SFTP request payload (20 of 20 total bytes) from SSH2 packet buffer (20 bytes in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: completely filled payload of 20 bytes (0 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:6>: received CLOSE (4) SFTP request (request ID 12, channel ID 0)
2018-03-15 12:34:35,032 [30711] <sftp:7>: received request: CLOSE 8fc9867310df242f
2018-03-15 12:34:35,041 [30711] <ssh2:15>: destroying unclosed channel ID 0 (0 bytes pending)
Log from manual version
2018-03-15 12:37:59,725 [30739] <sftp:6>: received READ (5) SFTP request (request ID 21, channel ID 0)
2018-03-15 12:37:59,725 [30739] <sftp:7>: received request: READ 5c57736371c82744 0 32768
2018-03-15 12:37:59,725 [30739] <sftp:8>: sending response: STATUS 1 'End of file' ('End of file' [-1])
2018-03-15 12:37:59,725 [30739] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 37 data bytes)
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2018-03-15 12:37:59,726 [30739] <ssh2:11>: channel ID 0 remote window size currently at 2095615 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet len = 44 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet padding len = 5 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet payload len = 38 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet MAC len = 16 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2018-03-15 12:37:59,726 [30739] <ssh2:17>: processing 29 bytes of data for channel ID 0
2018-03-15 12:37:59,726 [30739] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2018-03-15 12:37:59,726 [30739] <sftp:19>: using 29 bytes of SSH2 packet buffer data
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request packet len 25 from SSH2 packet buffer (25 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request type 4 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request payload size 24 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request ID 22 from SSH2 packet buffer (20 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: filling remaining SFTP request payload (20 of 20 total bytes) from SSH2 packet buffer (20 bytes in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: completely filled payload of 20 bytes (0 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:6>: received CLOSE (4) SFTP request (request ID 22, channel ID 0)
2018-03-15 12:37:59,726 [30739] <sftp:7>: received request: CLOSE 5c57736371c82744
2018-03-15 12:37:59,735 [30739] <sftp:8>: sending response: STATUS 0 'OK'
2018-03-15 12:37:59,735 [30739] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 28 data bytes)
2018-03-15 12:37:59,735 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:37:59,735 [30739] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (64 bytes)
2018-03-15 12:37:59,735 [30739] <ssh2:11>: channel ID 0 remote window size currently at 2095587 bytes
2018-03-15 12:37:59,736 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
From ProftpD server Trace log during scripted version
2018-03-15 12:34:35,029 [30711] <sftp:6>: received READ (5) SFTP request (request ID 11, channel ID 0)
2018-03-15 12:34:35,030 [30711] <sftp:7>: received request: READ 8fc9867310df242f 0 32768
2018-03-15 12:34:35,030 [30711] <sftp:8>: sending response: STATUS 1 'End of file' ('End of file' [-1])
2018-03-15 12:34:35,030 [30711] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 37 data bytes)
2018-03-15 12:34:35,030 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:34:35,030 [30711] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2018-03-15 12:34:35,031 [30711] <ssh2:11>: channel ID 0 remote window size currently at 2096633 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet len = 44 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet padding len = 5 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet payload len = 38 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:20>: SSH2 packet MAC len = 16 bytes
2018-03-15 12:34:35,032 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2018-03-15 12:34:35,032 [30711] <ssh2:17>: processing 29 bytes of data for channel ID 0
2018-03-15 12:34:35,032 [30711] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2018-03-15 12:34:35,032 [30711] <sftp:19>: using 29 bytes of SSH2 packet buffer data
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request packet len 25 from SSH2 packet buffer (25 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request type 4 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request payload size 24 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request ID 12 from SSH2 packet buffer (20 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: filling remaining SFTP request payload (20 of 20 total bytes) from SSH2 packet buffer (20 bytes in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: completely filled payload of 20 bytes (0 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:6>: received CLOSE (4) SFTP request (request ID 12, channel ID 0)
2018-03-15 12:34:35,032 [30711] <sftp:7>: received request: CLOSE 8fc9867310df242f
2018-03-15 12:34:35,041 [30711] <ssh2:15>: destroying unclosed channel ID 0 (0 bytes pending)
From SFTP Log on ProftpD Server
2018-03-15 12:34:34,638 mod_sftp/0.9.9[30711]: user 'DEV' authenticated via 'password' method
2018-03-15 12:34:34,997 mod_sftp/0.9.9[30711]: 'env' channel request: 'LANG' = 'en_US.UTF-8'
2018-03-15 12:34:34,998 mod_sftp/0.9.9[30711]: 'subsystem' channel request for 'sftp' subsystem
2018-03-15 12:34:35,001 mod_sftp/0.9.9[30711]: using SFTP protocol version 3 for this session (channel ID 0)
2018-03-15 12:34:35,006 mod_sftp/0.9.9[30711]: error resolving '/data_recieved': No such file or directory
2018-03-15 12:34:35,041 mod_sftp/0.9.9[30711]: aborting 1 unclosed file handle
script (which is from a Client so I've modified the variables side a bit)
export SFTP_DIR=data_recieved
export LOC_DIR=/root/
export SFTP_FILE_NAME_PATTERN=TES
export SFTP_CONF_NAME=testconf
sftp -vvvv -oPort=2222 DEV@ftpserver <<END
cd $SFTP_DIR
lcd $LOC_DIR
mput ${SFTP_FILE_NAME_PATTERN}
put ${SFTP_CONF_NAME}conf ${SFTP_CONF_NAME}conf
get testconfconf testnew.new
rm ${SFTP_CONF_NAME}conf
bye
END
From scripted version on sftp client end.
sftp> get testconfconf testnew.new
debug3: Looking up /testconfconf
debug3: Sent message fd 3 T:7 I:8
debug3: Wrote 64 bytes for a total of 3421
debug3: Received stat reply T:105 I:8
Fetching /testconfconf to testnew.new
debug3: Sent message fd 3 T:17 I:9
debug3: Wrote 64 bytes for a total of 3485
debug3: Received stat reply T:105 I:9
debug3: Sent message SSH2_FXP_OPEN I:10 P:/testconfconf
debug3: Wrote 80 bytes for a total of 3565
/testconfconf 0% 0 0.0KB/s --:-- ETAdebug3: Request range 0 -> 32767 (0/1)
debug3: Wrote 80 bytes for a total of 3645
debug3: Received reply T:103 I:11 R:1
debug3: Received data 0 -> 8
debug3: Short data block, re-requesting 9 -> 32767 ( 1)
debug3: Finish at 32768 ( 1)
debug3: Wrote 80 bytes for a total of 3725
debug3: Received reply T:101 I:12 R:1
/testconfconf 100% 9 0.0KB/s 00:00
debug3: Sent message SSH2_FXP_CLOSE I:13
debug3: Wrote 64 bytes for a total of 3789
debug3: Wrote 64 bytes for a total of 3853
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
#0 client-session (t4 r0 i0/0 o0/0 fd 4/5 cfd -1)
debug3: channel 0: close_fds r 4 w 5 e 6 c -1
debug1: fd 0 clearing O_NONBLOCK
debug3: fd 1 is not O_NONBLOCK
Connection to ftpserver closed by remote host.
Transferred: sent 3432, received 3672 bytes, in 0.6 seconds
Bytes per second: sent 5308.2, received 5679.4
debug1: Exit status -1
Connection closed
From Manual
sftp> get testconfconf
debug3: Looking up /testconfconf
debug3: Sent message fd 3 T:7 I:8
debug3: Wrote 64 bytes for a total of 3149
debug3: Received stat reply T:105 I:8
Fetching /testconfconf to testconfconf
debug3: Sent message fd 3 T:17 I:9
debug3: Wrote 64 bytes for a total of 3213
debug3: Received stat reply T:105 I:9
debug3: Sent message SSH2_FXP_OPEN I:10 P:/testconfconf
debug3: Wrote 80 bytes for a total of 3293
/testconfconf 0% 0 0.0KB/s --:-- ETAdebug3: Request range 0 -> 32767 (0/1)
debug3: Wrote 80 bytes for a total of 3373
debug3: Received reply T:103 I:11 R:1
debug3: Received data 0 -> 8
debug3: Short data block, re-requesting 9 -> 32767 ( 1)
debug3: Finish at 32768 ( 1)
debug3: Wrote 80 bytes for a total of 3453
debug3: Received reply T:101 I:12 R:1
/testconfconf 100% 9 0.0KB/s 00:00
debug3: Sent message SSH2_FXP_CLOSE I:13
debug3: Wrote 64 bytes for a total of 3517
debug3: SSH2_FXP_STATUS 0
So if I manually connect using sftp from a centos box to my Proftpd server and issue a get command to grab a file, all's good.
If I do it in a script, it fails after getting the file (next step would be to delete the file which it never does)
It's driving me round the bend abit, so any help would be greatly appreciated.
on the sftp client side
Log from Scripted version
2018-03-15 12:34:35,029 [30711] <sftp:6>: received READ (5) SFTP request (request ID 11, channel ID 0)
2018-03-15 12:34:35,030 [30711] <sftp:7>: received request: READ 8fc9867310df242f 0 32768
2018-03-15 12:34:35,030 [30711] <sftp:8>: sending response: STATUS 1 'End of file' ('End of file' [-1])
2018-03-15 12:34:35,030 [30711] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 37 data bytes)
2018-03-15 12:34:35,030 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:34:35,030 [30711] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2018-03-15 12:34:35,031 [30711] <ssh2:11>: channel ID 0 remote window size currently at 2096633 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet len = 44 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet padding len = 5 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet payload len = 38 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:20>: SSH2 packet MAC len = 16 bytes
2018-03-15 12:34:35,032 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2018-03-15 12:34:35,032 [30711] <ssh2:17>: processing 29 bytes of data for channel ID 0
2018-03-15 12:34:35,032 [30711] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2018-03-15 12:34:35,032 [30711] <sftp:19>: using 29 bytes of SSH2 packet buffer data
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request packet len 25 from SSH2 packet buffer (25 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request type 4 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request payload size 24 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request ID 12 from SSH2 packet buffer (20 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: filling remaining SFTP request payload (20 of 20 total bytes) from SSH2 packet buffer (20 bytes in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: completely filled payload of 20 bytes (0 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:6>: received CLOSE (4) SFTP request (request ID 12, channel ID 0)
2018-03-15 12:34:35,032 [30711] <sftp:7>: received request: CLOSE 8fc9867310df242f
2018-03-15 12:34:35,041 [30711] <ssh2:15>: destroying unclosed channel ID 0 (0 bytes pending)
Log from manual version
2018-03-15 12:37:59,725 [30739] <sftp:6>: received READ (5) SFTP request (request ID 21, channel ID 0)
2018-03-15 12:37:59,725 [30739] <sftp:7>: received request: READ 5c57736371c82744 0 32768
2018-03-15 12:37:59,725 [30739] <sftp:8>: sending response: STATUS 1 'End of file' ('End of file' [-1])
2018-03-15 12:37:59,725 [30739] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 37 data bytes)
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2018-03-15 12:37:59,726 [30739] <ssh2:11>: channel ID 0 remote window size currently at 2095615 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet len = 44 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet padding len = 5 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet payload len = 38 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:20>: SSH2 packet MAC len = 16 bytes
2018-03-15 12:37:59,726 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:37:59,726 [30739] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2018-03-15 12:37:59,726 [30739] <ssh2:17>: processing 29 bytes of data for channel ID 0
2018-03-15 12:37:59,726 [30739] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2018-03-15 12:37:59,726 [30739] <sftp:19>: using 29 bytes of SSH2 packet buffer data
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request packet len 25 from SSH2 packet buffer (25 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request type 4 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request payload size 24 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: read SFTP request ID 22 from SSH2 packet buffer (20 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: filling remaining SFTP request payload (20 of 20 total bytes) from SSH2 packet buffer (20 bytes in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:19>: completely filled payload of 20 bytes (0 bytes remaining in buffer)
2018-03-15 12:37:59,726 [30739] <sftp:6>: received CLOSE (4) SFTP request (request ID 22, channel ID 0)
2018-03-15 12:37:59,726 [30739] <sftp:7>: received request: CLOSE 5c57736371c82744
2018-03-15 12:37:59,735 [30739] <sftp:8>: sending response: STATUS 0 'OK'
2018-03-15 12:37:59,735 [30739] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 28 data bytes)
2018-03-15 12:37:59,735 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:37:59,735 [30739] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (64 bytes)
2018-03-15 12:37:59,735 [30739] <ssh2:11>: channel ID 0 remote window size currently at 2095587 bytes
2018-03-15 12:37:59,736 [30739] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
From ProftpD server Trace log during scripted version
2018-03-15 12:34:35,029 [30711] <sftp:6>: received READ (5) SFTP request (request ID 11, channel ID 0)
2018-03-15 12:34:35,030 [30711] <sftp:7>: received request: READ 8fc9867310df242f 0 32768
2018-03-15 12:34:35,030 [30711] <sftp:8>: sending response: STATUS 1 'End of file' ('End of file' [-1])
2018-03-15 12:34:35,030 [30711] <ssh2:9>: sending CHANNEL_DATA (remote channel ID 0, 37 data bytes)
2018-03-15 12:34:35,030 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 1 using select(2)
2018-03-15 12:34:35,030 [30711] <ssh2:3>: sent SSH_MSG_CHANNEL_DATA (94) packet (80 bytes)
2018-03-15 12:34:35,031 [30711] <ssh2:11>: channel ID 0 remote window size currently at 2096633 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet len = 44 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet padding len = 5 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:20>: SSH2 packet payload len = 38 bytes
2018-03-15 12:34:35,031 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:20>: SSH2 packet MAC len = 16 bytes
2018-03-15 12:34:35,032 [30711] <ssh2:19>: waiting for max of 600 secs while polling socket 0 using select(2)
2018-03-15 12:34:35,032 [30711] <ssh2:3>: received SSH_MSG_CHANNEL_DATA (94) packet
2018-03-15 12:34:35,032 [30711] <ssh2:17>: processing 29 bytes of data for channel ID 0
2018-03-15 12:34:35,032 [30711] <sftp:9>: reading SFTP data from SSH2 packet buffer (29 bytes)
2018-03-15 12:34:35,032 [30711] <sftp:19>: using 29 bytes of SSH2 packet buffer data
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request packet len 25 from SSH2 packet buffer (25 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request type 4 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request payload size 24 from SSH2 packet buffer (24 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: read SFTP request ID 12 from SSH2 packet buffer (20 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: filling remaining SFTP request payload (20 of 20 total bytes) from SSH2 packet buffer (20 bytes in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:19>: completely filled payload of 20 bytes (0 bytes remaining in buffer)
2018-03-15 12:34:35,032 [30711] <sftp:6>: received CLOSE (4) SFTP request (request ID 12, channel ID 0)
2018-03-15 12:34:35,032 [30711] <sftp:7>: received request: CLOSE 8fc9867310df242f
2018-03-15 12:34:35,041 [30711] <ssh2:15>: destroying unclosed channel ID 0 (0 bytes pending)
From SFTP Log on ProftpD Server
2018-03-15 12:34:34,638 mod_sftp/0.9.9[30711]: user 'DEV' authenticated via 'password' method
2018-03-15 12:34:34,997 mod_sftp/0.9.9[30711]: 'env' channel request: 'LANG' = 'en_US.UTF-8'
2018-03-15 12:34:34,998 mod_sftp/0.9.9[30711]: 'subsystem' channel request for 'sftp' subsystem
2018-03-15 12:34:35,001 mod_sftp/0.9.9[30711]: using SFTP protocol version 3 for this session (channel ID 0)
2018-03-15 12:34:35,006 mod_sftp/0.9.9[30711]: error resolving '/data_recieved': No such file or directory
2018-03-15 12:34:35,041 mod_sftp/0.9.9[30711]: aborting 1 unclosed file handle
script (which is from a Client so I've modified the variables side a bit)
export SFTP_DIR=data_recieved
export LOC_DIR=/root/
export SFTP_FILE_NAME_PATTERN=TES
export SFTP_CONF_NAME=testconf
sftp -vvvv -oPort=2222 DEV@ftpserver <<END
cd $SFTP_DIR
lcd $LOC_DIR
mput ${SFTP_FILE_NAME_PATTERN}
put ${SFTP_CONF_NAME}conf ${SFTP_CONF_NAME}conf
get testconfconf testnew.new
rm ${SFTP_CONF_NAME}conf
bye
END
From scripted version on sftp client end.
sftp> get testconfconf testnew.new
debug3: Looking up /testconfconf
debug3: Sent message fd 3 T:7 I:8
debug3: Wrote 64 bytes for a total of 3421
debug3: Received stat reply T:105 I:8
Fetching /testconfconf to testnew.new
debug3: Sent message fd 3 T:17 I:9
debug3: Wrote 64 bytes for a total of 3485
debug3: Received stat reply T:105 I:9
debug3: Sent message SSH2_FXP_OPEN I:10 P:/testconfconf
debug3: Wrote 80 bytes for a total of 3565
/testconfconf 0% 0 0.0KB/s --:-- ETAdebug3: Request range 0 -> 32767 (0/1)
debug3: Wrote 80 bytes for a total of 3645
debug3: Received reply T:103 I:11 R:1
debug3: Received data 0 -> 8
debug3: Short data block, re-requesting 9 -> 32767 ( 1)
debug3: Finish at 32768 ( 1)
debug3: Wrote 80 bytes for a total of 3725
debug3: Received reply T:101 I:12 R:1
/testconfconf 100% 9 0.0KB/s 00:00
debug3: Sent message SSH2_FXP_CLOSE I:13
debug3: Wrote 64 bytes for a total of 3789
debug3: Wrote 64 bytes for a total of 3853
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
#0 client-session (t4 r0 i0/0 o0/0 fd 4/5 cfd -1)
debug3: channel 0: close_fds r 4 w 5 e 6 c -1
debug1: fd 0 clearing O_NONBLOCK
debug3: fd 1 is not O_NONBLOCK
Connection to ftpserver closed by remote host.
Transferred: sent 3432, received 3672 bytes, in 0.6 seconds
Bytes per second: sent 5308.2, received 5679.4
debug1: Exit status -1
Connection closed
From Manual
sftp> get testconfconf
debug3: Looking up /testconfconf
debug3: Sent message fd 3 T:7 I:8
debug3: Wrote 64 bytes for a total of 3149
debug3: Received stat reply T:105 I:8
Fetching /testconfconf to testconfconf
debug3: Sent message fd 3 T:17 I:9
debug3: Wrote 64 bytes for a total of 3213
debug3: Received stat reply T:105 I:9
debug3: Sent message SSH2_FXP_OPEN I:10 P:/testconfconf
debug3: Wrote 80 bytes for a total of 3293
/testconfconf 0% 0 0.0KB/s --:-- ETAdebug3: Request range 0 -> 32767 (0/1)
debug3: Wrote 80 bytes for a total of 3373
debug3: Received reply T:103 I:11 R:1
debug3: Received data 0 -> 8
debug3: Short data block, re-requesting 9 -> 32767 ( 1)
debug3: Finish at 32768 ( 1)
debug3: Wrote 80 bytes for a total of 3453
debug3: Received reply T:101 I:12 R:1
/testconfconf 100% 9 0.0KB/s 00:00
debug3: Sent message SSH2_FXP_CLOSE I:13
debug3: Wrote 64 bytes for a total of 3517
debug3: SSH2_FXP_STATUS 0
This question needs an answer!
Become an EE member today
7 DAY FREE TRIALMembers can start a 7-Day Free trial then enjoy unlimited access to the platform.
View membership options
or
Learn why we charge membership fees
We get it - no one likes a content blocker. Take one extra minute and find out why we block content.
ASKER