EAP TTLS woes

[adrian.p.smith at bt.com]

I am testing EAP TTLS with Android and finding some mixed results.

Using identical WifiConfig on the devices I see an error on some:

Thu Sep 23 15:01:12 2021 : Debug: (4808) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:01:12 2021 : Debug: (4808) eap_ttls: Initiating new EAP-TLS session
Thu Sep 23 15:01:12 2021 : Debug: (4808) eap_ttls: [eaptls start] = request
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: Authenticate
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: Peer sent flags ---
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: Got final TLS record fragment (131 bytes)
Thu Sep 23 15:01:12 2021 : WARNING: (4809) eap_ttls: Total received TLS record fragments (131 bytes), does not equal indicated TLS record length (0 bytes)
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: [eaptls verify] = ok
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: Done initial handshake
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: (other): before/accept initialization
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: before/accept initialization
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: <<< recv TLS 1.1  [length 007e]
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: SSLv3 read client hello A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: >>> send TLS 1.1  [length 0039]
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: SSLv3 write server hello A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: >>> send TLS 1.1  [length 0bc0]
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: SSLv3 write certificate A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: >>> send TLS 1.1  [length 014b]
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: SSLv3 write key exchange A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: >>> send TLS 1.1  [length 0004]
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: SSLv3 write server done A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: SSLv3 flush data
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: In SSL Handshake Phase
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: In SSL Accept mode
Thu Sep 23 15:01:12 2021 : Debug: (4809) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap_ttls: Authenticate
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap_ttls: Peer sent flags ---
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap_ttls: Peer ACKed our handshake fragment
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap_ttls: [eaptls verify] = request
Thu Sep 23 15:01:12 2021 : Debug: (4810) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap_ttls: Authenticate
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap_ttls: Peer sent flags ---
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap_ttls: Peer ACKed our handshake fragment
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap_ttls: [eaptls verify] = request
Thu Sep 23 15:01:12 2021 : Debug: (4811) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap_ttls: Authenticate
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap_ttls: Peer sent flags ---
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap_ttls: Peer ACKed our handshake fragment
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap_ttls: [eaptls verify] = request
Thu Sep 23 15:01:12 2021 : Debug: (4812) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:01:12 2021 : Debug: (4813) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:01:12 2021 : Debug: (4813) eap_ttls: Authenticate
Thu Sep 23 15:01:12 2021 : Debug: (4813) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:01:12 2021 : Debug: (4813) eap_ttls: Peer sent flags ---
Thu Sep 23 15:01:12 2021 : Debug: (4813) eap_ttls: [eaptls verify] = ok
Thu Sep 23 15:01:12 2021 : Debug: (4813) eap_ttls: Done initial handshake

Thu Sep 23 15:01:12 2021 : Debug: (4813) eap_ttls: <<< recv TLS 1.1  [length 0002]
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: TLS Alert read:fatal:internal error
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: TLS_accept: Failed in SSLv3 read client certificate A
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: Failed in __FUNCTION__ (SSL_read)
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: s3_pkt.c[1275]:error:14094438:SSL routines:SSL3_READ_BYTES:tlsv1 alert internal error
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: s3_pkt.c[992]:error:140940E5:SSL routines:SSL3_READ_BYTES:ssl handshake failure
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: System call (I/O) error (-1)
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: TLS receive handshake failed during operation
Thu Sep 23 15:01:12 2021 : ERROR: (4813) eap_ttls: [eaptls process] = fail


The working device shows this log:

Thu Sep 23 15:07:35 2021 : Debug: (4844) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4844) eap_ttls: Initiating new EAP-TLS session
Thu Sep 23 15:07:35 2021 : Debug: (4844) eap_ttls: [eaptls start] = request
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: Authenticate
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: Peer sent flags ---
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: Got final TLS record fragment (141 bytes)
Thu Sep 23 15:07:35 2021 : WARNING: (4845) eap_ttls: Total received TLS record fragments (141 bytes), does not equal indicated TLS record length (0 bytes)
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: [eaptls verify] = ok
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: Done initial handshake
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: (other): before/accept initialization
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: before/accept initialization
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: <<< recv TLS 1.1  [length 0088]
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: SSLv3 read client hello A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: >>> send TLS 1.1  [length 0039]
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: SSLv3 write server hello A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: >>> send TLS 1.1  [length 0bc0]
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: SSLv3 write certificate A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: >>> send TLS 1.1  [length 014b]
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: SSLv3 write key exchange A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: >>> send TLS 1.1  [length 0004]
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: SSLv3 write server done A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: SSLv3 flush data
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: In SSL Handshake Phase
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: In SSL Accept mode
Thu Sep 23 15:07:35 2021 : Debug: (4845) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap_ttls: Authenticate
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap_ttls: Peer sent flags ---
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap_ttls: Peer ACKed our handshake fragment
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap_ttls: [eaptls verify] = request
Thu Sep 23 15:07:35 2021 : Debug: (4846) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap_ttls: Authenticate
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap_ttls: Peer sent flags ---
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap_ttls: Peer ACKed our handshake fragment
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap_ttls: [eaptls verify] = request
Thu Sep 23 15:07:35 2021 : Debug: (4847) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap_ttls: Authenticate
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap_ttls: Peer sent flags ---
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap_ttls: Peer ACKed our handshake fragment
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap_ttls: [eaptls verify] = request
Thu Sep 23 15:07:35 2021 : Debug: (4848) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: Authenticate
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: Peer sent flags ---
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: [eaptls verify] = ok
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: Done initial handshake

Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: <<< recv TLS 1.1  [length 0046]
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: TLS_accept: SSLv3 read client key exchange A
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: <<< recv TLS 1.1  [length 0001]
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: <<< recv TLS 1.1  [length 0010]
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: TLS_accept: SSLv3 read finished A
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: >>> send TLS 1.1  [length 0001]
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: TLS_accept: SSLv3 write change cipher spec A
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: >>> send TLS 1.1  [length 0010]
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: TLS_accept: SSLv3 write finished A
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: TLS_accept: SSLv3 flush data
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: (other): SSL negotiation finished successfully
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: SSL Connection Established
Thu Sep 23 15:07:35 2021 : Debug: (4849) eap_ttls: [eaptls process] = handled
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap: Calling submodule eap_ttls to process data
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: Authenticate
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: Continuing EAP-TLS
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: Peer sent flags ---
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: [eaptls verify] = ok
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: Done initial handshake
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: [eaptls process] = ok
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: Session established.  Proceeding to decode tunneled attributes
Thu Sep 23 15:07:35 2021 : Debug: (4850) eap_ttls: Got tunneled request



Any clues appreciated.

Adrian Smith