Hi All I'm trying to get Dovetail running on Z/os 2.1
I get loads of XEC6 abends and "FOTS1824 PRNG seed extraction failed" in the sysout.
Looking in to the EC6 abend it looks like a problem with callable services.
1, Is version: 2.4.1 2013-06-24 Z/os 2.1 compliant
2, Is any one running version: 2.4.1 2013-06-24 on Z/os 2.1
Regards
Stuart.
S COZPROC
£HASP100 COZPROC ON STCINRDR
IEF695I START COZPROC WITH JOBNAME COZPROC IS ASSIGNED TO USER TCPETP
, GROUP SYS1
£HASP373 COZPROC STARTED
IEF403I COZPROC - STARTED - TIME=15.47.50
£HASP100 BPXAS ON STCINRDR
£HASP373 BPXAS STARTED
IEF403I BPXAS - STARTED - TIME=15.48.03
BPXP024I BPXAS INITIATOR STARTED ON BEHALF OF JOB COZPROC2 RUNNING IN
ASID 008B
£HASP100 BPXAS ON STCINRDR
IEA989I SLIP TRAP ID=XEC6 MATCHED. JOBNAME=COZPROC6, ASID=00A6.
BPXP023I THREAD 12E1C60000000001, IN PROCESS 50397330, WAS 153
TERMINATED BY SIGNAL SIGINT, SENT FROM THREAD
12E1C00000000001, IN PROCESS 65681, UID 0, IN JOB COZPROC2.
IEF450I COZPROC6 *OMVSEX - ABEND=SEC6 U0000 REASON=0000FF02 154
TIME=15.48.09
£HASP373 BPXAS STARTED
IEF403I BPXAS - STARTED - TIME=15.48.11
BPXP024I BPXAS INITIATOR STARTED ON BEHALF OF JOB COZPROC2 RUNNING IN
ASID 008B
IEA989I SLIP TRAP ID=XEC6 MATCHED. JOBNAME=COZPROC2, ASID=00A6.
BPXP023I THREAD 12E1C60000000001, IN PROCESS 33620115, WAS 159
TERMINATED BY SIGNAL SIGINT, SENT FROM THREAD
12E1C00000000001, IN PROCESS 65681, UID 0, IN JOB COZPROC2.
IEF450I COZPROC2 *OMVSEX - ABEND=SEC6 U0000 REASON=0000FF02 160
TIME=15.48.16
IEA989I SLIP TRAP ID=XEC6 MATCHED. JOBNAME=COZPROC3, ASID=00A7.
CoZLauncherÝN¨: version: 2.4.1 2013-06-24
CoZLauncherÝN¨: Copyright (C) Dovetailed Technologies, LLC. 2006-2013. All rights reserved.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
CEE5206S The signal SIGINT was received.
FOTS1824 PRNG seed extraction failed
FOTS1945 ssh-rand-helper child produced insufficient data
CoZLauncherÝE¨: CoZAgent process (65678) ended with RC=255
CoZLauncherÝE¨: CoZAgent process (65678) ended, but no cozagent completion was recorded.
CoZLauncherÝE¨: CoZLauncher ended with RC=102
Z/os 2.1 Support
Re: Z/os 2.1 Support
First, just to check: you are trying to set up Co:Z Launcher and not Co:Z SFTP. Is that your intention?
The error that you are seeing (all FOTSxxx) errors are from IBM Ported Tools OpenSSH. It appears that OpenSSH is not setup properly.
Specifically, the message:
FOTS1945 ssh-rand-helper child produced insufficient data
indicates that IBM Ported Tools OpenSSH had a problem seeding random numbers. What you will want to do is setup IBM Ported Tools to use ICSF for random number support via "/dev/random". This will avoid "ssh-rand-helper" and is more secure and much faster.
The latest version of ICSF (which is on 2.1) will support for /dev/random works even if you con't have a crypto co-processor card.
The IBM Ported Tools OpenSSH User's Guide has a section on setting this up.
The error that you are seeing (all FOTSxxx) errors are from IBM Ported Tools OpenSSH. It appears that OpenSSH is not setup properly.
Specifically, the message:
FOTS1945 ssh-rand-helper child produced insufficient data
indicates that IBM Ported Tools OpenSSH had a problem seeding random numbers. What you will want to do is setup IBM Ported Tools to use ICSF for random number support via "/dev/random". This will avoid "ssh-rand-helper" and is more secure and much faster.
The latest version of ICSF (which is on 2.1) will support for /dev/random works even if you con't have a crypto co-processor card.
The IBM Ported Tools OpenSSH User's Guide has a section on setting this up.
-
Stuart-Willis
- Posts: 5
- Joined: Tue Oct 08, 2013 6:17 am
Re: Z/os 2.1 Support
Hi Sorry for the delay in repying I was trying to start the wrong thing I wanted the SFTP server not the Loader.
I now have it running bu I'm unable to logon to it I get Error: Could not open connection to `10.5.1.16': Could not open connection to `10.5.1.16': Connection lost at the Client end.
trace from PC
C:\Users\sw>sftpg3 -D "sftp*=14" 10.5.1.16
Setting debug level string to 'sftp*=14'.
04/11/2013 14:36:11:742 SftpSftpG3/sftpg3.c:532: AUDIT: 3000 Sft_client_start, Local username: SW, Program: sftpg3, Pid: 6732
04/11/2013 14:36:11:754 SftpLibServer/sshniosftpserver.c:9624: Server listener created.
04/11/2013 14:36:11:756 SftpLibServer/sshniosftpserver.c:9250: Server connection accepted.
04/11/2013 14:36:11:758 SftpLibClient/sshniosftpclient.c:385: SFTP Client event handler thread is starting.
04/11/2013 14:36:11:758 SftpLibServer/sshniosftpserver.c:9063: Processing request: INIT(1).
04/11/2013 14:36:11:763 SftpLibServer/sshniosftpserver.c:9071: Request INIT(1) processed.
04/11/2013 14:36:11:763 SftpAppLibSft/secsh_sft.c:4034: Client SFT protocol version is 3.
04/11/2013 14:36:11:768 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:770 SftpLibPath/sshniosftppath_win32.c:219: /// resolved to \\
04/11/2013 14:36:11:772 SftpLibServer/sshniosftpserver.c:2927: Before file-stat-extended@ssh.com: /// -> \\
04/11/2013 14:36:11:775 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:776 SftpAppLibSft/secsh_sft.c:3495: Peer claims to support extensions but has not returned attributes.
04/11/2013 14:36:11:782 SftpAppLibSft/secsh_sft.c:3511: Client system type is POSIX.
04/11/2013 14:36:11:784 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:787 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:790 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:792 SftpLibPath/sshniosftppath_win32.c:454: Decode result: C:\Users\sw
04/11/2013 14:36:11:794 SftpLibServer/sshniosftpserver.c:2927: Before file-stat-extended@ssh.com: . -> C:\Users\sw
04/11/2013 14:36:11:797 SftpLibServer/sshniosftpserver.c:2992: After file-stat-extended@ssh.com: . -> C:\Users\sw
04/11/2013 14:36:11:799 SftpLibServer/sshniosftpserver.c:2992: Flags: 3d, Type: dir, Size: 0, Perm: 40700
04/11/2013 14:36:11:802 SftpLibServer/sshniosftpserver.c:2992: Uid: 0, Gid: 0
04/11/2013 14:36:11:804 SftpLibServer/sshniosftpserver.c:2992: Ctime: 1266407918, Mtime: 1383325298, Atime: 1383325298
04/11/2013 14:36:11:807 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:809 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:812 SftpLibServer/sshniosftpserver.c:6593: Stream cancel failed. Session-Id: (null)
04/11/2013 14:36:11:814 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:814 SftpAppLibSft/secsh_sft.c:3619: Client supports EXTENDED streaming.
04/11/2013 14:36:11:819 SftpLibServer/sshniosftpserver.c:9063: Processing request: REALPATH(16).
04/11/2013 14:36:11:821 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:824 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:826 SftpLibPath/sshniosftppath_win32.c:454: Decode result: C:\Users\sw
04/11/2013 14:36:11:829 SftpLibServer/sshniosftpserver.c:8330: SSH_FXP_REALPATH: . -> C:\Users\sw
04/11/2013 14:36:11:832 SftpLibPath/sshniosftppath_win32.c:510: No virtual folders defined: C:/Users/sw
04/11/2013 14:36:11:834 SftpLibServer/sshniosftpserver.c:9071: Request REALPATH(16) processed.
04/11/2013 14:36:11:837 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:840 SftpLibPath/sshniosftppath_win32.c:219: C:/Users/sw resolved to C:\Users\sw
04/11/2013 14:36:11:843 SftpLibServer/sshniosftpserver.c:2927: Before file-stat-extended@ssh.com: C:/Users/sw -> C:\Users\sw
04/11/2013 14:36:11:845 SftpLibServer/sshniosftpserver.c:2992: After file-stat-extended@ssh.com: C:/Users/sw -> C:\Users\sw
04/11/2013 14:36:11:848 SftpLibServer/sshniosftpserver.c:2992: Flags: 3d, Type: dir, Size: 0, Perm: 40700
04/11/2013 14:36:11:851 SftpLibServer/sshniosftpserver.c:2992: Uid: 0, Gid: 0
04/11/2013 14:36:11:853 SftpLibServer/sshniosftpserver.c:2992: Ctime: 1266407918, Mtime: 1383325298, Atime: 1383325298
04/11/2013 14:36:11:855 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:855 SftpSftpG3/sftpg3.c:2943: Current working directory: C:/Users/sw
04/11/2013 14:36:11:860 SftpSftpG3/sftpg3.c:2556: User: NULL, Host: 10.5.1.16, Port: NULL
SW@10.5.1.16's password:
04/11/2013 14:36:30:456 SftpAppLibSft/secsh_sft.c:3860: Open sftp channel with connection id 17
04/11/2013 14:36:32:343 SftpAppLibSft/secsh_sft.c:3892: HANDLE conn id = 17
04/11/2013 14:36:32:345 SftpAppLibSft/secsh_sft.c:3748: Connection id: #17, Destination: SW@10.5.1.16#22, Protocol version: secsh2,
Cipher spec: aes128-cbc+hmac-sha1, Auth method: password, Compression: none, Exclusive: no
04/11/2013 14:36:32:351 SftpLibClient/sshniosftpclient.c:385: SFTP Client event handler thread is starting.
Error: Could not open connection to `10.5.1.16': Could not open connection to `10.5.1.16': Connection lost <========================================================
04/11/2013 14:36:39:447 SftpSftpG3/sftpg3.c:633: Exit code: 5
04/11/2013 14:36:39:450 SftpLibServer/sshniosftpserver.c:9087: EOF received.
04/11/2013 14:36:39:452 SftpSftpG3/sftpg3.c:1058: Destroying connection: SW@localhost
04/11/2013 14:36:39:455 SftpSftpG3/sftpg3.c:1058: Destroying connection: SW@10.5.1.16
C:\Users\sw>
Dovetail trace
ZosSettingsÝF¨: -> ZosSettings()
Co:Z SFTP Server version: 2.4.1 (5.0p1) 2013-06-24
Copyright (C) Dovetailed Technologies, LLC. 2008-2013. All rights reserved.
ZosSettingsÝF¨: clientCodePage set to ISO8859-1 (default)
ZosSettingsÝF¨: serverCodePage set to IBM-1047 (default)
ZosSettingsÝF¨: -> set(mode=binary)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(conddisp=catlg)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(overflow=wrap)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(linerule=flexible)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jesowner=SW)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jeslrecl=80)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jesrecfm=f)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jesstatus=*)
ZosSettingsÝF¨: <- set()
ZosSettingsÝT¨: -> readConfiguration()
ZosSettingsÝT¨: -> processConfigurationFile(/u//.ssh/cozsftp_server_config)
ZosSettingsÝD¨: no configuration file (/u//.ssh/cozsftp_server_config) found.
ZosSettingsÝT¨: <- processConfigurationFile()
ZosSettingsÝT¨: -> processConfigurationFile(/etc/ssh/cozsftp_server_config)
ZosSettingsÝT¨: processConfigurationFile: Processing fixed: configuration file section
ZosSettingsÝT¨: processConfigurationFile: Processing default: configuration file section
ZosSettingsÝT¨: <- processConfigurationFile()
ZosSettingsÝT¨: <- readConfiguration()
ZosSettingsÝF¨: <- ZosSettings()
ZosSettingsÝF¨: -> parseOptionString()
ZosSettingsÝF¨: <- parseOptionString()
ZosUtilÝT¨: -> zos_log_region_size()
ZosUtilÝD¨: region size requested = 55296K, Actual below/above limit = 9192K / 1039384K
ZosUtilÝT¨: <- zos_log_region_size()
ZosExitInterfaceÝF¨: -> ZosExitInterface()
ZosSmf119RecordÝF¨: -> ZosSmf119Record()
ZosSmf119RecordÝF¨: <- ZosSmf119Record()
ZosSmf119RecordÝF¨: -> ZosSmfFtpServerRecord(, )
ZosSmf119RecordÝF¨: -> initSockAddrs()
ZosSmf119RecordÝF¨: initSockAddrs: SSH_CONNECTION=10.5.1.199 4545 10.5.1.16 22
ZosSmf119RecordÝF¨: <- initSockAddrs()
ZosSmf119RecordÝF¨: <- ZosSmfFtpServerRecord()
ZosExitInterfaceÝF¨: ZosExitInterface: client_addr: 10.5.1.199 port: 4545
ZosExitInterfaceÝF¨: ZosExitInterface: server_addr: 10.5.1.16 port: 22
ZosExitInterfaceÝF¨: <- ZosExitInterface()
ZosExitInterfaceÝT¨: -> checkIP()
ZosExitInterfaceÝT¨: <- checkIP(true, rc=0)
ZosExitInterfaceÝT¨: -> checkPwd()
ZosExitInterfaceÝT¨: <- checkPwd(true, rc=0)
Thanks
Stuart.
I now have it running bu I'm unable to logon to it I get Error: Could not open connection to `10.5.1.16': Could not open connection to `10.5.1.16': Connection lost at the Client end.
trace from PC
C:\Users\sw>sftpg3 -D "sftp*=14" 10.5.1.16
Setting debug level string to 'sftp*=14'.
04/11/2013 14:36:11:742 SftpSftpG3/sftpg3.c:532: AUDIT: 3000 Sft_client_start, Local username: SW, Program: sftpg3, Pid: 6732
04/11/2013 14:36:11:754 SftpLibServer/sshniosftpserver.c:9624: Server listener created.
04/11/2013 14:36:11:756 SftpLibServer/sshniosftpserver.c:9250: Server connection accepted.
04/11/2013 14:36:11:758 SftpLibClient/sshniosftpclient.c:385: SFTP Client event handler thread is starting.
04/11/2013 14:36:11:758 SftpLibServer/sshniosftpserver.c:9063: Processing request: INIT(1).
04/11/2013 14:36:11:763 SftpLibServer/sshniosftpserver.c:9071: Request INIT(1) processed.
04/11/2013 14:36:11:763 SftpAppLibSft/secsh_sft.c:4034: Client SFT protocol version is 3.
04/11/2013 14:36:11:768 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:770 SftpLibPath/sshniosftppath_win32.c:219: /// resolved to \\
04/11/2013 14:36:11:772 SftpLibServer/sshniosftpserver.c:2927: Before file-stat-extended@ssh.com: /// -> \\
04/11/2013 14:36:11:775 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:776 SftpAppLibSft/secsh_sft.c:3495: Peer claims to support extensions but has not returned attributes.
04/11/2013 14:36:11:782 SftpAppLibSft/secsh_sft.c:3511: Client system type is POSIX.
04/11/2013 14:36:11:784 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:787 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:790 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:792 SftpLibPath/sshniosftppath_win32.c:454: Decode result: C:\Users\sw
04/11/2013 14:36:11:794 SftpLibServer/sshniosftpserver.c:2927: Before file-stat-extended@ssh.com: . -> C:\Users\sw
04/11/2013 14:36:11:797 SftpLibServer/sshniosftpserver.c:2992: After file-stat-extended@ssh.com: . -> C:\Users\sw
04/11/2013 14:36:11:799 SftpLibServer/sshniosftpserver.c:2992: Flags: 3d, Type: dir, Size: 0, Perm: 40700
04/11/2013 14:36:11:802 SftpLibServer/sshniosftpserver.c:2992: Uid: 0, Gid: 0
04/11/2013 14:36:11:804 SftpLibServer/sshniosftpserver.c:2992: Ctime: 1266407918, Mtime: 1383325298, Atime: 1383325298
04/11/2013 14:36:11:807 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:809 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:812 SftpLibServer/sshniosftpserver.c:6593: Stream cancel failed. Session-Id: (null)
04/11/2013 14:36:11:814 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:814 SftpAppLibSft/secsh_sft.c:3619: Client supports EXTENDED streaming.
04/11/2013 14:36:11:819 SftpLibServer/sshniosftpserver.c:9063: Processing request: REALPATH(16).
04/11/2013 14:36:11:821 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:824 SftpLibPath/sshniosftppath_win32.c:219: ./ resolved to C:\Users\sw
04/11/2013 14:36:11:826 SftpLibPath/sshniosftppath_win32.c:454: Decode result: C:\Users\sw
04/11/2013 14:36:11:829 SftpLibServer/sshniosftpserver.c:8330: SSH_FXP_REALPATH: . -> C:\Users\sw
04/11/2013 14:36:11:832 SftpLibPath/sshniosftppath_win32.c:510: No virtual folders defined: C:/Users/sw
04/11/2013 14:36:11:834 SftpLibServer/sshniosftpserver.c:9071: Request REALPATH(16) processed.
04/11/2013 14:36:11:837 SftpLibServer/sshniosftpserver.c:9063: Processing request: EXTENDED(200).
04/11/2013 14:36:11:840 SftpLibPath/sshniosftppath_win32.c:219: C:/Users/sw resolved to C:\Users\sw
04/11/2013 14:36:11:843 SftpLibServer/sshniosftpserver.c:2927: Before file-stat-extended@ssh.com: C:/Users/sw -> C:\Users\sw
04/11/2013 14:36:11:845 SftpLibServer/sshniosftpserver.c:2992: After file-stat-extended@ssh.com: C:/Users/sw -> C:\Users\sw
04/11/2013 14:36:11:848 SftpLibServer/sshniosftpserver.c:2992: Flags: 3d, Type: dir, Size: 0, Perm: 40700
04/11/2013 14:36:11:851 SftpLibServer/sshniosftpserver.c:2992: Uid: 0, Gid: 0
04/11/2013 14:36:11:853 SftpLibServer/sshniosftpserver.c:2992: Ctime: 1266407918, Mtime: 1383325298, Atime: 1383325298
04/11/2013 14:36:11:855 SftpLibServer/sshniosftpserver.c:9071: Request EXTENDED(200) processed.
04/11/2013 14:36:11:855 SftpSftpG3/sftpg3.c:2943: Current working directory: C:/Users/sw
04/11/2013 14:36:11:860 SftpSftpG3/sftpg3.c:2556: User: NULL, Host: 10.5.1.16, Port: NULL
SW@10.5.1.16's password:
04/11/2013 14:36:30:456 SftpAppLibSft/secsh_sft.c:3860: Open sftp channel with connection id 17
04/11/2013 14:36:32:343 SftpAppLibSft/secsh_sft.c:3892: HANDLE conn id = 17
04/11/2013 14:36:32:345 SftpAppLibSft/secsh_sft.c:3748: Connection id: #17, Destination: SW@10.5.1.16#22, Protocol version: secsh2,
Cipher spec: aes128-cbc+hmac-sha1, Auth method: password, Compression: none, Exclusive: no
04/11/2013 14:36:32:351 SftpLibClient/sshniosftpclient.c:385: SFTP Client event handler thread is starting.
Error: Could not open connection to `10.5.1.16': Could not open connection to `10.5.1.16': Connection lost <========================================================
04/11/2013 14:36:39:447 SftpSftpG3/sftpg3.c:633: Exit code: 5
04/11/2013 14:36:39:450 SftpLibServer/sshniosftpserver.c:9087: EOF received.
04/11/2013 14:36:39:452 SftpSftpG3/sftpg3.c:1058: Destroying connection: SW@localhost
04/11/2013 14:36:39:455 SftpSftpG3/sftpg3.c:1058: Destroying connection: SW@10.5.1.16
C:\Users\sw>
Dovetail trace
ZosSettingsÝF¨: -> ZosSettings()
Co:Z SFTP Server version: 2.4.1 (5.0p1) 2013-06-24
Copyright (C) Dovetailed Technologies, LLC. 2008-2013. All rights reserved.
ZosSettingsÝF¨: clientCodePage set to ISO8859-1 (default)
ZosSettingsÝF¨: serverCodePage set to IBM-1047 (default)
ZosSettingsÝF¨: -> set(mode=binary)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(conddisp=catlg)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(overflow=wrap)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(linerule=flexible)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jesowner=SW)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jeslrecl=80)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jesrecfm=f)
ZosSettingsÝF¨: <- set()
ZosSettingsÝF¨: -> set(jesstatus=*)
ZosSettingsÝF¨: <- set()
ZosSettingsÝT¨: -> readConfiguration()
ZosSettingsÝT¨: -> processConfigurationFile(/u//.ssh/cozsftp_server_config)
ZosSettingsÝD¨: no configuration file (/u//.ssh/cozsftp_server_config) found.
ZosSettingsÝT¨: <- processConfigurationFile()
ZosSettingsÝT¨: -> processConfigurationFile(/etc/ssh/cozsftp_server_config)
ZosSettingsÝT¨: processConfigurationFile: Processing fixed: configuration file section
ZosSettingsÝT¨: processConfigurationFile: Processing default: configuration file section
ZosSettingsÝT¨: <- processConfigurationFile()
ZosSettingsÝT¨: <- readConfiguration()
ZosSettingsÝF¨: <- ZosSettings()
ZosSettingsÝF¨: -> parseOptionString()
ZosSettingsÝF¨: <- parseOptionString()
ZosUtilÝT¨: -> zos_log_region_size()
ZosUtilÝD¨: region size requested = 55296K, Actual below/above limit = 9192K / 1039384K
ZosUtilÝT¨: <- zos_log_region_size()
ZosExitInterfaceÝF¨: -> ZosExitInterface()
ZosSmf119RecordÝF¨: -> ZosSmf119Record()
ZosSmf119RecordÝF¨: <- ZosSmf119Record()
ZosSmf119RecordÝF¨: -> ZosSmfFtpServerRecord(, )
ZosSmf119RecordÝF¨: -> initSockAddrs()
ZosSmf119RecordÝF¨: initSockAddrs: SSH_CONNECTION=10.5.1.199 4545 10.5.1.16 22
ZosSmf119RecordÝF¨: <- initSockAddrs()
ZosSmf119RecordÝF¨: <- ZosSmfFtpServerRecord()
ZosExitInterfaceÝF¨: ZosExitInterface: client_addr: 10.5.1.199 port: 4545
ZosExitInterfaceÝF¨: ZosExitInterface: server_addr: 10.5.1.16 port: 22
ZosExitInterfaceÝF¨: <- ZosExitInterface()
ZosExitInterfaceÝT¨: -> checkIP()
ZosExitInterfaceÝT¨: <- checkIP(true, rc=0)
ZosExitInterfaceÝT¨: -> checkPwd()
ZosExitInterfaceÝT¨: <- checkPwd(true, rc=0)
Thanks
Stuart.
Re: Z/os 2.1 Support
The first trace looks to be from a PC. It is strange, since in the trace it appears that it makes a connection to SFTP *BEFORE* the password prompt and *BEFORE* it says that it cannot make a connection. This doesn't make much sense to me.
When you connect to Co:Z SFTP server, first an SSH connection is made to IBM Ported Tools OpenSSH server (SSHD), and then a Co:Z SFTP session is started. If you are having a connection problem, first look at the error logs from SSHD. These are logged to syslogd - so you would need to have properly configured syslogd (which is also used for other IBM Comm Server functions). If no errors from SSHD in syslogd and there was a Co:Z SFTP session started then there should be a server log file. By default, these are in "/tmp/sftp-server.<userid>.<timestamp>.log.
I don't understand the purpose of the second "Dovetail" trace. This looks like a trace of the Co:Z SFTP client.
When you connect to Co:Z SFTP server, first an SSH connection is made to IBM Ported Tools OpenSSH server (SSHD), and then a Co:Z SFTP session is started. If you are having a connection problem, first look at the error logs from SSHD. These are logged to syslogd - so you would need to have properly configured syslogd (which is also used for other IBM Comm Server functions). If no errors from SSHD in syslogd and there was a Co:Z SFTP session started then there should be a server log file. By default, these are in "/tmp/sftp-server.<userid>.<timestamp>.log.
I don't understand the purpose of the second "Dovetail" trace. This looks like a trace of the Co:Z SFTP client.
-
Stuart-Willis
- Posts: 5
- Joined: Tue Oct 08, 2013 6:17 am
Re: Z/os 2.1 Support
Hi
The Dovetail Trace is a trace of the Divetail Server on the ZOS system.
export USE_COZ_SFTP=true
export SFTP_LOGFILE=/etc/ssh/cozlog.log
export COZ_LOG=F
set in sftp-server.rc
This is the output from syslogd I get Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: Received disconnect from 10.5.1.199: 11: Connection discarded by broker
Nov 4 15:00:39 Z13DEV/START2 SYSLOGD syslogd: FSUM1220 syslogd: restart
Nov 4 15:00:39 Z13DEV/START2 SYSLOGD syslogd: FSUM1232 syslogd: running non-swappable
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug2: fd 3 setting O_NONBLOCK
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: Bind to port 22 on ::.
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: Server listening on :: port 22.
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug2: fd 4 setting O_NONBLOCK
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: Bind to port 22 on 0.0.0.0.
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: Server listening on 0.0.0.0 port 22.
Nov 4 15:05:16 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: fd 6 clearing O_NONBLOCK
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: Forked child 50397301.
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug3: send_rexec_state: entering fd = 9 config len 238, zos_config len 42
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug3: ssh_msg_send: type 0
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug3: send_rexec_state: done
Nov 4 15:05:17 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: rexec start in 6 out 6 newsock 6 pipe 8 sock 9
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: inetd sockets after dupping: 3, 3
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: Connection from 10.5.1.199 port 8302
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: zsshSmfSetConnSmfStatus: SMF status is 0
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: zsshSmfTestRecord: SMF not collecting type 119, subtype 98 records: EDC5157I An internal error has occurred. (errno2=0x09210407).
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Client protocol version 2.0; client software version 6.2.2.198 SSH Secure Shell
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: no match: 6.2.2.198 SSH Secure Shell
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Enabling compatibility mode for protocol 2.0
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Local version string SSH-2.0-OpenSSH_5.0
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 3 setting O_NONBLOCK
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: Network child is on pid 16842879
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Current IBM Release level: 23
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: seclabel of AS: uid:0 pid:50397301
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: peer socket: rc:0 t:0 seclabel: terminal:0A0501C7 poe_profile:
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: Port of Entry information retained for uid:0 pid:50397301.
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: seclabel of AS: uid:0 pid:50397301
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: peer socket: rc:0 t:0 seclabel: terminal:0A0501C7 poe_profile:
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: /var/empty: rc:0 t:1 seclabel: terminal: poe_profile:
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: preauth child monitor started
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 4
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_sign
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_sign: signature 129DBAB0(55)
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 5
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: monitor_read: 4 used once, disabling now
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 6
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_pwnamallow
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: get_pwnamallow: input user name SW, user database name SW
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Trying to reverse map address 10.5.1.199.
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: parse_server_config: config reprocess config len 238
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: parse_server_config: config reprocess config len 42
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 7
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: monitor_read: 6 used once, disabling now
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 3
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_authserv: service=ssh-connection, style=
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: monitor_read: 3 used once, disabling now
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 10
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_authpassword: sending result 0
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 11
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: auth_log: authenticated 0, valid 1, failures 0, max 6, half 3, method none
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: Failed none for SW from 10.5.1.199 port 8302 ssh2
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 10
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_authpassword: sending result 1
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 11
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: auth_log: authenticated 1, valid 1, failures 0, max 6, half 3, method password
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: Accepted password for SW from 10.5.1.199 port 8302 ssh2
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: monitor_child_preauth: SW has been authenticated by privileged process
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Waiting for new keys
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive_expect entering: type 24
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_newkeys_from_blob: 129E9138(123)
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: mac_setup: found hmac-sha1
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Waiting for second key
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_newkeys_from_blob: 129E9138(123)
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: mac_setup: found hmac-sha1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Getting compression state
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Getting Network I/O buffers
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: set_newkeys: mode 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: set_newkeys: mode 1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Entering interactive session for SSH2.
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 4 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 5 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_init_dispatch_20
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 32768
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: input_session_request
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: channel 0: new [server-session]
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_new: init
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_new: session 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_open: channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_open: session 0: link with channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_open: confirm session
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_req: channel 0 request auth-agent-req@openssh.com reply 1
Nov 4 15:05:26 Z13DEV/SW SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_input_channel_req: session 0 req auth-agent-req@openssh.com
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: temporarily_use_uid: 0/0 (e=0/0)
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: restore_uid: 0/0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 7 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: fd 7 is O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: channel 1: new [auth socket]
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_input_channel_req: session 0 req subsystem
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: subsystem request for sftp
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: subsystem: exec() /wds/dovetail/bin/sftp-server.sh
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: do_exec: subsystem 1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: do_exec: passwd name=SW, uid=0, gid=0, dir=/u/, shell=/bin/sh
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: do_exec_no_pty: no JSCBAUTH propagation to child
Nov 4 15:05:26 Z13DEV/START2 SSHD6 sshd[50397301]: debug2: fd 3 setting TCP_NODELAY
Nov 4 15:05:26 Z13DEV/START2 SSHD6 sshd[50397301]: debug2: fd 11 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 10 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD6 sshd[33620095]: debug3: zsshCloseOldDev: fd=-1
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug3: zsshCloseOldDev: fd=-1
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug1: permanently_set_uid: 0/0
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug3: channel 1: close_fds r 7 w 7 e -1 c -1
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: rcvd eof
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: output open -> drain
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: obuf empty
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: close_write
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: output drain -> closed
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: rcvd close
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: close_read
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: input open -> closed
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: channel 0: will not send data after close
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: almost dead
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: gc: notify user
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close_by_channel: channel 0 child 33620095
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close_by_channel: channel 0: has child
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Received SIGCHLD.
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_pid: pid 33620095
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_exit_message: session 0 channel 0 pid 33620095
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: request exit-status confirm 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_exit_message: release channel 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: send close
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: is dead
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: gc: notify user
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close_by_channel: channel 0 child 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close: session 0 pid 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: gc: user detached
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: is dead
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: garbage collecting
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: channel 0: free: server-session, nchannels 2
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: channel 0: status: The following connections are open:
#0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: notify_done: reading
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: Received disconnect from 10.5.1.199: 11: Connection discarded by broker <=======================================
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: do_cleanup
Nov 4 15:05:42 Z13DEV/SW SSHD4 sshd[50397301]: debug1: temporarily_use_uid: 0/0 (e=0/0)
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: restore_uid: 0/0
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: zsshCloseOldDev: fd=-1
If I run the the same connection but with Subsystem.sftp./usr/lib/ssh/sftp-server in "sshd_config" instead of subsystem sftp /wds/dovetail/bin/sftp-server.sh i can get in ans all works as I would expect.
Regards
Stuart
The Dovetail Trace is a trace of the Divetail Server on the ZOS system.
export USE_COZ_SFTP=true
export SFTP_LOGFILE=/etc/ssh/cozlog.log
export COZ_LOG=F
set in sftp-server.rc
This is the output from syslogd I get Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: Received disconnect from 10.5.1.199: 11: Connection discarded by broker
Nov 4 15:00:39 Z13DEV/START2 SYSLOGD syslogd: FSUM1220 syslogd: restart
Nov 4 15:00:39 Z13DEV/START2 SYSLOGD syslogd: FSUM1232 syslogd: running non-swappable
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug2: fd 3 setting O_NONBLOCK
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: Bind to port 22 on ::.
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: Server listening on :: port 22.
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug2: fd 4 setting O_NONBLOCK
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: Bind to port 22 on 0.0.0.0.
Nov 4 15:03:38 Z13DEV/START2 SSHD3 sshd[33620086]: Server listening on 0.0.0.0 port 22.
Nov 4 15:05:16 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: fd 6 clearing O_NONBLOCK
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug1: Forked child 50397301.
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug3: send_rexec_state: entering fd = 9 config len 238, zos_config len 42
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug3: ssh_msg_send: type 0
Nov 4 15:05:17 Z13DEV/START2 SSHD3 sshd[33620086]: debug3: send_rexec_state: done
Nov 4 15:05:17 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: rexec start in 6 out 6 newsock 6 pipe 8 sock 9
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: inetd sockets after dupping: 3, 3
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: Connection from 10.5.1.199 port 8302
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: zsshSmfSetConnSmfStatus: SMF status is 0
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: zsshSmfTestRecord: SMF not collecting type 119, subtype 98 records: EDC5157I An internal error has occurred. (errno2=0x09210407).
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Client protocol version 2.0; client software version 6.2.2.198 SSH Secure Shell
Nov 4 15:05:20 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: no match: 6.2.2.198 SSH Secure Shell
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Enabling compatibility mode for protocol 2.0
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Local version string SSH-2.0-OpenSSH_5.0
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 3 setting O_NONBLOCK
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: Network child is on pid 16842879
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Current IBM Release level: 23
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: seclabel of AS: uid:0 pid:50397301
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: peer socket: rc:0 t:0 seclabel: terminal:0A0501C7 poe_profile:
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: Port of Entry information retained for uid:0 pid:50397301.
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: seclabel of AS: uid:0 pid:50397301
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: peer socket: rc:0 t:0 seclabel: terminal:0A0501C7 poe_profile:
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: MLS: /var/empty: rc:0 t:1 seclabel: terminal: poe_profile:
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: preauth child monitor started
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 4
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_sign
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_sign: signature 129DBAB0(55)
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 5
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: monitor_read: 4 used once, disabling now
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 6
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_pwnamallow
Nov 4 15:05:22 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: get_pwnamallow: input user name SW, user database name SW
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Trying to reverse map address 10.5.1.199.
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: parse_server_config: config reprocess config len 238
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: parse_server_config: config reprocess config len 42
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 7
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: monitor_read: 6 used once, disabling now
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 3
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_authserv: service=ssh-connection, style=
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: monitor_read: 3 used once, disabling now
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 10
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_authpassword: sending result 0
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 11
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: auth_log: authenticated 0, valid 1, failures 0, max 6, half 3, method none
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: Failed none for SW from 10.5.1.199 port 8302 ssh2
Nov 4 15:05:23 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: monitor_read: checking request 10
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_answer_authpassword: sending result 1
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_send entering: type 11
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: auth_log: authenticated 1, valid 1, failures 0, max 6, half 3, method password
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: Accepted password for SW from 10.5.1.199 port 8302 ssh2
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: monitor_child_preauth: SW has been authenticated by privileged process
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Waiting for new keys
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive_expect entering: type 24
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_request_receive entering
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_newkeys_from_blob: 129E9138(123)
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: mac_setup: found hmac-sha1
Nov 4 15:05:25 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Waiting for second key
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_newkeys_from_blob: 129E9138(123)
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: mac_setup: found hmac-sha1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Getting compression state
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: mm_get_keystate: Getting Network I/O buffers
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: set_newkeys: mode 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: set_newkeys: mode 1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Entering interactive session for SSH2.
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 4 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 5 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_init_dispatch_20
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_open: ctype session rchan 0 win 65536 max 32768
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: input_session_request
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: channel 0: new [server-session]
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_new: init
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_new: session 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_open: channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_open: session 0: link with channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_open: confirm session
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_req: channel 0 request auth-agent-req@openssh.com reply 1
Nov 4 15:05:26 Z13DEV/SW SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_input_channel_req: session 0 req auth-agent-req@openssh.com
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: temporarily_use_uid: 0/0 (e=0/0)
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: restore_uid: 0/0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 7 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: fd 7 is O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: channel 1: new [auth socket]
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: server_input_channel_req: channel 0 request subsystem reply 1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_input_channel_req: session 0 req subsystem
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: subsystem request for sftp
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: subsystem: exec() /wds/dovetail/bin/sftp-server.sh
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: do_exec: subsystem 1
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: do_exec: passwd name=SW, uid=0, gid=0, dir=/u/, shell=/bin/sh
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: do_exec_no_pty: no JSCBAUTH propagation to child
Nov 4 15:05:26 Z13DEV/START2 SSHD6 sshd[50397301]: debug2: fd 3 setting TCP_NODELAY
Nov 4 15:05:26 Z13DEV/START2 SSHD6 sshd[50397301]: debug2: fd 11 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: fd 10 setting O_NONBLOCK
Nov 4 15:05:26 Z13DEV/START2 SSHD6 sshd[33620095]: debug3: zsshCloseOldDev: fd=-1
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug3: zsshCloseOldDev: fd=-1
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug1: permanently_set_uid: 0/0
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1
Nov 4 15:05:27 Z13DEV/SW SSHD6 sshd[33620095]: debug3: channel 1: close_fds r 7 w 7 e -1 c -1
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: rcvd eof
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: output open -> drain
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: obuf empty
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: close_write
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: output drain -> closed
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: rcvd close
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: close_read
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: input open -> closed
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: channel 0: will not send data after close
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: almost dead
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: gc: notify user
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close_by_channel: channel 0 child 33620095
Nov 4 15:05:35 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close_by_channel: channel 0: has child
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: Received SIGCHLD.
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_pid: pid 33620095
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_exit_message: session 0 channel 0 pid 33620095
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: request exit-status confirm 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_exit_message: release channel 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: send close
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: is dead
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: gc: notify user
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_by_channel: session 0 channel 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close_by_channel: channel 0 child 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: session_close: session 0 pid 0
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: gc: user detached
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: is dead
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: channel 0: garbage collecting
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: channel 0: free: server-session, nchannels 2
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: channel 0: status: The following connections are open:
#0 server-session (t4 r0 i3/0 o3/0 fd -1/-1 cfd -1)
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: channel 0: close_fds r -1 w -1 e -1 c -1
Nov 4 15:05:37 Z13DEV/START2 SSHD4 sshd[50397301]: debug2: notify_done: reading
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: Received SSH2_MSG_IGNORE
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: Received disconnect from 10.5.1.199: 11: Connection discarded by broker <=======================================
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: do_cleanup
Nov 4 15:05:42 Z13DEV/SW SSHD4 sshd[50397301]: debug1: temporarily_use_uid: 0/0 (e=0/0)
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug1: restore_uid: 0/0
Nov 4 15:05:42 Z13DEV/START2 SSHD4 sshd[50397301]: debug3: zsshCloseOldDev: fd=-1
If I run the the same connection but with Subsystem.sftp./usr/lib/ssh/sftp-server in "sshd_config" instead of subsystem sftp /wds/dovetail/bin/sftp-server.sh i can get in ans all works as I would expect.
Regards
Stuart
Re: Z/os 2.1 Support
The SSHD log seems to indicate that the client dropped the connection.
It appears that the Tectia SFTP client is dropping the connection.
For diagnostic purposes, you might want to test another client like the free PuTTY psftp command.
It would be helpful to get additional tracing of the OpenSSH part of the Co:Z SFTP server code. To do this, add the following line to "sftp-server.rc":directory with the lines:
export SFTP_SERVER_OPTIONS="-e -l debug3"
Then please get the trace (by default, /tmp/sftp-server.<userid>.<timestamp>,log ) of the failing connection and please email to info@dovetail.com and we will take a look.
BTW: there is something very odd about the client trace: the "file-stat-extended@ssh.com" extended request seems to be being sent several times. Co:Z SFTP server is based on OpenSSH 5.0p1 and it doesn't support this request. It should never have been sent, since it would not have been advertised in the response to the INIT packet. The client trace also shows SSH_FTP_REALPATH requests resolving to C:\Users\sw.
I really doubt that this client trace is talking to the z/OS server running CO:Z SFTP. Could that be possible?
It appears that the Tectia SFTP client is dropping the connection.
For diagnostic purposes, you might want to test another client like the free PuTTY psftp command.
It would be helpful to get additional tracing of the OpenSSH part of the Co:Z SFTP server code. To do this, add the following line to "sftp-server.rc":directory with the lines:
export SFTP_SERVER_OPTIONS="-e -l debug3"
Then please get the trace (by default, /tmp/sftp-server.<userid>.<timestamp>,log ) of the failing connection and please email to info@dovetail.com and we will take a look.
BTW: there is something very odd about the client trace: the "file-stat-extended@ssh.com" extended request seems to be being sent several times. Co:Z SFTP server is based on OpenSSH 5.0p1 and it doesn't support this request. It should never have been sent, since it would not have been advertised in the response to the INIT packet. The client trace also shows SSH_FTP_REALPATH requests resolving to C:\Users\sw.
I really doubt that this client trace is talking to the z/OS server running CO:Z SFTP. Could that be possible?
-
Stuart-Willis
- Posts: 5
- Joined: Tue Oct 08, 2013 6:17 am
Re: Z/os 2.1 Support
From the trace, it appeared that non-packet data was being written to stdout by the Co:Z SFTP server process.
Confirmed with Stewart that an echo message was added to sftp-server.sh. This was removed and the connections worked properly.
Confirmed with Stewart that an echo message was added to sftp-server.sh. This was removed and the connections worked properly.
-
Stuart-Willis
- Posts: 5
- Joined: Tue Oct 08, 2013 6:17 am
Re: Z/os 2.1 Support
Big thanks to Dovetail support.
All down to user Error I added an echo "Start Dovetail" into the Dovetail "sftp-server.sh" script when I was first trying to get the server to work. A little knowledge is a dangerous thing.
Removed the line and all works now.
Stuart.
All down to user Error I added an echo "Start Dovetail" into the Dovetail "sftp-server.sh" script when I was first trying to get the server to work. A little knowledge is a dangerous thing.
Removed the line and all works now.
Stuart.