Thanks Quinn,
I'm working on getting a packet capture if I can, and am adding in more logging to our own tools to see if I can suss any more details out of what is happening. It feels like a network issue, but we can't replicate it on demand at the customer site or in our labs.
The TLS events I am interested in are 1, 2, 11, 12, 14, and 20. More than anything I guess I'm looking for a sanity check that I'm interperting these logs properly.
Annotated, and redacted, logs below. This Mac is on 10.13.6 and Wi-Fi.
Here we see the program flow from the user clicking "Sign In" all the way to the network disconnect.
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] Sign In button clicked
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] Format user and domain strings
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] Using managed domain
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] Removing domain from username
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:NoLoSwiftMech] Checking for local username
SecurityAgent: (CFOpenDirectory) Open a given node
SecurityAgent: (CFOpenDirectory) Querying records from directories
SecurityAgent: (CFOpenDirectory) Closing a node reference
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:NoLoSwiftMech] Results of local user check false
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] NoMAD Login User: ark, Domain: .okta.com
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] Attempt to authenticate user
The initial connection starts up:
First uses of a http call so the Cookie Store needs some setup:
SecurityAgent: (CFNetwork) Faulting in NSHTTPCookieStorage singleton
SecurityAgent: (CFNetwork) Faulting in CFHTTPCookieStorage singleton
SecurityAgent: (CFNetwork) Creating default cookie storage with process/bundle identifier
Connection setup starts:
SecurityAgent: (CFNetwork) TIC Enabling TLS [1:0x7fd4d7569120]
SecurityAgent: (CFNetwork) TIC TCP Conn Start [1:0x7fd4d7569120]
SecurityAgent: (CFNetwork) Task <980F7176-A1CB-4699-974A-5E11AC4282C9>.<1> setting up Connection 1
SecurityAgent: (libnetwork.dylib) [com.apple.network:] [1 ] start
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_start [1 .okta.com:443 initial path (null)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 initial path (null)] reported event path:start
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 waiting path (satisfied)] reported event path:satisfied path: [satisfied (Path is satisfied), interface: en0, ipv4, dns], uuid: BB97B450-EC0F-403F-BF69-55106D7A4F97
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 waiting path (satisfied)] skipping state update
Network reports that it doesn't know that name so it kicks off a DNS resolver. This service has three possible endpoints so we see it resolve all three of them:
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 in_progress resolver (satisfied)] reported event resolver:start_dns
SecurityAgent: (libsystem_network.dylib) [com.apple.network:] nw_resolver_create_dns_service_locked Starting host resolution .okta.com:443, flags 0x4000d000 proto 0
SecurityAgent: (libsystem_network.dylib) [com.apple.network:] nw_resolver_host_resolve_callback flags=0x3 ifindex=0 error=NoSuchRecord(-65554) hostname=.okta.com. addr=::.0 ttl=60
SecurityAgent: (libsystem_network.dylib) [com.apple.network:] nw_resolver_host_resolve_callback flags=0x3 ifindex=0 error=NoError(0) hostname=ok6-crtr-tls12-ec0e11a0c4a77237.elb.us-east-2.amazonaws.com. addr=52.14.242.23:0 ttl=58
SecurityAgent: (libsystem_network.dylib) [com.apple.network:] nw_resolver_host_resolve_callback flags=0x3 ifindex=0 error=NoError(0) hostname=ok6-crtr-tls12-ec0e11a0c4a77237.elb.us-east-2.amazonaws.com. addr=52.14.242.22:0 ttl=58
SecurityAgent: (libsystem_network.dylib) [com.apple.network:] nw_resolver_host_resolve_callback flags=0x2 ifindex=0 error=NoError(0) hostname=ok6-crtr-tls12-ec0e11a0c4a77237.elb.us-east-2.amazonaws.com. addr=52.14.242.21:0 ttl=58
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_resolver_update [1 .okta.com:443 in_progress resolver (satisfied)] Adding endpoint handler for 52.14.242.21:443
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_resolver_update [1 .okta.com:443 in_progress resolver (satisfied)] Adding endpoint handler for 52.14.242.23:443
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_resolver_update [1 .okta.com:443 in_progress resolver (satisfied)] Adding endpoint handler for 52.14.242.22:443
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 in_progress resolver (satisfied)] reported event resolver:receive_dns
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_resolver_start_next_child [1 .okta.com:443 in_progress resolver (satisfied)] starting child endpoint 52.14.242.21:443
The RR DNS got us started on the 52.14.242.21 dress so it starts Connection 1.1 to the address to negotiate the connection.
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_start [1.1 52.14.242.21:443 initial path (null)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1.1 52.14.242.21:443 initial path (null)] reported event path:start
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1.1 52.14.242.21:443 waiting path (satisfied)] reported event path:satisfied path: [satisfied (Path is satisfied), interface: en0, ipv4, dns], uuid: 9A65A469-64CB-4D04-A400-279D36A6AE33
SecurityAgent: (libnetwork.dylib) [com.apple.network:] -[NWConcrete_nw_endpoint_flow startWithHandler:] [1.1 52.14.242.21:443 waiting socket-flow (satisfied)] flow id 9A65A469-64CB-4D04-A400-279D36A6AE33
I'm not sure what this appears for here, but it feels like a place holder since it is just Info level.
SecurityAgent: (libsystem_network.dylib) [com.apple.network:] nw_parameters_copy_protocol_array_for_level Link level protocols are currently unsupported
Continuing on connection 1.1...
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1.1 52.14.242.21:443 in_progress socket-flow (satisfied)] reported event flow:start_connect
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_resolver_start_next_child [1 .okta.com:443 in_progress resolver (satisfied)] starting next child endpoint in 155ms
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_flow_protocol_connected [1.1 52.14.242.21:443 in_progress socket-flow (satisfied)] Transport protocol connected
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1.1 52.14.242.21:443 in_progress socket-flow (satisfied)] reported event flow:finish_transport
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 in_progress resolver (satisfied)] reported event flow:finish_transport
Since we aren't using the other IP addresses we see connection 1.2 and 1.3 get canceled:
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel [1.2 52.14.242.23:443 initial path (null)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel [1.3 52.14.242.22:443 initial path (null)]
Now I get a flurry of TIC TLS Events (1, 2, 11, 12, 14) and a few informational messages out of BoringSSL on what appears to be connection 1. I'm guessing that there is some correlation between the high and low level events here.
The trust result returns a 0 so I take that to mean it was all fine.
SecurityAgent: (CFNetwork) TIC TLS Event [1:0x7fd4d7569120]: 1, Pending(0)
SecurityAgent: (CFNetwork) TIC TLS Event [1:0x7fd4d7569120]: 2, Pending(0)
SecurityAgent: (libboringssl.dylib) [com.apple.network.boringssl:BoringSSL] Function boringssl_context_get_peer_npn_data: line 1551 Peer's advertised NPN data is NULL or empty
SecurityAgent: (libboringssl.dylib) [com.apple.network.boringssl:BoringSSL] Function _boringssl_context_SSL_ctx_verify_callback: line 2463 Verifying certificate from callback
SecurityAgent: (libboringssl.dylib) [com.apple.network.boringssl:BoringSSL] Function boringssl_context_build_peer_trust: line 1251 [0x7fd4d774c8f0] SecTrustCreateWithCertificates result: 0 0x7fd4dab76b30
SecurityAgent: (CFNetwork) TIC TLS Event [1:0x7fd4d7569120]: 11, Pending(0)
SecurityAgent: (CFNetwork) TIC TLS Event [1:0x7fd4d7569120]: 12, Pending(0)
SecurityAgent: (CFNetwork) TIC TLS Event [1:0x7fd4d7569120]: 14, Pending(0)
SecurityAgent: (Security) SecTrustEvaluateIfNecessary
SecurityAgent: (CFNetwork) TIC TLS Trust Result [1:0x7fd4d7569120]: 0
Now it looks like the endpoint connection on 1.1 continues and the Security framework is recording some analytics.
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_flow_protocol_connected [1.1 52.14.242.21:443 in_progress socket-flow (satisfied)] Output protocol connected
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_flow_connected_path_change [1.1 52.14.242.21:443 ready socket-flow (satisfied)] Connected path is satisfied, viable
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1.1 52.14.242.21:443 ready socket-flow (satisfied)] reported event flow:finish_connect
SecurityAgent: (Security) SecTrustReportTLSAnalytics
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 ready resolver (satisfied)] reported event flow:finish_connect
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1.1 52.14.242.21:443 ready socket-flow (satisfied)] reported event flow:changed_viability
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_connection_endpoint_report [1 .okta.com:443 ready resolver (satisfied)] reported event flow:changed_viability
But lo! What is this on connection 1? A TIC TLS event 20, followed by a TIC TCP error 16, which looks like a device busy error. Then a 1 and 8 to start tearing things down. I thought that connection 1 was just being used for the DNS, but I'm not so sure.
SecurityAgent: (CFNetwork) TIC TLS Event [1:0x7fd4d7569120]: 20, Pending(0)
SecurityAgent: (CFNetwork) TIC TCP Conn Connected [1:0x7fd4d7569120]: Err(16)
SecurityAgent: (CFNetwork) TIC TCP Conn Event [1:0x7fd4d7569120]: 1
SecurityAgent: (CFNetwork) TIC TCP Conn Event [1:0x7fd4d7569120]: 8
SecurityAgent: (CFNetwork) TIC TLS Handshake Complete [1:0x7fd4d7569120]
The handshake finishes and the connection on 1.1 connects, but now I see CFNetwork changing over to connection 1. That connection was just issued a close event.
It lives long enough to send a request and get a reply, in this case we get a MFA challenge back but...
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_flow_protocol_connected [1.1 52.14.242.21:443 ready socket-flow (satisfied)] Output protocol connected
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_flow_connected_path_change [1.1 52.14.242.21:443 ready socket-flow (satisfied)] Connected path is satisfied, viable
SecurityAgent: (CFNetwork) Task <980F7176-A1CB-4699-974A-5E11AC4282C9>.<1> now using Connection 1
SecurityAgent: (Security) SecKeychainAddCallback
SecurityAgent: (CFNetwork) Task <980F7176-A1CB-4699-974A-5E11AC4282C9>.<1> sent request, body S
SecurityAgent: (CFNetwork) Task <980F7176-A1CB-4699-974A-5E11AC4282C9>.<1> received response, status 200 content C
SecurityAgent: (CFNetwork) Task <980F7176-A1CB-4699-974A-5E11AC4282C9>.<1> response ended
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] NoMAD Login MFA Challenge received.
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] NoMAD Login MFA Challenge: [NoMADAuth.Factor(id: "opf29lh0coeYtlLGu2p7", factorType: "push", provider: "OKTA", vendorName: "OKTA", profile: ["platform": ANDROID, "credentialId": @.com, "keys": <__NSSingleObjectArrayI 0x7fd4d743f7b0>(
{
kid = default;
kty = PKIX;
use = sig;
x5c = (
"MIIBIjANBhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAzSKjjMozIOs9jkSl9fPDQAfB0dH5Xhvp\nKy15FP/vdl7tlDB3gqyZlTJuAetp3bASZtWyuYj7z4jHFgF9IEcyjUQwNAPIoJTGujGU/7949\nDS3TdRlLOszkoCh8+0YfhFyV28oqGAF/e+kg5LJPrtfTpvd37HSgPyzDCTq93FnP6ijJPAiC1t5m\nHViFkB21o6Iee8V5bkoagKmwEy5GEhfeGKUn74XntxMzdf0GgROb5pZDtt6TeRHpn0sSImn9w\n73YVUHvBYS7h5ZHkHdJp8HfLUp+t549NbBTh1dwQ9hotp15PofAdPunl65d3L9pm7Cqn/9gSnSQW\ngu6Y8QIDAQAB\n"
);
}
)
, "name": Moto G (5) Plus, "version": 24, "deviceType": SmartPhone_Android], links: ["verify": {
hints = {
allow = (
POST
);
};
href = "https://.okta.com/api/v1/authn/factors/opf29lh0coeYtu2p7/verify";
}], options: [:], state: "challe.
SecurityAgent: (NoMADLoginOkta) [menu.nomad.login:UI] NoMAD Login Authentication MFA Required
SecurityAgent: (LaunchServices) [com.apple.launchservices:default] LSExceptions shared instance invalidated for timeout.
Connection 1 was issued a close event after the DNS resolver finished. CFNetwork switched over to connection 1 but now Boring throws a fit because the connection was closed out from under it.
SecurityAgent: (libboringssl.dylib) [com.apple.network.boringssl:BoringSSL] Function boringssl_session_errorlog: line 2881 [boringssl_session_read] SSL_ERROR_ZERO_RETURN(6): operation failed because the connection was cleanly shut down with a close_notify alert
SecurityAgent: (CFNetwork) TIC TCP Conn Event [1:0x7fd4d7569120]: 2
SecurityAgent: (CFNetwork) TIC TCP Conn Cancel [1:0x7fd4d7569120]
SecurityAgent: (libboringssl.dylib) [com.apple.network.boringssl:BoringSSL] Function boringssl_session_errorlog: line 2881 [boringssl_session_read] SSL_ERROR_ZERO_RETURN(6): operation failed because the connection was cleanly shut down with a close_notify alert
SecurityAgent: (libboringssl.dylib) [com.apple.network.boringssl:BoringSSL] Function boringssl_session_errorlog: line 2881 [boringssl_session_read] SSL_ERROR_ZERO_RETURN(6): operation failed because the connection was cleanly shut down with a close_notify alert
Now we see everything get sent close requests and our auth process fails because the network is gone.
SecurityAgent: (libnetwork.dylib) [com.apple.network:] [1 stream, pid: 2324, tls] cancelled
[1.1 9A65A469-64CB-4D04-A400-279D36A6AE33 .49377<->]
Connected Path: satisfied (Path is satisfied), interface: en0, ipv4, dns
Duration: 5.850s, DNS @0.000s took 0.049s, TCP @0.050s took 0.084s, TLS took 0.188s
bytes in/out: 5282/866, packets in/out: 8/4, rtt: 0.076s, retransmitted packets: 0, out-of-order packets: 0
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel [1 .okta.com:443 ready resolver (satisfied)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel [1.1 52.14.242.21:443 ready socket-flow (satisfied)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_flow_protocol_disconnected [1.1 52.14.242.21:443 cancelled socket-flow (null)] Output protocol disconnected
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel [1.2 52.14.242.23:443 cancelled path (null)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel Handler already cancelled, ignoring cancel
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel [1.3 52.14.242.22:443 cancelled path (null)]
SecurityAgent: (libnetwork.dylib) [com.apple.network:] nw_endpoint_handler_cancel Handler already cancelled, ignoring cancel
SecurityAgent: (Security) SecTrustReportTLSAnalytics