Ask a Question

Fatal error 'ProtocolVersion'

0 votes
by (120 points)

Hello

I get this error on connect to pop3

I need to recover mails, is not the same as: http://forum.rebex.net/3358/tlsexception-fatal-error-protocolversion

       Dim m_pop3RemoteServerAddress = "pop3.example.org"
       Dim tlsParameters As TlsParameters = New TlsParameters
        tlsParameters.Version = TlsVersion.Any
        tlsParameters.AllowedSuites = TlsCipherSuite.All
        tlsParameters.CertificateVerifier = CertificateVerifier.AcceptAll
        tlsParameters.CommonName = m_pop3RemoteServerAddress

        client = New Pop3
        client.Settings.SslAllowedVersions = TlsVersion.Any
        client.Settings.SslAllowedSuites = TlsCipherSuite.All
        client.Settings.SslAcceptAllCertificates = True

        'client.Connect(m_pop3RemoteServerAddress, CInt(m_pop3Port), m_pop3SecurityMode)
        client.Connect(m_pop3RemoteServerAddress, CInt(m_pop3Port), tlsParameters, m_pop3SecurityMode)

The error: System.Exception: An error occurred: Fatal error 'ProtocolVersion' has been encountered on the local connection end.

Some help?
Thanks

by (147k points)
Please create a communication log using Pop3 object's LogWriter property (as described at https://rebex.net/kb/logging/) and either post it here or mail it to support@rebex.net for analysis. Thanks!
by (120 points)
Hello
I put complete log of Rebex:

2019-03-18 13:06:33.367 Opening log file.
2019-03-18 13:06:33.367 INFO FileLogWriter(1)[1] Info: Assembly: Rebex.Common 2018 R4 for .NET 4.0-4.7
2019-03-18 13:06:33.382 INFO FileLogWriter(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-03-18 13:06:33.382 DEBUG FileLogWriter(1)[1] Info: Culture: es; Windows-1252
2019-03-18 13:06:33.429 DEBUG Pop3(1)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2019-03-18 13:06:33.429 INFO Pop3(1)[1] Info: Connecting to popserver:995 using Pop3.
2019-03-18 13:06:33.429 INFO Pop3(1)[1] Info: Assembly: Rebex.Pop3 2018 R4 for .NET 4.0-4.7 (Trial)
2019-03-18 13:06:33.429 INFO Pop3(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-03-18 13:06:33.429 DEBUG Pop3(1)[1] Info: Culture: es; Windows-1252
2019-03-18 13:06:33.429 INFO Pop3(1)[1] Info: Connecting to popserver.
2019-03-18 13:06:33.445 DEBUG Pop3(1)[1] Proxy: Resolving 'popserver'.
2019-03-18 13:06:33.461 DEBUG Pop3(1)[1] Proxy: Connecting to 10.123.6.103:995 (no proxy).
2019-03-18 13:06:33.507 DEBUG Pop3(1)[1] Info: Connection succeeded.
2019-03-18 13:06:33.507 DEBUG Pop3(1)[1] Info: Upgrading connection to TLS/SSL.
2019-03-18 13:06:33.523 INFO Pop3(1)[1] TLS: Warning: SSL 3.0 has been deprecated. According to RFC 7568, it must no longer be used.
2019-03-18 13:06:33.570 DEBUG Pop3(1)[1] TLS: Enabled cipher suites: 0x000FFFFFFFF4F666.
2019-03-18 13:06:33.648 DEBUG Pop3(1)[1] TLS: Applicable cipher suites: 0x000FFFFFFFF4F666.
2019-03-18 13:06:33.695 INFO Pop3(1)[1] TLS: State StateChange:Negotiating
2019-03-18 13:06:33.695 DEBUG Pop3(1)[1] TLS: HandshakeMessage:ClientHello was sent.
2019-03-18 13:06:33.695 DEBUG Pop3(1)[1] TLS: Invalid TLS packet received:
 0000 |2D-45-52-52-20-43-6F-6E 6E-65-63-74-69-6F-6E-20| -ERR Connection
 0010 |69-73-20-63-6C-6F-73-65 64-2E-20-31-33-0D-0A   | is closed. 13..
2019-03-18 13:06:33.742 DEBUG Pop3(1)[1] TLS: Error while processing TLS packet: Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end.
   at jcry.recf()
   at jcry.recg()
2019-03-18 13:06:33.757 INFO Pop3(1)[1] TLS: Alert Alert:Alert was sent.
2019-03-18 13:06:33.757 INFO Pop3(1)[1] TLS: State StateChange:Closed
2019-03-18 13:06:33.757 DEBUG Pop3(1)[1] TLS: Closing TLS socket.
2019-03-18 13:06:33.757 DEBUG Pop3(1)[1] Info: State changed from 'Connecting' to 'Disconnected'.
2019-03-18 13:06:33.757 ERROR Pop3(1)[1] Info: Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end. ---> Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end. ---> Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end.
   at jcry.recf()
   at jcry.recg()
   --- End of inner exception stack trace ---
   at jcry.recg()
   at jcry.recn()
   at Rebex.Net.TlsSocket.Negotiate()
   at lahu.ytil(TlsParameters jz)
   at Rebex.Net.Pop3.ynch(TlsParameters bm, Boolean bn)
   --- End of inner exception stack trace ---
   at Rebex.Net.Pop3.ynch(TlsParameters bm, Boolean bn)
   at Rebex.Net.Pop3.yncf(String bf, Int32 bg, TlsParameters bh, SslMode bi)

1 Answer

0 votes
by (147k points)
edited by

According to the log, the POP3 server sends the following unencrypted error message when the client connects to it and attempts to negotiate a TLS session: "ERR Connection is closed. 13" This triggered a protocol error because POP3 at port 995 is supposed to be sending TLS/SSL packets, not plaintext data.

This is a server-side issue - the POP3 server is simply not willing to negotiate a TLS/SSL session and rejects POP3 clients immediately. The server log should contain more information about this. The issue seems to be similar to this one, which was caused by Microsoft Exchange server with improperly configured certificates.

by (120 points)
Hello

Ok the port is incorrect. Now with correct port 110 i have "2019-04-08 16:32:23.430 DEBUG Pop3(1)[1] TLS: Invalid TLS packet received":

08/04/2019 16:32:23 - Recuperando información desde el servidor outlook.prysmian.gph.local con user sa.cmrma01es
08/04/2019 16:32:23 - Iniciando Rebex Log...
2019-04-08 16:32:23.102 Opening log file.
2019-04-08 16:32:23.102 INFO FileLogWriter(1)[1] Info: Assembly: Rebex.Common 2018 R4 for .NET 4.0-4.7
2019-04-08 16:32:23.102 INFO FileLogWriter(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-04-08 16:32:23.102 DEBUG FileLogWriter(1)[1] Info: Culture: es; Windows-1252
2019-04-08 16:32:23.149 DEBUG Pop3(1)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2019-04-08 16:32:23.149 INFO Pop3(1)[1] Info: Connecting to outlook.prysmian.gph.local:110 using Pop3.
2019-04-08 16:32:23.149 INFO Pop3(1)[1] Info: Assembly: Rebex.Pop3 2018 R4 for .NET 4.0-4.7 (Trial)
2019-04-08 16:32:23.149 INFO Pop3(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-04-08 16:32:23.149 DEBUG Pop3(1)[1] Info: Culture: es; Windows-1252
2019-04-08 16:32:23.149 INFO Pop3(1)[1] Info: Connecting to outlook.prysmian.gph.local.
2019-04-08 16:32:23.180 DEBUG Pop3(1)[1] Proxy: Resolving 'outlook.prysmian.gph.local'.
2019-04-08 16:32:23.180 DEBUG Pop3(1)[1] Proxy: Connecting to 10.123.6.103:110 (no proxy).
2019-04-08 16:32:23.243 DEBUG Pop3(1)[1] Info: Connection succeeded.
2019-04-08 16:32:23.243 DEBUG Pop3(1)[1] Info: Upgrading connection to TLS/SSL.
2019-04-08 16:32:23.258 INFO Pop3(1)[1] TLS: Warning: SSL 3.0 has been deprecated. According to RFC 7568, it must no longer be used.
2019-04-08 16:32:23.290 DEBUG Pop3(1)[1] TLS: Enabled cipher suites: 0x000FFFFFFFF4F666.
2019-04-08 16:32:23.383 DEBUG Pop3(1)[1] TLS: Applicable cipher suites: 0x000FFFFFFFF4F666.
2019-04-08 16:32:23.415 INFO Pop3(1)[1] TLS: State StateChange:Negotiating
2019-04-08 16:32:23.415 DEBUG Pop3(1)[1] TLS: HandshakeMessage:ClientHello was sent.
2019-04-08 16:32:23.430 DEBUG Pop3(1)[1] TLS: Invalid TLS packet received:
 0000 |2B-4F-4B-20-54-68-65-20 4D-69-63-72-6F-73-6F-66| +OK The Microsof
 0010 |74-20-45-78-63-68-61-6E 67-65-20-50-4F-50-33-20| t Exchange POP3
 0020 |73-65-72-76-69-63-65-20 69-73-20-72-65-61-64-79| service is ready
 0030 |2E-0D-0A                                       | ...
2019-04-08 16:32:23.493 DEBUG Pop3(1)[1] TLS: Error while processing TLS packet: Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end.
   at jcry.recf()
   at jcry.recg()
2019-04-08 16:32:23.493 INFO Pop3(1)[1] TLS: Alert Alert:Alert was sent.
2019-04-08 16:32:23.493 INFO Pop3(1)[1] TLS: State StateChange:Closed
2019-04-08 16:32:23.493 DEBUG Pop3(1)[1] TLS: Closing TLS socket.
2019-04-08 16:32:23.493 DEBUG Pop3(1)[1] Info: State changed from 'Connecting' to 'Disconnected'.
2019-04-08 16:32:23.493 ERROR Pop3(1)[1] Info: Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end. ---> Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end. ---> Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end.
   at jcry.recf()
   at jcry.recg()
   --- End of inner exception stack trace ---
   at jcry.recg()
   at jcry.recn()
   at Rebex.Net.TlsSocket.Negotiate()
   at lahu.ytil(TlsParameters jz)
   at Rebex.Net.Pop3.ynch(TlsParameters bm, Boolean bn)
   --- End of inner exception stack trace ---
   at Rebex.Net.Pop3.ynch(TlsParameters bm, Boolean bn)
   at Rebex.Net.Pop3.yncf(String bf, Int32 bg, TlsParameters bh, SslMode bi)

Any idea?
by (147k points)
It looks like you are trying to connect to a POP3 server on port 110 using "implicit TLS/SSL" (SslMode.Implicit). However, port 110 is usually configured to use "explicit TLS/SSL". Please try passing SslMode.Explicit to Pop3 object's Connect method instead.

See https://www.rebex.net/secure-mail.net/features/connecting.aspx#connecting-ssl for additional information on TLS/SSL modes.
by (120 points)
edited by
Hello

I change it and now I have another error

I reminder the code:
            client = New Pop3
            client.LogWriter = new Rebex.FileLogWriter( UtilProj.GetLogFileWithExtension, Rebex.LogLevel.Debug)
            client.Settings.SslAllowedVersions = TlsVersion.Any
            client.Settings.SslAllowedSuites = TlsCipherSuite.All
            client.Settings.SslAcceptAllCertificates = True
            client.Connect(m_pop3RemoteServerAddress, 110, SslMode.Explicit)



Error log:
15/05/2019 16:06:31 - m_pop3RemoteServerAddress xxxxxxxxxxxxxxxxx
15/05/2019 16:06:31 - m_pop3UserName xxxxxxxxxxxxx
15/05/2019 16:06:31 - m_pop3Password xxxxxxxxxxxx
15/05/2019 16:06:31 - m_pop3Port 110
15/05/2019 16:06:31 - m_pop3SecurityMode 1
15/05/2019 16:06:34 - Iniciando Rebex Log...
2019-05-15 16:06:34.275 Opening log file.
2019-05-15 16:06:34.275 INFO FileLogWriter(1)[1] Info: Assembly: Rebex.Common 2018 R4 for .NET 4.0-4.7
2019-05-15 16:06:34.291 INFO FileLogWriter(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-05-15 16:06:34.291 DEBUG FileLogWriter(1)[1] Info: Culture: es; Windows-1252
2019-05-15 16:06:37.359 DEBUG Pop3(1)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2019-05-15 16:06:37.359 INFO Pop3(1)[1] Info: Connecting to outlook.prysmian.gph.local:110 using Pop3.
2019-05-15 16:06:37.359 INFO Pop3(1)[1] Info: Assembly: Rebex.Pop3 2018 R4 for .NET 4.0-4.7 (Trial)
2019-05-15 16:06:37.359 INFO Pop3(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-05-15 16:06:37.359 DEBUG Pop3(1)[1] Info: Culture: es; Windows-1252
2019-05-15 16:06:37.375 INFO Pop3(1)[1] Info: Connecting to outlook.prysmian.gph.local.
2019-05-15 16:06:37.391 DEBUG Pop3(1)[1] Proxy: Resolving 'outlook.prysmian.gph.local'.
2019-05-15 16:06:37.391 DEBUG Pop3(1)[1] Proxy: Connecting to 10.123.6.103:110 (no proxy).
2019-05-15 16:06:37.453 DEBUG Pop3(1)[1] Info: Connection succeeded.
2019-05-15 16:06:37.500 DEBUG Pop3(1)[1] Info: State changed from 'Connecting' to 'Reading'.
2019-05-15 16:06:37.500 INFO Pop3(1)[1] Response: +OK The Microsoft Exchange POP3 service is ready.
2019-05-15 16:06:37.500 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Ready'.
2019-05-15 16:06:37.516 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Sending'.
2019-05-15 16:06:37.516 INFO Pop3(1)[1] Command: CAPA
2019-05-15 16:06:37.516 DEBUG Pop3(1)[1] Info: State changed from 'Sending' to 'Reading'.
2019-05-15 16:06:37.562 INFO Pop3(1)[1] Response: +OK
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Downloading'.
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Response: TOP
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Response: UIDL
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Response: SASL NTLM GSSAPI PLAIN
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Response: USER
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Response: .
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Info: State changed from 'Downloading' to 'Ready'.
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Sending'.
2019-05-15 16:06:37.562 INFO Pop3(1)[1] Command: STLS
2019-05-15 16:06:37.562 DEBUG Pop3(1)[1] Info: State changed from 'Sending' to 'Reading'.
2019-05-15 16:06:37.609 INFO Pop3(1)[1] Response: -ERR Command is not valid in this state.
2019-05-15 16:06:37.609 DEBUG Pop3(1)[1] Info: State changed from 'Reading' to 'Ready'.
2019-05-15 16:06:37.609 DEBUG Pop3(1)[1] Info: State changed from 'Ready' to 'Disconnected'.
2019-05-15 16:06:37.625 ERROR Pop3(1)[1] Info: Rebex.Net.Pop3Exception: Command is not valid in this state.
   at Rebex.Net.Pop3.yncb(Boolean aw, Boolean ax, String& ay)
   at Rebex.Net.Pop3.yncn(TlsParameters bs)
   at Rebex.Net.Pop3.yncf(String bf, Int32 bg, TlsParameters bh, SslMode bi)
2019-05-15 16:06:43.691 DEBUG Pop3(1)[1] Info: State changed from 'Disconnected' to 'Connecting'.
2019-05-15 16:06:43.691 INFO Pop3(1)[1] Info: Connecting to outlook.prysmian.gph.local:110 using Pop3.
2019-05-15 16:06:43.691 INFO Pop3(1)[1] Info: Assembly: Rebex.Pop3 2018 R4 for .NET 4.0-4.7 (Trial)
2019-05-15 16:06:43.691 INFO Pop3(1)[1] Info: Platform: Windows 6.2.9200 32-bit; CLR: 4.0.30319.42000
2019-05-15 16:06:43.691 DEBUG Pop3(1)[1] Info: Culture: es; Windows-1252
2019-05-15 16:06:43.691 INFO Pop3(1)[1] Info: Connecting to outlook.prysmian.gph.local.
2019-05-15 16:06:43.691 DEBUG Pop3(1)[1] Proxy: Resolving 'outlook.prysmian.gph.local'.
2019-05-15 16:06:43.691 DEBUG Pop3(1)[1] Proxy: Connecting to 10.123.6.103:110 (no proxy).
2019-05-15 16:06:43.738 DEBUG Pop3(1)[1] Info: Connection succeeded.
2019-05-15 16:06:43.738 DEBUG Pop3(1)[1] Info: Upgrading connection to TLS/SSL.
2019-05-15 16:06:43.738 INFO Pop3(1)[1] TLS: Warning: SSL 3.0 has been deprecated. According to RFC 7568, it must no longer be used.
2019-05-15 16:06:43.785 DEBUG Pop3(1)[1] TLS: Enabled cipher suites: 0x000FFFFFFFF4F666.
2019-05-15 16:06:43.879 DEBUG Pop3(1)[1] TLS: Applicable cipher suites: 0x000FFFFFFFF4F666.
2019-05-15 16:06:43.910 INFO Pop3(1)[1] TLS: State StateChange:Negotiating
2019-05-15 16:06:43.910 DEBUG Pop3(1)[1] TLS: HandshakeMessage:ClientHello was sent.
2019-05-15 16:06:43.910 DEBUG Pop3(1)[1] TLS: Invalid TLS packet received:
 0000 |2B-4F-4B-20-54-68-65-20 4D-69-63-72-6F-73-6F-66| +OK The Microsof
 0010 |74-20-45-78-63-68-61-6E 67-65-20-50-4F-50-33-20| t Exchange POP3
 0020 |73-65-72-76-69-63-65-20 69-73-20-72-65-61-64-79| service is ready
 0030 |2E-0D-0A                                       | ...
2019-05-15 16:06:43.926 DEBUG Pop3(1)[1] TLS: Error while processing TLS packet: Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end.
   at jcry.recf()
   at jcry.recg()
2019-05-15 16:06:43.926 INFO Pop3(1)[1] TLS: Alert Alert:Alert was sent.
2019-05-15 16:06:43.926 INFO Pop3(1)[1] TLS: State StateChange:Closed
2019-05-15 16:06:43.926 DEBUG Pop3(1)[1] TLS: Closing TLS socket.
2019-05-15 16:06:43.926 DEBUG Pop3(1)[1] Info: State changed from 'Connecting' to 'Disconnected'.
2019-05-15 16:06:43.926 ERROR Pop3(1)[1] Info: Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end. ---> Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end. ---> Rebex.Net.TlsException: Fatal error 'ProtocolVersion' has been encountered on the local connection end.
   at jcry.recf()
   at jcry.recg()
   --- End of inner exception stack trace ---
   at jcry.recg()
   at jcry.recn()
   at Rebex.Net.TlsSocket.Negotiate()
   at lahu.ytil(TlsParameters jz)
   at Rebex.Net.Pop3.ynch(TlsParameters bm, Boolean bn)
   --- End of inner exception stack trace ---
   at Rebex.Net.Pop3.ynch(TlsParameters bm, Boolean bn)
   at Rebex.Net.Pop3.yncf(String bf, Int32 bg, TlsParameters bh, SslMode bi)

Any ideas? Thanks
by (147k points)
The "Command is not valid in this state" error occurred because when the POP3 client asked the POP3 server to negotiate an explicitly-secure TLS/SSL session, the server replied with a strange response. The response actually seems to indicate that the server doesn't seem to support POP3 over explicit TLS at all - instead of starting the negotiation or refusing it, it fails with a generic error that basically means "you are supposed to authenticate first before issuing any non-trivial commands".

The "Fatal error 'ProtocolVersion' has been encountered on the local connection end" occurred because you were trying to establish an implicitly-secure POP3 over TLS/SSL session against a non-implicit POP3 port, which is not going to work. Please try connecting to a different port (usually 995) that supports POP3 implicit TLS/SSL.

For additional information about different modes of TLS/SSL usage, see the following article: https://www.rebex.net/kb/tls-ssl-explicit-implicit/
...