SFTP connection closed, I can't find the problem ...

A discussion of Co:Z sftp, a port of OpenSSH sftp for z/OS
Post Reply
Marc
Posts: 9
Joined: Thu Sep 04, 2014 5:25 am

SFTP connection closed, I can't find the problem ...

Post by Marc » Thu Sep 04, 2014 5:57 am

Hello,

I have two z/OS 1.13 LPARs with coz toolkit installed.

When I try to SFTP from the first LPAR to The Second LPAR, I get a connection closed and I can't see anything in the debug.
When I try to SFTP from the second LPAR to the first, it runs fine

Can I get more debug information to solve the problem ?

Thank you.

From an ssh session in putty on the first LPAR, I type :

sftp -vvv intgie
(intgie is the second lpar)

The debug output :

Code: Select all

login as: a500
a500@192.168.1.2's password:

$ sftp intgie
Connecting to intgie...
FOTS0841 Connection closed
$ sftp -vvv intgie
Connecting to intgie...
debug3: zsshSmfCreatePipe: SMF pipe created fdout=7, fdin=8
debug1: Reading configuration data /etc/ssh/zos_ssh_config
OpenSSH_5.0p1, OpenSSL 1.0.1c 10 May 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug3: cipher ok: aes128-cbc [aes128-cbc,aes192-cbc,aes256-cbc]
debug3: cipher ok: aes192-cbc [aes128-cbc,aes192-cbc,aes256-cbc]
debug3: cipher ok: aes256-cbc [aes128-cbc,aes192-cbc,aes256-cbc]
debug3: ciphers ok: [aes128-cbc,aes192-cbc,aes256-cbc]
debug1: Reading configuration data /etc/ssh/zos_ssh_config
debug3: Seeding PRNG from /usr/lib/ssh/ssh-rand-helper
debug1: zsshSmfSetConnSmfStatus: SMF status is 0
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug1: zsshVerifyIcsfSetup: ICSF FMID is 'HCR7780 '
debug1: zsshVerifyIcsfSetup (163): CSFIQA successful: return code = 0, reason co                                                                                                                               de = 0
debug2: -----------------------------------
debug2: CRYPTO   SIZE     KEY      SOURCE
debug2: -----------------------------------
debug2: AES      256      CLEAR    CPU
debug2: DES      56       CLEAR    CPU
debug2: MDC-2    128      NA       CPU
debug2: MDC-4    128      NA       CPU
debug2: MD5      128      NA       SW
debug2: RPMD-160 160      NA       SW
debug2: SHA-1    160      NA       CPU
debug2: SHA-2    512      NA       CPU
debug2: TDES     168      CLEAR    CPU
debug2: ssh_connect: needpriv 0
debug1: Connecting to intgie [172.31.101.148] port 22.
debug1: Connection established.
debug1: cipher_init: none from source OpenSSL
debug1: cipher_init: none from source OpenSSL
debug3: zsshGetpw: passwd name=A500, uid=1500, gid=4000013, dir=/u/A500, shell=/                                                                                                                               bin/sh
debug3: Not a RSA1 key file /u/A500/.ssh/id_rsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: missing keytype
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: missing keytype
debug1: identity file /u/A500/.ssh/id_rsa type 1
debug1: identity file /u/A500/.ssh/id_dsa type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.0
debug1: match: OpenSSH_5.0 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.0
debug2: fd 3 setting O_NONBLOCK
debug3: RNG is ready, skipping seeding
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-g                                                                                                                               roup-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-cbc,aes192-cbc,aes256-cbc
debug2: kex_parse_kexinit: aes128-cbc,aes192-cbc,aes256-cbc
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160                                                                                                                               ,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160                                                                                                                               ,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-g                                                                                                                               roup-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour12                                                                                                                               8,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rij                                                                                                                               ndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour12                                                                                                                               8,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rij                                                                                                                               ndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160                                                                                                                               ,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160                                                                                                                               ,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none
debug2: kex_parse_kexinit: none
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug1: mac_setup_by_id: hmac-md5 from source ICSF
debug2: mac_setup: found hmac-md5
debug1: kex: server->client aes128-cbc hmac-md5 none
debug1: mac_setup_by_id: hmac-md5 from source ICSF
debug2: mac_setup: found hmac-md5
debug1: kex: client->server aes128-cbc hmac-md5 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<1024<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug2: dh_gen_key: priv key bits set: 108/256
debug2: bits set: 533/1024
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: check_host_in_hostfile: filename /u/A500/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 6
debug3: check_host_in_hostfile: filename /u/A500/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 3
debug1: Host 'intgie' is known and matches the RSA host key.
debug1: Found key in /u/A500/.ssh/known_hosts:6
debug2: bits set: 514/1024
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: zsshIcsfMacInit (402): CSFPTRC successful: return code = 0, reason code                                                                                                                                = 0, handle = 'SYSTOK-SESSION-ONLY             00000000S   '
debug1: cipher_init: aes128-cbc from source ICSF
debug1: zsshIcsfCipherInit (930): CSFPTRC successful: return code = 0, reason co                                                                                                                               de = 0, handle = 'SYSTOK-SESSION-ONLY             00000001S   '
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: zsshIcsfMacInit (402): CSFPTRC successful: return code = 0, reason code                                                                                                                                = 0, handle = 'SYSTOK-SESSION-ONLY             00000002S   '
debug1: cipher_init: aes128-cbc from source ICSF
debug1: zsshIcsfCipherInit (930): CSFPTRC successful: return code = 0, reason co                                                                                                                               de = 0, handle = 'SYSTOK-SESSION-ONLY             00000003S   '
debug1: SSH2_MSG_NEWKEYS received
debug1: zsshIcsfMacCompute (509): CSFPOWH successful: return code = 0, reason co                                                                                                                               de = 0
debug1: zsshIcsfMacCompute (548): CSFPOWH successful: return code = 0, reason co                                                                                                                               de = 0
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug1: zsshIcsfMacCompute (509): CSFPOWH successful: return code = 0, reason co                                                                                                                               de = 0
debug1: zsshIcsfMacCompute (548): CSFPOWH successful: return code = 0, reason co                                                                                                                               de = 0
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /u/A500/.ssh/id_rsa (16258980)
debug2: key: /u/A500/.ssh/id_dsa (0)
debug1: Authentications that can continue: publickey,password
debug3: start over, passed a different list publickey,password
debug3: preferred publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering public key: /u/A500/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 277
debug2: input_userauth_pk_ok: fp f6:0c:5d:98:e2:49:37:9c:eb:15:a6:9c:47:e8:d8:57
debug3: sign_and_send_pubkey
debug1: read PEM private key done: type RSA
debug1: Authentication succeeded (publickey).
debug3: zsshSmfWritePipe: Not collecting SMF data.  status=0
debug2: fd 4 setting O_NONBLOCK
debug2: fd 5 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Entering interactive session.
debug2: callback start
debug2: client_session2_setup: id 0
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug2: fd 3 setting TCP_NODELAY
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel 0: rcvd eof
debug2: channel 0: output open -> drain
debug2: channel 0: obuf empty
debug2: channel 0: close_write
debug2: channel 0: output drain -> closed
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug2: channel 0: rcvd close
debug2: channel 0: close_read
debug2: channel 0: input open -> closed
debug3: channel 0: will not send data after close
debug2: channel 0: almost dead
debug2: channel 0: gc: notify user
debug2: channel 0: gc: user detached
debug2: channel 0: send close
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: client-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 client-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)

debug3: channel 0: close_fds r -1 w -1 e 6 c -1
debug1: fd 0 clearing O_NONBLOCK
debug1: fd 1 clearing O_NONBLOCK
debug1: Transferred: stdin 0, stdout 0, stderr 0 bytes in 0.1 seconds
debug1: Bytes per second: stdin 0.0, stdout 0.0, stderr 0.0
debug1: Exit status 141
debug1: zsshIcsfCipherCleanup (1131): CSFPTRD successful: return code = 0, reaso                                                                                                                               n code = 0, handle = 'SYSTOK-SESSION-ONLY             00000001S   '
debug1: zsshIcsfCipherCleanup (1131): CSFPTRD successful: return code = 0, reaso                                                                                                                               n code = 0, handle = 'SYSTOK-SESSION-ONLY             00000003S   '
debug3: __catgets: NLS setup complete (1), using message catalog openssh.cat
FOTS0841 Connection closed
$

From an ssh session in putty on the second LPAR, I type :

sftp -vvv tarrco
(tarrco is the first lpar)

The debug output :

Code: Select all

login as: a500
a500@172.31.101.148's password:
$ sftp -vvv tarrco
Connecting to tarrco...
debug3: zsshSmfCreatePipe: SMF pipe created fdout=7, fdin=8
debug1: Reading configuration data /etc/ssh/zos_ssh_config
OpenSSH_5.0p1, OpenSSL 1.0.1c 10 May 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Reading configuration data /etc/ssh/zos_ssh_config
debug3: Seeding PRNG from /usr/lib/ssh/ssh-rand-helper
debug1: zsshSmfSetConnSmfStatus: SMF status is 0
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug2: ssh_connect: needpriv 0
debug1: Connecting to tarrco [192.168.1.2] port 22.
debug1: Connection established.
debug1: cipher_init: none from source OpenSSL
debug1: cipher_init: none from source OpenSSL
debug3: zsshGetpw: passwd name=A500, uid=1500, gid=4000013, dir=/u/A500, shell=/bin/sh
debug3: Not a RSA1 key file /u/A500/.ssh/id_rsa.
debug2: key_type_from_name: unknown key type '-----BEGIN'
debug3: key_read: missing keytype
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug3: key_read: missing whitespace
debug2: key_type_from_name: unknown key type '-----END'
debug3: key_read: missing keytype
debug1: identity file /u/A500/.ssh/id_rsa type 1
debug1: identity file /u/A500/.ssh/id_dsa type -1
debug1: Remote protocol version 2.0, remote software version OpenSSH_5.0
debug1: match: OpenSSH_5.0 pat OpenSSH*
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_5.0
debug2: fd 3 setting O_NONBLOCK
debug3: RNG is ready, skipping seeding
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit: none,zlib@openssh.com,zlib
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit: diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa
debug2: kex_parse_kexinit: aes128-cbc,aes192-cbc,aes256-cbc
debug2: kex_parse_kexinit: aes128-cbc,aes192-cbc,aes256-cbc
debug2: kex_parse_kexinit: hmac-sha1,hmac-sha1-96
debug2: kex_parse_kexinit: hmac-sha1,hmac-sha1-96
debug2: kex_parse_kexinit: none
debug2: kex_parse_kexinit: none
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit:
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug1: mac_setup_by_id: hmac-sha1 from source OpenSSL
debug2: mac_setup: found hmac-sha1
debug1: kex: server->client aes128-cbc hmac-sha1 none
debug1: mac_setup_by_id: hmac-sha1 from source OpenSSL
debug2: mac_setup: found hmac-sha1
debug1: kex: client->server aes128-cbc hmac-sha1 none
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST(1024<2048<8192) sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug2: dh_gen_key: priv key bits set: 159/320
debug2: bits set: 1049/2048
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
debug3: check_host_in_hostfile: filename /u/A500/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 4
debug3: check_host_in_hostfile: filename /u/A500/.ssh/known_hosts
debug3: check_host_in_hostfile: match line 4
debug1: Host 'tarrco' is known and matches the RSA host key.
debug1: Found key in /u/A500/.ssh/known_hosts:4
debug2: bits set: 1034/2048
debug1: ssh_rsa_verify: signature correct
debug2: kex_derive_keys
debug2: set_newkeys: mode 1
debug1: cipher_init: aes128-cbc from source OpenSSL
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug2: set_newkeys: mode 0
debug1: cipher_init: aes128-cbc from source OpenSSL
debug1: SSH2_MSG_NEWKEYS received
debug1: SSH2_MSG_SERVICE_REQUEST sent
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug2: key: /u/A500/.ssh/id_rsa (16258950)
debug2: key: /u/A500/.ssh/id_dsa (0)
debug1: Authentications that can continue: publickey,password
debug3: start over, passed a different list publickey,password
debug3: preferred publickey,keyboard-interactive,password
debug3: authmethod_lookup publickey
debug3: remaining preferred: keyboard-interactive,password
debug3: authmethod_is_enabled publickey
debug1: Next authentication method: publickey
debug1: Offering public key: /u/A500/.ssh/id_rsa
debug3: send_pubkey_test
debug2: we sent a publickey packet, wait for reply
debug1: Server accepts key: pkalg ssh-rsa blen 277
debug2: input_userauth_pk_ok: fp f5:fc:b8:e3:2f:b6:8c:3a:7d:35:28:e0:ab:c4:34:a1
debug3: sign_and_send_pubkey
debug1: read PEM private key done: type RSA
debug1: Authentication succeeded (publickey).
debug3: zsshSmfWritePipe: Not collecting SMF data.  status=0
debug2: fd 4 setting O_NONBLOCK
debug2: fd 5 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug3: ssh_session2_open: channel_new: 0
debug2: channel 0: send open
debug1: Entering interactive session.
debug2: callback start
debug2: client_session2_setup: id 0
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug2: fd 3 setting TCP_NODELAY
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: Remote version: 3
debug2: Init extension: "posix-rename@openssh.com"
debug2: Init extension: "coz-zopts@dovetail.com"
debug3: Sent message fd 6 T:16 I:1
debug3: SSH_FXP_REALPATH . -> /u/A500
sftp>

dovetail
Site Admin
Posts: 1961
Joined: Thu Jul 29, 2004 12:12 pm

Re: SFTP connection closed, I can't find the problem ...

Post by dovetail » Thu Sep 04, 2014 3:16 pm

For the failure (connection first to second), it appears that the server is dropping the connection.

You will need to check syslogd for sshd error messages to find the cause. The exact filename will depend on how your /etc/syslog.conf is set up.

Also, I cannot see that you are using Co:Z SFTP - it appears that on the first LPAR that you are using the IBM sftp command. But this is unrelated to the error I believe. The problem is probably with the underlying IBM Ported Tools ssh connection.

Marc
Posts: 9
Joined: Thu Sep 04, 2014 5:25 am

Re: SFTP connection closed, I can't find the problem ...

Post by Marc » Fri Sep 05, 2014 7:03 am

Hello,

Thank you for the answer.
Yes I was using IBM sftp, but if I try cozsftp, the result is the same...
I did more tests, the sshd server on the second lpar was coz245, if I use IBM sshd server, I have no problems!
I could not find any errors in syslogd logs.
I use coz245 server on some other lpars, and it runs fine, so coz is not the problem...anyway I would like to debug in order to solve the problem :
when we want to debug IBM sshd, we do this in sshd.config :

Code: Select all

SyslogFacility DAEMON
LogLevel DEBUG3
Subsystem sftp /usr/lib/ssh/sftp-server -f DAEMON -l DEBUG3
Is it the same way to debug coz server ?

Code: Select all

Subsystem sftp /u/coz245/bin/sftp-server.sh -f DAEMON -l DEBUG3
Thank you for help.

dovetail
Site Admin
Posts: 1961
Joined: Thu Jul 29, 2004 12:12 pm

Re: SFTP connection closed, I can't find the problem ...

Post by dovetail » Fri Sep 05, 2014 7:36 am

Please describe how you have configured sshd_config for Co:Z SFTP.

When this fails, do you get a session log file in /tmp or any errors in syslogd?

Marc
Posts: 9
Joined: Thu Sep 04, 2014 5:25 am

Re: SFTP connection closed, I can't find the problem ...

Post by Marc » Fri Sep 05, 2014 8:47 am

Hi,

I do not have any session files in /tmp

Here is sshd_config

Code: Select all

# /****PROPRIETARY_STATEMENT******************************************/
# /*                                                                 */
# /*   LICENSED MATERIALS - PROPERTY OF IBM                          */
# /*   5655-M23 COPYRIGHT IBM CORP. 2004, 2009                       */
# /*                                                                 */
# /*   STATUS= HOS1120                                               */
# /*                                                                 */
# /****END_OF_PROPRIETARY_STATEMENT***********************************/

# $Id: sshd_config,v 1.77.1.7 2009/04/14 12:18:56 RTHEIS Exp $

# This is the sshd server system-wide configuration file.  See
# sshd_config(5) for more information.

# This sshd was compiled with PATH=/usr/bin:/bin:/usr/sbin:/sbin

# The strategy used for options in the default sshd_config shipped with
# OpenSSH is to specify options with their default value where
# possible, but leave them commented.  Uncommented options change a
# default value.

#Port 22
#AddressFamily any
#ListenAddress 0.0.0.0
#ListenAddress ::

# Disable legacy (protocol version 1) support in the server.
Protocol 2

# Ciphers aes128-ctr,aes192-ctr,aes256-ctr,arcfour256,arcfour128,aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,aes192-cbc,aes256-cbc,arcfour,rijndael-cbc@lysator.liu.se
# MACs hmac-md5,hmac-sha1,umac-64@openssh.com,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96

# HostKey for protocol version 1
#HostKey /etc/ssh/ssh_host_key
# HostKeys for protocol version 2
HostKey /etc/ssh/ssh_host_intgie_rsa_key

# Lifetime and size of ephemeral version 1 server key
#KeyRegenerationInterval 1h
#ServerKeyBits 768

# Logging
# obsoletes QuietMode and FascistLogging
#SyslogFacility AUTH
#LogLevel INFO

# Authentication:

#LoginGraceTime 2m
#PermitRootLogin yes
#StrictModes yes
#MaxAuthTries 6

#RSAAuthentication yes
#PubkeyAuthentication yes
#AuthorizedKeysFile	.ssh/authorized_keys

# rhosts authentication should not be used
#RhostsAuthentication no
# For this to work you will also need host keys in /etc/ssh/ssh_known_hosts
#RhostsRSAAuthentication no
# similar for protocol version 2
#HostbasedAuthentication no
# Change to yes if you don't trust ~/.ssh/known_hosts for
# RhostsRSAAuthentication and HostbasedAuthentication
#IgnoreUserKnownHosts no
# Don't read the user's ~/.rhosts and ~/.shosts files
#IgnoreRhosts yes

# To disable tunneled clear text passwords, change to no here!
#PasswordAuthentication yes
#PermitEmptyPasswords no

#ChallengeResponseAuthentication no

# Kerberos options
#KerberosAuthentication no
#KerberosOrLocalPasswd yes
#KerberosTicketCleanup yes
#KerberosGetAFSToken no

# GSSAPI options
#GSSAPIAuthentication no
#GSSAPICleanupCredentials yes

# Set this to 'yes' to enable PAM authentication, account processing,
# and session processing. If this is enabled, PAM authentication will
# be allowed through the ChallengeResponseAuthentication and
# PasswordAuthentication.  Depending on your PAM configuration,
# PAM authentication via ChallengeResponseAuthentication may bypass
# the setting of "PermitRootLogin without-password".
# If you just want the PAM account and session checks to run without
# PAM authentication, then enable this but set PasswordAuthentication
# and ChallengeResponseAuthentication to 'no'.
#UsePAM no

#AllowTcpForwarding no
#GatewayPorts no
#X11Forwarding no
#X11DisplayOffset 10
#X11UseLocalhost yes
#PrintMotd yes
#PrintLastLog no
#TCPKeepAlive yes
#UseLogin no
#UsePrivilegeSeparation yes
#PermitUserEnvironment no
#Compression no
#ClientAliveInterval 0
#ClientAliveCountMax 3
#UseDNS yes
#PidFile /var/run/sshd.pid
#MaxStartups 10
#PermitTunnel no
#ChrootDirectory none

# no default banner path
#Banner none

# override default of no subsystems
#ubsystem	sftp	/usr/lib/ssh/sftp-server

# Example of overriding settings on a per-user basis
#Match User anoncvs
#	X11Forwarding no
#	AllowTcpForwarding no
#	ForceCommand cvs server
SyslogFacility DAEMON
LogLevel DEBUG3
Subsystem sftp /u/coz245/bin/sftp-server.sh -f DAEMON -l DEBUG3
#Subsystem sftp /usr/lib/ssh/sftp-server -f DAEMON -l DEBUG3
Here is the syslogd log at time of the problem, I can't see any errors (that I can recognise) :

Code: Select all

Sep  5 15:36:08 INTGIE syslogd: FSUM1220 syslogd: restart
Sep  5 15:36:08 INTGIE syslogd: FSUM1237 Job SYSLOGD  running in local-only mode
Sep  5 15:36:08 INTGIE syslogd: FSUM1232 syslogd: running non-swappable
Sep  5 13:37:16 INTGIE sshd[16843487]: debug2: fd 3 setting O_NONBLOCK 
Sep  5 13:37:16 INTGIE sshd[16843487]: debug1: Bind to port 22 on 0.0.0.0. 
Sep  5 13:37:16 INTGIE sshd[16843487]: Server listening on 0.0.0.0 port 22. 
Sep  5 13:37:31 INTGIE sshd[16843487]: debug1: fd 4 clearing O_NONBLOCK 
Sep  5 13:37:31 INTGIE sshd[16843487]: debug1: Forked child 83952348. 
Sep  5 13:37:31 INTGIE sshd[16843487]: debug3: send_rexec_state: entering fd = 8 config len 281, zos_config len 30 
Sep  5 13:37:31 INTGIE sshd[16843487]: debug3: ssh_msg_send: type 0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: rexec start in 4 out 4 newsock 4 pipe 7 sock 8 
Sep  5 13:37:31 INTGIE sshd[16843487]: debug3: send_rexec_state: done 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: inetd sockets after dupping: 3, 3 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: cipher_init: none from source OpenSSL 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: cipher_init: none from source OpenSSL 
Sep  5 13:37:31 INTGIE sshd[83952348]: Connection from 172.31.100.91 port 6137 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: zsshSmfSetConnSmfStatus: SMF status is 0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: zsshSmfTestRecord: SMF is collecting type 119, subtype 98 records 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: zsshSmfSetCommonData: SMF type 119 subtype 98  
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: Client protocol version 2.0; client software version OpenSSH_5.0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: match: OpenSSH_5.0 pat OpenSSH* 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: Enabling compatibility mode for protocol 2.0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: Local version string SSH-2.0-OpenSSH_5.0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: fd 3 setting O_NONBLOCK 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: Network child is on pid 50397649 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: Current IBM Release level: 23 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: MLS: seclabel of AS:          uid:0  pid:83952348 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: MLS: peer socket: rc:0 t:0 seclabel: terminal:AC1F645B poe_profile:  
Sep  5 13:37:31 INTGIE sshd[83952348]: Port of Entry information retained for uid:0  pid:83952348. 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: MLS: seclabel of AS:          uid:0  pid:83952348 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: MLS: peer socket: rc:0 t:0 seclabel: terminal:AC1F645B poe_profile:  
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: MLS: /var/empty: rc:0 t:1 seclabel: terminal: poe_profile:  
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: preauth child monitor started 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_moduli: got parameters: 1024 1024 8192 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 1 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: monitor_read: 0 used once, disabling now 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 4 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_sign 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_sign: signature 16258030(271) 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 5 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: monitor_read: 4 used once, disabling now 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 6 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_pwnamallow 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: get_pwnamallow: input user name A500, user database name A500 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: Trying to reverse map address 172.31.100.91. 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: parse_server_config: config reprocess config len 281 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: parse_server_config: config reprocess config len 30 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 7 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: monitor_read: 6 used once, disabling now 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 3 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_authserv: service=ssh-connection, style= 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: monitor_read: 3 used once, disabling now 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 10 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_authpassword: sending result 0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 11 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: auth_log: authenticated 0, valid 1, failures 0, max 6, half 3, method none 
Sep  5 13:37:31 INTGIE sshd[83952348]: Failed none for A500 from 172.31.100.91 port 6137 ssh2 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 20 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyallowed entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyallowed: key_from_blob: 162611A0 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: temporarily_use_uid: 1500/4000013 (e=0/1) 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: trying public key file /u/A500/.ssh/authorized_keys 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: secure_filename: checking '/u/A500/.ssh' 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: secure_filename: checking '/u/A500' 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: secure_filename: terminating check at '/u/A500' 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: matching key found: file /u/A500/.ssh/authorized_keys, line 1 
Sep  5 13:37:31 INTGIE sshd[83952348]: Found matching RSA key: f6:0c:5d:98:e2:49:37:9c:eb:15:a6:9c:47:e8:d8:57 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: restore_uid: 0/1 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyallowed: key 162611A0 is allowed 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 21 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 20 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyallowed entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyallowed: key_from_blob: 16261328 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: temporarily_use_uid: 1500/4000013 (e=0/1) 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: trying public key file /u/A500/.ssh/authorized_keys 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: secure_filename: checking '/u/A500/.ssh' 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: secure_filename: checking '/u/A500' 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: secure_filename: terminating check at '/u/A500' 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: matching key found: file /u/A500/.ssh/authorized_keys, line 1 
Sep  5 13:37:31 INTGIE sshd[83952348]: Found matching RSA key: f6:0c:5d:98:e2:49:37:9c:eb:15:a6:9c:47:e8:d8:57 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: restore_uid: 0/1 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyallowed: key 16261328 is allowed 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 21 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 22 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: ssh_rsa_verify: signature correct 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_keyverify: key 162605A8 signature verified 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_send entering: type 23 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: auth_log: authenticated 1, valid 1, failures 0, max 6, half 3, method publickey 
Sep  5 13:37:31 INTGIE sshd[83952348]: Accepted publickey for A500 from 172.31.100.91 port 6137 ssh2 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: monitor_child_preauth: A500 has been authenticated by privileged process 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_get_keystate: Waiting for new keys 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive_expect entering: type 24 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_newkeys_from_blob: 162611F8(118) 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: mac_setup_by_id: hmac-md5 from source OpenSSL 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: mac_setup: found hmac-md5 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_get_keystate: Waiting for second key 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_newkeys_from_blob: 162611F8(118) 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug1: mac_setup_by_id: hmac-md5 from source OpenSSL 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: mac_setup: found hmac-md5 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_get_keystate: Getting compression state 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_get_keystate: Getting Network I/O buffers 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug2: User child is on pid 67174865 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_request_receive entering 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: permanently_set_uid: 1500/4000013 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: zsshCloseOldDev: fd=5 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: privsep_postauth: old /dev not required: fd=-1 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: set_newkeys: mode 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: cipher_init: aes128-cbc from source OpenSSL 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: set_newkeys: mode 1 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: cipher_init: aes128-cbc from source OpenSSL 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: Entering interactive session for SSH2. 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: fd 5 setting O_NONBLOCK 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: fd 7 setting O_NONBLOCK 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: server_init_dispatch_20 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: server_input_channel_open: ctype session rchan 0 win 2097152 max 32768 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: input_session_request 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: channel 0: new [server-session] 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_new: init 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_new: session 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_open: channel 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_open: session 0: link with channel 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: server_input_channel_open: confirm session 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: server_input_channel_req: channel 0 request subsystem reply 1 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_by_channel: session 0 channel 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_input_channel_req: session 0 req subsystem 
Sep  5 13:37:31 INTGIE sshd[67174865]: subsystem request for sftp 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: subsystem: exec() /u/coz245/bin/sftp-server.sh -f DAEMON -l DEBUG3 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: do_exec: subsystem 1 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: do_exec: passwd name=A500, uid=1500, gid=4000013, dir=/u/A500, shell=/bin/sh 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: do_exec_no_pty: no JSCBAUTH propagation to child 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: fd 3 setting TCP_NODELAY 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: fd 11 setting O_NONBLOCK 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: fd 10 setting O_NONBLOCK 
Sep  5 13:37:31 INTGIE sshd[67175107]: debug3: zsshCloseOldDev: fd=-1 
Sep  5 13:37:31 INTGIE sshd[67175107]: debug3: zsshCloseOldDev: fd=-1 
Sep  5 13:37:31 INTGIE sshd[67175107]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: read<=0 rfd 11 len 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: read failed 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: close_read 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: input open -> drain 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: ibuf empty 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: send eof 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: input drain -> closed 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: notify_done: reading 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: Received SIGCHLD. 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_by_pid: pid 67175107 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_exit_message: session 0 channel 0 pid 67175107 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: request exit-status confirm 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_exit_message: release channel 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: write failed 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: close_write 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: output open -> closed 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: send close 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: channel 0: will not send data after close 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: rcvd close 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: channel 0: will not send data after close 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: is dead 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: gc: notify user 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_by_channel: session 0 channel 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_close_by_channel: channel 0 child 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: session_close: session 0 pid 0 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: gc: user detached 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: is dead 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug2: channel 0: garbage collecting 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: channel 0: free: server-session, nchannels 1 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: channel 0: status: The following connections are open:
   #0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)
 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1 
Sep  5 13:37:31 INTGIE sshd[67174865]: Connection closed by 172.31.100.91 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug1: do_cleanup 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: zsshCloseOldDev: fd=-1 
Sep  5 13:37:31 INTGIE sshd[67174865]: Closing connection to 172.31.100.91 
Sep  5 13:37:31 INTGIE sshd[67174865]: debug3: mm_request_send entering: type 58 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: monitor_read: checking request 58 
Sep  5 13:37:31 INTGIE sshd[83952348]: debug3: mm_answer_term: tearing down sessions 


dovetail
Site Admin
Posts: 1961
Joined: Thu Jul 29, 2004 12:12 pm

Re: SFTP connection closed, I can't find the problem ...

Post by dovetail » Fri Sep 05, 2014 1:02 pm

command arguments such as "-f DAEMON -l DEBUG3" are not supported by Co:Z sftp-server.sh

These should be removed from sshd_config, but I'm not sure that this is your problem. I would think that any arguments would just be ignored.

From the syslogd messages, it just looks like the sftp-server.sh process terminates without doing anything.

If configured properly, the sftp-server.sh script should create a session log file. Look at the comments in the script for more information about configuring it.

One thing that you could try is to just test running the sftp client locally on z/OS connected to the Co:Z SFTP server to see if that works.

To do this, login to a z/OS ssh Unix shell to the same LPAR (say, using PuTTY), with the same z/OS userid and try this:

$ sftp -P /u/coz245/bin/sftp-server.sh
Attaching to /u/coz245/bin/sftp-server.sh...
sftp> ls /+
/+/error.log /+/mode=binary

This should also create a session log, by default in /tmp.

Marc
Posts: 9
Joined: Thu Sep 04, 2014 5:25 am

Re: SFTP connection closed, I can't find the problem ...

Post by Marc » Tue Sep 09, 2014 2:18 am

Hi,
This helped me to find the problem.
The trouble was with sftp-server.rc, as I created it using cut and paste from another LPAR using an emulator with another codepage so I got a translation problem "#" on the was not recognised by the second LPAR expecting "£".
Thank you for help an sorry for my mistake. :oops:

Post Reply