On Sat, Jun 30, 2012 at 4:52 AM, Charles Marcus
<CMarcus at media-brokers.com> wrote:> On 2012-06-29 5:41 PM, Zac Israel <zac.israel at gmail.com> wrote:
>>
>> The system at 172.16.0.13 is a zimbra proxy. ?I can see in the logs
>> that it initially complains about my ssl cert, and if I remove
>> ssl=any-cert it fails because my cert is self signed, so I know it is
>> talking to the proxy and doing starttls which is a requirement of
>> zimbra. ?Unfortunately I have not found a way to see the full exchange
>> between dovecot and my zimbra proxy other than tcp dump, which just
>> shows a small packet exchange.
>
>
> And unfortunately you failed to provide critical evidence - in this case
the
> actual logs (and the tcpdump since you already have it) of a failed
session,
> rather than your interpretation of it. But at least you provided your
config
> (Timo is so good that often that is enough by itself, but even his crystal
> ball sometimes has problems).
>
> I have found over the years that if you are having a problem to the point
> that you need to ask for help, it is time to step back and take a fresh
look
> at *everything* - including having other eyes looking at *all* of the
> evidence.
>
> --
>
> Best regards,
>
> Charles
Very sorry for the omission, please find the dovecot logs and tcpdump
session attached. Please let me know if I can provide any other
information and thank you again for your time.
Zac
-------------- next part --------------
Jun 29 17:00:57 imap-test dovecot: master: Dovecot v2.0.19 starting up (core
dumps disabled)
Jun 29 17:00:58 imap-test dovecot: auth: Debug: Loading modules from directory:
/usr/lib/dovecot/modules/auth
Jun 29 17:00:58 imap-test dovecot: auth: Debug: auth client connected
(pid=31182)
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x10, ret=1:
before/accept initialization [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: before/accept initialization [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 read client hello A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write server hello A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write certificate A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write key exchange A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write server done A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 flush data [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 read client key exchange A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 read finished A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write session ticket A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write change cipher spec A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 write finished A [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2001,
ret=1: SSLv3 flush data [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x20, ret=1:
SSL negotiation finished successfully [127.0.0.1]
Jun 29 17:00:58 imap-test dovecot: imap-login: Warning: SSL: where=0x2002,
ret=1: SSL negotiation finished successfully [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: auth: Debug: client in: AUTH 1 PLAIN
service=imap secured lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=49940
resp=<hidden>
Jun 29 17:01:10 imap-test dovecot: auth: Debug: static(zac.israel at
domain.com,127.0.0.1): lookup
Jun 29 17:01:10 imap-test dovecot: auth: Debug: static(zac.israel at
domain.com,127.0.0.1): Allowing any password
Jun 29 17:01:10 imap-test dovecot: auth: Debug: client out: OK 1
user=zac.israel at domain.com proxy host=172.16.0.13 port=143 proxy_timeout=5
starttls=y ssl=any-cert pass=<hidden>
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x10, ret=1:
before/connect initialization [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: before/connect initialization [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: unknown state [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1002,
ret=-1: unknown state [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 read server hello A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Invalid certificate: self signed
certificate in certificate chain:
/C=US/ST=State/L=City/O=COMPANY/OU=IT/CN=COMPANY CA/emailAddress=it at
domain.com
Jun 29 17:01:10 imap-test dovecot: imap-login: Invalid certificate: unsupported
certificate purpose: /C=US/ST=State/L=City/O=COMPANY/OU=IT/CN=COMPANY
CA/emailAddress=it at domain.com
Jun 29 17:01:10 imap-test dovecot: imap-login: Invalid certificate: unable to
get certificate CRL:
/C=US/ST=State/L=City/O=COMPANY/OU=IT/CN=mail.int.domain.com
Jun 29 17:01:10 imap-test dovecot: imap-login: Invalid certificate: unable to
get certificate CRL: /C=US/ST=State/L=City/O=COMPANY/OU=IT/CN=COMPANY
CA/emailAddress=it at domain.com
Jun 29 17:01:10 imap-test dovecot: imap-login: Valid certificate:
/C=US/ST=State/L=City/O=COMPANY/OU=IT/CN=COMPANY CA/emailAddress=it at
domain.com
Jun 29 17:01:10 imap-test dovecot: imap-login: Valid certificate:
/C=US/ST=State/L=City/O=COMPANY/OU=IT/CN=mail.int.domain.com
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 read server certificate A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 read server key exchange A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 read server done A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 write client key exchange A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 write change cipher spec A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 write finished A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 flush data [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1002,
ret=-1: SSLv3 read server session ticket A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1002,
ret=-1: SSLv3 read server session ticket A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 read server session ticket A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1001,
ret=1: SSLv3 read finished A [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x20, ret=1:
SSL negotiation finished successfully [127.0.0.1]
Jun 29 17:01:10 imap-test dovecot: imap-login: Warning: SSL: where=0x1002,
ret=1: SSL negotiation finished successfully [127.0.0.1]
Jun 29 17:01:44 imap-test dovecot: imap-login: Warning: SSL alert: where=0x4008,
ret=256: warning close notify [127.0.0.1]
Jun 29 17:03:58 imap-test dovecot: imap-login: Disconnected: Inactivity (auth
failed, 1 attempts): user=<zac.israel at domain.com>, method=PLAIN,
rip=127.0.0.1, lip=127.0.0.1, TLS: Disconnected
Jun 29 17:03:58 imap-test dovecot: imap-login: Warning: SSL alert: where=0x4008,
ret=256: warning close notify [127.0.0.1]
-------------- next part --------------
root at imap-test:~# tcpdump -n -i eth0 host 172.16.0.13
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 65535 bytes
09:36:00.886811 ARP, Request who-has 172.16.0.13 tell 172.16.0.66, length 28
09:36:00.888071 ARP, Reply 172.16.0.13 is-at 00:50:56:b5:81:76, length 46
09:36:00.888088 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [S], seq
2509538212, win 14600, options [mss 1460,sackOK,TS val 41913867 ecr 0,nop,wscale
2], length 0
09:36:00.888456 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [S.], seq
703703456, ack 2509538213, win 14480, options [mss 1460,sackOK,TS val 3304080992
ecr 41913867,nop,wscale 7], length 0
09:36:00.888493 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [.], ack 1, win
3650, options [nop,nop,TS val 41913867 ecr 3304080992], length 0
09:36:00.889084 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [P.], seq 1:19,
ack 1, win 114, options [nop,nop,TS val 3304080993 ecr 41913867], length 18
09:36:00.889107 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [.], ack 19,
win 3650, options [nop,nop,TS val 41913867 ecr 3304080993], length 0
09:36:00.889372 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [P.], seq 1:13,
ack 19, win 3650, options [nop,nop,TS val 41913867 ecr 3304080993], length 12
09:36:00.889716 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [.], ack 13,
win 114, options [nop,nop,TS val 3304080993 ecr 41913867], length 0
09:36:00.889805 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [P.], seq
19:35, ack 13, win 114, options [nop,nop,TS val 3304080993 ecr 41913867], length
16
09:36:00.890583 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [P.], seq
13:239, ack 35, win 3650, options [nop,nop,TS val 41913868 ecr 3304080993],
length 226
09:36:00.896904 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [P.], seq
35:2546, ack 239, win 122, options [nop,nop,TS val 3304081000 ecr 41913868],
length 2511
09:36:00.896929 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [.], ack 2546,
win 4374, options [nop,nop,TS val 41913869 ecr 3304081000], length 0
09:36:00.902988 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [P.], seq
239:437, ack 2546, win 4374, options [nop,nop,TS val 41913871 ecr 3304081000],
length 198
09:36:00.907031 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [P.], seq
2546:2780, ack 437, win 130, options [nop,nop,TS val 3304081011 ecr 41913871],
length 234
09:36:00.908024 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [P.], seq
437:554, ack 2780, win 5098, options [nop,nop,TS val 41913872 ecr 3304081011],
length 117
09:36:00.908429 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [P.], seq
2780:3089, ack 554, win 130, options [nop,nop,TS val 3304081012 ecr 41913872],
length 309
09:36:00.946464 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [.], ack 3089,
win 5822, options [nop,nop,TS val 41913882 ecr 3304081012], length 0
09:38:45.491173 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [P.], seq
554:591, ack 3089, win 5822, options [nop,nop,TS val 41955018 ecr 3304081012],
length 37
09:38:45.491251 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [F.], seq 591,
ack 3089, win 5822, options [nop,nop,TS val 41955018 ecr 3304081012], length 0
09:38:45.494136 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [P.], seq
3089:3174, ack 592, win 130, options [nop,nop,TS val 3304245600 ecr 41955018],
length 85
09:38:45.494169 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [R], seq
2509538804, win 0, length 0
09:38:45.494176 IP 172.16.0.13.143 > 172.16.0.66.35641: Flags [F.], seq 3174,
ack 592, win 130, options [nop,nop,TS val 3304245600 ecr 41955018], length 0
09:38:45.494221 IP 172.16.0.66.35641 > 172.16.0.13.143: Flags [R], seq
2509538804, win 0, length 0
09:38:50.493026 ARP, Request who-has 172.16.0.66 tell 172.16.0.13, length 46
09:38:50.493057 ARP, Reply 172.16.0.66 is-at 00:50:56:b5:81:b0, length 28