0 votes
by (120 points)

Hello, I am trying to download POP3 mail from a free email account (@alice.it)

Unfortunately I get an exception during login:

Rebex.Net.Pop3Exception: Invalid POP3 response.

I found a workaround by selecting auth type = ClearText

I would like to attach verbose log file but I think it contains sensitive data (username and pass)

Applies to: Rebex Secure Mail
by (134k points)
Please attach a log at LogLevel.Debug - this should be sufficient to tell what's going on. There is no password in the debug log, and if there is a username, you can replace it. Also, make sure that you use the latest version of Rebex Secure Mail.
by (120 points)
2022-11-07 10:18:18.064 Opening log file.
2022-11-07 10:18:18.071 INFO FileLogWriter(1)[1] Info: Assembly: Rebex.Common R6.8 for .NET 6.0
2022-11-07 10:18:18.078 INFO FileLogWriter(1)[1] Info: Platform: Windows 11 (Build 22000) 64-bit; CLR: .NET 7.0.0-rc.2.22472.3
2022-11-07 10:18:18.082 DEBUG FileLogWriter(1)[1] Info: Culture: it; windows-1252
2022-11-07 10:18:18.326 DEBUG Pop3(1)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2022-11-07 10:18:18.326 INFO Pop3(1)[1] Info: Connecting to in.alice.it:110 using Pop3.
2022-11-07 10:18:18.326 INFO Pop3(1)[1] Info: Assembly: Rebex.Pop3 R6.8 for .NET 6.0 (Trial)
2022-11-07 10:18:18.326 INFO Pop3(1)[1] Info: Platform: Windows 11 (Build 22000) 64-bit; CLR: .NET 7.0.0-rc.2.22472.3
2022-11-07 10:18:18.327 DEBUG Pop3(1)[1] Info: Culture: it; windows-1252
2022-11-07 10:18:18.332 INFO Pop3(1)[1] Info: Connecting to in.alice.it.
2022-11-07 10:18:18.375 DEBUG Pop3(1)[1] Proxy: Resolving 'in.alice.it'.
2022-11-07 10:18:18.444 DEBUG Pop3(1)[1] Proxy: Connecting to 34.147.41.170:110 (no proxy).
2022-11-07 10:18:18.475 DEBUG Pop3(1)[1] Proxy: Connection established.
2022-11-07 10:18:18.477 DEBUG Pop3(1)[1] Info: Connection succeeded.
2022-11-07 10:18:18.489 DEBUG Pop3(1)[1] Info: State changed from 'Connecting' to 'Reading'.
2022-11-07 10:18:18.491 INFO Pop3(1)[1] Response: +OK POP3 Server
2022-11-07 10:18:18.491 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Ready'.
2022-11-07 10:18:18.494 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Sending'.
2022-11-07 10:18:18.495 INFO Pop3(1)[1] Command: CAPA
2022-11-07 10:18:18.495 DEBUG Pop3(1)[1] Info: State changed from 'Sending' to 'Reading'.
2022-11-07 10:18:18.514 INFO Pop3(1)[1] Response: +OK Capability list follows
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Downloading'.
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: TOP
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: USER
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: RESP_CODES
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: PIPELINING
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: EXPIRE NEVER
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: UIDL
2022-11-07 10:18:18.514 DEBUG Pop3(1)[1] Response: STLS
2022-11-07 10:18:18.515 DEBUG Pop3(1)[1] Response: SASL PLAIN
2022-11-07 10:18:18.516 DEBUG Pop3(1)[1] Response: .
2022-11-07 10:18:18.516 DEBUG Pop3(1)[1] Info: State changed from 'Downloading' to 'Ready'.
2022-11-07 10:18:18.828 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Sending'.
2022-11-07 10:18:18.828 INFO Pop3(1)[1] Command: AUTH PLAIN
2022-11-07 10:18:18.828 DEBUG Pop3(1)[1] Info: State changed from 'Sending' to 'Reading'.
2022-11-07 10:18:18.848 INFO Pop3(1)[1] Response: +
2022-11-07 10:18:18.873 ERROR Pop3(1)[1] Info: Rebex.Net.Pop3Exception: Invalid POP3 response.
   at Rebex.Net.Pop3.inudi(Boolean p0, Boolean p1, String& p2)
   at Rebex.Net.Pop3.ogpyh(String p0, Boolean p1, Boolean p2)
   at Rebex.Net.Pop3.qgtjx(String p0, String p1, Pop3Authentication p2, GssApiProvider p3)
   at Rebex.Net.Pop3.fzyje(String p0, String p1, Pop3Authentication p2)
by (120 points)
it looks like there is not username/password in the log file even with Verbose:



2022-11-07 10:21:18.138 Opening log file.
2022-11-07 10:21:18.145 INFO FileLogWriter(1)[1] Info: Assembly: Rebex.Common R6.8 for .NET 6.0
2022-11-07 10:21:18.151 INFO FileLogWriter(1)[1] Info: Platform: Windows 11 (Build 22000) 64-bit; CLR: .NET 7.0.0-rc.2.22472.3
2022-11-07 10:21:18.155 DEBUG FileLogWriter(1)[1] Info: Culture: it; windows-1252
2022-11-07 10:21:18.189 DEBUG Pop3(1)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2022-11-07 10:21:18.189 INFO Pop3(1)[1] Info: Connecting to in.alice.it:110 using Pop3.
2022-11-07 10:21:18.189 INFO Pop3(1)[1] Info: Assembly: Rebex.Pop3 R6.8 for .NET 6.0 (Trial)
2022-11-07 10:21:18.189 INFO Pop3(1)[1] Info: Platform: Windows 11 (Build 22000) 64-bit; CLR: .NET 7.0.0-rc.2.22472.3
2022-11-07 10:21:18.189 DEBUG Pop3(1)[1] Info: Culture: it; windows-1252
2022-11-07 10:21:18.196 INFO Pop3(1)[1] Info: Connecting to in.alice.it.
2022-11-07 10:21:18.237 DEBUG Pop3(1)[1] Proxy: Resolving 'in.alice.it'.
2022-11-07 10:21:18.270 DEBUG Pop3(1)[1] Proxy: Connecting to 34.147.41.170:110 (no proxy).
2022-11-07 10:21:18.302 DEBUG Pop3(1)[1] Proxy: Connection established.
2022-11-07 10:21:18.303 DEBUG Pop3(1)[1] Info: Connection succeeded.
2022-11-07 10:21:18.317 DEBUG Pop3(1)[1] Info: State changed from 'Connecting' to 'Reading'.
2022-11-07 10:21:18.319 VERBOSE Pop3(1)[1] Info: Received data:
 0000 |2B-4F-4B-20-50-4F-50-33 20-53-65-72-76-65-72-0D| +OK POP3 Server.
 0010 |0A                                             | .
2022-11-07 10:21:18.320 INFO Pop3(1)[1] Response: +OK POP3 Server
2022-11-07 10:21:18.320 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Ready'.
2022-11-07 10:21:18.322 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Sending'.
2022-11-07 10:21:18.323 VERBOSE Pop3(1)[1] Info: Sent data:
 0000 |43-41-50-41-0D-0A                              | CAPA..
2022-11-07 10:21:18.323 INFO Pop3(1)[1] Command: CAPA
2022-11-07 10:21:18.323 DEBUG Pop3(1)[1] Info: State changed from 'Sending' to 'Reading'.
2022-11-07 10:21:18.344 VERBOSE Pop3(1)[1] Info: Received data:
 0000 |2B-4F-4B-20-43-61-70-61 62-69-6C-69-74-79-20-6C| +OK Capability l
 0010 |69-73-74-20-66-6F-6C-6C 6F-77-73-0D-0A-54-4F-50| ist follows..TOP
 0020 |0D-0A-55-53-45-52-0D-0A 52-45-53-50-5F-43-4F-44| ..USER..RESP_COD
 0030 |45-53-0D-0A-50-49-50-45 4C-49-4E-49-4E-47-0D-0A| ES..PIPELINING..
 0040 |45-58-50-49-52-45-20-4E 45-56-45-52-0D-0A-55-49| EXPIRE NEVER..UI
 0050 |44-4C-0D-0A-53-54-4C-53 0D-0A-53-41-53-4C-20-50| DL..STLS..SASL P
 0060 |4C-41-49-4E-0D-0A-2E-0D 0A                     | LAIN.....
2022-11-07 10:21:18.344 INFO Pop3(1)[1] Response: +OK Capability list follows
2022-11-07 10:21:18.344 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Downloading'.
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: TOP
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: USER
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: RESP_CODES
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: PIPELINING
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: EXPIRE NEVER
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: UIDL
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: STLS
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: SASL PLAIN
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Response: .
2022-11-07 10:21:18.345 DEBUG Pop3(1)[1] Info: State changed from 'Downloading' to 'Ready'.
2022-11-07 10:21:18.352 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Sending'.
2022-11-07 10:21:18.352 VERBOSE Pop3(1)[1] Info: Sent data:
 0000 |41-55-54-48-20-50-4C-41 49-4E-0D-0A            | AUTH PLAIN..
2022-11-07 10:21:18.352 INFO Pop3(1)[1] Command: AUTH PLAIN
2022-11-07 10:21:18.352 DEBUG Pop3(1)[1] Info: State changed from 'Sending' to 'Reading'.
2022-11-07 10:21:18.372 VERBOSE Pop3(1)[1] Info: Received data:
 0000 |2B-0D-0A                                       | +..
2022-11-07 10:21:18.372 INFO Pop3(1)[1] Response: +
2022-11-07 10:21:18.396 ERROR Pop3(1)[1] Info: Rebex.Net.Pop3Exception: Invalid POP3 response.
   at Rebex.Net.Pop3.inudi(Boolean p0, Boolean p1, String& p2)
   at Rebex.Net.Pop3.ogpyh(String p0, Boolean p1, Boolean p2)
   at Rebex.Net.Pop3.qgtjx(String p0, String p1, Pop3Authentication p2, GssApiProvider p3)
   at Rebex.Net.Pop3.fzyje(String p0, String p1, Pop3Authentication p2)

1 Answer

0 votes
by (134k points)

Thanks for the log! The error is caused by a server-side bug in the server's implementation of AUTH PLAIN authentication method. The server violates this part of RFC 5034:

In POP3, an empty server challenge is defined as a line with only
a "+", followed by a single space.

The server at in.alice.it sends the "+" character, but does not send the single space character. Therefore, the response really is invalid and it triggers the "Invalid POP3 response" error in our client.

Please report this to the service vendor so they can fix it.

...