SFTP colocado obtém EOF inesperado no arquivo 50M na primeira transferência do dia

Question

Estou executando o SFTP para colocar um arquivo em um novo cliente externo. Temos cerca de 10 outros clientes, alguns internos e outros externos, aos quais enviamos sem problemas. Este novo cliente está em uma VPN conosco (alguns de nossos outros clientes também estão em VPNs conosco, mas não todos) e responde a um comando put com um EOF após transmitir cerca de 40M de um arquivo 50M. Isso aconteceu em 10 das últimas 14 execuções.

Exceto por duas ocasiões, o EOF é recebido uma vez, na primeira execução do dia, por volta das 5:00 da manhã. Quando eu executo o SFTP novamente em poucos minutos, o comando put funciona e o arquivo completo é transmitido. Para o resto do dia, também funciona. Na mesma execução, também enviamos dois outros arquivos, um é 1M e o outro é 10M. Meu script classifica a lista de arquivos por tamanho de arquivo, para que os arquivos menores sejam enviados primeiro. Tudo isso está na mesma conexão. Meu script primeiro se conecta, envia a senha e garante que seja aceito, faz um diretório de mudança, comando ls e comando df. Em seguida, há um loop no script para colocar todos os arquivos listados. Os dois primeiros arquivos são colocados com sucesso e, em seguida, o terceiro é colocado, mas ele falha com um EOF.

Nas duas ocasiões que são a exceção, recebi um EOF na segunda tentativa e, em seguida, o put teve sucesso na terceira tentativa. No total, isso foi 10 das últimas 14 corridas. As outras quatro corridas funcionaram com sucesso na primeira vez (do dia). Esse trabalho é executado na mesma época (4:50 a 5:15). Eu falei com o cliente e mudei o tempo ligeiramente para contornar os intervalos que eles executam o processo de monitor de pasta. Mas isso não faz diferença.

Estamos executando o OpenSSH_6.0p1 no AIX 7.1 e eles estão executando o OpenSSH_7.4p1 no CentOS Linux 7.4. Duas vezes tentei executar o SFTP a partir da linha de comando com a opção verbose (-vvv) e o put funcionou nessas duas ocasiões. Vou atualizar meu script para de alguma forma capturar saída detalhada para um arquivo de log. Mas eu obtive este EOF tanto em um script quanto na linha de comando, então não acho que seja o script. E eu posso enviar dois outros arquivos primeiro ok, então não é apenas um problema com o primeiro arquivo enviado. E não é apenas um problema de tamanho de arquivo, mesmo que ele falhe apenas no arquivo 50M, porque funciona bem alguns minutos depois.

Então, algumas das minhas perguntas são: o que pode causar um EOF em uma operação de venda? Eu encontrei a especificação RFC da versão 2 para SFTP e não vejo menção de um EOF para operações put, apenas para obter operações. Pode haver algum processo em segundo plano no CentOS Linux que pode causar um EOF em uma grande transferência de arquivos? Demora cerca de 25 segundos para transmitir. Isso poderia ser um erro de rede? A qualidade da rede pode ser ruim no começo, mas depois de alguns minutos atualiza automaticamente para um nível mais alto de qualidade? O cliente está a 2700 milhas de distância. Obrigado por qualquer comentário. Peter

UPDATE: o fornecedor me enviou o registro de depuração de SFTP e não vejo nenhuma causa específica:

28745   debug1: request 786: write "/upload/X_Y_Z_file_20180315040147.txt" (handle 0) off 25329664 len 32768
28745   debug3: request 786: sent status 0
28745   sent status Success
28745   debug1: request 787: write "/upload/X_Y_Z_file_20180315040147.txt" (handle 0) off 25362432 len 32768
28745   debug3: request 787: sent status 0
28745   sent status Success
28745   debug1: request 788: write "/upload/X_Y_Z_file_20180315040147.txt" (handle 0) off 25395200 len 32768
28745   debug3: request 788: sent status 0
28745   sent status Success
28745   debug1: read eof
28745   forced close "/upload/X_Y_Z_file_20180315040147.txt" bytes read 0 written 25427968
28745   session closed for local user abc from [1.2.3.4]

Edit: Eu não acho que o meu script é o problema (mas eu sei como isso soa), porque eu recebo o mesmo problema se eu usar um script ou executar o comando SFTP a partir da linha de comando. O script usa EXPECT para interceptar a resposta SFTP, que é '100%' ou EOF ou TIMEOUT. Vou anexar o script assim que descobrir como fazer isso.

Edit: Aqui está o script para o sftp put:

#! /usr/bin/ksh
# The following line is seen as a continuecomment by Tcl\
exec $QUOVADX_INSTALL_DIR/integrator/bin/hcitcl "$0" ${1+"$@"}

# subroutines first
proc gts {} { 
   set tt [clock format [clock seconds] -format {%y/%m/%d %H:%M:%S} ]
   set ms [format %03d [expr {[clock clicks -milliseconds] % 1000}]]
   return $tt.$ms 
}

# proc to write to debug file
proc debugw {msg} {
  global debugfile
  set fh [open $debugfile a] ; puts $fh "$msg" ; close $fh
}


set frdir [lindex $argv 0]
set lfile [lindex $argv 1]
set todir [lindex $argv 2]
set site  [lindex $argv 3]

set debug $::env(cldebug)
set parmfile $::env(clparmfile)
set module "sftp_put_list"

# get debugfilename
if {$debug} {set debugfile [exec getdebugfile.tcl] ; global debugfile}
if {$debug} {debugw "[gts] $module start"}
if {$debug} {debugw "[gts] $module processing files in list $lfile"}

# get SFTP connection parms from parmfile using $site as key
set hfile [open $parmfile r] ; set data [read $hfile] ; close $hfile
set lList [split $data "\n"] ; set pos [lsearch -regexp $lList "^key_sftp_$site"]
lassign [split [lindex $lList $pos] " "] key port url pass
if {$debug > 1} {debugw "[gts] $module key: $key port $port url $url pass $pass"}

# url with vertical bar means the first part is the userid and second is the url
set userList [split "$url" "|"] ; lassign $userList user url
if {$debug} {debugw "[gts] $module userList: $userList"}
set ullen [llength $userList]
if {$debug} {debugw "[gts] $module userList length: $ullen"} 


log_user 0

# start/spawn the sftp process - either simple user url or separate user  
if {[llength $userList] eq 1} {
  set hname "$user"
  spawn /usr/bin/sftp -o Port=$port -o ConnectTimeout=60  $user 
  if {$debug} {debugw "[gts] $module connection uses simple user url $user"}
} else {
  set hname "$url"
  spawn /usr/bin/sftp -o Port=$port -o ConnectTimeout=60 -o User=$user $url
  if {$debug} {debugw "[gts] $module connection uses separate user $user and url $url"}
}

set pass_word_prompt "*?assword:*"
set sftp_prompt "*?ftp>"
set timeout 300

set sftp_put_timeout 1000
set prompt_timeout 300

#--------------------------------------------------------------
# first, wait for the password prompt - if a password is required!
#--------------------------------------------------------------
if {$pass ne "#"} {
  expect {
    eof {
       echo "sftp EOF waiting for password prompt|NA"
       if {$debug} {debugw "[gts] $module EOF received waiting for password prompt from $hname - exit 8"}
       exit 8
    }
    "$pass_word_prompt" {
       if {$debug} {debugw "[gts] $module password prompt received and answered"}
    }
    timeout {
       echo "sftp timeout waiting for password prompt|NA"
       if {$debug} {debugw "[gts] $module timeout waiting for password prompt from $hname - exit 8"}
       exit 8
    }
  }

  set timeout $prompt_timeout
  send "$pass\r"
  expect {
    eof {
      echo "sftp EOF waiting for command prompt after entering password|NA"
      if {$debug} {debugw "[gts] $module EOF received waiting for command prompt from $hname after entering password - exit 8"}
      exit 8
    }
    "$sftp_prompt" {
      if {$debug} {debugw "[gts] $module received command prompt; will enter LCD command"}
    }
    timeout {
      echo "sftp timeout after $prompt_timeout seconds waiting for command prompt after entering password|NA"
      if {$debug} {debugw "[gts] $module timeout after $prompt_timeout seconds waiting for command prompt from $hname after entering password - exit 8"}
      exit 8
    }
  }
} else {
  expect {
    eof {
      echo "sftp EOF waiting for command prompt after logging on|NA"
      if {$debug} {debugw "[gts] $module EOF received waiting for command prompt from $hname after logging on - exit 8"}
      exit 8
    }
    "$sftp_prompt" {
      if {$debug} {debugw "[gts] $module received command prompt; will enter LCD command"}
    }
    timeout {
      echo "sftp timeout after $prompt_timeout seconds waiting for command prompt after logging on|NA"
      if {$debug} {debugw "[gts] $module timeout after $prompt_timeout seconds waiting for command prompt from $hname after logging on - exit 8"}
      exit 8
    }
  }

}

#--------------------------------------------------------------
# lcd to local directory from where you will send the file(s)
#--------------------------------------------------------------
set timeout $prompt_timeout
send "lcd $frdir\r"
expect {
   eof {
     echo "sftp EOF waiting for command prompt after entering LCD|NA"
     if {$debug} {debugw "[gts] $module EOF received waiting for command prompt from $hname after entering LCD - exit 8"}
     exit 8
   }
   "$sftp_prompt" {
     if {$debug} {debugw "[gts] $module received command prompt after LCD ; will enter CD command"}
   }
   timeout {
     echo "sftp timeout after $prompt_timeout seconds waiting for command prompt after entering LCD|NA"
     if {$debug} {debugw "[gts] $module timeout after $prompt_timeout seconds waiting for command prompt from $hname after entering LCD - exit 8"}
     exit 8
   }
}

#--------------------------------------------------------------
# cd to remote directory where you will put the file(s)
#--------------------------------------------------------------
set timeout $prompt_timeout
send "cd $todir\r"
expect {
  eof {
    echo "sftp EOF waiting for command prompt after entering CD command|NA"
    if {$debug} {debugw "[gts] $module EOF received waiting for prompt from $hname after entering CD command - exit 8"}
    exit 8
  }
  "No such file or directory" {
    echo "remote directory $todir not found or not accessible|NA"
    if {$debug} {debugw "[gts] $module remote directory $todir not found or not accessible at $hname - exit 8"}
    exit 8
  }
  "$sftp_prompt" {
    if {$debug} {debugw "[gts] $module received command prompt after CD; will execute PWD command"}
  }
  timeout {
    echo "sftp timeout after $prompt_timeout seconds waiting for prompt after entering CD command|NA"
    if {$debug} {debugw "[gts] $module timeout after $prompt_timeou seconds waiting for command prompt from $hname after entering CD command - exit 8"}
    exit 8
  }
}


#--------------------------------------------------------------
# print working directory
#--------------------------------------------------------------
set timeout $prompt_timeout
send "pwd\r"
expect {
  eof {
    echo "sftp EOF waiting for command prompt after entering pwd command|NA"
    if {$debug} {debugw "[gts] $module EOF received waiting for prompt from $hname after entering pwd command - exit 8"}
    exit 8
  }
  "$sftp_prompt" {
    set response $expect_out(0,string)
    set rwd [lindex [split "$response" ":"] 1] 
    set rwd [lindex [split "$rwd" "\r" ] 0]
    if {$debug} {debugw "[gts] $module pwd: $rwd"}
    if {$debug} {debugw "[gts] $module received command prompt after PWD; will execute DIR command"}
  }
  timeout {
    echo "sftp timeout after $prompt_timeout seconds waiting for prompt after entering pwd command|NA"
    if {$debug} {debugw "[gts] $module timeout after $prompt_timeout seconds waiting for command prompt from $hname after entering pwd command - exit 8"}
    exit 8
  }
}

#--------------------------------------------------------------
# directory list
#--------------------------------------------------------------
set timeout $prompt_timeout
send "ls -l\r"
expect {
  eof {
    echo "sftp EOF waiting for command prompt after entering dir command|NA"
    if {$debug} {debugw "[gts] $module EOF received waiting for prompt from $hname after entering dir command - exit 8"}
    exit 8
  }
  "$sftp_prompt" {
    set response $expect_out(0,string)
    set dir [lrange [split "$response" "\r"] 1 end-1] 
    set dir [string map {\{ "" \} ""} "$dir"]
    set dir [string trim "$dir"]
    if {$debug} {debugw "[gts] $module dir: \r$dir"}
    if {$debug} {debugw "[gts] $module received command prompt after DIR; will execute PUT command"}
  }
  timeout {
    echo "sftp timeout after $prompt_timeout seconds waiting for prompt after entering dir command|NA"
    if {$debug} {debugw "[gts] $module timeout after $prompt_timeout seconds waiting for command prompt from $hname after entering dir command - exit 8"}
    exit 8
  }
}

#------------------------------------------------
# loop through list of files - put each file to remote sftp server
#------------------------------------------------
set hfile [open $lfile r] ; set data [read $hfile] ; close $hfile
set flist [string map {"\n" " "} "$data" ] ; set flist [string trim "$flist"] 
set flist [split $flist " "] ; set nfiles [llength $flist]
if {$debug} {debugw "[gts] $module $nfiles file names found in list file $lfile"}

set ct 0
while {$ct < $nfiles} {
  set nextfile [lindex $flist $ct]
  if {$debug} {debugw "[gts] $module starting SFTP Put for filename $nextfile"}
  set dct [expr $ct + 1]

  set timeout $sftp_put_timeout
  send "put $nextfile\r"
  expect {
    eof {
      set response $expect_out(0,string)
      echo "sftp EOF waiting for command prompt after entering put command|$nextfile"
      if {$debug} {debugw "[gts] $module put file $dct - $nextfile failed"}
      if {$debug} {debugw "[gts] $module EOF response from Put:\n$response"}
      if {$debug} {debugw "[gts] $module EOF received waiting for prompt from $hname after entering put command - exit 8"}
      exit 8
    }
    "100%*$sftp_prompt" {
      if {$debug} {debugw "[gts] $module received PUT 100% and command prompt after PUT"}
      if {$debug} {debugw "[gts] $module put file $dct - $nextfile succeeded"}
    }
    timeout {
      echo "sftp timeout after $sftp_put_timeout seconds waiting for prompt after entering put command|$nextfile"
      if {$debug} {debugw "[gts] $module timeout after $sftp_put_timeout seconds waiting for command prompt from $hname after entering put command - exit 8"}
      exit 8
    }
  }

  incr ct
}

#--------------------------------------------------------------
# post transfer directory list
#--------------------------------------------------------------
set timeout $prompt_timeout
send "ls -l\r"
expect {
  eof {
    echo "sftp EOF waiting for command prompt after entering dir command|NA"
    if {$debug} {debugw "[gts] $module EOF received waiting for prompt from $hname after entering dir command - exit 8"}
    exit 8
  }
  "$sftp_prompt" {
    set response $expect_out(0,string)
    set dir [lrange [split "$response" "\r"] 1 end-1] 
    set dir [string map {\{ "" \} ""} "$dir"]
    set dir [string trim "$dir"]
    if {$debug} {debugw "[gts] $module dir: \r$dir"}
    if {$debug} {debugw "[gts] $module received command prompt after dir; will execute QUIT command"}
  }
  timeout {
    echo "sftp timeout after $prompt_timeout seconds waiting for prompt after entering dir command|NA"
    if {$debug} {debugw "[gts] $module timeout after $prompt_timeout seconds waiting for command prompt from $hname after entering dir command - exit 8"}
    exit 8
  }
}

#---------------------------------------------------------
# sftp checks for spawn EOF and will terminate prematurely
# unless you add extra expect command
#---------------------------------------------------------
set timeout $prompt_timeout
send "quit\r"
expect {
  eof {
    if {$debug} {debugw "[gts] $module EOF expected and received after QUIT command|NA"}
    exit 0
  }
  "$sftp_prompt" {
    echo "unexpected sftp prompt after entering QUIT command - should be EOF|NA"
    if {$debug} {debugw "[gts] $module unexpected sftp prompt after entering QUIT command - should be EOF - exit 2"}
    exit 2
  }
  timeout {
    echo "sftp timeout after $prompt_timeout seconds waiting for EOF after QUIT command|NA"
    if {$debug} {debugw "[gts] $module sftp timeout after $prompt_timeout seconds waiting for EOF after QUIT command - exit 8"}
    exit 8
  }
}

exit 0