Help with SFTP from VMS to Windows

[VMS Unix Admin]

I've not been able to get a batch mode SFTP transfer to work. I can log in interactively OK. The administrator on the remote system has registered the public key that I generated and sent. I put a copy of the public key in the .ssh2 sub directory on the remote host.

I've looked through related threads in this forum and so far have not found the magic bullet. Any suggestions would be appreciated.

Here is what I'm using to test and the results.

Software Version Information:

MILC2(D_DEV)$ tcpip show version

HP TCP/IP Services for OpenVMS Alpha Version V5.6 - ECO 2
on an hp AlphaServer GS1280 7/1150 running OpenVMS V8.3

The test DCL procedure:

MILC2(D_DEV)$ type sftp_test.com
$!
$! Test SFTP batch job.
$!
$ set verify
$!
$ SFTP "-D" "-B"tmp_ftp.sftp "sftpFubar@somewhere.xxx.com"
$!
$ exit

The input SFTP command script. I inserted a (ASCII 10) after each line in the script below:

MILC2(D_DEV)$ type tmp_ftp.sftp
pwd

ls -l

exit

MILC2(D_DEV)$ submit/noprint/keep/log/notify SFTP_TEST.COM

MILC2(D_DEV)$ type SFTP_TEST.LOG
---------- Batch Job Submission Information ----------

Current Time : 29-JAN-2009 15:40:12.38
Job Submitted by (USERNAME) : D_DEV
Job UIC : [D_DEV]
Job ACCOUNT Name :
JOB Name : SFTP_TEST
Log File :
QUEUE Name : MILC2$BATCH
SUBMISSION TIME of Job : 29-JAN-2009 15:40:12.44
FILENAME Submitted : _DSA100:[USER.D_DEV]SFTP_TEST.COM;6
Job Entry Number : 4292

# Jobs Executing in this Queue : 3

----------------------------------------------------
$!
$ SFTP "-D" "-B"tmp_ftp.sftp "sftpFubar@somewhere.xxx.com"
Ssh2SftpServer/SSHFILEXFERS.C:2074: Received SSH_FXP_INIT
Ssh2SftpServer/SSHFILEXFERS.C:2119: version is 3
argv[0] = /sys$system/tcpip$ssh_ssh2
argv[1] = -v
argv[2] = -x
argv[3] = -a
argv[4] = -o
argv[5] = passwordprompt %U@%H's password:
argv[6] = -o
argv[7] = authenticationnotify yes
argv[8] = -o
argv[9] = BatchMode yes
argv[10] = sftpFubar@somewhere.xxx.com
argv[11] = -s
argv[12] = sftp
debug: Ssh2/SSH2.C:1885: CRTL version (SYS$SHARE:DECC$SHR.EXE ident) is V8.3-01
debug: SshAppCommon/SSHAPPCOMMON.C:313: Allocating global SshRegex context.
debug: Connecting to somewhere.xxx.com, port 22... (SOCKS not used)
debug: Ssh2/SSH2.C:2861: Entering event loop.
debug: Ssh2Client/SSHCLIENT.C:1609: Creating transport protocol.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "publickey" to usable methods.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "keyboard-interactive" to usable methods.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "password" to usable methods.
debug: Ssh2Client/SSHCLIENT.C:1650: Creating userauth protocol.
debug: client supports 3 auth methods: 'publickey,keyboard-interactive,password'
debug: SshUnixTcp/SSHUNIXTCP.C:1390: using local hostname MILC2.MAYO.EDU
debug: Ssh2Common/SSHCOMMON.C:541: local ip = 129.176.186.23, local port = 61921
debug: Ssh2Common/SSHCOMMON.C:543: remote ip = 65.164.45.25, remote port = 22
debug: SshConnection/SSHCONN.C:2311: Wrapping...
debug: Remote version: SSH-2.0-1.82 sshlib: WinSSHD 4.23
debug: Major: 1 Minor: 82 Revision: 0
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 20 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 30 to connection
debug: Ssh2Transport/TRCOMMON.C:2306: lang s to c: `', lang c to s: `'
debug: Ssh2Transport/TRCOMMON.C:2371: c_to_s: cipher aes128-cbc, mac hmac-sha1, compression none
debug: Ssh2Transport/TRCOMMON.C:2374: s_to_c: cipher aes128-cbc, mac hmac-sha1, compression none
debug: Remote host key found from database.
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 21 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 5 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Ssh2Common/SSHCOMMON.C:342: Received SSH_CROSS_STARTUP packet from connection protocol.
debug: Ssh2Common/SSHCOMMON.C:392: Received SSH_CROSS_ALGORITHMS packet from connection protocol.
debug: server offers auth methods 'publickey,password'.
debug: SshConfig/SSHCONFIG.C:3335: Unable to open ssh2/identification
debug: Ssh2AuthClient/SSHAUTHC.C:374: Method 'publickey' disabled.
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: server offers auth methods 'publickey,password'.
debug: Ssh2AuthPasswdClient/AUTHC-PASSWD.C:291: In Batchmode, so we're not asking the user for password.
debug: Ssh2AuthClient/SSHAUTHC.C:374: Method 'password' disabled.
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: server offers auth methods 'publickey,password'.
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 1 to connection
debug: Ssh2Common/SSHCOMMON.C:180: DISCONNECT received: No further authentication methods available.

warning: Authentication failed.

debug: Ssh2/SSH2.C:320: locally_generated = TRUE

Disconnected; no more authentication methods available (No further authentication methods available.).

debug: Ssh2Client/SSHCLIENT.C:1685: Destroying client.
debug: SshConfig/SSHCONFIG.C:2836: Freeing pki. (host_pki != NULL, user_pki = NULL)
debug: SshConnection/SSHCONN.C:2363: Destroying SshConn object.
debug: Ssh2Client/SSHCLIENT.C:1753: Destroying client completed.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:109: Destroying authentication method array.

FATAL: ssh2 client failed to authenticate. (or you have too old ssh2 installed, check with ssh2 "-V")
%TCPIP-F-SSH_FATAL, non-specific fatal error condition
D_DEV job terminated at 29-JAN-2009 15:40:14.46

[Steven Schweda]

> I can log in interactively OK.

Does that mean that the same SFTP command
works interactively? And the batch job is
submitted by (or on behalf of) the same user?

> [...]
> debug: SshConfig/SSHCONFIG.C:3335: Unable to open ssh2/identification
> debug: Ssh2AuthClient/SSHAUTHC.C:374: Method 'publickey' disabled.
> [...]

This looks to me like a clue. What's in the
"[.ssh2]identification." file under
your/his/her SYS$LOGIN?

Perhaps some "SHOW " commands
in the batch command procedure would add some
light, too.

[VMS Unix Admin]

Steve, you were correct. It looks like the authentication is working now. The problem was the IDENTIFICATION file (lack of).

The problem is now the input batch file. I attempted to convert the file to stream-lf. Details on the input file are at the bottom.

MILC2(D_DEV)$ type SFTP_TEST.LOG
---------- Batch Job Submission Information ----------

Current Time : 30-JAN-2009 13:47:28.23
Job Submitted by (USERNAME) : D_DEV
Job UIC : [D_DEV]
Job ACCOUNT Name :
JOB Name : SFTP_TEST
Log File :
QUEUE Name : MILC2$BATCH
SUBMISSION TIME of Job : 30-JAN-2009 13:47:28.34
FILENAME Submitted : _DSA100:[USER.D_DEV]SFTP_TEST.COM;7
Job Entry Number : 6634
----------------------------------------------------

$!
$ SFTP "-D" "-B"tmp_ftp.sftp_slf "sftpFubar@somewhere.xxx.com"
Ssh2SftpServer/SSHFILEXFERS.C:2074: Received SSH_FXP_INIT
Ssh2SftpServer/SSHFILEXFERS.C:2119: version is 3
argv[0] = /sys$system/tcpip$ssh_ssh2
argv[1] = -v
argv[2] = -x
argv[3] = -a
argv[4] = -o
argv[5] = passwordprompt %U@%H's password:
argv[6] = -o
argv[7] = authenticationnotify yes
argv[8] = -o
argv[9] = BatchMode yes
argv[10] = sftpFubar@somewhere.xxx.com
argv[11] = -s
argv[12] = sftp
debug: Ssh2/SSH2.C:1885: CRTL version (SYS$SHARE:DECC$SHR.EXE ident) is V8.3-01
debug: SshAppCommon/SSHAPPCOMMON.C:313: Allocating global SshRegex context.
debug: SshConfig/SSHCONFIG.C:3427: Metaconfig parsing stopped at line 4.
debug: SshConfig/SSHCONFIG.C:869: Setting variable 'VerboseMode' to 'FALSE'.
debug: Connecting to somewhere.xxx.com, port 22... (SOCKS not used)
debug: Ssh2/SSH2.C:2861: Entering event loop.
debug: Ssh2Client/SSHCLIENT.C:1609: Creating transport protocol.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "hostbased" to usable methods.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "publickey" to usable methods.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "password" to usable methods.
debug: Ssh2Client/SSHCLIENT.C:1650: Creating userauth protocol.
debug: client supports 3 auth methods: 'hostbased,publickey,password'
debug: SshUnixTcp/SSHUNIXTCP.C:1390: using local hostname MILC2.MAYO.EDU
debug: Ssh2Common/SSHCOMMON.C:541: local ip = 129.176.186.23, local port = 25722
debug: Ssh2Common/SSHCOMMON.C:543: remote ip = 65.164.45.25, remote port = 22
debug: SshConnection/SSHCONN.C:2311: Wrapping...
debug: Remote version: SSH-2.0-1.82 sshlib: WinSSHD 4.23
debug: Major: 1 Minor: 82 Revision: 0
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 20 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 30 to connection
debug: Ssh2Transport/TRCOMMON.C:2306: lang s to c: `', lang c to s: `'
debug: Ssh2Transport/TRCOMMON.C:2371: c_to_s: cipher aes128-cbc, mac hmac-sha1, compression none
debug: Ssh2Transport/TRCOMMON.C:2374: s_to_c: cipher aes128-cbc, mac hmac-sha1, compression none
debug: Remote host key found from database.
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 21 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 5 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Ssh2Common/SSHCOMMON.C:342: Received SSH_CROSS_STARTUP packet from connection protocol.
debug: Ssh2Common/SSHCOMMON.C:392: Received SSH_CROSS_ALGORITHMS packet from connection protocol.
debug: server offers auth methods 'publickey,password'.
debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:1677: adding keyfile "/DEV_EXE/user/d_dev/ssh2/ID_DSA_2048_A" to candidates

debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Constructing and sending signature in publickey authentication.
debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:869: ssh_client_auth_pubkey_send_signature: reading /DEV_EXE/user/d_dev/ssh2/ID_DSA_2048_A
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:1915: Public key authentication was successful.
debug: Ssh2Common/SSHCOMMON.C:310: Received SSH_CROSS_AUTHENTICATED packet from connection protocol.
debug: Ssh2Common/SSHCOMMON.C:852: num_channels now 1
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 90 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 98 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 94 to connection

Error: Could not read the batchfile.

ssh_pipe_stream_destroy
%TCPIP-E-SSH_FC_ERROR, error in ssh file transfer operation
D_DEV job terminated at 30-JAN-2009 13:47:30.84

MILC2(D_DEV)$ dir/full tmp_ftp.sftp_slf

Directory DEV_EXE:[USER.D_DEV]

TMP_FTP.SFTP_SLF;2 File ID: (482,15,0)
Size: 1/121 Owner: [D_DEV]
Created: 30-JAN-2009 13:42:03.12
Revised: 30-JAN-2009 13:45:52.56 (2)
Expires:
Backup:
Effective:
Recording:
Accessed:
Attributes:
Modified:
Linkcount: 1
File organization: Sequential
Shelved state: Online
Caching attribute: Writethrough
File attributes: Allocation: 121, Extend: 0, Global buffer count: 0, No version limit
Record format: Stream_LF, maximum 0 bytes, longest 5 bytes
Record attributes: Carriage return carriage control
RMS attributes: None
Journaling enabled: None
File protection: System:RWED, Owner:RWED, Group:RE, World:
Access Cntrl List: None
Client attributes: None

MILC2(D_DEV)$ show def
dev_exe:[user.d_dev]

MILC2(D_DEV)$ show log sys$login
"SYS$LOGIN" = "dev_exe:[user.d_dev]" (LNM$JOB_88AC14C0)

[Steven Schweda]

> debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:1915: Public key authentication was successful.

Ok. _Now_ it looks like a normal DCL
mistake.

> FILENAME Submitted : _DSA100:[USER.D_DEV]SFTP_TEST.COM;7

> Error: Could not read the batchfile.

If the "batchfile" is in [.D_DEV] (with the
batch command procedure), then you'd better
have a "SET DEFAULT [.D_DEV]" in that batch
job procedure, because it will start in
SYS$LOGIN, _not_ the directory where the
procedure itself resides. A batch-safe
command procedure might begin with code like:

$ prc = f$environment( "procedure")
$ prc_dev_dir = f$parse( prc, , , "device")+ f$parse( prc, , , "directory")
$ set default 'prc_dev_dir'

(All that intimidating SFTP/SSH debug stuff
tends to obscure the more elementary
problems.)

[Steven Schweda]

> MILC2(D_DEV)$ show def
> dev_exe:[user.d_dev]
>
> MILC2(D_DEV)$ show log sys$login
> "SYS$LOGIN" = "dev_exe:[user.d_dev]" (LNM$JOB_88AC14C0)

Hmmm. Did I quit reading too soon (again)?

Does the command procedure now work
interactively, and fail only in batch? If
so, then _something_ must be different in the
environments.

[VMS Unix Admin]

Both the command procedure DCL file (sftp_test.com) and the input "batchfile" (currently named sftp_tmp.slf) to the SFTP procedure reside in sys$login of the user (D_DEV) that submits the VMS batch job. The D-DEV user is fully privleged. I thought that would be the simplest case to test since by default, that is where VMS batch job would be when it started (as user D_DEV), correct? I opened up the file protections on the SFTP input script as well as converted it to stream-lf format. I assumed that the batchfile that SFTP was complaining about. I also tried specifying the path to the file on the sftp command line:

$ SFTP "-D" "-B""/sys$login/sftp_tmp.slf" "sftpFubar@somewhere.xxx.com"

Same error.

The interactive SFTP session works interactively only. No script use was attempted. I simply put the FTP commands that worked interactively in the SFTP input script.

I'm out of ideas.

[Steven Schweda]

Around here:

alp $ tcpip show version

HP TCP/IP Services for OpenVMS Alpha Version V5.4 - ECO 7
on a COMPAQ Professional Workstation XP1000 running OpenVMS V7.3-2

alp $ ssh "-V"
alp$dka0:[sys0.syscommon.][sysexe]tcpip$ssh_ssh2.exe: SSH Secure Shell OpenVMS (
V5.5) 3.2.0 on COMPAQ Professional Workstation - VMS V7.3-2

alp $ sftp "-V"
alp$dka0:[sys0.syscommon.][sysexe]tcpip$ssh_sftp2.exe: SSH Secure Shell OpenVMS
(V5.5) 3.2.0 on COMPAQ Professional Workstation - VMS V7.3-2

alp $ dg

Directory ALP$DKA0:[SMS.SFTPB]

SFTPB.BAT;1 1 30-JAN-2009 14:07:17.80 (RWED,RWED,RE,)
SFTPB.COM;2 1 30-JAN-2009 14:08:06.45 (RWED,RWED,RE,)
SFTPBB.COM;1 1 30-JAN-2009 14:16:33.58 (RWED,RWED,RE,)

Total of 3 files, 3 blocks.

alp $ type SFTPB.BAT
get sftpb.test
alp $ type SFTPB.COM
$ sftp "-B" sftpb.bat sms@alp
alp $ @ SFTPB.COM
sftp> get sftpb.test
sftpb.test | 38B | 0.0 kB/s | TOC: 00:00:01 | 100%

Ssh2SftpServer/SSHFILEXFERS.C:2909: Received SSH_FXP_CLOSE
Ssh2SftpServer/SSHFILEXFERS.C:3013: Closed file `./sftpb.test' (handle=4d8e0d)

And, it seems to have fetched the file:

alp $ dg

Directory ALP$DKA0:[SMS.SFTPB]

SFTPB.BAT;1 1 30-JAN-2009 14:07:17.80 (RWED,RWED,RE,)
SFTPB.COM;2 1 30-JAN-2009 14:08:06.45 (RWED,RWED,RE,)
SFTPB.TEST;1 1 30-JAN-2009 14:56:50.59 (RWED,RWED,RE,)
SFTPBB.COM;1 1 30-JAN-2009 14:16:33.58 (RWED,RWED,RE,)

Total of 4 files, 4 blocks.

If I SUBMIT SFTPB.COM, it fails with one of
those "Could not read the batchfile"
complaints:

alp $ sub SFTPB.COM
Job SFTPB (queue SYS$BATCH_ALP, entry 256) started on SYS$BATCH_ALP
alp $

Job SFTPB (queue SYS$BATCH_ALP, entry 256) terminated with error status
alp $ type [-]SFTPB.LOG
$ Set NoOn
$ VERIFY = F$VERIFY(F$TRNLNM("SYLOGIN_VERIFY"))
Error: Could not read the batchfile.
%TCPIP-E-SSH_FC_ERROR, error in ssh file transfer operation
SMS job terminated at 30-JAN-2009 14:59:28.76

Accounting information:
Buffered I/O count: 712 Peak working set size: 6976
Direct I/O count: 135 Peak virtual size: 181952
Page faults: 511 Mounted volumes: 0
Charged CPU time: 0 00:00:00.17 Elapsed time: 0 00:00:15.18
alp $

But if I use this one, it works:

lp $ type SFTPBB.COM
$ prc = f$environment( "procedure")
$ prc_dev_dir = f$parse( prc, , , "device")+ f$parse( prc, , , "directory")
$ set default 'prc_dev_dir'
$!
$ sftp "-B" sftpb.bat sms@alp
alp $ delete SFTPB.TEST;*

alp $ sub SFTPBB.COM
Job SFTPBB (queue SYS$BATCH_ALP, entry 257) started on SYS$BATCH_ALP
alp $

Job SFTPBB (queue SYS$BATCH_ALP, entry 257) completed
alp $ type [-]SFTPBB.LOG
$ Set NoOn
$ VERIFY = F$VERIFY(F$TRNLNM("SYLOGIN_VERIFY"))
sftp> get sftpb.test
sftpb.test | 38B | 0.0 kB/s | TOC: 00:00:01 | 100%
SMS job terminated at 30-JAN-2009 15:01:19.98

Accounting information:
Buffered I/O count: 783 Peak working set size: 7904
Direct I/O count: 142 Peak virtual size: 181904
Page faults: 576 Mounted volumes: 0
Charged CPU time: 0 00:00:00.23 Elapsed time: 0 00:00:14.58
alp $

And the test file's back:

alp $ dg

Directory ALP$DKA0:[SMS.SFTPB]

SFTPB.BAT;1 1 30-JAN-2009 14:07:17.80 (RWED,RWED,RE,)
SFTPB.COM;2 1 30-JAN-2009 14:08:06.45 (RWED,RWED,RE,)
SFTPB.TEST;1 1 30-JAN-2009 15:01:19.34 (RWED,RWED,RE,)
SFTPBB.COM;1 1 30-JAN-2009 14:16:33.58 (RWED,RWED,RE,)

Total of 4 files, 4 blocks.

Other than a space between "-B" and the file
name, I don't see any big differences
between your failing stuff and my working
stuff. As you would expect:

alp $ write sys$output f$file_attributes( "SFTPB.BAT", "RFM")
STMLF


> [...] , correct?

Why ask me? Put some SHOW and/or WRITE
SYS$OUTPUT stuff into the procedure, and get
(much) better stuff than my opinion. When
in doubt, consult reality.

[VMS Unix Admin]

I have a firm grip on reality, thanks.

The user is D_DEV

Sys$login is:

MILC2(D_DEV)$ show log sys$login
"SYS$LOGIN" = "dev_exe:[user.d_dev]" (LNM$JOB_88AC14C0)

The batch job is submitted by D_DEV. Both files, the DCL batch script and the SFTP batch inout file resides in sys$login for D_DEV.

MILC2(D_DEV)$ mc authorize show d_dev

Username: D_DEV Owner: V500 dev Account
Account: UIC: [525,0] ([D_DEV])
CLI: DCL Tables: DCLTABLES
Default: dev_exe:[user.d_dev]

MILC2(D_DEV)$ dir/sec *sftp*.*;

Directory DEV_EXE:[USER.D_DEV]

SFTP_TEST.COM;16 1 30-JAN-2009 16:04:19.12 [D_DEV] (RWED,RWED,RE,)
SFTP_TEST.LOG;25 14 30-JAN-2009 16:04:38.27 [D_DEV] (RWED,RWED,RE,)
SFTP_TMP.SLF;2 1 30-JAN-2009 14:40:44.06 [D_DEV] (RWED,RWED,RWED,RWED)

[Steven Schweda]

> I have a firm grip on reality, thanks.

Glad to hear it.

> Sys$login is:
> [...]

This is all very nice, but I'd have more
confidence in all of it if the actual (batch)
command procedure were saying it. We know
that it all works when you do it
interactively (don't we?). The mystery is
what's going on in the procedure. Diagnostic
commands in a different environment may be
misleading.

Did you try to reconstruct my test case?

[VMS Unix Admin]

If I insert a space between the "-B" and the batch file name, I get the following error:

$!
$ SFTP "-D" "-B" TMP_FTP.SFTP "sftpMayo@essenceweb.isf.com"
Too many arguments.
Usage: sftp2 [-D debug_level_spec] [-B batchfile] [-S path] [-h]
[-V] [-P port] [-b buffer_size]
[-4] [-6] "[-C]" [-o option_to_ssh2]
[user@]host[#port]


If I execute the following command interactively, it executes the SFTP command and gives me a sftp> prompt, waiting for input. So it apparently ignores the "-B" switch.
SFTP "-D" "-B"SFTP_TMP.SLF "sftpFubar@somewhere.xxx.com"

This is the partial output. Note that BatchMode is not mentioned in the arguments.

MILC2(D_DEV)$ SFTP "-D" "-BSFTP_TMP.SLF" "sftpFubar@somewhere.xxx.com"
Ssh2SftpServer/SSHFILEXFERS.C:2074: Received SSH_FXP_INIT
Ssh2SftpServer/SSHFILEXFERS.C:2119: version is 3
argv[0] = /sys$system/tcpip$ssh_ssh2
argv[1] = -v
argv[2] = -x
argv[3] = -a
argv[4] = -o
argv[5] = passwordprompt %U@%H's password:
argv[6] = -o
argv[7] = authenticationnotify yes
argv[8] = sftpFubar@somewhere.xxx.com
argv[9] = -s
argv[10] = sftp

Here is the info from a batch run with no space between the"-B" switch and the file name and with the suggested added code lines. The result was the same.

MILC2(D_DEV)$ type SFTP_TEST.COM
$!
$! Test SFTPbatch job.
$!
$! set verify
$!
$! SFTP "-D" "-B""/sys$login/sftp_tmp.slf" "sftpMayo@essenceweb.isf.com"
$!
$ say := write sys$output
$!
$ say ""
$ say "Executing ''f$environment("PROCEDURE")'"
$ set verify
$!
$ show default
$ show process/all
$ dir/full TMP_FTP.SFTP;
$!
$ prc = f$environment( "procedure")
$ prc_dev_dir = f$parse( prc, , , "device")+ f$parse( prc, , , "directory")
$ set default DEV_EXE:[USER.D_DEV]
$ show def
$!
$ SFTP "-D" "-B"SFTP_TMP.SLF "sftpMayo@essenceweb.isf.com"
$!
$ exit

This is SFTP batch input file:

MILC2(D_DEV)$ type SFTP_TMP.SLF
pwd
ls -l
exit


MILC2(D_DEV)$ submit/noprint/keep/log/notify SFTP_TEST.COM
Job SFTP_TEST (queue MILC2$BATCH, entry 8075) started on MILC2$BATCH
Job SFTP_TEST (queue MILC2$BATCH, entry 8075) terminated with error status

MILC2(D_DEV)$ type SFTP_TEST.LOG

---------- Batch Job Submission Information ----------

Current Time : 30-JAN-2009 21:24:48.19
Job Submitted by (USERNAME) : D_DEV
Job UIC : [D_DEV]
Job ACCOUNT Name :
JOB Name : SFTP_TEST
Log File :
QUEUE Name : MILC2$BATCH
SUBMISSION TIME of Job : 30-JAN-2009 21:24:48.32
FILENAME Submitted : _DSA100:[USER.D_DEV]SFTP_TEST.COM;19
Job Entry Number : 8075
----------------------------------------------------

Executing DEV_EXE:[USER.D_DEV]SFTP_TEST.COM;19
$!
$ show default
dev_exe:[user.d_dev]
$ show process/all

30-JAN-2009 21:24:48.79 User: D_DEV Process ID: 22C5ED22
Node: MILC2 Process name: "BATCH_8075"

Terminal:
User Identifier: [D_DEV]
Base priority: 4
Default file spec: dev_exe:[user.d_dev]
Number of Kthreads: 1

Process Quotas:
Account name:
CPU limit: Infinite Direct I/O limit: 32767
Buffered I/O byte count quota: 498912 Buffered I/O limit: 32767
Timer queue entry quota: 255 Open file quota: 1022
Paging file quota: 991456 Subprocess quota: 64
Default page fault cluster: 64 AST quota: 32766
Enqueue quota: 16776959 Shared file limit: 0
Max detached processes: 0 Max active jobs: 0

Accounting information:
Buffered I/O count: 880 Peak working set size: 3440
Direct I/O count: 274 Peak virtual size: 175232
Page faults: 337 Mounted volumes: 0
Images activated: 5
Elapsed CPU time: 0 00:00:00.14
Connect time: 0 00:00:00.71

Authorized privileges:
ACNT ALLSPOOL ALTPRI AUDIT BUGCHK BYPASS
CMEXEC CMKRNL DIAGNOSE DOWNGRADE EXQUOTA GROUP
GRPNAM GRPPRV IMPERSONATE IMPORT LOG_IO MOUNT
NETMBX OPER PFNMAP PHY_IO PRMCEB PRMGBL
PRMMBX PSWAPM READALL SECURITY SETPRV SHARE
SHMEM SYSGBL SYSLCK SYSNAM SYSPRV TMPMBX
UPGRADE VOLPRO WORLD

Process privileges:
ACNT may suppress accounting messages
ALLSPOOL may allocate spooled device
ALTPRI may set any priority value
AUDIT may direct audit to system security audit log
BUGCHK may make bug check log entries
BYPASS may bypass all object access controls
CMEXEC may change mode to exec
CMKRNL may change mode to kernel
DIAGNOSE may diagnose devices
DOWNGRADE may downgrade object secrecy
EXQUOTA may exceed disk quota
GROUP may affect other processes in same group
GRPNAM may insert in group logical name table
GRPPRV may access group objects via system protection
IMPERSONATE may impersonate another user
IMPORT may set classification for unlabeled object
LOG_IO may do logical i/o
MOUNT may execute mount acp function
NETMBX may create network device
OPER may perform operator functions
PFNMAP may map to specific physical pages
PHY_IO may do physical i/o
PRMCEB may create permanent common event clusters
PRMGBL may create permanent global sections
PRMMBX may create permanent mailbox
PSWAPM may change process swap mode
READALL may read anything as the owner
SECURITY may perform security administration functions
SETPRV may set any privilege bit
SHARE may assign channels to non-shared devices
SHMEM may create/delete objects in shared memory
SYSGBL may create system wide global sections
SYSLCK may lock system wide resources
SYSNAM may insert in system logical name table
SYSPRV may access objects via system protection
TMPMBX may create temporary mailbox
UPGRADE may upgrade object integrity
VOLPRO may override volume protection
WORLD may affect other processes in the world

Process rights:
D_DEV resource
BATCH
ORA_DBA
REG_ADMIN
ORA_DEV1_DBA
MQM resource

System rights:
SYS$NODE_MILC2
Auto-unshelve: on
Image Dump: off
Soft CPU Affinity: off
Parse Style: Traditional
Case Lookup: Blind
Units: Blocks
Token Size: Traditional
Home RAD: 0
Scheduling class name: none

Process Dynamic Memory Area
Current Size (KB) 824.00 Current Size (Pagelets) 1648
Free Space (KB) 806.34 Space in Use (KB) 17.65
Largest Var Block (KB) 800.00 Smallest Var Block (bytes) 32
Number of Free Blocks 5 Free Blocks LEQU 64 bytes 1

There is 1 process in this job:

BATCH_8075 (*)

$ dir/full TMP_FTP.SFTP;

Directory DEV_EXE:[USER.D_DEV]

TMP_FTP.SFTP;4 File ID: (518,10,0)
Size: 1/121 Owner: [D_DEV]
Created: 30-JAN-2009 16:01:03.69
Revised: 30-JAN-2009 16:02:01.27 (3)
Expires:
Backup:
Effective:
Recording:
Accessed:
Attributes:
Modified:
Linkcount: 1
File organization: Sequential
Shelved state: Online
Caching attribute: Writethrough
File attributes: Allocation: 121, Extend: 0, Global buffer count: 0, No version limit
Record format: Stream_LF, maximum 255 bytes, longest 5 bytes
Record attributes: Carriage return carriage control
RMS attributes: None
Journaling enabled: None
File protection: System:RWED, Owner:RWED, Group:RWED, World:RWED
Access Cntrl List: None
Client attributes: None

Total of 1 file, 1/121 blocks.
$!
$ prc = f$environment( "procedure")
$ prc_dev_dir = f$parse( prc, , , "device")+ f$parse( prc, , , "directory")
$ set default DEV_EXE:[USER.D_DEV]
$ show def
DEV_EXE:[USER.D_DEV]
$!
$ SFTP "-D" "-B"SFTP_TMP.SLF "sftpFubar@somewhere.xxx.com"
Ssh2SftpServer/SSHFILEXFERS.C:2074: Received SSH_FXP_INIT
Ssh2SftpServer/SSHFILEXFERS.C:2119: version is 3
argv[0] = /sys$system/tcpip$ssh_ssh2
argv[1] = -v
argv[2] = -x
argv[3] = -a
argv[4] = -o
argv[5] = passwordprompt %U@%H's password:
argv[6] = -o
argv[7] = authenticationnotify yes
argv[8] = -o
argv[9] = BatchMode yes
argv[10] = sftpFubar@somewhere.xxx.com
argv[11] = -s
argv[12] = sftp
debug: Ssh2/SSH2.C:1885: CRTL version (SYS$SHARE:DECC$SHR.EXE ident) is V8.3-01
debug: SshAppCommon/SSHAPPCOMMON.C:313: Allocating global SshRegex context.
debug: SshConfig/SSHCONFIG.C:3427: Metaconfig parsing stopped at line 4.
debug: SshConfig/SSHCONFIG.C:869: Setting variable 'VerboseMode' to 'FALSE'.
debug: Connecting to somewhere.xxx.com, port 22... (SOCKS not used)
debug: Ssh2/SSH2.C:2861: Entering event loop.
debug: Ssh2Client/SSHCLIENT.C:1609: Creating transport protocol.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "hostbased" to usable methods.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "publickey" to usable methods.
debug: SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "password" to usable methods.
debug: Ssh2Client/SSHCLIENT.C:1650: Creating userauth protocol.
debug: client supports 3 auth methods: 'hostbased,publickey,password'
debug: SshUnixTcp/SSHUNIXTCP.C:1390: using local hostname MILC2.MAYO.EDU
debug: Ssh2Common/SSHCOMMON.C:541: local ip = 129.176.186.23, local port = 27198
debug: Ssh2Common/SSHCOMMON.C:543: remote ip = 65.164.45.25, remote port = 22
debug: SshConnection/SSHCONN.C:2311: Wrapping...
debug: Remote version: SSH-2.0-1.82 sshlib: WinSSHD 4.23
debug: Major: 1 Minor: 82 Revision: 0
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 20 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 30 to connection
debug: Ssh2Transport/TRCOMMON.C:2306: lang s to c: `', lang c to s: `'
debug: Ssh2Transport/TRCOMMON.C:2371: c_to_s: cipher aes128-cbc, mac hmac-sha1, compression none
debug: Ssh2Transport/TRCOMMON.C:2374: s_to_c: cipher aes128-cbc, mac hmac-sha1, compression none
debug: Remote host key found from database.
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 21 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 5 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Ssh2Common/SSHCOMMON.C:342: Received SSH_CROSS_STARTUP packet from connection protocol.
debug: Ssh2Common/SSHCOMMON.C:392: Received SSH_CROSS_ALGORITHMS packet from connection protocol.
debug: server offers auth methods 'publickey,password'.
debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:1677: adding keyfile "/DEV_EXE/user/d_dev/ssh2/ID_DSA_2048_A" o candidates
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Constructing and sending signature in publickey authentication.
debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:869: ssh_client_auth_pubkey_send_signature: reading DEV_EXE/user/d_dev/ssh2/ID_DSA_2048_A
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 50 to connection
debug: Ssh2AuthPubKeyClient/AUTHC-PUBKEY.C:1915: Public key authentication was successful.
debug: Ssh2Common/SSHCOMMON.C:310: Received SSH_CROSS_AUTHENTICATED packet from connection protocol.
debug: Ssh2Common/SSHCOMMON.C:852: num_channels now 1
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 90 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 98 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 2 to connection
debug: Ssh2Transport/TRCOMMON.C:1105: Sending packet with type 94 to connection

Error: Could not read the batchfile.
ssh_pipe_stream_destroy
%TCPIP-E-SSH_FC_ERROR, error in ssh file transfer operation
D_DEV job terminated at 30-JAN-2009 21:24:51.30


Thanks for the help so far. We've made progress. I thought once the authentication was solved, the rest would be easy...