Hello Wojtek, I would expect UID FETCH 1:* XXX on an empty mailbox to return OK
Kinda: C: A0 UID FETCH 1:* UID S: A0 OK FETCH completed. The way to go regarding non compliance to IMAP syntax/grammar/logic would be: - Try to get the exact IMAP exchange. Evolution is especially handy regarding this as allows turning on advanced IMAP debugging that actually drops the IMAP conversation to a log file. - That exchange can actually be reused in order to write a MPT test that actually acts as an "integration test" - Then we need to address the faulty logic in protocols/imap . Unit tests may be written if relevant. - Open a JIRA ticket to track the defect - Open a PR referencing the JIRA issue in the title + commit messages (starts with JAMES-XXXX) for automatic linking Here, it seems rather straightforward, here is the MPT output I came up with that reproduces the issue (sorry I was curious!) : https://github.com/apache/james-project/pull/2385 Regarding the fix, I believe it is rather the way FetchProcessor handles an empty range. - currently it considers empty ranges as bad input. While it MAY be legitimate with commands that alter state (COPY MOVE STORE EXPUNGE REPLACE) it is definitly inappropriate for FETCH. - It likely rather should skip the given range rather than throwing an exception in FetchProcessor line 205. - (in the recent IMAP work, we mostly ported the existing code without questionning its actual logic and we likely missed that one-line test coverage to uncover this issue). Do you want to get a look at the issue? Ps: SELECT is mandatory to work with a folder content. TB is necessarily doing it, though it may be clever enough to infer from the SELECT command (or the STATUS counters) that the folder is empty and thus that opening it may not be needed. > it would be handy if the log would contain complete received command, even >for learning/understanding better what's going on/what was received (for >example UID fetch lacks actual parameters) Regarding actual IMAP logging... The MDC logging context is set with precious debugging information including user supplied parameters. You may need to configure your logging output to include MDC to benefit from it. Would it fit your needs? I agree the "GOT Tag" messages are useless and may be removed. AbstractProcessor (org.apache.james.imap.processor.base.AbstractProcessor) have a debug log logging the command along side the associated MDC, which shall be enough... Though this is the interpretation of IMAP exchanges by James and not the actual IMAP exchanges. However that is true that I did often ended up tweaking the IMAP network layer to extract the IMAP exchange. Having a standard ready to use way to do this would be handy I believe. The IMAP parsers are read ahead (reads data as needed) thus getting the exact user input is tricky, but if needed we could add traces onto NettyImapRequestLineReader and drop a copy of the buffer as a log. For what james sends we sould put a trace into ChannelImapResponseWriter:write. In oth case we shall beware of eager evaluation of the logging input as computing the traces content may be expensive. Do you want to get a shot at this too?-- Best regards, Benoit TELLIER General manager of Linagora VIETNAM. Product owner for Team-Mail product. Chairman of the Apache James project. Mail: btell...@linagora.com Tel: (0033) 6 77 26 04 58 (WhatsApp, Signal) On Aug 20, 2024 8:00 PM, from Wojtek Hi, So I've been debugging issue with following error being returned when using Evolution on empty mailbox. It requests "UID FETCH 1:*" -- not sure if that's correct (complete log below [1]) It should be handled in `org.apache.james.imap.processor.AbstractMailboxProcessor#messageRange` and it returns `Optional.empty()`, because `selected.existsCount()` returns 0 (SelectedMailbox, empty mailbox?) On the face of it range `1:*` looks valid but IMAP is quite complex so I wouldn't be surprised if in this case it wasn't. Any hint how to deal with/fix that error correctly would be appreciated. Btw. it would be handy if the log would contain complete received command, even for learning/understanding better what's going on/what was received (for example UID fetch lacks actual parameters) PS. Surprisingly Thunderbird doesn't trigger the error but looking at the logs it seems that's because TB doesn't send `SELECT` command? [1] log: ``` [2024-08-20 19:23:07.614] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandTagged(): Got <tag>: Tag{value=F00066} [2024-08-20 19:23:07.614] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandNamed(): Got <command>: SELECT [2024-08-20 19:23:07.624] [DEBUG] [ boundedElastic-16] o.a.j.m.s.StoreMailboxManager.getMailbox(): Loaded mailbox #private:admin@atlantiscity:INBOX [2024-08-20 19:23:07.658] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandTagged(): Got <tag>: Tag{value=F00067} [2024-08-20 19:23:07.658] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandNamed(): Got <command>: IDLE [2024-08-20 19:23:11.211] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandTagged(): Got <tag>: Tag{value=F00068} [2024-08-20 19:23:11.212] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandNamed(): Got <command>: STATUS [2024-08-20 19:23:11.213] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.p.StatusProcessor.lambda$logInitialRequest$8(): Status called on mailbox named #private:admin@atlantiscity:Archive [2024-08-20 19:23:11.219] [DEBUG] [ boundedElastic-16] o.a.j.m.s.StoreMailboxManager.getMailbox(): Loaded mailbox #private:admin@atlantiscity:Archive [2024-08-20 19:23:11.234] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandTagged(): Got <tag>: Tag{value=F00069} [2024-08-20 19:23:11.234] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandNamed(): Got <command>: SELECT [2024-08-20 19:23:11.240] [DEBUG] [ boundedElastic-16] o.a.j.m.s.StoreMailboxManager.getMailbox(): Loaded mailbox #private:admin@atlantiscity:Archive [2024-08-20 19:23:11.274] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandTagged(): Got <tag>: Tag{value=F00070} [2024-08-20 19:23:11.274] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.m.DefaultImapDecoder.decodeCommandNamed(): Got <command>: UID [2024-08-20 19:23:11.274] [DEBUG] [ imapserver-ssl-io-6] o.a.j.i.d.p.UidCommandParser.decode(): Got <command>: UID FETCH [2024-08-20 19:23:11.276] [DEBUG] [ boundedElastic-16] o.a.j.m.s.StoreMailboxManager.lambda$getMailboxReactive$2(): Loaded mailbox 41356 #private:admin@atlantiscity:Archive [2024-08-20 19:23:11.277] [DEBUG] [ boundedElastic-16] o.a.j.i.p.f.FetchProcessor.lambda$processRequestReactive$5(): Fetch failed for mailbox 41356 because of invalid sequence-set [IdRange ( 1->9223372036854775807 )] org.apache.james.mailbox.exception.MessageRangeException: 1:9223372036854775807 is an invalid range at org.apache.james.imap.processor.fetch.FetchProcessor.lambda$doFetch$9(FetchProcessor.java:205) Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: Assembly trace from producer [reactor.core.publisher.MonoFlatMap] : reactor.core.publisher.Mono.flatMap(Mono.java:3171) org.apache.james.imap.processor.fetch.FetchProcessor.processRequestReactive(FetchProcessor.java:162) Error has been observed at the following site(s): *__Mono.flatMap ⇢ at org.apache.james.imap.processor.fetch.FetchProcessor.processRequestReactive(FetchProcessor.java:162) Original Stack Trace: at org.apache.james.imap.processor.fetch.FetchProcessor.lambda$doFetch$9(FetchProcessor.java:205) at java.base/java.util.Optional.orElseThrow(Optional.java:403) at org.apache.james.imap.processor.fetch.FetchProcessor.doFetch(FetchProcessor.java:205) at org.apache.james.imap.processor.fetch.FetchProcessor.lambda$processRequestReactive$4(FetchProcessor.java:185) at com.github.fge.lambdas.functions.FunctionChainer.lambda$sneakyThrow$49(FunctionChainer.java:74) at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:132) at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:129) at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:79) at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:252) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) at java.base/java.lang.Thread.run(Thread.java:1583) ``` -- Wojtek --------------------------------------------------------------------- To unsubscribe, e-mail: server-dev-unsubscr...@james.apache.org For additional commands, e-mail: server-dev-h...@james.apache.org
