search

domainaware / parsedmarc

A Python package and CLI for parsing aggregate and forensic DMARC reports
https://domainaware.github.io/parsedmarc/
Apache License 2.0
986 stars 214 forks source link

Error deleting or moving messages #302

Open lpandolfini opened 2 years ago

lpandolfini commented 2 years ago

Hello,

first of all I would like to thank you for this wonderful software, it's really useful!

I have it running inside a docker container and checking an IMAP email (running on a hMailServer server), everything works fine with the "test" option, but if I remove the test option then I get an error when trying to move or delete the messages.

The parsedmarc version inside the docker container is the following:

root@107b49199cf8:/# parsedmarc -v
7.1.1
root@107b49199cf8:/#

The application debug log is this (with a batch size of 5):

   DEBUG:__init__.py:1116:Found 294 messages in INBOX
   DEBUG:__init__.py:1123:Processing 5 messages
   DEBUG:__init__.py:1128:Processing message 1 of 5: UID 2
    INFO:__init__.py:806:Parsing mail from noreply-dmarc-support@google.com
   DEBUG:__init__.py:1128:Processing message 2 of 5: UID 3
    INFO:__init__.py:806:Parsing mail from noreply-dmarc-support@google.com
   DEBUG:__init__.py:1128:Processing message 3 of 5: UID 4
    INFO:__init__.py:806:Parsing mail from noreply-dmarc-support@google.com
   DEBUG:__init__.py:1128:Processing message 4 of 5: UID 5
    INFO:__init__.py:806:Parsing mail from noreply-dmarc-support@google.com
   DEBUG:__init__.py:1128:Processing message 5 of 5: UID 6
    INFO:__init__.py:806:Parsing mail from noreply-dmarc-support@google.com
   DEBUG:__init__.py:1183:Moving aggregate report messages from INBOX to Archive/Aggregate
   DEBUG:__init__.py:1189:Moving message 1 of 5: UID 2
   ERROR:__init__.py:1196:IMAP error: Error moving message UID 2: UID command error: BAD [b'No mail number specified']
   DEBUG:__init__.py:1189:Moving message 2 of 5: UID 3
   ERROR:__init__.py:1196:IMAP error: Error moving message UID 3: UID command error: BAD [b'No mail number specified']
   DEBUG:__init__.py:1189:Moving message 3 of 5: UID 4
   ERROR:__init__.py:1196:IMAP error: Error moving message UID 4: UID command error: BAD [b'No mail number specified']
   DEBUG:__init__.py:1189:Moving message 4 of 5: UID 5
   ERROR:__init__.py:1196:IMAP error: Error moving message UID 5: UID command error: BAD [b'No mail number specified']
   DEBUG:__init__.py:1189:Moving message 5 of 5: UID 6
   ERROR:__init__.py:1196:IMAP error: Error moving message UID 6: UID command error: BAD [b'No mail number specified']
    INFO:elastic.py:298:Saving aggregate report to Elasticsearch

And the corresponding log from the IMAP server is the following (for a full cycle for the batch size):

"RECEIVED: FOIF358 LIST "" "Archive""
"SENT: * LIST (\HasChildren) "." "Archive"[nl]FOIF358 OK LIST completed"
"RECEIVED: FOIF359 LIST "" "Archive.Aggregate""
"SENT: * LIST (\HasNoChildren) "." "Archive.Aggregate"[nl]FOIF359 OK LIST completed"
"RECEIVED: FOIF360 LIST "" "Archive.Forensic""
"SENT: * LIST (\HasNoChildren) "." "Archive.Forensic"[nl]FOIF360 OK LIST completed"
"RECEIVED: FOIF361 LIST "" "Archive.Invalid""
"SENT: * LIST (\HasNoChildren) "." "Archive.Invalid"[nl]FOIF361 OK LIST completed"
"RECEIVED: FOIF362 UID SEARCH ALL"
"SENT: * SEARCH 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296"
"SENT: FOIF362 OK UID completed"
"RECEIVED: FOIF363 UID FETCH 2 (RFC822)"
"SENT: * 1 FETCH (UID 2 RFC822 {3561}"
"SENT: )"
"SENT: FOIF363 OK UID completed"
"RECEIVED: FOIF364 UID FETCH 3 (RFC822)"
"SENT: * 2 FETCH (UID 3 RFC822 {3562}"
"SENT: )"
"SENT: FOIF364 OK UID completed"
"RECEIVED: FOIF365 UID FETCH 4 (RFC822)"
"SENT: * 3 FETCH (UID 4 RFC822 {3565}"
"SENT: )"
"SENT: FOIF365 OK UID completed"
"RECEIVED: FOIF366 UID FETCH 5 (RFC822)"
"SENT: * 4 FETCH (UID 5 RFC822 {3561}"
"SENT: )"
"SENT: FOIF366 OK UID completed"
"RECEIVED: FOIF367 UID FETCH 6 (RFC822)"
"SENT: * 5 FETCH (UID 6 RFC822 {3560}"
"SENT: )"
"SENT: FOIF367 OK UID completed"
"RECEIVED: FOIF368 UID STORE 2 +FLAGS.SILENT (\Deleted)"
"SENT: FOIF368 OK UID completed"
"RECEIVED: FOIF369 UID EXPUNGE 2"
"SENT: FOIF369 BAD No mail number specified"
"RECEIVED: FOIF370 UID STORE 3 +FLAGS.SILENT (\Deleted)"
"SENT: FOIF370 OK UID completed"
"RECEIVED: FOIF371 UID EXPUNGE 3"
"SENT: FOIF371 BAD No mail number specified"
"RECEIVED: FOIF372 UID STORE 4 +FLAGS.SILENT (\Deleted)"
"SENT: FOIF372 OK UID completed"
"RECEIVED: FOIF373 UID EXPUNGE 4"
"SENT: FOIF373 BAD No mail number specified"
"RECEIVED: FOIF374 UID STORE 5 +FLAGS.SILENT (\Deleted)"
"SENT: FOIF374 OK UID completed"
"RECEIVED: FOIF375 UID EXPUNGE 5"
"SENT: FOIF375 BAD No mail number specified"
"RECEIVED: FOIF376 UID STORE 6 +FLAGS.SILENT (\Deleted)"
"SENT: FOIF376 OK UID completed"
"RECEIVED: FOIF377 UID EXPUNGE 6"
"SENT: FOIF377 BAD No mail number specified"
"RECEIVED: FOIF378 UID SEARCH ALL"
"SENT: * SEARCH 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296"
"SENT: FOIF378 OK UID completed"
"RECEIVED: FOIF379 IDLE"

Can someone help me identify the problem?

Thanks Luca

JCToribio commented 2 years ago

Similar....

INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']
    INFO:cli.py:755:Starting parsedmarc
   DEBUG:__init__.py:1093:Found 1 messages in INBOX
   DEBUG:__init__.py:1100:Processing 1 messages
   DEBUG:__init__.py:1105:Processing message 1 of 1: UID 4
    INFO:__init__.py:810:Parsing mail from Jonathan Toribio <jchristiantp@gmail.com>
 WARNING:__init__.py:1124:Message with subject "Process Test" is not a valid DMARC report
   DEBUG:__init__.py:1128:Deleting message UID 4
   ERROR:cli.py:945:Mailbox Error: UID command error: BAD [b'No mail number specified']

Using hmailserver....

"IMAPD" 2456    9398    "2022-08-01 11:53:34.991"   "192.168.100.26"    "SENT: * OK IMAPrev1"
"IMAPD" 2508    9398    "2022-08-01 11:53:34.995"   "192.168.100.26"    "RECEIVED: KGIA0 CAPABILITY"
"IMAPD" 2508    9398    "2022-08-01 11:53:34.995"   "192.168.100.26"    "SENT: * CAPABILITY IMAP4 IMAP4rev1 CHILDREN IDLE QUOTA SORT ACL NAMESPACE RIGHTS=texk[nl]KGIA0 OK CAPABILITY completed"
"IMAPD" 2456    9398    "2022-08-01 11:53:34.997"   "192.168.100.26"    "RECEIVED: KGIA1 LOGIN dmarc@columbus.infotier.com ***"
"IMAPD" 2456    9398    "2022-08-01 11:53:34.997"   "192.168.100.26"    "SENT: KGIA1 OK LOGIN completed"
"IMAPD" 2508    9398    "2022-08-01 11:53:34.998"   "192.168.100.26"    "RECEIVED: KGIA2 CAPABILITY"
"IMAPD" 2508    9398    "2022-08-01 11:53:34.998"   "192.168.100.26"    "SENT: * CAPABILITY IMAP4 IMAP4rev1 CHILDREN IDLE QUOTA SORT ACL NAMESPACE RIGHTS=texk[nl]KGIA2 OK CAPABILITY completed"
"IMAPD" 2500    9398    "2022-08-01 11:53:34.999"   "192.168.100.26"    "RECEIVED: KGIA3 LIST "" "*""
"IMAPD" 2500    9398    "2022-08-01 11:53:34.999"   "192.168.100.26"    "SENT: * LIST (\HasChildren) "." "INBOX"[nl]* LIST (\HasChildren) "." "INBOX.Processed"[nl]* LIST (\HasNoChildren) "." "INBOX.Processed.Aggregate"[nl]* LIST (\HasNoChildren) "." "INBOX.Processed.Forensic"[nl]* LIST (\HasNoChildren) "." "INBOX.Processed.Invalid"[nl]* LIST (\HasNoChildren) "." "Sent"[nl]* LIST (\HasNoChildren) "." "Trash"[nl]KGIA3 OK LIST completed"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.002"   "192.168.100.26"    "RECEIVED: KGIA4 NAMESPACE"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.002"   "192.168.100.26"    "SENT: * NAMESPACE (("" ".")) NIL (("#Public" "."))[nl]KGIA4 OK namespace command complete"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.004"   "192.168.100.26"    "RECEIVED: KGIA5 SELECT "INBOX""
"IMAPD" 2500    9398    "2022-08-01 11:53:35.004"   "192.168.100.26"    "SENT: * 1 EXISTS[nl]* 0 RECENT[nl]* FLAGS (\Deleted \Seen \Draft \Answered \Flagged)[nl]* OK [UIDVALIDITY 1658763561] current uidvalidity[nl]* OK [UIDNEXT 5] next uid[nl]* OK [PERMANENTFLAGS (\Deleted \Seen \Draft \Answered \Flagged)] limited[nl]KGIA5 OK [READ-WRITE] SELECT completed"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.007"   "192.168.100.26"    "RECEIVED: KGIA6 LIST "" "INBOX.Processed""
"IMAPD" 2500    9398    "2022-08-01 11:53:35.007"   "192.168.100.26"    "SENT: * LIST (\HasChildren) "." "INBOX.Processed"[nl]KGIA6 OK LIST completed"
"IMAPD" 2456    9398    "2022-08-01 11:53:35.008"   "192.168.100.26"    "RECEIVED: KGIA7 LIST "" "INBOX.Processed.Aggregate""
"IMAPD" 2456    9398    "2022-08-01 11:53:35.008"   "192.168.100.26"    "SENT: * LIST (\HasNoChildren) "." "INBOX.Processed.Aggregate"[nl]KGIA7 OK LIST completed"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.010"   "192.168.100.26"    "RECEIVED: KGIA8 LIST "" "INBOX.Processed.Forensic""
"IMAPD" 2500    9398    "2022-08-01 11:53:35.010"   "192.168.100.26"    "SENT: * LIST (\HasNoChildren) "." "INBOX.Processed.Forensic"[nl]KGIA8 OK LIST completed"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.011"   "192.168.100.26"    "RECEIVED: KGIA9 LIST "" "INBOX.Processed.Invalid""
"IMAPD" 2500    9398    "2022-08-01 11:53:35.011"   "192.168.100.26"    "SENT: * LIST (\HasNoChildren) "." "INBOX.Processed.Invalid"[nl]KGIA9 OK LIST completed"
"IMAPD" 2508    9398    "2022-08-01 11:53:35.012"   "192.168.100.26"    "RECEIVED: KGIA10 SELECT "INBOX""
"IMAPD" 2508    9398    "2022-08-01 11:53:35.012"   "192.168.100.26"    "SENT: * 1 EXISTS[nl]* 0 RECENT[nl]* FLAGS (\Deleted \Seen \Draft \Answered \Flagged)[nl]* OK [UIDVALIDITY 1658763561] current uidvalidity[nl]* OK [UIDNEXT 5] next uid[nl]* OK [PERMANENTFLAGS (\Deleted \Seen \Draft \Answered \Flagged)] limited[nl]KGIA10 OK [READ-WRITE] SELECT completed"
"IMAPD" 2508    9398    "2022-08-01 11:53:35.059"   "192.168.100.26"    "RECEIVED: KGIA11 UID SEARCH ALL"
"IMAPD" 2508    9398    "2022-08-01 11:53:35.059"   "192.168.100.26"    "SENT: * SEARCH 4"
"IMAPD" 2508    9398    "2022-08-01 11:53:35.059"   "192.168.100.26"    "SENT: KGIA11 OK UID completed"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.061"   "192.168.100.26"    "RECEIVED: KGIA12 UID FETCH 4 (RFC822)"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.062"   "192.168.100.26"    "SENT: * 1 FETCH (UID 4 RFC822 {2671}"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.062"   "192.168.100.26"    "SENT: )"
"IMAPD" 2500    9398    "2022-08-01 11:53:35.062"   "192.168.100.26"    "SENT: KGIA12 OK UID completed"
lpandolfini commented 2 years ago

Interesting.... so that seems to be a problem related to hMailServer!

JCToribio commented 2 years ago

I don't think so. I think is parsedmarc not issuing the command EXPUNGE correctly. Like is missing or positioning a parameter incorrectly, then hmail says BAD "No mail number". Container works, for now I'm just moving the reports manually after they are processed.

"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "SENT: HLEK62935 BAD No mail number specified"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "RECEIVED: HLEK62936 UID STORE 8 +FLAGS.SILENT (\Deleted)"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "SENT: HLEK62936 OK UID completed"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "RECEIVED: HLEK62937 UID EXPUNGE 8"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "SENT: HLEK62937 BAD No mail number specified"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "RECEIVED: HLEK62938 UID STORE 9 +FLAGS.SILENT (\Deleted)"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "SENT: HLEK62938 OK UID completed"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "RECEIVED: HLEK62939 UID EXPUNGE 9"
"IMAPD" 2512    17170   "2022-08-02 11:21:54.902"   "192.168.100.26"    "SENT: HLEK62939 BAD No mail number specified"
"IMAPD" 2496    17170   "2022-08-02 11:21:54.918"   "192.168.100.26"    "RECEIVED: HLEK62940 UID STORE 10 +FLAGS.SILENT (\Deleted)"
"IMAPD" 2496    17170   "2022-08-02 11:21:54.918"   "192.168.100.26"    "SENT: HLEK62940 OK UID completed"
"IMAPD" 2496    17170   "2022-08-02 11:21:54.918"   "192.168.100.26"    "RECEIVED: HLEK62941 UID EXPUNGE 10"
"IMAPD" 2496    17170   "2022-08-02 11:21:54.918"   "192.168.100.26"    "SENT: HLEK62941 BAD No mail number specified"
lpandolfini commented 2 years ago

Agree, but it seems that this is happening only to you and me using hMailServer, and not to other people with different mailservers, maybe hMailServer is too picky and is discarding the EXPUNGE command. RIght now I'm just not deleting the messages, and I'm moving them manually too. thanks Luca

lpandolfini commented 2 years ago

I checked the RFCs for both IMAP and UIDPLUS extension: RFC 3501 RFC 4315 and i see that the client is sending the UID EXPUNGE command, but the specification says that the expected argument is a sequence set:

C: A003 UID EXPUNGE 3000:3002
S: * 3 EXPUNGE
S: * 3 EXPUNGE
S: * 3 EXPUNGE
S: A003 OK UID EXPUNGE completed

but in the hMailServer log the message received is like:

C: HLEK62941 UID EXPUNGE 10

This is the hMailServer source code that is raising the error "No mail number specified":

// Copy the first word containing the message sequence
long lSecWordStartPos = sCommand.Find(_T(" "), 5) + 1;
long lSecWordEndPos = sCommand.Find(_T(" "), lSecWordStartPos);
long lSecWordLength = lSecWordEndPos - lSecWordStartPos;
String sMailNo = sCommand.Mid(lSecWordStartPos, lSecWordLength);

// Copy the second word containing the actual command.
String sShowPart = sCommand.Mid(lSecWordEndPos + 1);

if (sMailNo.IsEmpty())
     return IMAPResult(IMAPResult::ResultBad, "No mail number specified");

So I think that the issue here is that the client is sending just a single mail number instead of a sequence, what do you think?

Thanks Luca

TinyBigJacko commented 1 year ago

In case it's helpful, I'm seeing the same error (lots) and I'm also using hMailserver, so that's another one on the correlation heap!

Looking at the details in the RFCs (current version of the one first you helpfully provided is https://datatracker.ietf.org/doc/html/rfc9051#section-6.4.3 - but it's essentially the same in the area of EXPUNGE anyway), I believe this is a case of hMailServer simply not yet supporting UIDPLUS (which is where the UID EXPUNGE command comes from), and parsedmarc simply assuming it does, which is kinda bad form.

parsedmarc sends the UID EXPUNGE command in a well-formatted condition for a UIDPLUS-capable mailserver, but because hMailServer doesn't speak that extension, it chokes, attempting to parse it as a 'base-level' UID command, not knowing the difference.

According to the UIDPLUS RFC, the correct handling of a non-UIDPLUS-capable mailserver is as follows:

      If the server does not support the UIDPLUS capability, the client
      should fall back to using the STORE command to temporarily remove
      the \Deleted flag from messages it does not want to remove, then
      issuing the EXPUNGE command.  Finally, the client should use the
      STORE command to restore the \Deleted flag on the messages in
      which it was temporarily removed.

IIRC, the client (in this case parsedmarc) is told a set of extensions that the mailserver knows or can handle, and the client is duty-bound to handle that appropriately. I'd say it's looking like parsedmarc is at fault here, by ploughing on with an unsupported (as far as the mailserver is concerned) set of instructions - but of course, writing the special case fallback handling using STORE, EXPUNGE, STORE method is going to be more work for the developer, and he may already have enough to do!

I might have a crack at it myself and put up a PR, but don't hold your breath! I'm in somewhat uncharted personal territory here, and pushed for time myself!

TinyBigJacko commented 1 year ago

Hi guys,

I've done bit more digging and would probably say this is not a parsedmarc problem either (though a solution could be put in and the problem mitigated, but it's probably not the best place).

The root cause is in imapclient (see https://github.com/mjs/imapclient/blob/d0f5c4e927ddda1972066ef04242a09d2dc2a666/imapclient/imapclient.py#L1469 ) and the fact that it ASSUMES that UIDPLUS functionality is available on the IMAP server without proving it for itself. It's possible it is working on the assumption that if a caller of this function is enclosing a list of UIDs to expunge, then that caller has tested capabilities beforehand, but that's a dangerous assumption, because evidently most callers do not. They send a list of UIDs for expunging, and rely on the final taskmaster to decide on the right method.

IMHO the issue needs to be solved in imapclient.expunge, nowhere else.

For those interested, here's my paper-trail of function calling references that I used to get to the root cause. If you spot any glaring mistakes, please let me know!

CONTEXT: parsedmarc

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/__init__.py#L1024 - get_dmarc_reports_from_mailbox() function definition

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/__init__.py#L1196 - get_dmarc_reports_from_mailbox() - first/main call of func

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/__init__.py#L1129 - move method called on connection object (move to invalid folder)

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/__init__.py#L1163 - move method (aggregates folder)

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/__init__.py#L1183 - move method (forensics folder)

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/__init__.py#L31 - Mailbox connection object imported from parsedmarc.mail

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/mail/mailbox_connection.py#L5 - mailbox connection class template object

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/mail/imap.py#L11 - Mailbox connection object used for IMAP

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/mail/imap.py#L24 - call to use external lib for IMAPClient (note, not imapclient, at this stage)

https://github.com/domainaware/parsedmarc/blob/49f9d75413478844756efcf6cb0b9a9a80b9c39a/parsedmarc/mail/imap.py#L4 - IMAPClient imported here, from mailsuite (external repo)

CONTEXT: mailsuite

https://github.com/seanthegeek/mailsuite/ - mailsuite lives here https://github.com/seanthegeek/mailsuite/blob/8e892d76c3519225af72ebdad59178d7edb28804/mailsuite/imap.py - this is where mailsuite handles imap

https://github.com/seanthegeek/mailsuite/blob/8e892d76c3519225af72ebdad59178d7edb28804/mailsuite/imap.py#L354 - this is the def for exportable, exposed move_messages func

https://github.com/seanthegeek/mailsuite/blob/8e892d76c3519225af72ebdad59178d7edb28804/mailsuite/imap.py#L316 - this is the def for the internal, private _move_messages func

+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+- A side observation: https://github.com/seanthegeek/mailsuite/blob/8e892d76c3519225af72ebdad59178d7edb28804/mailsuite/imap.py#L329 - checks for MOVE supported on IMAP4 server, but not UIDPLUS. (MOVE is an RFC Standards Proposal - https://www.rfc-editor.org/rfc/rfc6851.html - It circumvents all the EXPUNGE handling and detection issues almost entirely, when it's implemented, but sadly, not all servers have it yet).

If MOVE capability is found, mailsuite uses it, otherwise falls back to individual per UID copy/delete method. In our (hMailServer) case, MOVE capability is absent, so it does it the long way. +-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-

Both move methods end up using mailsuite.imap.delete function, defined here - https://github.com/seanthegeek/mailsuite/blob/8e892d76c3519225af72ebdad59178d7edb28804/mailsuite/imap.py#L266

This is where things start to go wrong:- https://github.com/seanthegeek/mailsuite/blob/8e892d76c3519225af72ebdad59178d7edb28804/mailsuite/imap.py#L283 - imapclient's expunge function is called explicitly with a list of UIDs that have been deleted and want flushing away. There is no verification here in mailclient that UIDPLUS is supported on the current server, but really, imo that is imapclient's job to determine, given that it is the one that 'bangs the metal'...

UID EXPUNGE, is part of UIDPLUS - https://www.rfc-editor.org/rfc/rfc4315

CONTEXT: imapclient

https://github.com/mjs/imapclient/blob/d0f5c4e927ddda1972066ef04242a09d2dc2a666/imapclient/imapclient.py#L1469 - this is where imapclient defines its expunge function (repo-owner @mjs) The issue is that imapclient.expunge interprets being handed a list of UIDs as implied proof of UIDPLUS-capability, and decides to just go ahead and use the UID EXPUNGE method to expunge these UIDs en-masse, rather than expunging them the long-winded way (storing each in turn, expunging by UID, rinse, repeat etc).

Author cites RFC3501 which is obsolete - should be https://www.rfc-editor.org/rfc/rfc9051, but there is very little (perhaps no) practical difference between the sections about EXPUNGE.

https://www.rfc-editor.org/rfc/rfc9051#section-6.4.3 - defines the (global) EXPUNGE command which purges all messages that have \Deleted flags set, through the entire mailbox. https://www.rfc-editor.org/rfc/rfc9051#section-7.5.1 - describes the responses from servers for this global EXPUNGE command.

The problem stems from the following factors: hMailserver is not yet UIDPLUS-capable, but that's allowed. I am assuming at this point, that it correctly does not show/offer it as a capability when questioned by clients. imapclient ASSUMES that if its expunge function is called with a list of message UIDs, then it is safe to just invoke the UIDPLUS-only command: UID EXPUNGE. This is not wise, because there is no guarantee that the calling client(s) (in this case, mailsuite, and prior to that, parsedmarc) have checked for UIDPLUS capability and refrained from calling the imapclient.expunge function with a UID list. They may (quite reasonably) be assuming that imapclient will handle such a list either 'uid by uid' in the longhanded way, or via UID EXPUNGE if it's possible; they've delegated that choice to imapclient to discover and make.

Solution:

imapclient needs to be more cautious and verify that UID EXPUNGE is available on the IMAP4 server, by checking for UIDPLUS capability. If it isn't there, don't use UID EXPUNGE to handle a list of UIDs, do them UID by UID. The RFC explains the process here in https://www.rfc-editor.org/rfc/rfc4315#section-2.1

      If the server does not support the UIDPLUS capability, the client
      should fall back to using the STORE command to temporarily remove
      the \Deleted flag from messages it does not want to remove, then
      issuing the EXPUNGE command.  Finally, the client should use the
      STORE command to restore the \Deleted flag on the messages in
      which it was temporarily removed.

The UIDPLUS RFC also offers the alternative of just using the old, global EXPUNGE command to expunge everything marked \Deleted, but this is highly likely to give undesirable results from time to time (by removing things from the mailbox that are unconnected with the current operation by this client, which may affect other operations, perhaps even ongoing via other clients connected at the time. The UID by UID approach is definitely the preferred fallback if no UID EXPUNGE/UIDPLUS availability on the server).

TL;DR - The problem is in imapclient - https://github.com/mjs/imapclient/blob/d0f5c4e927ddda1972066ef04242a09d2dc2a666/imapclient/imapclient.py#L1469. It needs to stop assuming UIDPLUS capability without checking, and handle multi-UID expunge lists given to it, in the correct way to suit the IMAP server it is talking to.

TinyBigJacko commented 1 year ago

I've opened an issue on the IMAPClient repo here: https://github.com/mjs/imapclient/issues/496 - if anyone wants to follow it or weigh in with a vote of support! :)