search

scanner / asimap

Pure python based IMAP server with a MH based file store
BSD 3-Clause "New" or "Revised" License
42 stars 7 forks source link

COPY's take way too long #307

Open scanner opened 1 month ago

scanner commented 1 month ago 
DEBUG:client.command: FINISH: Client: 127.0.0.1:47404, IMAP Command '16439.109 UID COPY' took 69.956 seconds

that was copying one message from the inbox to the Archive folder. My initial thought is that getting the locks necessary to read from one folder and write to the other are blocking behind some other locks, but that is still rather long.

Investigation is necessary (which means more debug logging statements)

scanner commented 1 month ago

Not just COPY's. There are times SELECT and STATUS timeout as well.

[2024-07-12 12:26:23,126] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 7, '929.280 STATUS', '4.285 SELECT', '4.286 SELECT', '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS'
[2024-07-12 12:26:24,118] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 7, '4.285 SELECT', '4.286 SELECT', '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT'
[2024-07-12 12:26:24,123] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 7, '4.285 SELECT', '4.286 SELECT', '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT'
[2024-07-12 12:26:24,126] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 7, '4.285 SELECT', '4.286 SELECT', '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT'
[2024-07-12 12:26:43,507] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 6, '4.286 SELECT', '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT'
[2024-07-12 12:27:24,006] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 6, '4.286 SELECT', '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT'
[2024-07-12 12:27:44,391] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 6, '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT', '4.295 SELECT'
[2024-07-12 12:28:24,925] scanner@apricot.com            DEBUG:user_server.run: Commands in progress: 6, '4.287 SELECT', '4.288 SELECT', '4.289 SELECT', '927.291 STATUS', '4.294 SELECT', '4.295 SELECT'
[2024-07-12 12:28:45,200] scanner@apricot.com            ERROR:client.command: 4.287 BAD Command timed out
[2024-07-12 12:28:45,202] scanner@apricot.com            DEBUG:client.command: FINISH: Client: 127.0.0.1:40298, IMAP Command '4.287 SELECT' took 360.012 seconds

Maybe something is getting stuck and a lock is lost resulting in these timeouts? (Or some operation is taking too long, blocking everything else behind it.)

scanner commented 1 month ago

I believe that we need to pass the IMAP Command down into the mbox module. Not because it needs any of the data to operate, but it lets us generate better log messages, and extend timeouts.

All the functions in the mbox module should work fine if the IMAP Command is not specified.