Freeradius 3.0.21+dfsg-3build1 fails test of moonshot-gss-eap

[Christian Ehrhardt ]

As part of the openssl3 transition [1] built fine.
But it got stuck in proposed due to the test of moonshot-gss-eap failing on all architectures [2].

Note: ssl deps worked find
 Depends: libc6 (>= 2.34), libcap2 (>= 1:2.10), libpcap0.8 (>= 1.0.0), libpcre3, libssl3 (>= 3.0.0~~alpha1), libtalloc2 (>= 2.0.4~git20101213)

Ginggs and Vorlon already tried to retry the run, but the result seems to be reproducible.
A migration-reference/0 run worked so we can't reset it that way either and need to investigate what is broken.

The error around gss eap encryption might indicate a real issue with openssl3 in this case:

autopkgtest [01:23:20]: test gss-client: [-----------------------
/etc/freeradius/3.0/sites-enabled /tmp/autopkgtest.n36ySc/build.67K/src
/tmp/autopkgtest.n36ySc/build.67K/src
gss_acquire_cred: 0/0
gss_acquire_cred: 0/0
gss_acquire_cred: 0/0
gss_acquire_cred: 0/0
starting...
gss_acquire_cred: 0/0
gss_acquire_cred: 0/0
gss_acquire_cred: 0/0
dbus-daemon[3317]: [session uid=0 pid=3317] Activating service name='org.janet.Moonshot' requested by ':1.0' (uid=0 pid=3314 comm="gss-client -spnego localhost host@localhost testme" label="unconfined")
dbus-daemon[3317]: [session uid=0 pid=3317] Successfully activated service 'org.janet.Moonshot'
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state IDLE
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=0 method=1 vendor=0 vendorMethod=0
EAP: EAP entering state IDENTITY
CTRL-EVENT-EAP-STARTED EAP authentication started
EAP: Status notification: started (param=)
EAP: EAP-Request Identity data - hexdump_ascii(len=0):
EAP: using anonymous identity - hexdump_ascii(len=9):
Could not connect to dbus session bus. (DBUS_SESSION_BUS_ADDRESS="unix:abstract=/tmp/dbus-x7alEQSVuk,guid=58444b39b51122ff1552b7e561ba9509")
You may want to unset DBUS_SESSION_BUS_ADDRESS or try 'dbus-run-session' to start a session bus.
     40 74 65 73 74 2e 63 6f 6d @test.com
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=1 method=4 vendor=0 vendorMethod=0
EAP: EAP entering state GET_METHOD
EAP: configuration does not allow: vendor 0 method 4
EAP: vendor 0 method 4 not allowed
CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
EAP: Status notification: refuse proposed method (param=MD5)
EAP: Building EAP-Nak (requested type 4 vendor=0 method=0 not allowed)
EAP: allowed methods - hexdump(len=1): 15
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=2 method=21 vendor=0 vendorMethod=0
EAP: EAP entering state GET_METHOD
CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21
EAP: Status notification: accept proposed method (param=TTLS)
EAP: Initialize selected EAP method: vendor 0 method 21 (TTLS)
EAP-TTLS: Phase2 type: EAP
TLS: Phase2 EAP types - hexdump(len=72): 00 00 00 00 04 00 00 00 00 00 00 00 1a 00 00 00 00 00 00 00 06 00 00 00 00 00 00 00 05 00 00 00 00 00 00 00 11 00 00 00 00 00 00 00 2f 00 00 00 00 00 00 00 2e 00 00 00 00 00 00 00 30 00 00 00 00 00 00 00 33 00 00 00
TLS: using phase1 config options
CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected
EAP: EAP entering state METHOD
SSL: Received packet(len=6) - Flags 0x20
EAP-TTLS: Start (server ver=0, own ver=0)
SSL: (where=0x10 ret=0x1)
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:before SSL initialization
OpenSSL: TX ver=0x301 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
OpenSSL: TX ver=0x303 content_type=22 (handshake/client hello)
OpenSSL: Message - hexdump(len=183): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS write client hello
SSL: (where=0x1002 ret=0xffffffff)
SSL: SSL_connect:error in SSLv3/TLS write client hello
SSL: SSL_connect - want more data
SSL: 188 bytes pending from ssl_out
SSL: 188 bytes left to be sent out (of total 188 bytes)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL eapRespData=0x562fe1abccd0
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=3 method=21 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=1004) - Flags 0xc0
SSL: TLS Message Length: 1262
SSL: Need 268 bytes more input data
SSL: Building ACK (type=21 id=3 ver=0)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL eapRespData=0x562fe1abd950
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=4 method=21 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=278) - Flags 0x80
SSL: TLS Message Length: 1262
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS write client hello
OpenSSL: RX ver=0x303 content_type=22 (handshake/server hello)
OpenSSL: Message - hexdump(len=61): [REMOVED]
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS read server hello
OpenSSL: RX ver=0x303 content_type=22 (handshake/certificate)
OpenSSL: Message - hexdump(len=844): [REMOVED]
TLS: tls_verify_cb - preverify_ok=1 err=18 (self-signed certificate) ca_cert_verify=0 depth=0 buf='/CN=autopkgtest'
EAP: Status notification: remote certificate verification (param=success)
TLS: tls_verify_cb - preverify_ok=1 err=18 (self-signed certificate) ca_cert_verify=0 depth=0 buf='/CN=autopkgtest'
EAP: Status notification: remote certificate verification (param=success)
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS read server certificate
OpenSSL: RX ver=0x303 content_type=22 (handshake/server key exchange)
OpenSSL: Message - hexdump(len=333): [REMOVED]
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS read server key exchange
OpenSSL: RX ver=0x303 content_type=22 (handshake/server hello done)
OpenSSL: Message - hexdump(len=4): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS read server done
OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
OpenSSL: TX ver=0x303 content_type=22 (handshake/client key exchange)
OpenSSL: Message - hexdump(len=70): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS write client key exchange
OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
OpenSSL: TX ver=0x303 content_type=20 (change cipher spec/)
OpenSSL: Message - hexdump(len=1): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS write change cipher spec
OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
OpenSSL: TX ver=0x303 content_type=22 (handshake/finished)
OpenSSL: Message - hexdump(len=16): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS write finished
SSL: (where=0x1002 ret=0xffffffff)
SSL: SSL_connect:error in SSLv3/TLS write finished
SSL: SSL_connect - want more data
SSL: 126 bytes pending from ssl_out
SSL: 126 bytes left to be sent out (of total 126 bytes)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL eapRespData=0x562fe1ad9b10
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=5 method=21 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=61) - Flags 0x80
SSL: TLS Message Length: 51
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS write finished
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS read change cipher spec
OpenSSL: RX ver=0x303 content_type=22 (handshake/finished)
OpenSSL: Message - hexdump(len=16): [REMOVED]
SSL: (where=0x1001 ret=0x1)
SSL: SSL_connect:SSLv3/TLS read finished
SSL: (where=0x20 ret=0x1)
SSL: (where=0x1002 ret=0x1)
SSL: 0 bytes pending from ssl_out
OpenSSL: Handshake finished - resumed=0
SSL: No Application Data included
SSL: No data to be sent out
EAP-TTLS: TLS done, proceed to Phase 2
EAP-TTLS: Derived key - hexdump(len=64): [REMOVED]
EAP-TTLS: Derived EMSK - hexdump(len=64): [REMOVED]
EAP-TTLS: Derived Session-Id - hexdump(len=65): 15 35 93 ac a6 ce 34 49 a7 3c e9 38 71 78 d0 62 9a ac 71 00 a2 b6 13 cf 35 60 f4 6a 36 80 64 2f c1 4e 5e 8a 13 30 b3 89 bd 13 fa 84 72 4b 1e 82 3d 6a 61 eb d5 15 e2 b9 80 af c8 54 ed 8a 63 4e 0a
EAP-TTLS: received 0 bytes encrypted data for Phase 2
EAP-TTLS: empty data in beginning of Phase 2 - use fake EAP-Request Identity
EAP-TTLS: Phase 2 EAP Request: type=1
EAP: using real identity - hexdump_ascii(len=14):
     73 74 65 76 65 40 74 65 73 74 2e 63 6f 6d <email address hidden>
EAP-TTLS: AVP encapsulate EAP Response - hexdump(len=19): 02 00 00 13 01 73 74 65 76 65 40 74 65 73 74 2e 63 6f 6d
EAP-TTLS: Encrypting Phase 2 data - hexdump(len=28): [REMOVED]
OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: 57 bytes left to be sent out (of total 57 bytes)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=FAIL eapRespData=0x562fe1abda70
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=6 method=21 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=71) - Flags 0x80
SSL: TLS Message Length: 61
EAP-TTLS: received 61 bytes encrypted data for Phase 2
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
EAP-TTLS: Decrypted Phase 2 AVPs - hexdump(len=32): 00 00 00 4f 40 00 00 1e 01 01 00 16 04 10 b2 0e 3d 18 38 47 0e 21 a4 89 f8 17 5a 3a 34 e4 00 00
EAP-TTLS: AVP: code=79 flags=0x40 length=30
EAP-TTLS: AVP data - hexdump(len=22): 01 01 00 16 04 10 b2 0e 3d 18 38 47 0e 21 a4 89 f8 17 5a 3a 34 e4
EAP-TTLS: AVP - EAP Message
EAP-TTLS: Phase 2 EAP - hexdump(len=22): 01 01 00 16 04 10 b2 0e 3d 18 38 47 0e 21 a4 89 f8 17 5a 3a 34 e4
EAP-TTLS: received Phase 2: code=1 identifier=1 length=22
EAP-TTLS: Phase 2 EAP Request: type=4
EAP-TTLS: Selected Phase 2 EAP vendor 0 method 4
EAP-MD5: Challenge - hexdump(len=16): b2 0e 3d 18 38 47 0e 21 a4 89 f8 17 5a 3a 34 e4
EAP-MD5: Generating Challenge Response
EAP-MD5: Response - hexdump(len=16): 15 e3 07 81 04 1a 85 18 ee fc 53 db 85 89 d9 2d
EAP-TTLS: AVP encapsulate EAP Response - hexdump(len=22): 02 01 00 16 04 10 15 e3 07 81 04 1a 85 18 ee fc 53 db 85 89 d9 2d
EAP-TTLS: Encrypting Phase 2 data - hexdump(len=68): [REMOVED]
OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
SSL: 97 bytes left to be sent out (of total 97 bytes)
EAP-TTLS: Authentication completed successfully (MAY_CONT)
EAP: method process -> ignore=FALSE methodState=MAY_CONT decision=COND_SUCC eapRespData=0x562fe1ad02a0
EAP: Session-Id - hexdump(len=65): 15 35 93 ac a6 ce 34 49 a7 3c e9 38 71 78 d0 62 9a ac 71 00 a2 b6 13 cf 35 60 f4 6a 36 80 64 2f c1 4e 5e 8a 13 30 b3 89 bd 13 fa 84 72 4b 1e 82 3d 6a 61 eb d5 15 e2 b9 80 af c8 54 ed 8a 63 4e 0a
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
gss_accept_sec_context: 1/0
EAP: EAP entering state RECEIVED
EAP: Received EAP-Request id=7 method=21 vendor=0 vendorMethod=0
EAP: EAP entering state METHOD
SSL: Received packet(len=75) - Flags 0x80
SSL: TLS Message Length: 65
EAP-TTLS: received 65 bytes encrypted data for Phase 2
OpenSSL: RX ver=0x303 content_type=256 (TLS header info/)
OpenSSL: Message - hexdump(len=5): [REMOVED]
EAP-TTLS: Decrypted Phase 2 AVPs - hexdump(len=36): 00 00 00 87 c0 00 00 21 00 00 64 16 02 00 11 01 a4 06 68 6f 73 74 a5 0b 6c 6f 63 61 6c 68 6f 73 74 00 00 00
EAP-TTLS: AVP: code=135 flags=0xc0 length=33
EAP-TTLS: AVP vendor_id 25622
EAP-TTLS: AVP data - hexdump(len=21): 02 00 11 01 a4 06 68 6f 73 74 a5 0b 6c 6f 63 61 6c 68 6f 73 74
EAP-TTLS: AVP - Channel Binding Message
EAP-TTLS: Authentication completed successfully
SSL: Building ACK (type=21 id=7 ver=0)
EAP: method process -> ignore=FALSE methodState=DONE decision=COND_SUCC eapRespData=0x562fe1abdca0
EAP: Session-Id - hexdump(len=65): 15 35 93 ac a6 ce 34 49 a7 3c e9 38 71 78 d0 62 9a ac 71 00 a2 b6 13 cf 35 60 f4 6a 36 80 64 2f c1 4e 5e 8a 13 30 b3 89 bd 13 fa 84 72 4b 1e 82 3d 6a 61 eb d5 15 e2 b9 80 af c8 54 ed 8a 63 4e 0a
EAP: EAP entering state SEND_RESPONSE
EAP: EAP entering state IDLE
gss_init_sec_context: 1/0
### finalize_class::finalize_class(): Constructing
GSS-API error accepting context: Invalid credential was supplied
GSS-API error accepting context: Authentication rejected by RADIUS server
gss_accept_sec_context: 655360/2109382925
### ~finalize_class::~finalize_class() : initStatus=00100000
### gssEapFinalize()
EAP: deinitialize previously used EAP method (21, TTLS) at EAP deinit
gss_init_sec_context: 655360/2109382925
sending token length: Broken pipe
### finalize_class::finalize_class(): Constructing
Sending init_sec_context token (size=81)...continue needed...
Sending init_sec_context token (size=50)...continue needed...
Sending init_sec_context token (size=42)...continue needed...
Sending init_sec_context token (size=235)...continue needed...
Sending init_sec_context token (size=42)...continue needed...
Sending init_sec_context token (size=173)...continue needed...
Sending init_sec_context token (size=99)...continue needed...
Sending init_sec_context token (size=142)...continue needed...
Sending init_sec_context token (size=42)...continue needed...
Sending init_sec_context token (size=9)...### ~finalize_class::~finalize_class() : initStatus=00100000
### gssEapFinalize()
autopkgtest [01:23:23]: test gss-client: -----------------------]
gss-client FAIL non-zero exit status 1autopkgtest [01:23:23]: test gss-client: - - - - - - - - - - results - - - - - - - - - -

[1]: https://launchpad.net/ubuntu/+source/freeradius/3.0.21+dfsg-3build1
[2]: https://autopkgtest.ubuntu.com/results/autopkgtest-jammy/jammy/amd64/m/moonshot-gss-eap/20211216_012335_fb8b5@/log.gz

[Christian Ehrhardt  (paelzer)]

Reproducible in local autopkgtest

Good:
### gss_eap_shib_attr_provider::init(): Initializing ShibResolver library
### finalize_class::finalize_class(): Constructing
Sending init_sec_context token (size=81)...continue needed...
Sending init_sec_context token (size=50)...continue needed...
Sending init_sec_context token (size=42)...continue needed...
Sending init_sec_context token (size=235)...continue needed...
Sending init_sec_context token (size=42)...continue needed...
Sending init_sec_context token (size=173)...continue needed...
Sending init_sec_context token (size=99)...continue needed...
Sending init_sec_context token (size=142)...continue needed...
Sending init_sec_context token (size=42)...continue needed...
Sending init_sec_context token (size=60)...continue needed...

context flag: GSS_C_MUTUAL_FLAG
context flag: GSS_C_REPLAY_FLAG
context flag: GSS_C_SEQUENCE_FLAG
context flag: GSS_C_CONF_FLAG
context flag: GSS_C_INTEG_FLAG
"<email address hidden>" to "host/localhost", lifetime -1, flags 13e, locally initiated, open
Name type of source name is { 1 2 840 113554 1 2 1 1 }.
Mechanism { 1 3 6 1 5 5 15 1 1 17 } supports 6 names
  0: { 1 2 840 113554 1 2 1 1 }
  1: { 1 2 840 113554 1 2 1 4 }
  2: { 1 3 6 1 5 6 4 }
  3: { 1 3 6 1 5 6 6 }
  4: { 1 3 6 1 5 5 15 2 1 }
  5: { 1 3 6 1 5 6 3 }
Signature verified.
### finalize_class::finalize_class(): Constructing
2021-12-16 09:44:16 WARN Shibboleth.Application : no MetadataProvider available, configure at least one for standard SSO usage
2021-12-16 09:44:16 ERROR OpenSSL : error code: 33558530 in ../crypto/bio/bss_file.c, line 288
2021-12-16 09:44:16 ERROR OpenSSL : error data: fopen('/etc/shibboleth/sp-signing-key.pem','r')
2021-12-16 09:44:16 ERROR OpenSSL : error code: 537346050 in ../crypto/bio/bss_file.c, line 290
2021-12-16 09:44:16 ERROR XMLTooling.CredentialResolver.Chaining : caught exception processing embedded CredentialResolver element: Unable to load private key from file (/etc/shibboleth/sp-signing-key.pem).
2021-12-16 09:44:16 ERROR OpenSSL : error code: 33558530 in ../crypto/bio/bss_file.c, line 288
2021-12-16 09:44:16 ERROR OpenSSL : error data: fopen('/etc/shibboleth/sp-encrypt-key.pem','r')
2021-12-16 09:44:16 ERROR OpenSSL : error code: 537346050 in ../crypto/bio/bss_file.c, line 290
2021-12-16 09:44:16 ERROR XMLTooling.CredentialResolver.Chaining : caught exception processing embedded CredentialResolver element: Unable to load private key from file (/etc/shibboleth/sp-encrypt-key.pem).
context flag: GSS_C_MUTUAL_FLAG
context flag: GSS_C_REPLAY_FLAG
context flag: GSS_C_SEQUENCE_FLAG
context flag: GSS_C_CONF_FLAG
context flag: GSS_C_INTEG_FLAG
Attribute urn:ietf:params:gss:radius-attribute 79 Authenticated Complete

03070004

Attribute urn:ietf:params:gss:radius-attribute 80 Authenticated Complete

fea2dc1b41a181201e5650cd85cf90f5

Attribute urn:ietf:params:gss:radius-attribute 1 Authenticated Complete

@test.com

40746573742e636f6d

Accepted connection: "@test.com"
Received message: "testmessage"
NOOP token
### ShibFinalizer::ShibFinalizer(): Constructing
### gssEapAttrProvidersInitInternal(): Calling gssEapSamlAttrProvidersInit()
### gssEapAttrProvidersInitInternal(): Setti...

[Sam Hartman (hartmans)]

>>>>> "Christian" == Christian Ehrhardt  <email address hidden> writes:

    Christian> Reproducible in local autopkgtest

Let me make sure I'm understanding.
You are saying that prior to penssl 3, the test works, but with
openssl3, the test fails?

What is the ssl version in the successful tests?
For example from the failing test we have:
OpenSSL: TX ver=0x303 content_type=22 (handshake/client hello)

What's the txver from that message in the successful test?
Unfortunately, EAP-TTLS is a bit sensitive to the TLS protocol version
in use for some annoying standardization reasons.

It looks like things are failing on the server side.
The autopkgtest produces the freeradius log (which is admittedly huge)
as a test artifact.
Could I get a pointer to a failing freeradius log?

I'm also going to bring this bug to the attention of Moonshot upstream.

[Alan DeKok (aland-freeradius)]

My $0.02 is to try the head of v3.0.x. I don't recall if we put in fixes specifically for OpenSSL 3, but perhaps.

We've also *significantly* updated the TLS debugging output. It's a lot clearer, and gives a lot more information.

[Christian Ehrhardt  (paelzer)]

Hi Sam and Alan,

> Christian> Reproducible in local autopkgtest
>
> Let me make sure I'm understanding.
> You are saying that prior to penssl 3, the test works, but with
> openssl3, the test fails?

Yes that is correct

> What is the ssl version in the successful tests?
> For example from the failing test we have:
> OpenSSL: TX ver=0x303 content_type=22 (handshake/client hello)

Good: 1.1.1l-1ubuntu1
Bad: 3.0.0-1ubuntu1

But to be complete, since not all components have let go of libssl1.1 we always have both ssl versions installed. Just freeradius is linking to one or the other.

Good:
ubuntu@autopkgtest:~$ dpkg -l libssl3 libssl1.1 freeradius moonshot-gss-eap
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-================-===============-============-============================================================
ii freeradius 3.0.21+dfsg-3 amd64 high-performance and highly configurable RADIUS server
ii libssl1.1:amd64 1.1.1l-1ubuntu1 amd64 Secure Sockets Layer toolkit - shared libraries
ii libssl3:amd64 3.0.0-1ubuntu1 amd64 Secure Sockets Layer toolkit - shared libraries
ii moonshot-gss-eap 1.0.1-6ubuntu2 amd64 Moonshot Federated Authentication - authentication mechanism
ubuntu@autopkgtest:~$ ldd /usr/sbin/freeradius | grep ssl
 libssl.so.1.1 => /lib/x86_64-linux-gnu/libssl.so.1.1 (0x00007f0d3a268000)

Bad:
ubuntu@autopkgtest:~$ dpkg -l libssl3 libssl1.1 freeradius moonshot-gss-eap
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-================-===================-============-============================================================
ii freeradius 3.0.21+dfsg-3build1 amd64 high-performance and highly configurable RADIUS server
ii libssl1.1:amd64 1.1.1l-1ubuntu1 amd64 Secure Sockets Layer toolkit - shared libraries
ii libssl3:amd64 3.0.0-1ubuntu1 amd64 Secure Sockets Layer toolkit - shared libraries
ii moonshot-gss-eap 1.0.1-6ubuntu2 amd64 Moonshot Federated Authentication - authentication mechanism
ubuntu@autopkgtest:~$ ldd /usr/sbin/freeradius | grep ssl
 libssl.so.3 => /lib/x86_64-linux-gnu/libssl.so.3 (0x00007f965de31000)

> What's the txver from that message in the successful test?
> Unfortunately, EAP-TTLS is a bit sensitive to the TLS protocol version
> in use for some annoying standardization reasons.

Interestingly that is the same in both:
Good: OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)
Bad: OpenSSL: TX ver=0x303 content_type=256 (TLS header info/)

But that is probably defined by moonshot who in Ubuntu [1] had a no change rebuild against the new openssl.

[1]: https://launchpad.net/ubuntu/+source/moonshot-gss-eap/1.0.1-6ubuntu2

> It looks like things are failing on the server side.
> The autopkgtest produces the...

[Alan DeKok (aland-freeradius)]

I would suggest trying 3.0.25. If that works, don't even bother trying to debug this. OpenSSL has minor behavior differences across a major version change.

[Andreas Hasenack (ahasenack)]

Thanks Alan, I'll try that

[Andreas Hasenack (ahasenack)]

Plain 3.0.25 didn't work, and I had to patch it because openssl3 got rid of FIPS_mode(). I didn't cherry pick any other changes from master, but there may be others. Might try the v3.0.x branch

[Andreas Hasenack (ahasenack)]

I think I found the fix in the v3.0.x branch, testing.

[Andreas Hasenack (ahasenack)]

With this patch https://github.com/FreeRADIUS/freeradius-server/commit/a1f5fd2213c0104d0e124d804ab8c210c9fedb18:

From a1f5fd2213c0104d0e124d804ab8c210c9fedb18 Mon Sep 17 00:00:00 2001
From: "Alan T. DeKok" <email address hidden>
Date: Thu, 30 Dec 2021 15:31:55 -0500
Subject: [PATCH] OpenSSL3 sends invalid content types all of the time...

---
 src/main/cb.c | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/src/main/cb.c b/src/main/cb.c
index 372b8fa8228..0796914b41f 100644
--- a/src/main/cb.c
+++ b/src/main/cb.c
@@ -132,11 +132,11 @@ void cbtls_msg(int write_p, int msg_version, int content_type,
  tls_session_t *state = (tls_session_t *)arg;

  /*
- * OpenSSL 1.0.2 calls this function with 'pseudo'
- * content types. Which breaks our tracking of
- * the SSL Session state.
+ * OpenSSL calls this function with 'pseudo' content
+ * types. Which breaks our tracking of the SSL Session
+ * state.
   */
- if ((msg_version == 0) && (content_type > UINT8_MAX)) {
+ if ((msg_version == 0) || (content_type >= UINT8_MAX)) {
   DEBUG4("(TLS) Ignoring cbtls_msg call with pseudo content type %i, version %i",
          content_type, msg_version);
   return;

The test passes, and it does log "Ignoring cbtls_msg call ..." multiple times:
...
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: Authenticate
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: Continuing EAP-TLS
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: Peer sent flags ---
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: [eaptls verify] = ok
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: Done initial handshake
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: (other): before SSL initialization
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: TLS_accept: before SSL initialization
Fri Jan 7 13:42:19 2022 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 769
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: TLS_accept: before SSL initialization
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: <<< recv TLS 1.3 [length 00b7]
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: TLS_accept: SSLv3/TLS read client hello
Fri Jan 7 13:42:19 2022 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 771
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: >>> send TLS 1.2 [length 003d]
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: TLS_accept: SSLv3/TLS write server hello
Fri Jan 7 13:42:19 2022 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 771
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: >>> send TLS 1.2 [length 0345]
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: TLS_accept: SSLv3/TLS write certificate
Fri Jan 7 13:42:19 2022 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 771
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: >>> send TLS 1.2 [length 014d]
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: TLS_accept: SSLv3/TLS write key exchange
Fri Jan 7 13:42:19 2022 : Debug: Ignoring cbtls_msg call with pseudo content type 256, version 771
Fri Jan 7 13:42:19 2022 : Debug: (2) eap_ttls: >>> send TLS 1.2 [length 0004]
...

I thought this would also be needed https://github.com/FreeRADIUS/free...

[Alan DeKok (aland-freeradius)]

There are a LOT of changes required to get FreeRADIUS working with OpenSSL3.

We will be releasing 3.0.26 in January to address these, and other issues. I'd suggest waiting for that.

[Andreas Hasenack (ahasenack)]

> Debug: Ignoring cbtls_msg call with pseudo content type 256, version 769

These troubled me a bit. When there is pseudo content type, the docs say the version is set to 0. From https://www.openssl.org/docs/man3.0/man3/SSL_CTX_set_msg_callback.html:

version

    The protocol version according to which the protocol message is interpreted by the library such as TLS1_3_VERSION, TLS1_2_VERSION etc. This is set to 0 for the SSL3_RT_HEADER pseudo content type (see NOTES below).

But we see version set to 769, then 771. And the code was correctly checking for version 0 AND some content_type, but the patch changes that to an OR.

I then found this openssl bug, still open: https://github.com/openssl/openssl/issues/17262
"SSL_CTX_set_msg_callback - cb function version argument in 3.0.0 does not match documentation"

So I now understand the OR change, just not why content_type is compared with UINT8_MAX. The docs say that pseudo content types have very specific values. Again from that manpage:

content_type

    This is one of the content type values defined in the protocol specification (SSL3_RT_CHANGE_CIPHER_SPEC, SSL3_RT_ALERT, SSL3_RT_HANDSHAKE; but never SSL3_RT_APPLICATION_DATA because the callback will only be called for protocol messages). Alternatively it may be a "pseudo" content type. These pseudo content types are used to signal some other event in the processing of data (see NOTES below).

And

Pseudo content type values may be sent at various points during the processing of data. The following pseudo content types are currently defined:

SSL3_RT_HEADER
(...)
SSL3_RT_INNER_CONTENT_TYPE

All of these I found defined in /usr/include/openssl/ssl3.h:
$ grep -E "^#[[:blank:]]*define.*(SSL3_RT_CHANGE_CIPHER_SPEC|SSL3_RT_ALERT|SSL3_RT_HANDSHAKE|SSL3_RT_HEADER|SSL3_RT_INNER_CONTENT_TYPE)" -w /usr/include/openssl/ssl3.h
# define SSL3_RT_CHANGE_CIPHER_SPEC 20
# define SSL3_RT_ALERT 21
# define SSL3_RT_HANDSHAKE 22
# define SSL3_RT_HEADER 0x100
# define SSL3_RT_INNER_CONTENT_TYPE 0x101

While they are all less than UINT8_MAX, UINT8_MAX seems an arbitrary threshold, unless it's mentioned in some other documentation I didn't find yet.

[Andreas Hasenack (ahasenack)]

> We will be releasing 3.0.26 in January to address these, and other issues. I'd suggest waiting for that.

Thanks Alan!

[Alan DeKok (aland-freeradius)]

> So I now understand the OR change, just not why content_type is compared with UINT8_MAX.

The TLS specification (RFC 8446, among others) says that the ContentType field is an 8-bit value.

Therefore anything past that is not a real content type, and is "invented" by OpenSSL.

[Simon Chopin (schopin)]

Hi,

The feature freeze is looming closer :)

Alan, is there any visibility on the 3.0.26 release?

Thanks in advance :)

[Alan DeKok (aland-freeradius)]

We'll try to get it out this week.

[Launchpad Janitor (janitor)]

This bug was fixed in the package freeradius - 3.0.26~dfsg~git20220223.1.00ed0241fa-0ubuntu2

---------------
freeradius (3.0.26~dfsg~git20220223.1.00ed0241fa-0ubuntu2) jammy; urgency=medium

  * Fix radtest client crash when using mschap auth (LP: #1962046):
    - d/p/fix-mschap-client-crash-1.patch: load the OpenSSL legacy
      providers
    - d/p/fix-mschap-client-crash-2.patch: need OpenSSL3 init for
      MD5 too
    - d/t/test-freeradius.py: test more authentication mechanisms

 -- Andreas Hasenack <email address hidden> Fri, 25 Feb 2022 10:19:18 -0300