Very Computer

I've installe SUSE 7.2 succesfully on my computer. Sendmail, fetchmail and
imapd are also konfigured and works fine. There are only two things, witch
are not so nice...

1. When i try to access the IMAP-Server from a WIN-Workstation with Outlook
Express it takes al long time (see the log below).

2. I cannot access the IMAP-Server with an eMail-Notifier tool. The Access
is not granted.

With hopes that you con help me...

Michael Consten

IMAP Log started at 08/10/2001 09:09:59
IMAP: 09:09:59 [db] Die Verbindung mit 'suse.moschoto.local' an Anschluss
143 wird hergestellt.
IMAP: 09:09:59 [db] OnNotify: asOld = 0, asNew = 4, ae = 0
IMAP: 09:09:59 [db] OnNotify: asOld = 4, asNew = 5, ae = 2
IMAP: 09:09:59 [db] OnNotify: asOld = 5, asNew = 5, ae = 4
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] * OK [CAPABILITY IMAP4 IMAP4REV1 STARTTLS
LOGIN-REFERRALS AUTH=LOGIN] suse.moschoto.local IMAP4rev1 2000.287 at Fri,
10 Aug 2001 09:06:22 +0200 (CEST)
IMAP: 09:10:00 [tx] 000X CAPABILITY
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] * CAPABILITY IMAP4 IMAP4REV1 STARTTLS NAMESPACE IDLE
MAILBOX-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT
MULTIAPPEND LOGIN-REFERRALS AUTH=LOGIN
IMAP: 09:10:00 [rx] 000X OK CAPABILITY completed
IMAP: 09:10:00 [tx] LOGIN command sent
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] * CAPABILITY IMAP4 IMAP4REV1 STARTTLS NAMESPACE IDLE
MAILBOX-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT
MULTIAPPEND
IMAP: 09:10:00 [rx] 000Y OK LOGIN completed
IMAP: 09:10:00 [tx] 000Z IDLE
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] + Ready for argument
IMAP: 09:10:00 [tx] DONE
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] 000Z OK IDLE completed
IMAP: 09:10:00 [tx] 0010 STATUS "Entw&APw-rfe" (MESSAGES UNSEEN)
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] * STATUS Entw&APw-rfe (MESSAGES 0 UNSEEN 0)
IMAP: 09:10:00 [rx] 0010 OK STATUS completed
IMAP: 09:10:00 [tx] 0011 IDLE
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] + Ready for argument
IMAP: 09:10:00 [tx] DONE
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] 0011 OK IDLE completed
IMAP: 09:10:00 [tx] 0012 STATUS "Gesendete Objekte" (MESSAGES UNSEEN)
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] * STATUS "Gesendete Objekte" (MESSAGES 11 UNSEEN 0)
IMAP: 09:10:00 [rx] 0012 OK STATUS completed
IMAP: 09:10:00 [tx] 0013 IDLE
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] + Ready for argument
IMAP: 09:10:00 [tx] DONE
IMAP: 09:10:00 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:00 [rx] 0013 OK IDLE completed
IMAP: 09:10:00 [tx] 0014 STATUS "INBOX" (MESSAGES UNSEEN)
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] * STATUS INBOX (MESSAGES 110 UNSEEN 0)
IMAP: 09:10:12 [rx] 0014 OK STATUS completed
IMAP: 09:10:12 [tx] 0015 IDLE
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] + Ready for argument
IMAP: 09:10:12 [tx] Dropping connection, LOGOUT sent
IMAP: 09:10:12 [db] Die Verbindung mit 'suse.moschoto.local' wurde beendet.
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 0, ae = 5

Microsoft Internet Messaging API 5.50.4522.1200
IMAP Log started at 08/10/2001 09:10:12
IMAP: 09:10:12 [db] Die Verbindung mit 'suse.moschoto.local' an Anschluss
143 wird hergestellt.
IMAP: 09:10:12 [db] OnNotify: asOld = 0, asNew = 4, ae = 0
IMAP: 09:10:12 [db] OnNotify: asOld = 4, asNew = 5, ae = 2
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 4
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] * OK [CAPABILITY IMAP4 IMAP4REV1 STARTTLS
LOGIN-REFERRALS AUTH=LOGIN] suse.moschoto.local IMAP4rev1 2000.287 at Fri,
10 Aug 2001 09:06:35 +0200 (CEST)
IMAP: 09:10:12 [tx] 0016 CAPABILITY
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] * CAPABILITY IMAP4 IMAP4REV1 STARTTLS NAMESPACE IDLE
MAILBOX-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT
MULTIAPPEND LOGIN-REFERRALS AUTH=LOGIN
IMAP: 09:10:12 [rx] 0016 OK CAPABILITY completed
IMAP: 09:10:12 [tx] LOGIN command sent
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] * CAPABILITY IMAP4 IMAP4REV1 STARTTLS NAMESPACE IDLE
MAILBOX-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT
MULTIAPPEND
IMAP: 09:10:12 [rx] 0017 OK LOGIN completed
IMAP: 09:10:12 [tx] 0018 IDLE
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] + Ready for argument
IMAP: 09:10:12 [tx] DONE
IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:12 [rx] 0018 OK IDLE completed
IMAP: 09:10:12 [tx] 0019 SELECT "INBOX"
IMAP: 09:10:24 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:24 [rx] * 110 EXISTS
IMAP: 09:10:24 [rx] * 0 RECENT
IMAP: 09:10:24 [rx] * OK [UIDVALIDITY 993623040] UID validity status
IMAP: 09:10:24 [rx] * OK [UIDNEXT 135] Predicted next UID
IMAP: 09:10:24 [rx] * FLAGS (\Answered \Flagged \Deleted \Draft \Seen)
IMAP: 09:10:24 [rx] * OK [PERMANENTFLAGS (\* \Answered \Flagged \Deleted
\Draft \Seen)] Permanent flags
IMAP: 09:10:24 [rx] 0019 OK [READ-WRITE] SELECT completed
IMAP: 09:10:24 [tx] 001A IDLE
IMAP: 09:10:24 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
IMAP: 09:10:24 [rx] + Ready for argument
IMAP: 09:10:24 [tx] Dropping connection, LOGOUT sent
IMAP: 09:10:24 [db] Die Verbindung mit 'suse.moschoto.local' wurde beendet.
IMAP: 09:10:24 [db] OnNotify: asOld = 5, asNew = 0, ae = 5

...

Quote:> 1. When i try to access the IMAP-Server from a WIN-Workstation with
> Outlook Express it takes al long time (see the log below).
...
> IMAP: 09:10:00 [rx] 0013 OK IDLE completed
> IMAP: 09:10:00 [tx] 0014 STATUS "INBOX" (MESSAGES UNSEEN)
> IMAP: 09:10:12 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
> IMAP: 09:10:12 [rx] * STATUS INBOX (MESSAGES 110 UNSEEN 0)
> IMAP: 09:10:12 [rx] 0014 OK STATUS completed
...
> IMAP: 09:10:12 [tx] 0019 SELECT "INBOX"
> IMAP: 09:10:24 [db] OnNotify: asOld = 5, asNew = 5, ae = 3
> IMAP: 09:10:24 [rx] * 110 EXISTS
> IMAP: 09:10:24 [rx] * 0 RECENT
> IMAP: 09:10:24 [rx] * OK [UIDVALIDITY 993623040] UID validity status
> IMAP: 09:10:24 [rx] * OK [UIDNEXT 135] Predicted next UID
> IMAP: 09:10:24 [rx] * FLAGS (\Answered \Flagged \Deleted \Draft \Seen)
> IMAP: 09:10:24 [rx] * OK [PERMANENTFLAGS (\* \Answered \Flagged \Deleted
> \Draft \Seen)] Permanent flags
> IMAP: 09:10:24 [rx] 0019 OK [READ-WRITE] SELECT completed

To know what exactly is timing out I suggest you use tcpdum or ethereal
(nice gui) to see what other network packets are going out during those 12
seconds.

With tcpdump: Install tcpdump, then "tcpdump -n".

The -n is important, otherwise tcpdump will generate dns queries, then log
its own dns queries and generate even more dns queries to do so, etc ad
infinite.

Or, use: "tcpdump -w some-output-file", and after the capture look at the
results with "tcpdump -r some-output-file".

Enrique Perez-Terron

Hi!,

Quote:> I've installe SUSE 7.2 succesfully on my computer. Sendmail, fetchmail and
> imapd are also konfigured and works fine. There are only two things, witch
> are not so nice...

Do you run a domain name server in the organisation, and if you do, does it
provide reverse DNS lookup facilities.  That is, given an IP address, can it
tell you the hostname of the connection.

See ya

Dean Thompson

--
+____________________________+____________________________________________+

| Bach. Computing (Hons)     | ICQ     - 45191180                         |
| PhD Student                | Office  - <Off-Campus>                     |
| School Comp.Sci & Soft.Eng | Phone   - +61 3 9903 2787 (Gen. Office)    |
| MONASH (Caulfield Campus)  | Fax     - +61 3 9903 1077                  |
| Melbourne, Australia       |                                            |
+----------------------------+--------------------------------------------+

here is the tcpdump.log, i think that the reverse look-up is fine...

For your understanding:

The eMail-Client is R17 at 192.168.0.101
eMail Server is Suse at 192.168.0.5
DNS-Server is Server at 192.168.0.1
the default gateway is set to 192.168.0.254
Router is a Bintec X1200 at 192.168.0.254
The IP 192.168.0.115 is another workstation.

I Hope you can help...

Thanks a lot.

Michael Consten
Cons...@Scholz-Starke.de

local domain is moschoto.local14:46:49.951206 192.168.0.254.bintec-admin >
192.168.0.255.bintec-admin: udp 354
14:46:50.121206 arp who-has suse.moschoto.local tell r17.moschoto.local
14:46:50.121206 arp reply suse.moschoto.local (0:80:c8:e2:67:be) is-at
0:80:c8:e2:67:be (0:50:ba:13:af:95)
14:46:50.121206 r17.moschoto.local.2150 > suse.moschoto.local.imap: S
639250577:639250577(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
14:46:50.121206 suse.moschoto.local.imap > r17.moschoto.local.2150: S
2974369005:2974369005(0) ack 639250578 win 5840 <mss 1460,nop,nop,sackOK>
(DF)
14:46:50.121206 r17.moschoto.local.2150 > suse.moschoto.local.imap: . 1:1(0)
ack 1 win 17520 (DF)
14:46:50.131206 suse.moschoto.local.1224 > r17.moschoto.local.ident: S
2977104568:2977104568(0) win 5840 <mss 1460,sackOK,timestamp 94736445
0,nop,wscale 0> (DF)
14:46:50.131206 r17.moschoto.local.ident > suse.moschoto.local.1224: R
0:0(0) ack 2977104569 win 0
14:46:50.191206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
1:153(152) ack 1 win 5840 (DF)
14:46:50.191206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
1:18(17) ack 153 win 17368 (DF)
14:46:50.191206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
153:153(0) ack 18 win 5840 (DF)
14:46:50.191206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
153:344(191) ack 18 win 5840 (DF)
14:46:50.191206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
18:51(33) ack 344 win 17177 (DF)
14:46:50.231206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
344:344(0) ack 51 win 5840 (DF)
14:46:50.241206 suse.moschoto.local.1043 > server.moschoto.local.domain:
22249+ PTR? 101.0.168.192.in-addr.arpa. (44) (DF)
14:46:50.241206 server.moschoto.local.domain > suse.moschoto.local.1043:
22249* 1/0/0 PTR r17.moschoto.local. (76)
14:46:50.241206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
344:503(159) ack 51 win 5840 (DF)
14:46:50.241206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
51:62(11) ack 503 win 17018 (DF)
14:46:50.241206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
503:503(0) ack 62 win 5840 (DF)
14:46:50.241206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
503:525(22) ack 62 win 5840 (DF)
14:46:50.241206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
62:68(6) ack 525 win 16996 (DF)
14:46:50.251206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
525:549(24) ack 68 win 5840 (DF)
14:46:50.251206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
68:114(46) ack 549 win 16972 (DF)
14:46:50.251206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
549:620(71) ack 114 win 5840 (DF)
14:46:50.251206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
114:125(11) ack 620 win 16901 (DF)
14:46:50.251206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
620:642(22) ack 125 win 5840 (DF)
14:46:50.251206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
125:131(6) ack 642 win 16879 (DF)
14:46:50.261206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
642:666(24) ack 131 win 5840 (DF)
14:46:50.261206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
131:182(51) ack 666 win 16855 (DF)
14:46:50.301206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
666:666(0) ack 182 win 5840 (DF)
14:46:50.451206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
666:745(79) ack 182 win 5840 (DF)
14:46:50.451206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
182:193(11) ack 745 win 16776 (DF)
14:46:50.451206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
745:745(0) ack 193 win 5840 (DF)
14:46:50.451206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
745:767(22) ack 193 win 5840 (DF)
14:46:50.451206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
193:199(6) ack 767 win 16754 (DF)
14:46:50.451206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
767:791(24) ack 199 win 5840 (DF)
14:46:50.451206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
199:238(39) ack 791 win 16730 (DF)
14:46:50.491206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
791:791(0) ack 238 win 5840 (DF)
14:46:51.421206 192.168.0.115.alta-ana-lm > 229.55.150.208.vpjp: udp 150
14:46:52.511206 0:a0:f9:2:b4:c0 Broadcast 8137 60:
14:46:54.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp
354
14:46:55.241206 arp who-has server.moschoto.local tell suse.moschoto.local
(0:80:c8:e2:67:be)
14:46:55.241206 arp reply server.moschoto.local is-at 0:80:c8:cd:29:71
(0:80:c8:e2:67:be)
14:46:59.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp
354
14:47:00.561206 arp who-has r11.moschoto.local tell server.moschoto.local
14:47:03.871206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
791:857(66) ack 238 win 5840 (DF)
14:47:03.871206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
238:249(11) ack 857 win 16664 (DF)
14:47:03.871206 suse.moschoto.local.imap > r17.moschoto.local.2150: .
857:857(0) ack 249 win 5840 (DF)
14:47:03.871206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
857:879(22) ack 249 win 5840 (DF)
14:47:03.871206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P
249:268(19) ack 879 win 16642 (DF)
14:47:03.871206 r17.moschoto.local.2150 > suse.moschoto.local.imap: F
268:268(0) ack 879 win 16642 (DF)
14:47:03.871206 suse.moschoto.local.imap > r17.moschoto.local.2150: P
879:903(24) ack 269 win 5840 (DF)
14:47:03.871206 r17.moschoto.local.2150 > suse.moschoto.local.imap: R
639250846:639250846(0) win 0 (DF)
14:47:03.881206 r17.moschoto.local.2151 > suse.moschoto.local.imap: S
642743352:642743352(0) win 16384 <mss 1460,nop,nop,sackOK> (DF)
14:47:03.881206 suse.moschoto.local.imap > r17.moschoto.local.2151: S
2995393546:2995393546(0) ack 642743353 win 5840 <mss 1460,nop,nop,sackOK>
(DF)
14:47:03.881206 r17.moschoto.local.2151 > suse.moschoto.local.imap: . 1:1(0)
ack 1 win 17520 (DF)
14:47:03.901206 suse.moschoto.local.1226 > r17.moschoto.local.ident: S
2994984792:2994984792(0) win 5840 <mss 1460,sackOK,timestamp 94737822
0,nop,wscale 0> (DF)
14:47:03.901206 r17.moschoto.local.ident > suse.moschoto.local.1226: R
0:0(0) ack 2994984793 win 0
14:47:03.961206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
1:153(152) ack 1 win 5840 (DF)
14:47:03.961206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
1:18(17) ack 153 win 17368 (DF)
14:47:03.961206 suse.moschoto.local.imap > r17.moschoto.local.2151: .
153:153(0) ack 18 win 5840 (DF)
14:47:03.961206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
153:344(191) ack 18 win 5840 (DF)
14:47:03.961206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
18:51(33) ack 344 win 17177 (DF)
14:47:04.001206 suse.moschoto.local.imap > r17.moschoto.local.2151: .
344:344(0) ack 51 win 5840 (DF)
14:47:04.001206 suse.moschoto.local.1043 > server.moschoto.local.domain:
39663+ PTR? 101.0.168.192.in-addr.arpa. (44) (DF)
14:47:04.001206 server.moschoto.local.domain > suse.moschoto.local.1043:
39663* 1/0/0 PTR r17.moschoto.local. (76)
14:47:04.001206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
344:503(159) ack 51 win 5840 (DF)
14:47:04.001206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
51:62(11) ack 503 win 17018 (DF)
14:47:04.001206 suse.moschoto.local.imap > r17.moschoto.local.2151: .
503:503(0) ack 62 win 5840 (DF)
14:47:04.001206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
503:525(22) ack 62 win 5840 (DF)
14:47:04.001206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
62:68(6) ack 525 win 16996 (DF)
14:47:04.001206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
525:549(24) ack 68 win 5840 (DF)
14:47:04.001206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
68:89(21) ack 549 win 16972 (DF)
14:47:04.041206 suse.moschoto.local.imap > r17.moschoto.local.2151: .
549:549(0) ack 89 win 5840 (DF)
14:47:04.061206 suse.moschoto.local.imap > r17.moschoto.local.2132: P
2364642956:2364642981(25) ack 492491374 win 6432 (DF)
14:47:04.061206 r17.moschoto.local.2132 > suse.moschoto.local.imap: P
1:20(19) ack 25 win 17398 (DF)
14:47:04.061206 r17.moschoto.local.2132 > suse.moschoto.local.imap: F
20:20(0) ack 25 win 17398 (DF)
14:47:04.081206 suse.moschoto.local.imap > r17.moschoto.local.2132: R
25:25(0) ack 21 win 6432 (DF)
14:47:04.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp
354
14:47:09.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp
354
14:47:11.431206 192.168.0.115.alta-ana-lm > 229.55.150.208.vpjp: udp 150
14:47:14.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp
354
14:47:17.731206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
549:892(343) ack 89 win 5840 (DF)
14:47:17.731206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
89:100(11) ack 892 win 16629 (DF)
14:47:17.731206 suse.moschoto.local.imap > r17.moschoto.local.2151: .
892:892(0) ack 100 win 5840 (DF)
14:47:17.731206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
892:914(22) ack 100 win 5840 (DF)
14:47:17.731206 r17.moschoto.local.2151 > suse.moschoto.local.imap: P
100:119(19) ack 914 win 16607 (DF)
14:47:17.731206 r17.moschoto.local.2151 > suse.moschoto.local.imap: F
119:119(0) ack 914 win 16607 (DF)
14:47:17.731206 suse.moschoto.local.imap > r17.moschoto.local.2151: P
914:938(24) ack 120 win 5840 (DF)
14:47:17.741206 r17.moschoto.local.2151 > suse.moschoto.local.imap: R
642743472:642743472(0) win 0 (DF)
14:47:18.501206 arp who-has 192.168.0.2 tell server.moschoto.local

read more »

...

Quote:> 14:46:50.451206 r17.moschoto.local.2150 > suse.moschoto.local.imap: P 199:238(39) ack 791 win 16730 (DF)
> 14:46:50.491206 suse.moschoto.local.imap > r17.moschoto.local.2150: . 791:791(0) ack 238 win 5840 (DF)
> 14:46:51.421206 192.168.0.115.alta-ana-lm > 229.55.150.208.vpjp: udp 150
> 14:46:52.511206 0:a0:f9:2:b4:c0 Broadcast 8137 60:
> 14:46:54.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp 354
> 14:46:55.241206 arp who-has server.moschoto.local tell suse.moschoto.local (0:80:c8:e2:67:be)
> 14:46:55.241206 arp reply server.moschoto.local is-at 0:80:c8:cd:29:71 (0:80:c8:e2:67:be)
> 14:46:59.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin: udp 354
> 14:47:00.561206 arp who-has r11.moschoto.local tell server.moschoto.local
> 14:47:03.871206 suse.moschoto.local.imap > r17.moschoto.local.2150: P 791:857(66) ack 238 win 5840 (DF)

The first delay takes place between 14.46.50.451206 and 14.47.03.871206.

At this point, the client has had a quick exchenge of messages with
the imap server, the client using port 2150.

The client has just sent a mesage of 39 bytes. I cannot tell what the
contents of this message was, only that 39 bytes seems too much for an
IDLE command.

So far the whole interchange has taken 0.33 seconds.

Now the imap server (suse) provides an ACK of those 39 bytes, but no
response. After 0.93 seconds other messages appear, but I cannot say
what they are, but they seem totally unrelated. At the end of the
delay the silence is broken by the server providing a response.

I think the intervening datagrams are most likely unrelated because
the mostly originate from other computers.

The 192.168.0.115 is, you say another workstation.  The ethernet
broadcast is from 0:a0:f9:2:b4:c0, while r17 has 0:50:ba:13:af:95,
according to the arp reply at 14.46.50.121206. Suse has
0:80:c8:e2:67:be.
Then there is an IP broadcast from the router.
Then Suse arps for the IP address of the dns server.
The router broadcasts again.
The dns server arps for the IP of r11.

I think it would be interesting to know what the request from r17 was
and perhaps what the answer was. Could that provide a clue?

If you still have the tcpdump -w file, you an get the first bytes of
each message (the tcp stream data) by adding the the option -a.  Be
warned that if you post it you could be posting a password that you
would rather kept secret.

The output of the -a option is not very pleasant though, as
the IP and TCP headers are included in the ascii output.

The typical structure of an IMAP request is a line with a tag, the a
command verb and possibly arguments. The tag is arbitrary, only that
each tag is used just once during each session. The server includes
the tag in the response, since it is possible to have several
outstanding requests and the client needs to know which request is
being answered. The server can also emit responses without requests,
in which case the tag is just a *. Sometimes a request is actually
answered with "*" responses while the formal tagged response just say
"done" or similar. (I do not remember the details.)

A typical exchange goes like this: (server responses are mostly
truncated as only part of the network packages have been logged)

S:* OK [CAPABILITY IMAP4 IMAP4REV1 STARTTLS LOGIN-REFERRALS AUTH=LOGIN] arabia.it-r.com IMAP
C:0000 CAPABILITY
S:* CAPABILITY IMAP4 IMAP4REV1 STARTTLS NAMESPACE IDLE MAILBOX-REFERRALS SCAN SORT THREAD=RE
C:0001 LOGIN "elisabeth" "trallala" (password mangled by me)
S:* CAPABILITY IMAP4 IMAP4REV1 STARTTLS NAMESPACE IDLE MAILBOX-REFERRALS SCAN SORT THREAD=RE
C:0002 IDLE
S:+ Ready for argument
C:DONE
S:0002 OK IDLE completed
C:0003 LIST "" ""
S:* LIST (\NoSelect) "/" ""
S:0003 OK LIST completed
C:0004 IDLE
S:+ Ready for argument
C:DONE
S:0004 OK IDLE completed
C:0005 LIST "" "INBOX"
S:* LIST (\NoInferiors) NIL INBOX
S:0005 OK LIST completed
C:0006 LSUB "" "*"
S:0006 OK LSUB completed
C:0007 IDLE
S:+ Ready for argument
C:DONE
S:0007 OK IDLE completed
C:0008 SELECT "INBOX"
S:* 10 EXISTS
S:* 0 RECENT
S:* OK [UIDVALIDITY 991687152] UID validity status
S:* OK [UIDNEXT 1
C:0009 UID FETCH 11:* (UID FLAGS RFC822.SIZE BODY.PEEK[HEADER] INTERNALDATE)
S:* 10 FETCH (UID 10 FLAGS (\Seen) RFC822.SIZE 3129 BODY[HEADER] {741}

C:000A UID FETCH 1:10 (UID FLAGS)
S:* 1 FETCH (UID 1 FLAGS (\Seen \Answered))
S:* 2 FETCH (UID 2 FLAGS (\Seen))
S:* 3 FETCH (UID000B NOOP
S:000B OK NOOP completed
C:000C IDLE
S:+ Ready for argument
C:DONE
C:ZZZZ LOGOUT
S:000C OK IDLE completed

Some of these commands requires imapd to scan potentially large
mailbox files to determine the number of messages, which have been
seen before, what are the subject lines, etc.

There are also commands that make imapd walk directory trees.

If you find out what the command is whose response is delayed it might
be a clue.

Yours Enrique

i don't understand what you mean with tcpdump with option -a; the output
i've posted is created with the command tcpdump -a -r .... what have i to do
else??

Thanks for your help...

Michael Consten

Quote:> > 14:46:50.491206 suse.moschoto.local.imap > r17.moschoto.local.2150: .

Quote:> > 14:46:51.421206 192.168.0.115.alta-ana-lm > 229.55.150.208.vpjp: udp 150
> > 14:46:52.511206 0:a0:f9:2:b4:c0 Broadcast 8137 60:
> > 14:46:54.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin:
udp 354
> > 14:46:55.241206 arp who-has server.moschoto.local tell

Quote:> > 14:46:55.241206 arp reply server.moschoto.local is-at 0:80:c8:cd:29:71
(0:80:c8:e2:67:be)
> > 14:46:59.941206 192.168.0.254.bintec-admin > 192.168.0.255.bintec-admin:
udp 354
> > 14:47:00.561206 arp who-has r11.moschoto.local tell

Quote:> > 14:47:03.871206 suse.moschoto.local.imap > r17.moschoto.local.2150: P

Quote:

> ...

> The first delay takes place between 14.46.50.451206 and 14.47.03.871206.

> At this point, the client has had a quick exchenge of messages with
> the imap server, the client using port 2150.

> The client has just sent a mesage of 39 bytes. I cannot tell what the
> contents of this message was, only that 39 bytes seems too much for an
> IDLE command.

> So far the whole interchange has taken 0.33 seconds.

> Now the imap server (suse) provides an ACK of those 39 bytes, but no
> response. After 0.93 seconds other messages appear, but I cannot say
> what they are, but they seem totally unrelated. At the end of the
> delay the silence is broken by the server providing a response.

> I think the intervening datagrams are most likely unrelated because
> the mostly originate from other computers.

> The 192.168.0.115 is, you say another workstation.  The ethernet
> broadcast is from 0:a0:f9:2:b4:c0, while r17 has 0:50:ba:13:af:95,
> according to the arp reply at 14.46.50.121206. Suse has
> 0:80:c8:e2:67:be.
> Then there is an IP broadcast from the router.
> Then Suse arps for the IP address of the dns server.
> The router broadcasts again.
> The dns server arps for the IP of r11.

> I think it would be interesting to know what the request from r17 was
> and perhaps what the answer was. Could that provide a clue?

> If you still have the tcpdump -w file, you an get the first bytes of
> each message (the tcp stream data) by adding the the option -a.  Be
> warned that if you post it you could be posting a password that you
> would rather kept secret.

> The output of the -a option is not very pleasant though, as
> the IP and TCP headers are included in the ascii output.

> The typical structure of an IMAP request is a line with a tag, the a
> command verb and possibly arguments. The tag is arbitrary, only that
> each tag is used just once during each session. The server includes
> the tag in the response, since it is possible to have several
> outstanding requests and the client needs to know which request is
> being answered. The server can also emit responses without requests,
> in which case the tag is just a *. Sometimes a request is actually
> answered with "*" responses while the formal tagged response just say
> "done" or similar. (I do not remember the details.)

> A typical exchange goes like this: (server responses are mostly
> truncated as only part of the network packages have been logged)

> S:* OK [CAPABILITY IMAP4 IMAP4REV1 STARTTLS LOGIN-REFERRALS AUTH=LOGIN]

Quote:>?Hi,

>?i don't understand what you mean with tcpdump with option -a; the output
>?i've posted is created with the command tcpdump -a -r .... what have i to
>?do else??

When I use tcpdump I get something like this:

21:31:36.180829 ppp0 < www.google.com.www > ti49a80-0227.bb.online.no.1033: S
1650517357:1650517357(0) ack 1667586319 win 15532 <mss 1412,sackOK,timestamp
261602290 118306,nop,wscale 0> (DF)

21:31:36.181042 ppp0 > ti49a80-0227.bb.online.no.1033 > www.google.com.www: .
1:1(0) ack 1 win 5808 <nop,nop,timestamp 118308 261602290> (DF)

? ? ? ? ? ? ? ? ? ? ? ? ?^O.. ....
21:31:36.181149 eth0 > PPPoE ?[ses 0x1637] ti49a80-0227.bb.online.no.1033 >
www.google.com.www: . 1:1(0) ack 1 win 5808 <nop,nop,timestamp 118308
261602290> (DF)

21:31:38.543793 ppp0 > ti49a80-0227.bb.online.no.1033 > www.google.com.www: P
1:447(446) ack 1 win 5808 <nop,nop,timestamp 118544 261602290> (DF)

? ? ? ? ? ? ? ? ? ? ? ? ?^O.. .... ?G E ?T ? ?/ s ?e a ?r c ?h ?
? ? ? ? ? ? ? ? ? ? ? ? ? q = ?l i ?n u ?x % ?2 0 ?r o ?u t ?i n
? ? ? ? ? ? ? ? ? ? ? ? ? g ? ?H T ?T P ?/ 1 ?. 1 ^M^J ?C o ?n n
? ? ? ? ? ? ? ? ? ? ? ? ? e c ?t i ?o n ?: ? ?K e ?e p ?- A ?l i
? ? ? ? ? ? ? ? ? ? ? ? ? v e ^M^J ?U s ?e r ?- A ?g e ?n t ?:
? ? ? ? ? ? ? ? ? ? ? ? ? M o
21:31:38.544744 eth0 > PPPoE ?[ses 0x1637] ti49a80-0227.bb.online.no.1033 >
www.google.com.www: P 1:447(446) ack 1 win 5808 <nop,nop,timestamp 118544
261602290> (DF)

? ? ? ? ? ? ? ? ? ? ? ? ? / s ?e a ?r c ?h ? ?q = ?l i ?n u ?x %
? ? ? ? ? ? ? ? ? ? ? ? ? 2 0 ?r o ?u t ?i n ?g ? ?H T ?T P ?/ 1
? ? ? ? ? ? ? ? ? ? ? ? ? . 1 ^M^J ?C o ?n n ?e c ?t i ?o n ?:
? ? ? ? ? ? ? ? ? ? ? ? ? K e ?e p ?- A ?l i ?v e ^M^J ?U s ?e r
? ? ? ? ? ? ? ? ? ? ? ? ? - A

Here there are blocks of ?ascii ?characters, representing the headers and
contents of the datagrams. The datagrams are truncated by default ?after 130
characters. This amount can be increased if you, during capture, have
specified the "-s 1550" option. (I.e., 1500 is an example, no datagrams on my
network is larger than ?about 1550 characters.

In the last message above you can see part of the HTTP request

I do not know why you did not get a similar output withthe same options. I
used:

???????? tcpdump -w /tmp/quique.out

and

???????? tcpdump -a -r /tmp/quique.out

I you use ethereal you do not have to specify ?any options. On the other hand
it seems like you cannot capture all interfaces at once in ethereal. You
would have to start several session to do that. On the other hand, with
ethereal you can right click on a tcp datagram and select "follow tcp
session", and ZAP!! there is a window with the whole interchange of messages
in that session, without headers or any other nuissances, and data in one
direction in a red font. Very nice.

I though about it after sending the last posting, that even if any particular
IMAP transaction type got pointed at, what should I say then? I am afraid
that I would not be muxh wiser. But this is perhaps where a newsgroup has its
stronges point, perhaps somebody else is following this thread and knows what
to do next.

If I had to solve the problem myself, lacking any deep Eurekas by the sight
of , e.g., an IMAP LIST command just before the 12-seconds delay, I would
start the imap daemon under surveilance of strace. This program logs all
system calls made by the inferior process, with time stamps and reasonable
indications of the parameters passed as well as the results.

Then I expect to see, e.g., the program doing a locking of a file, and
blocking for 10 seconds on that system call, or perhaps I would see 100000
directory scans... ?

I have never tries this specifically ?with imapd or with any other daemon.
I usually runstrace this way:

???????? strace -o outputfile command args...

Then I can tail the output file in another window, or wait for the program
completion.

The output looks like this:

open("/home/enrique/Trash", O_RDONLY) ? = 4
read(4, "From MAILER-DAEMON Mon Jun 18 00"..., 1023) = 1023
close(4) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
utime("/home/enrique/Trash", [2001/08/13-11:39:14, 2001/07/03-23:57:58]) = 0
stat64("/home/enrique/Trash", {st_mode=S_IFREG|0600, st_size=211270, ...}) = 0
open("/home/enrique/Trash", O_RDONLY) ? = 4
read(4, "From MAILER-DAEMON Mon Jun 18 00"..., 1023) = 1023
close(4) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
utime("/home/enrique/Trash", [2001/08/13-11:39:14, 2001/07/03-23:57:58]) = 0
alarm(0) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
alarm(0) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
time(NULL) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 997992941
alarm(0) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
alarm(0) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
alarm(0) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
alarm(0) ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?= 0
lstat64("/home/enrique/Trash.lock", 0xbfffd430) = -1 ENOENT (No such file or
directory)

Inthis case I just tried to have xinetd start "/usr/bin/strace -o
/tmp/inetd.strace ?/usr/sbin/imapd", but then xinetd complained.

Instead I wrote this shell script:

#!/bin/bash

Then I made it executable and directed xinetd (/etc/xinetd.d/imap) to use
this script as the "server".

What we see is only a little fraction of the output.
I was wrong w.r.t timestamps. There are none, execpt that imapd asks the
kernel about the time, and we see the answer in the log.

(There are options see the man page, to get timestamps)

We also see that imapd opens one of my mail folders, the Trash, but is does
only read the first block. (The stat system call revealed that the file size
was 211270, I have to see what I have there and empty it.)
The log also reveals that imapd tries to stat a lock file, but finds that the
file does not exist.

There are very many calls to alarm(0). Perhaps the program needs some
implrovement? Or is this somehow an effect of the delays introduced by strace?
Imapd runs noticeable slower now...

If you still want to work with this, I hope this can be some help.

Enrique.