Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bug: CREATE succeeds even if mailbox with same name already exists #360

Closed
heinrich-ulbricht opened this issue Jan 6, 2021 · 3 comments
Closed
Assignees
Milestone

Comments

@heinrich-ulbricht
Copy link

heinrich-ulbricht commented Jan 6, 2021

Scenario

I'm creating folders/mailboxes in a highly parallel fashion. While doing this I discovered that when several threads try to create a folder/mailbox with the same name at the same time several of them succeed. This is unexpected. According to the spec it is an error to create a mailbox with a duplicate name. So only one thread should succeed.

How am I testing?

Using MailKit and a .NET Core C# console application I spin up 100 threads which all try to create a folder with the same name at nearly the same time.

Expected behavior

I expect one of the threads to succeed and 99 to fail with an error.

Observed behavior

At times 10 threads are "successful", or 11 threads, or 4 threads. Sometimes it works and 99 report an error while only one succeeds. The behavior is the same with or without restarting Greenmail between tests.

Repro

I suspect you can use any library or tool to create folders/mailboxes with the same name at the same time via >10 parallel threads. Note that I am using a separate connection per thread.

Conclusion

I suspect there is an error in Greenmail with handling highly concurrent requests to create a new mailbox.

Notes

I discovered this while unit testing. My application does not really need 100 threads creating the same folder in parallel. But an edge case test behaved unexpected which is how I came to investigate this further.

(And if it's not Greenmail it must be MailKit, but for now I'm assuming MailKit works as advertised.)

@marcelmay marcelmay added the bug label Jan 6, 2021
@marcelmay marcelmay self-assigned this Jan 6, 2021
@marcelmay marcelmay added this to the 1.6.2 milestone Jan 6, 2021
@heinrich-ulbricht
Copy link
Author

heinrich-ulbricht commented Jan 7, 2021

Another observation although I only had the chance to see this once: even after exiting my test application my test folder was being re-created in Greenmail. So it went like this:

  • run my test app with 100 threads
  • exit the test app (might have been terminated)
  • go to my e-mail client and delete the test folder manually
  • the folder reappears multiple times (which I wouldn't expect)

The folder got re-created twice after deleting it manually. Could it be that the request do create the folder somehow got queued although the requesting client already disconnected/went away? Im not sure if my client disconnected or I just terminated it. Might be the latter or some strange coincidence of things but I thought I'd mention this just in case it's relevant.

@marcelmay
Copy link
Member

I tried to run a simple create-and-recreate, which on protocol level seems to work as expected (A8 NO CREATE failed. .. so as specified):

A8 CREATE INBOX.foo-folder
340     WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox INBOX.foo-folder already exists.
	at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
	at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
	at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
	at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
	at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
	at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
	at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:160)
	at java.lang.Thread.run(Thread.java:748)
A8 NO CREATE failed. Mailbox INBOX.foo-folder already exists.

You could try to run in verbose mode (-Dgreenmail.verbose)?
It also looks like the test app is still running, which you would also see in the verbose output.

When creating a folder which already exist, some APIs are quite tolerant.
Eg JavaMail Folder.create only returns false but does not throw an Exception (therefore not strongly indicating failure, just 'hinting').
Could this be the case for MailKit as well?

marcelmay added a commit that referenced this issue Jan 7, 2021
@heinrich-ulbricht
Copy link
Author

heinrich-ulbricht commented Jan 9, 2021

I'm a dummy. After looking at the verbose log and seeing it correctly showing 9 server-side errors while my client only "received" 5 I saw that I increased the error counter in a non-thread-safe fashion. I forgot the lock.

Sorry for the hassle and thanks for looking into this.

For sake of completeness here is the verbose log:

20713   DEBUG   imap.ImapRequestHandler| C: tag=A00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=I00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=G00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=F00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=C00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=E00000004, command=LIST
20714   DEBUG map.ImapRequestLineReader| IMAP Line received : <C00000004 LIST "" "INBOX"\r\n>
20714   DEBUG map.ImapRequestLineReader| IMAP Line received : <E00000004 LIST "" "INBOX"\r\n>
20713   DEBUG   imap.ImapRequestHandler| C: tag=H00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=J00000004, command=LIST
20713   DEBUG   imap.ImapRequestHandler| C: tag=D00000004, command=LIST
20715   DEBUG map.ImapRequestLineReader| IMAP Line received : <H00000004 LIST "" "INBOX"\r\n>
20714   DEBUG map.ImapRequestLineReader| IMAP Line received : <I00000004 LIST "" "INBOX"\r\n>
20714   DEBUG map.ImapRequestLineReader| IMAP Line received : <A00000004 LIST "" "INBOX"\r\n>
20714   DEBUG map.ImapRequestLineReader| IMAP Line received : <G00000004 LIST "" "INBOX"\r\n>
20714   DEBUG map.ImapRequestLineReader| IMAP Line received : <F00000004 LIST "" "INBOX"\r\n>
20713   DEBUG   imap.ImapRequestHandler| C: tag=B00000004, command=LIST
20716   DEBUG map.ImapRequestLineReader| IMAP Line received : <J00000004 LIST "" "INBOX"\r\n>
20716   DEBUG map.ImapRequestLineReader| IMAP Line received : <B00000004 LIST "" "INBOX"\r\n>
20716   DEBUG map.ImapRequestLineReader| IMAP Line received : <D00000004 LIST "" "INBOX"\r\n>
20725   DEBUG   imap.ImapRequestHandler| C: tag=E00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=G00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=H00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=I00000005, command=CREATE
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <G00000005 CREATE test\r\n>
20725   DEBUG   imap.ImapRequestHandler| C: tag=C00000005, command=CREATE
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <C00000005 CREATE test\r\n>
20725   DEBUG   imap.ImapRequestHandler| C: tag=A00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=D00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=F00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=B00000005, command=CREATE
20725   DEBUG   imap.ImapRequestHandler| C: tag=J00000005, command=CREATE
20726   DEBUG map.ImapRequestLineReader| IMAP Line received : <B00000005 CREATE test\r\n>
20726   DEBUG map.ImapRequestLineReader| IMAP Line received : <F00000005 CREATE test\r\n>
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <D00000005 CREATE test\r\n>
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <A00000005 CREATE test\r\n>
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <I00000005 CREATE test\r\n>
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <H00000005 CREATE test\r\n>
20725   DEBUG map.ImapRequestLineReader| IMAP Line received : <E00000005 CREATE test\r\n>
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20726   DEBUG map.ImapRequestLineReader| IMAP Line received : <J00000005 CREATE test\r\n>
20729   DEBUG   imap.ImapRequestHandler| C: tag=G00000006, command=LIST
20726   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20729   WARN     commands.CreateCommand| Error processing command
com.icegreen.greenmail.store.FolderException: Mailbox already exists.
        at com.icegreen.greenmail.imap.ImapHostManagerImpl.createMailbox(ImapHostManagerImpl.java:104)
        at com.icegreen.greenmail.imap.commands.CreateCommand.doProcess(CreateCommand.java:37)
        at com.icegreen.greenmail.imap.commands.CommandTemplate.process(CommandTemplate.java:57)
        at com.icegreen.greenmail.imap.ImapRequestHandler.doProcessRequest(ImapRequestHandler.java:96)
        at com.icegreen.greenmail.imap.ImapRequestHandler.handleRequest(ImapRequestHandler.java:51)
        at com.icegreen.greenmail.imap.ImapHandler.run(ImapHandler.java:71)
        at com.icegreen.greenmail.server.AbstractServer.lambda$handleClientSocket$0(AbstractServer.java:158)
        at java.lang.Thread.run(Thread.java:748)
20730   DEBUG map.ImapRequestLineReader| IMAP Line received : <G00000006 LIST "" test\r\n>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20733   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>
20776   DEBUG map.ImapRequestLineReader| IMAP Line received : <�>

I also tested with Dovecot. Dovecot doesn't raise errors at all. If there is a folder name collision the CREATE returns successful, as if the folder was a new one. Don't know what's better.

Side note: Since I'm using the Greenmail Docker container I looked up how to configure the verbose parameter here. It does not work as documented on Windows, Windows needs double-quotes like so: GREENMAIL_OPTS="-Dgreenmail.setup.test.all ... :/

Again, thanks for your time and help in solving this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants