[Postfixbuch-users] warning: network_biopair_interop: error reading 5 bytes from the network

So Okt 24 15:35:36 CEST 2010

Hallo Kollegen!

Folgendes Szenario:

Mail-Client: 2.7.1-1 Debian Squeeze
Mail-Server: 2.5.5-1.1 Debian Lenny

Der Client liefert per TLS ein, der Server entscheidet anhand des
präsentierten Clientzertifikats über das Relaying (check_ccert_access).

Soweit funktioniert alles. Nur sehe ich nach erfolgter Kommunikation
im Logfile des Clients:

postfix/smtp[3538]: setting up TLS connection to mail.lab.swapon.de[2001:6f8:12ec:10::25]:25
postfix/smtp[3538]: Verified TLS connection established to mail.lab.swapon.de[2001:6f8:12ec:10::25]:25: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
postfix/smtp[3538]: 2184980532D: to=<fsn at lab.swapon.de>, orig_to=<root>, relay=mail.lab.swapon.de[2001:6f8:12ec:10::25]:25, delay=0.51, delays=0.07/0.01/0.33/0.09, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as BFB35131AA)
postfix/smtp[3538]: warning: network_biopair_interop: error reading 5 bytes from the network: Connection reset by peer

Auf dem Server sieht alles in Ordnung aus, keine Fehlermeldungen bzw.
Warnings sichtbar.

Nun habe ich mal einen tcpdump angefertigt:

  1   0.000000 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP 39580 > smtp [SYN] Seq=0 Win=5760 Len=0 MSS=1440 TSV=1454672 TSER=0 WS=7
  2   0.002347 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [SYN, ACK] Seq=0 Ack=1 Win=5712 Len=0 MSS=1440 TSV=795381212 TSER=1454672 WS=6
  3   0.002380 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP 39580 > smtp [ACK] Seq=1 Ack=1 Win=5760 Len=0 TSV=1454673 TSER=795381212
  4   0.065563 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 SMTP S: 220 mail.lab.swapon.de ESMTP Postfix
  5   0.065583 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP 39580 > smtp [ACK] Seq=1 Ack=39 Win=5760 Len=0 TSV=1454689 TSER=795381228
  6   0.065666 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 SMTP C: EHLO phoenix.lab.swapon.de
  7   0.066093 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [ACK] Seq=39 Ack=29 Win=5760 Len=0 TSV=795381228 TSER=1454689
  8   0.066109 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 SMTP S: 250-mail.lab.swapon.de | 250-PIPELINING | 250-SIZE 10240000 | 250-ETRN | 250-STARTTLS | 250-ENHANCEDSTATUSCODES | 250-8BITMIME | 250 DSN
  9   0.066186 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 SMTP C: STARTTLS
 10   0.066602 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 SMTP S: 220 2.0.0 Ready to start TLS
 11   0.067936 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 SSL Client Hello
 12   0.106074 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [ACK] Seq=200 Ack=1302 Win=8576 Len=0 TSV=795381239 TSER=1454689
 13   0.144959 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TLSv1 Server Hello, 
 14   0.145000 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TLSv1 Certificate, Server Key Exchange, Certificate Request, Server Hello Done
 15   0.145021 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP 39580 > smtp [ACK] Seq=1302 Ack=2932 Win=12544 Len=0 TSV=1454708 TSER=795381248
 16   0.154838 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP [TCP segment of a reassembled PDU]
 17   0.154877 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TLSv1 Certificate, Client Key Exchange, Certificate Verify, Change Cipher Spec, Encrypted Handshake Message
 18   0.155376 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [ACK] Seq=2932 Ack=2730 Win=11456 Len=0 TSV=795381251 TSER=1454711
 19   0.155411 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [ACK] Seq=2932 Ack=3638 Win=14336 Len=0 TSV=795381251 TSER=1454711
 20   0.184549 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TLSv1 Encrypted Handshake Message, Change Cipher Spec, Encrypted Handshake Message
 21   0.224971 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP 39580 > smtp [ACK] Seq=3638 Ack=4158 Win=15488 Len=0 TSV=1454728 TSER=795381258
 22   0.326873 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TLSv1 Application Data
 23   0.327928 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TLSv1 Application Data
 24   0.327965 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TCP 39580 > smtp [ACK] Seq=3707 Ack=4291 Win=18304 Len=0 TSV=1454754 TSER=795381294
 25   0.328175 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TLSv1 Application Data
 26   0.366085 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [ACK] Seq=4291 Ack=3808 Win=14336 Len=0 TSV=795381304 TSER=1454754
 27   0.372678 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TLSv1 Application Data
 28   0.372891 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TLSv1 Application Data
 29   0.373310 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [ACK] Seq=4376 Ack=4165 Win=17152 Len=0 TSV=795381305 TSER=1454766
 30   0.418930 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TLSv1 Application Data
 31   0.419126 2001:6f8:12ec:11::1024:0 -> 2001:6f8:12ec:10::25 TLSv1 Encrypted Alert
 32   0.419939 2001:6f8:12ec:10::25 -> 2001:6f8:12ec:11::1024:0 TCP smtp > 39580 [RST, ACK] Seq=4461 Ack=4202 Win=17152 Len=0 TSV=795381317 TSER=1454777

Sieht soweit alles super aus. Bis auf Paket 31. Der Client schickt ein
mysteriöses Alert und der Server schnappt ein und beendet sofort per Reset
die Verbindung.

Hat jemand eine Ahnung was da vorgeht und wie man das debuggen kann?
Google ist voll davon, aber weitergeholfen hat mir (bis jetzt) nichts.

Sorry für die lange Zeilenlänge.

mfg Friedemann