Backups intermittently fail with status 24 or 42 within a few seconds of the start of data transfer.

Problem

Some backup streams on the client will unexpectedly report a broken socket while the media server processes are still preparing the media to receive the backup image.  

During the early moments of a backup, the client will begin sending data. If the media server process is not yet at a point where it can accept the data, the TCP SO_RCVBUF space on the remote host will fill and the TCP Window will close.    In turn, the TCP SO_SNDBUF space on the local host will also fill and the next write to the socket will block.

Such delays are normal, and when the remote application is ready for (more) data, the SO_RCVBUF space will empty and a TCP Window Update will be sent to the local host so that it can again begin transmitting data on the socket.   If the remote application delays an excessively long time, then the TCP stack will abort the socket and the blocked write will return errno 32 = EPIPE.   But on this host, the EPIPE is sometimes being returned after a delay of only 1 - 3 seconds, but not always.

Error Message

The job details display one of two symptoms depending on the timing. 

Typically the failure will appear as a status 24 because the client will report the failure to bpbrm while bptm is still getting the media ready. 

10/21/2010 11:29:21 - started process bpbrm (pid=3462)

10/21/2010 11:29:29 - Error bpbrm (pid=3462) from client myclient: ERR - Cannot write to STDOUT. Errno = 32: Broken pipe

10/21/2010 11:29:25 - connecting

10/21/2010 11:29:25 - connected; connect time: 0:00:00

10/21/2010 11:29:34 - Error bptm (pid=3464) media manager terminated by parent process

10/21/2010 11:29:35 - end writing

socket write failed (24)  

The failure may also appear as a status 42 if, during the time when bpbkar is receiving the error and informing bpbrm, bptm finishes readying the media, reads the available data, and receives a TCP RESET from the client host in response to the TCP Window Update. 

10/21/2010 8:41:32 AM - Error bptm(pid=4236) unable to perform read from client socket, connection may have been broken

10/21/2010 8:41:43 AM - end writing; write time: 00:00:01

network read failed(42)

Cause

The bpbkar debug log confirms that the first few files were read and the associated meta data passed to bpbrm.  The first part of the tar image will also be written on the socket to bptm.  The number of files that will be read depends on their size and the amount of TCP buffer space available on the hosts.  But the main clue is the short elapse time relative to the start of the data transfer. 

12:56:35.428 [12587] <4> bpbkar PrintFile: /

12:56:35.440 [12587] <4> bpbkar PrintFile: /opt/

...snip...

12:56:36.168 [12587] <4> bpbkar PrintFile: /opt/OV/nonOV/perl/a/lib/5.8.8/pod/perlopenbsd.pod

12:56:36.170 [12587] <4> bpbkar PrintFile: /opt/OV/nonOV/perl/a/lib/5.8.8/pod/perlopentut.pod

12:56:40.702 [12587] <16> flush_archive(): ERR - Cannot write to STDOUT. Errno = 32: Broken pipe

12:56:40.706 [12587] <16> bpbkar Exit: ERR - bpbkar FATAL exit status = 24: socket write failed

12:56:40.711 [12587] <4> bpbkar Exit: INF - EXIT STATUS 24: socket write failed

A truss of bpbkar confirms that the O/S returned EPIPE about 3 seconds after the attempt to write to the socket to bptm.  Notice that meta data is written successfully to the bpbrm socket before the failure and that the error message is sent successfully after the failure. 

12587/1:    18.2276 write(2, " F i l   -   0   3 1   9".., 99)  = 99

12587/1:    write(1, 0x00296A90, 524288)    (sleeping...)

12587/1:    21.7892 write(1, " d l e s   t o   S T D I".., 524288)  Err#32 EPIPE

12587/1:    21.8210 write(2, " E R R   -  ", 6)         = 6

12587/1:    21.8221 write(2, " C a n n o t   w r i t e".., 47)  = 47

12587/1:    21.8231 write(2, "\n", 1)               = 1

12587/1:    21.8296 write(2, " I N F   -  ", 6)         = 6

12587/1:    21.8305 write(2, " E X I T   S T A T U S  ".., 35)  = 35

12587/1:    21.8315 write(2, "\n", 1)               = 1

12587/1:    21.8325 close(1)                    = 0  

A network trace confirms that the O/S raised the EPIPE during a brief pause before the TCP Window reopened.  Notice that a TCP RESET or FIN was not received from the network, but that the client host does send back a TCP RESET after the TCP Window Update is received.  This will affect bptm if it has not already been stopped by bpbrm.

833 12:56:37.17026 3.3.3.3 -> 2.2.2.2 TCP D=662 S=13782 Ack=3625715306 Seq=3009467682 Len=1460 Win=49640

834 12:56:37.17031 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009447242 Seq=3625715306 Len=0 Win=22064

835 12:56:37.17056 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009450162 Seq=3625715306 Len=0 Win=19144

836 12:56:37.17056 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009453082 Seq=3625715306 Len=0 Win=16224

837 12:56:37.17057 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009456002 Seq=3625715306 Len=0 Win=13304

838 12:56:37.17057 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009458922 Seq=3625715306 Len=0 Win=10384

839 12:56:37.17076 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009461842 Seq=3625715306 Len=0 Win=7464

840 12:56:37.17077 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009464762 Seq=3625715306 Len=0 Win=4544

841 12:56:37.17097 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009467682 Seq=3625715306 Len=0 Win=1624

843 12:56:37.29786 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 Ack=3009469142 Seq=3625715306 Len=0 Win=164

844 12:56:37.76184 3.3.3.3 -> 2.2.2.2 TCP D=662 S=13782 [TCP Window Full] Push Ack=3625715306 Seq=3009469142 Len=164 Win=49640

845 12:56:37.87913 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 [TCP ZeroWindow] Ack=3009469306 Seq=3625715306 Len=0 Win=0

846 12:56:38.23173 3.3.3.3 -> 2.2.2.2 TCP D=662 S=13782 [TCP ZeroWindowProbe] Push Ack=3625715306 Seq=3009469306 Len=1 Win=49640

847 12:56:38.23223 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 [TCP ZeroWindowProbeAck] Ack=3009469306 Seq=3625715306 Len=0 Win=0

848 12:56:38.70180 3.3.3.3 -> 2.2.2.2 TCP D=662 S=13782 [TCP ZeroWindowProbe] Ack=3625715306 Seq=3009469306 Len=1 Win=49640

849 12:56:38.70210 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 [TCP ZeroWindowProbeAck] Ack=3009469306 Seq=3625715306 Len=0 Win=0

… point at which the client O/S returned EPIPE for the write …

… just one second before the media server was ready for more data …

861 12:56:41.44654 2.2.2.2 -> 3.3.3.3 TCP D=13782 S=662 [TCP Window Update] Ack=3009469306 Seq=3625715306 Len=0 Win=49640

… but the client host O/S returns a TCP RESET because it has already aborted the socket …

862 12:56:41.45176 3.3.3.3 -> 2.2.2.2 TCP D=662 S=13782 Rst Seq=3009469306 Len=0 Win=0

The bpbrm debug log confirms that it received meta data from bpbkar then, after a 2.4 second delay, it receives the error indication from bpbkar.  At which point bpbrm requested that the bptm child also be stopped.

12:56:36.477 [26651] <2> bpbrm main: ADDED FILES TO DB FOR myclient_1284584988 1 /opt/oracle/

12:56:40.878 [26651] <16> bpbrm main: from client myclient: ERR - Cannot write to STDOUT. Errno = 32: Broken pipe

...snip...

12:56:41.644 [26651] <2> bpbrm main: client myclient EXIT STATUS = 24: socket write failed

12:56:41.644 [26651] <2> bpbrm kill_child_process: start

12:56:41.644 [26651] <2> bpbrm wait_for_child: start

12:56:45.738 [26651] <2> bpbrm wait_for_child: child exit_status = 82 signal_status = 0

The bptm debug log confirms that it is still getting the disk storage setup at the time that the time bpbrm sends the signal one to cause termination.  It had not attempted to yet read from the socket.

12:56:45.810 [26667] <2> get_plugin_version: libstspibasicdisk.so (AdvancedDisk:==AdvancedDisk) build=10.0 operating=10 vendor <>

12:56:45.811 [26667] <2> bp_sts_open_server: plugin version = 10

12:56:45.813 [26667] <2> bptm: STS attach host is myserver

12:56:45.994 [26667] <2> logconnections: BPDBM CONNECT FROM 2.2.2.2.47620 TO 1.1.1.1.13724

12:56:46.514 [26667] <2> logconnections: BPDBM CONNECT FROM 2.2.2.2.47622 TO 1.1.1.1.13724

12:56:46.855 [26667] <2> Media_dispatch_signal: calling catch_signal for 1 (bptm.c:19485) delay 1 seconds

...snip...

12:56:47.710 [26667] <2> catch_signal: EXITING with status 82

Repeated evidence gathering showed that the client host O/S only raised the EPIPE when the TCP Window Full condition was present, typically 3 - 8 seconds after the window closed.

Solution

This problem was resolved on multiple client hosts by stopping and restarting the inetd process via the Service Management Facility.   On two of the client hosts, the entire host needed to be rebooted to resolve the problem.

The precise root cause was not available, but it is likely that at the time inetd was last started, there was an unusual and incompatible combination of TCP and/or kernel tunables in place.   One or more of the setting must have been changed to a compatible value before the problem was noticed because all settings appeared normal during debugging.   However, the restarted instance of inetd clearly picked up a better environment than the prior instance.

Applies To

This problem was observed during the initial build/installation of new logical domains on Solaris 10 using the vnet1:1 network interface.