Weird problem with user folders

Mon Jan 26 12:26:03 EST 2004

Can you generate telemetry logs of both working and broken users?

-Rob

On Mon, 26 Jan 2004, Tuomas Toropainen wrote:

> [sending this message third time, let's see if it passes through]
>
> Weird things are happening with my cyrus test installation. It seems that
> some users can change and create folders as normal, but some can not. I
> have been unable to determine anything common linking these problematic
> and non-problematic users.
>
> This is hard to explain but I'll try. I have used 2 imap clients: mutt and
> pine. Let's start with mutt.
>
> When "working" user logs in and tries to change folder (keys c and ?
> pressed in mutt) mutt displays folder list and lets user choose folder
> (INBOX.toinen in this example) without problems. Logs related to this case
> look like this:
>
> ---8<---
> Jan 23 15:48:25 torakka1 master[20335]: about to exec /v/net/imap.cc.jyu.fi/cyrus/bin/imapd
> Jan 23 15:48:25 torakka1 imap[20335]: executed
> Jan 23 15:48:25 torakka1 imapd[20335]: accepted connection
> Jan 23 15:48:25 torakka1 imapd[20335]: mystore: starting txn 2147483667
> Jan 23 15:48:25 torakka1 imapd[20335]: mystore: committing txn 2147483667
> Jan 23 15:48:25 torakka1 imapd[20335]: starttls: TLSv1 with cipher AES256-SHA (256/256 bits new) no authentication
> Jan 23 15:48:33 torakka1 imapd[20335]: login: localhost.localdomain[127.0.0.1] tjt plaintext+TLS
> Jan 23 15:48:33 torakka1 imapd[20335]: seen_db: user tjt opened /v/net/imap.cc.jyu.fi/var/user/t/tjt.seen
> Jan 23 15:48:33 torakka1 imapd[20335]: open: user tjt opened INBOX
> Jan 23 15:49:11 torakka1 imapd[20335]: open: user tjt opened INBOX.toinen
> ---8<---
>
> Also creating new folder in mutt (c,?,C) works fine.
>
> Then, using problematic user account and trying to change folders (c,?)
> results in mutt opening new connection and asking login/pass again. This
> happens 3 times (first after ?, second after choosing INBOX. tree and
> third when opening folder).
>
> ---8<---
> Jan 23 15:53:54 torakka1 master[20345]: about to exec /v/net/imap.cc.jyu.fi/cyrus/bin/imapd
> Jan 23 15:53:54 torakka1 imap[20345]: executed
> Jan 23 15:53:54 torakka1 imapd[20345]: accepted connection
> Jan 23 15:53:54 torakka1 imapd[20345]: mystore: starting txn 2147483679
> Jan 23 15:53:54 torakka1 imapd[20345]: mystore: committing txn 2147483679
> Jan 23 15:53:54 torakka1 imapd[20345]: starttls: TLSv1 with cipher AES256-SHA (256/256 bits new) no authentication
> Jan 23 15:53:58 torakka1 imapd[20345]: login: localhost.localdomain[127.0.0.1] aapo plaintext+TLS
> Jan 23 15:53:58 torakka1 imapd[20345]: seen_db: user aapo opened /v/net/imap.cc.jyu.fi/var/user/a/aapo.seen
> Jan 23 15:53:58 torakka1 imapd[20345]: open: user aapo opened INBOX
> Jan 23 15:54:02 torakka1 master[20346]: about to exec /v/net/imap.cc.jyu.fi/cyrus/bin/imapd
> Jan 23 15:54:02 torakka1 imap[20346]: executed
> Jan 23 15:54:02 torakka1 imapd[20346]: accepted connection
> Jan 23 15:54:02 torakka1 imapd[20346]: mystore: starting txn 2147483684
> Jan 23 15:54:02 torakka1 imapd[20346]: mystore: committing txn 2147483684
> Jan 23 15:54:02 torakka1 imapd[20346]: starttls: TLSv1 with cipher AES256-SHA (256/256 bits new) no authentication
> Jan 23 15:54:07 torakka1 imapd[20346]: login: localhost.localdomain[127.0.0.1] aapo plaintext+TLS
> Jan 23 15:54:08 torakka1 master[20347]: about to exec /v/net/imap.cc.jyu.fi/cyrus/bin/imapd
> Jan 23 15:54:08 torakka1 imap[20347]: executed
> Jan 23 15:54:08 torakka1 imapd[20347]: accepted connection
> Jan 23 15:54:08 torakka1 imapd[20347]: mystore: starting txn 2147483689
> Jan 23 15:54:08 torakka1 imapd[20347]: mystore: committing txn 2147483689
> Jan 23 15:54:08 torakka1 imapd[20347]: starttls: TLSv1 with cipher AES256-SHA (256/256 bits new) no authentication
> Jan 23 15:54:13 torakka1 imapd[20347]: login: localhost.localdomain[127.0.0.1] aapo plaintext+TLS
> Jan 23 15:54:18 torakka1 master[20348]: about to exec /v/net/imap.cc.jyu.fi/cyrus/bin/imapd
> Jan 23 15:54:18 torakka1 imap[20348]: executed
> Jan 23 15:54:18 torakka1 imapd[20348]: accepted connection
> Jan 23 15:54:18 torakka1 imapd[20348]: mystore: starting txn 2147483694
> Jan 23 15:54:18 torakka1 imapd[20348]: mystore: committing txn 2147483694
> Jan 23 15:54:18 torakka1 imapd[20348]: starttls: TLSv1 with cipher AES256-SHA (256/256 bits new) no authentication
> Jan 23 15:54:22 torakka1 imapd[20348]: login: localhost.localdomain[127.0.0.1] aapo plaintext+TLS
> Jan 23 15:54:22 torakka1 imapd[20348]: seen_db: user aapo opened /v/net/imap.cc.jyu.fi/var/user/a/aapo.seen
> Jan 23 15:54:22 torakka1 imapd[20348]: open: user aapo opened INBOX.testi
> ---8<---
>
> Same things happen with pine, it asks login 3 times. With working user
> pine doesn't ask login more than 1 time.
>
> With problem user mutt refuses to create new folders, pressing C results
> always in new connection and nothing else. Pine still creates folders, but
> asks login every time 2 times.
>
> I have tried to debug this a lot and searched mailing list, but have found
> nothing. So please, if someone could tell me what's going wrong, i'd be
> very happy.
>
> Here is my cyrus imapd.conf:
>
> ---8<---
> postmaster: postmaster
> configdirectory: /v/net/imap.cc.jyu.fi/var
> partition-default: /v/net/imap.cc.jyu.fi/var/spool/imap
> sasl_saslauthd_path: /v/net/imap.cc.jyu.fi/var/run/saslauthd/mux
> sasl_pwcheck_method: saslauthd
> lmtp_admins: lmtpadmin
> admins: cyrus
> allowanonymouslogin: no
> allowplaintext: yes
> sasl_mech_list: PLAIN
> servername: torakka1.cc.jyu.fi
> autocreatequota: 10000
> reject8bit: no
> quotawarn: 90
> timeout: 30
> poptimeout: 10
> sievedir: /v/net/imap.cc.jyu.fi/sieve
> sendmail: /usr/sbin/sendmail
> sieve_maxscriptsize: 32
> sieve_maxscripts: 5
> tls_ca_file: /v/net/imap.cc.jyu.fi/var/imap/server.pem
> tls_cert_file: /v/net/imap.cc.jyu.fi/var/imap/server.pem
> tls_key_file: /v/net/imap.cc.jyu.fi/var/imap/server.pem
> ---8<---
>
> I also have tried logging to /v/net/imap.cc.jyu.fi/var/log/<user>, but the
> logs have revealed nothing. Everything is identical between working and
> non-working user, as long as it comes to listing folders.
>
> Working user:
> ---8<---
> >1074868578>a0003 OK User logged in
> <1074868578<a0004 LIST "" ""
> >1074868578>* LIST (\Noselect) "." ""
> a0004 OK Completed (0.000 secs 0 calls)
> <1074868578<a0005 SELECT "INBOX"
> >1074868578>* FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
> * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
> * 0 EXISTS
> * 0 RECENT
> * OK [UIDVALIDITY 1074864825]
> * OK [UIDNEXT 1]
> a0005 OK [READ-WRITE] Completed
> <1074868578<a0006 MYRIGHTS "INBOX"
> >1074868578>* MYRIGHTS INBOX lrswipcda
> a0006 OK Completed
> <1074868578<a0007 NOOP
> >1074868578>a0007 OK Completed
> <1074868581<a0008 NAMESPACE
> >1074868581>* NAMESPACE (("INBOX." ".")) (("user." ".")) (("" "."))
> a0008 OK Completed
> <1074868581<a0009 LIST "" "INBOX.%"
> >1074868581>* LIST (\HasNoChildren) "." "INBOX.kolmas"
> * LIST (\HasNoChildren) "." "INBOX.toinen"
> a0009 OK Completed (0.010 secs 3 calls)
> <1074868581<a0010 LIST "" "user.%"
> >1074868581>a0010 OK Completed (0.000 secs 1 calls)
> <1074868581<a0011 LIST "" "%"
> >1074868581>* LIST (\HasChildren) "." "INBOX"
> a0011 OK Completed (0.000 secs 4 calls)
> <1074868583<a0012 LIST "" "INBOX.%"
> >1074868583>* LIST (\HasNoChildren) "." "INBOX.kolmas"
> * LIST (\HasNoChildren) "." "INBOX.toinen"
> a0012 OK Completed (0.000 secs 3 calls)
> <1074868585<a0013 CLOSE
> >1074868585>a0013 OK Completed
> <1074868586<a0014 SELECT "INBOX.toinen"
> >1074868586>* FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
> * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
> * 0 EXISTS
> * 0 RECENT
> * OK [UIDVALIDITY 1074864843]
> * OK [UIDNEXT 1]
> a0014 OK [READ-WRITE] Completed
> <1074868586<a0015 MYRIGHTS "INBOX.toinen"
> >1074868586>* MYRIGHTS INBOX.toinen lrswipcda
> a0015 OK Completed
> <1074868587<a0016 CLOSE
> >1074868587>a0016 OK Completed
> <1074868587<a0017 LOGOUT
> >1074868587>* BYE LOGOUT received
> a0017 OK Completed
> ---8<---
>
> And non-working user, first connection:
> ---8<---
> >1074868859>a0003 OK User logged in
> <1074868859<a0004 LIST "" ""
> >1074868859>* LIST (\Noselect) "." ""
> a0004 OK Completed (0.000 secs 0 calls)
> <1074868859<a0005 SELECT "INBOX"
> >1074868859>* FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
> * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
> * 0 EXISTS
> * 0 RECENT
> * OK [UIDVALIDITY 1074862204]
> * OK [UIDNEXT 1]
> a0005 OK [READ-WRITE] Completed
> <1074868859<a0006 MYRIGHTS "INBOX"
> >1074868859>* MYRIGHTS INBOX lrswipcda
> a0006 OK Completed
> <1074868859<a0007 NOOP
> >1074868859>a0007 OK Completed
> ---8<---
>
> second connection:
> ---8<---
> >1074868864>a0003 OK User logged in
> <1074868864<a0004 LIST "" ""
> >1074868864>* LIST (\Noselect) "." ""
> a0004 OK Completed (0.000 secs 0 calls)
> <1074868864<a0005 NAMESPACE
> >1074868864>* NAMESPACE (("INBOX." ".")) (("user." ".")) (("" "."))
> a0005 OK Completed
> <1074868864<a0006 LIST "" "INBOX.%"
> >1074868864>* LIST (\HasNoChildren) "." "INBOX.atoinen"
> a0006 OK Completed (0.000 secs 2 calls)
> <1074868864<a0007 LIST "" "user.%"
> >1074868864>a0007 OK Completed (0.000 secs 1 calls)
> <1074868864<a0008 LIST "" "%"
> >1074868864>* LIST (\HasChildren) "." "INBOX"
> a0008 OK Completed (0.000 secs 3 calls)
> ---8<---
>
> It looks like working user's client says NAMESPACE when non-working's one
> opens new connection in which second command after login and LIST is the
> same NAMESPACE, getting same reply. I would blame mutt if it was the only
> client, but as pine behaves roughly same way, and with other users they
> both work, I cant believe this is client's fault.
>
> I have installed cyrus-imapd 2.1.16 on 3 different redhat 9 and 2 fedora
> machines. No difference.
>
> I'm starting to think if I have ate too many red mushrooms ;)
>
>
>

-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
Rob Siemborski * Andrew Systems Group * Cyert Hall 207 * 412-268-7456
Research Systems Programmer * /usr/contributed Gatekeeper