Broken Pipe while downloading a large file (errno2=0x76697242)

[jfwalker]

Our company sends datasets from the mainframe (IBM's zPDT mainframe emulator, which is running under Red Hat Linux, Server Edition) to an Ubuntu server using COZBATCH SFTP. Once in a while we receive a “Broken Pipe” message, but the file is successfully transferred on a rerun of the job.
However, we have a 100 Gb file that continues to get a Broken Pipe message after about 90 minutes of processing. Our data group tells us that that they regularly receive larger files from server-clients.
Initially we thought that the following parameters would solve the issue, but they have not.
ssh_opts="$ssh_opts -oServerAliveCountMax=9200"
ssh_opts="$ssh_opts -oServerAliveInterval=30"
We have tried everything we know to do without success. Anyone have any suggestions?

[dovetail]

Please post exactly the messages that you are receiving

[jfwalker]

Here is parts of STDERR. most of which I do not understand....
Please look at the line ending with "/jfw".

********************************* Top of Data *******************************
Co:Z SFTP version: 5.1.1 (6.4p1) 2018-06-01
Copyright (C) Dovetailed Technologies, LLC. 2008-2018. All rights reserved.
Connecting to 10.45.4.33...
[64.432] debug3: connect_to_server arg=/bin/ssh
[64.432] debug3: connect_to_server arg=-oForwardX11 no
[64.432] debug3: connect_to_server arg=-oForwardAgent no
[64.433] debug3: connect_to_server arg=-oClearAllForwardings yes
[64.433] debug3: connect_to_server arg=-v
[64.433] debug3: connect_to_server arg=-v
[64.433] debug3: connect_to_server arg=-v
[64.433] debug3: connect_to_server arg=-o
[64.434] debug3: connect_to_server arg=BatchMode=no
[64.434] debug3: connect_to_server arg=-o
[64.434] debug3: connect_to_server arg=Compression=yes
[64.434] debug3: connect_to_server arg=-o
[64.434] debug3: connect_to_server arg=ConnectTimeout=300
[64.434] debug3: connect_to_server arg=-o
[64.434] debug3: connect_to_server arg=ServerAliveCountMax=9200
[64.434] debug3: connect_to_server arg=-o
[64.434] debug3: connect_to_server arg=ServerAliveInterval=30
[64.434] debug3: connect_to_server arg=-o
[64.435] debug3: connect_to_server arg=StrictHostKeyChecking=no
[64.435] debug3: connect_to_server arg=-o
[64.435] debug3: connect_to_server arg=Port=22
[64.435] debug3: connect_to_server arg=-o
[64.435] debug3: connect_to_server arg=PasswordAuthentication=no
[64.435] debug3: connect_to_server arg=-o
[64.435] debug3: connect_to_server arg=PubkeyAuthentication=yes
[64.435] debug3: connect_to_server arg=-o
[64.435] debug3: connect_to_server arg=PreferredAuthentications=publickey
[64.435] debug3: connect_to_server arg=-obatchmode yes
[64.436] debug3: connect_to_server arg=-l
[64.436] debug3: connect_to_server arg=xxxxxxxx
[64.436] debug3: connect_to_server arg=-oProtocol 2
[64.436] debug3: connect_to_server arg=-s
[64.436] debug3: connect_to_server arg=--
[64.436] debug3: connect_to_server arg=10.45.4.33
[64.436] debug3: connect_to_server arg=sftp
OpenSSH_6.4, OpenSSL 1.0.1c 10 May 2012
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: zsshSmfSetConnSmfStatus: SMF status is 0
debug2: ssh_connect: needpriv 0
debug1: Connecting to 10.45.4.33 [10.45.4.33] port 22.
debug2: fd 3 setting O_NONBLOCK
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug1: cipher_init: none from source OpenSSL
debug1: cipher_init: none from source OpenSSL

debug3: timeout: 299998 ms remain after connect <---- what does this mean??? /jfw

...........
...........
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0
debug2: callback start
debug2: fd 3 setting TCP_NODELAY
debug2: client_session2_setup: id 0
debug1: Sending subsystem: sftp
debug2: channel 0: request subsystem confirm 1
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 2097152
debug2: channel_input_status_confirm: type 99 id 0
debug2: subsystem request accepted on channel 0
[67.883] debug2: Remote version: 3
[67.884] debug2: Server supports extension "posix-rename@openssh.com" revision 1
[67.884] debug2: Server supports extension "statvfs@openssh.com" revision 2
[67.884] debug2: Server supports extension "fstatvfs@openssh.com" revision 2
[67.884] debug2: Server supports extension "hardlink@openssh.com" revision 1
[67.884] debug2: Unrecognised server extension "fsync@openssh.com"
Connected to 10.45.4.33.
Connection established, local_addr=10.45.3.50 local_port=1791 remote_addr=10.45.
[68.118] debug3: Sent message fd 7 T:16 I:0
[68.122] debug3: SSH_FXP_REALPATH . -> /home/fwalker size 0
[68.127] debug3: Sending SSH2_FXP_READDIR I:2
[68.141] debug3: Received reply T:104 I:2
[68.142] debug3: Received 8 SSH2_FXP_NAME responses
[68.142] debug3: Sending SSH2_FXP_READDIR I:3
[68.146] debug3: Received reply T:101 I:3
[68.146] debug3: Received SSH2_FXP_STATUS 1
[68.146] debug3: Sent message SSH2_FXP_CLOSE I:4
[68.150] debug3: SSH2_FXP_STATUS 0
[68.151] debug3: Sent message fd 7 T:16 I:5
[68.155] debug3: SSH_FXP_REALPATH /data/datat033a/clienthome/abc/efgxxxxxxx
[68.155] debug3: Sent message fd 7 T:17 I:6
[68.159] debug3: Received stat reply T:105 I:6
[68.160] debug3: Sent message fd 7 T:17 I:7
[68.164] debug3: Received stat reply T:101 I:7
[68.164] debug1: Couldn't stat remote file: No such file or directory
ZosSettings: Transfer options: clientcp=IBM-1047,mode=text,servercp=ISO8859-1
ZosDataset: Opening dataset DD:TESTFILE for read
[68.206] debug3: Sent message SSH2_FXP_OPEN I:8 O:x1a P:/data/datat033a/clientho
[68.212] debug3: Sent message SSH2_FXP_WRITE I:9 O:0 S:32768
[68.225] debug3: SSH2_FXP_STATUS 0
[68.225] debug3: In write loop, ack for 9 32768 bytes at 0
[68.227] debug3: Sent message SSH2_FXP_WRITE I:10 O:32768 S:32768
[68.228] debug3: Sent message SSH2_FXP_WRITE I:11 O:65536 S:32768
[68.229] debug3: Sent message SSH2_FXP_WRITE I:12 O:98304 S:32768
[68.237] debug3: Sent message SSH2_FXP_WRITE I:13 O:131072 S:32768
[68.246] debug3: Sent message SSH2_FXP_WRITE I:14 O:163840 S:32768
[68.251] debug3: Sent message SSH2_FXP_WRITE I:15 O:196608 S:32768
debug2: channel 0: rcvd adjust 98891

[68.260] debug3: Sent message SSH2_FXP_WRITE I:16 O:229376 S:32768
[68.269] debug3: Sent message SSH2_FXP_WRITE I:17 O:262144 S:32768
[68.273] debug3: Sent message SSH2_FXP_WRITE I:18 O:294912 S:32768
[68.283] debug3: Sent message SSH2_FXP_WRITE I:19 O:327680 S:32768
debug2: channel 0: rcvd adjust 114688

[68.292] debug3: Sent message SSH2_FXP_WRITE I:20 O:360448 S:32768
[68.296] debug3: Sent message SSH2_FXP_WRITE I:21 O:393216 S:32768
[68.305] debug3: Sent message SSH2_FXP_WRITE I:22 O:425984 S:32768
debug2: channel 0: rcvd adjust 114688

[68.316] debug3: Sent message SSH2_FXP_WRITE I:23 O:458752 S:32768
[68.319] debug3: Sent message SSH2_FXP_WRITE I:24 O:491520 S:32768
[68.325] debug3: Sent message SSH2_FXP_WRITE I:25 O:524288 S:32768
[68.335] debug3: Sent message SSH2_FXP_WRITE I:26 O:557056 S:32768
[68.336] debug3: Sent message SSH2_FXP_WRITE I:27 O:589824 S:32768
debug2: channel 0: rcvd adjust 114688
...................
..................
[68.582] debug3: Sent message SSH2_FXP_WRITE I:73 O:2097152 S:32768
[68.591] debug3: Sent message SSH2_FXP_WRITE I:74 O:2129920 S:32768
[68.591] debug3: SSH2_FXP_STATUS 0
[68.591] debug3: In write loop, ack for 10 32768 bytes at 32768
[68.592] debug3: Sent message SSH2_FXP_WRITE I:75 O:2162688 S:32768
[68.592] debug3: SSH2_FXP_STATUS 0
[68.592] debug3: In write loop, ack for 11 32768 bytes at 65536
[68.593] debug3: Sent message SSH2_FXP_WRITE I:76 O:2195456 S:32768
[68.593] debug3: SSH2_FXP_STATUS 0
[68.593] debug3: In write loop, ack for 12 32768 bytes at 98304
debug2: channel 0: rcvd adjust 147456
......................
.........................
at line 8,281,909

[03.970] debug3: Sent message SSH2_FXP_WRITE I:2321427 O:76068225024 S:32768
[03.970] debug3: SSH2_FXP_STATUS 0
[03.970] debug3: In write loop, ack for 2321363 32768 bytes at 76066127872
[03.971] debug3: Sent message SSH2_FXP_WRITE I:2321428 O:76068257792 S:32768
[03.971] debug3: SSH2_FXP_STATUS 0
[03.971] debug3: In write loop, ack for 2321364 32768 bytes at 76066160640
[03.982] debug3: Sent message SSH2_FXP_WRITE I:2321429 O:76068290560 S:32768
[03.982] debug3: SSH2_FXP_STATUS 0
[03.982] debug3: In write loop, ack for 2321365 32768 bytes at 76066193408
[03.982] debug3: Sent message SSH2_FXP_WRITE I:2321430 O:76068323328 S:32768
[03.983] debug3: SSH2_FXP_STATUS 0
[03.983] debug3: In write loop, ack for 2321366 32768 bytes at 76066226176
[03.983] debug3: Sent message SSH2_FXP_WRITE I:2321431 O:76068356096 S:32768
debug3: __catgets: NLS setup complete (1), using message catalog openssh.cat

FOTS1933 Write failed: EDC5140I Broken pipe. (errno2=0x76697242)

[18.203] Connection closed
******************************** Bottom of Data ********************************

[dovetail]

This error indicates that z/OS OpenSSH got a write error on its socket:

FOTS1933 Write failed: EDC5140I Broken pipe. (errno2=0x76697242)

If you look up the reason code:
> bpxmtext 76697242
TCPIP
JRConnTCBNotFound: A TCB was not found for the specified socket.

Action: Use a valid socket descriptor.

This isn't really that helpful, but it seems to mean that the socket was reset.

You might have to contact IBM for more information on how to find out what happened to the socket.
Another option would be to post a question on the IBM TCP list: IBMTCP-L@vm.marist.edu

[jfwalker]

Thanks for the information and link.

[dovetail]

Since it seems like you might have a networking problem under zPDT, you might also try the zPDT newsgroup:

z1090@yahoogroups.com

[giltjr]

Do you see any message in z/OS syslog about a task abending or being canceled? If it is always after 90 minutes, there could be some time limit and the task is being canceled.