sshd write failed

[Rasmus Kaj]

lör 2012-01-28 klockan 19:53 +0100 skrev Rasmus Kaj:
> Jag har råkat ut för ett märkligt problem med sshd på FreeBSD 8.2.  När
> jag för över större filer säger avbryts kopplingen plötsligt mitt i.
> 

Efter att ha provat att köra servern i debugläge var ju nästa naturliga
steg att köra ktrace på sshd.  Mycket riktigt är det ett write-anrop som
får permission denied.   Vad jag begriper så är det som ska skrivas helt
enkelt data till socketen.

En sak som kan vara intressant är att write har misslyckats några gånger
innan dess, med errno 35 Resource temporarily unavailable.

Här kommer anrop och returer från write från en lämplig del av ktracen:

  4609 sshd     CALL  write(0x3,0x801e65000,0x60)
  4609 sshd     RET   write 96/0x60
  4609 sshd     CALL  write(0x3,0x801e65000,0x40)
  4609 sshd     RET   write 64/0x40
  4609 sshd     CALL  write(0x8,0x801e72000,0x1)
  4609 sshd     RET   write 1
  4610 scp      CALL  write(0x1,0x80184a000,0x20000)
  4610 scp      RET   write 65536/0x10000
  4610 scp      CALL  write(0x1,0x80185a000,0x10000)
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4610 scp      CALL  write(0x1,0x80185a000,0x10000)
  4610 scp      RET   write 16384/0x4000
  4610 scp      CALL  write(0x1,0x80185e000,0xc000)
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4610 scp      CALL  write(0x1,0x80185e000,0xc000)
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4610 scp      RET   write 16384/0x4000
  4610 scp      CALL  write(0x1,0x801862000,0x8000)
  4609 sshd     RET   write 16432/0x4030
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4610 scp      CALL  write(0x1,0x801862000,0x8000)
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4610 scp      RET   write 16384/0x4000
  4609 sshd     RET   write 16432/0x4030
  4610 scp      CALL  write(0x1,0x801866000,0x4000)
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4610 scp      CALL  write(0x1,0x801866000,0x4000)
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4610 scp      RET   write 16384/0x4000
  4609 sshd     RET   write 6232/0x1858
  4610 scp      CALL  write(0x1,0x80184a000,0x20000)
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4610 scp      CALL  write(0x1,0x80184a000,0x20000)
  4609 sshd     CALL  write(0x3,0x801e85858,0x6808)
  4610 scp      RET   write 16384/0x4000
  4610 scp      CALL  write(0x1,0x80184e000,0x1c000)
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4609 sshd     RET   write 26632/0x6808
  4610 scp      CALL  write(0x1,0x80184e000,0x1c000)
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4609 sshd     RET   write -1 errno 13 Permission denied
  4610 scp      RET   write 16384/0x4000
  4610 scp      CALL  write(0x1,0x801852000,0x18000)
  4610 scp      RET   write -1 errno 35 Resource temporarily unavailable
  4610 scp      CALL  write(0x1,0x801852000,0x18000)
  4610 scp      RET   write -1 errno 32 Broken pipe

Om jag har fattat rätt hur det hänger ihop så skriver "scp" det data som
ska föras över på sin stdout (0x1), vilket läses av "sshd" som krypterar
datat och skriver det på nätsocketen (0x3).  De gånger scp får Resource
temporarily unavailable är det sshd som inte har hunnit få iväg det den
fick förra gången än.  Tittar man bara på write från sshd ser man:

  4609 sshd     RET   write 64/0x40
  4609 sshd     CALL  write(0x8,0x801e72000,0x1)
  4609 sshd     RET   write 1
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4609 sshd     RET   write 16432/0x4030
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4609 sshd     RET   write 16432/0x4030
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4609 sshd     RET   write 6232/0x1858
  4609 sshd     CALL  write(0x3,0x801e85858,0x6808)
  4609 sshd     RET   write 26632/0x6808
  4609 sshd     CALL  write(0x3,0x801e84000,0x4030)
  4609 sshd     RET   write -1 errno 13 Permission denied

Den skriver ett par block om 0x4030 om går bra, sen skriver den ett till
och får inte iväg hela.  Sen skriver den det som blev över av det
blocket tillsammans med nästa block (0x6808) och det går bra.  Sen
skriver den ett block till och får plötsligt permission denied.  Varför
det?  Fortfarande ingen aning ...

// Rasmus