LoggerFlush hanging in UnitTest

[DanielAsher]

Hi,

I'm trying to use NSLogger in Xcode XCTests running on the simulator with the desktop viewer running on a separate computer over wifi. I read the advice about using LoggerFlush(nil, true). This works much of the time, but if I don't run a test for a while, the first run will hang on the following line.

NSLogger/Client/iOS/LoggerClient.m

Line 598 in 7c3255d

pthread_cond_wait(&logger->logQueueEmpty, &logger->logQueueMutex);

Most often, I can kill the process and rerun and LoggerFlush will return and the desktop viewer will show the logs.

If I allow it to timeout (about 4/5 minutes), xctest reports:

nw_socket_handle_socket_event [C1.1.1:1] Socket SO_ERROR [60: Operation timed out]
nw_connection_get_connected_socket [C1] Client called nw_connection_get_connected_socket on unconnected nw_connection

Could anyone suggest a direction of investigation?

Here are the NSLogger console logs from a successful round-trip:

default	17:43:34.396914 +0100	NSLogger	TCP Conn [59:0x600000d88540] using empty proxy configuration
default	17:43:34.396952 +0100	NSLogger	Stream client bypassing proxies on TCP Conn [59:0x600000d88540]
default	17:43:34.396976 +0100	NSLogger	TCP Conn 0x600000d88540 started
default	17:43:34.397165 +0100	NSLogger	[C59 IPv6#a5ef142f.49857 tcp, local: IPv6#6b40a382.60544, legacy-socket, server] start
default	17:43:34.397455 +0100	NSLogger	TCP Conn [60:0x600000dd8600] using empty proxy configuration
default	17:43:34.397528 +0100	NSLogger	Stream client bypassing proxies on TCP Conn [60:0x600000dd8600]
default	17:43:34.397558 +0100	NSLogger	TCP Conn 0x600000dd8600 started
default	17:43:34.397943 +0100	NSLogger	nw_connection_report_state_with_handler_locked [C59] reporting state preparing
default	17:43:34.397985 +0100	NSLogger	nw_endpoint_flow_protocol_connected [C59 IPv6#a5ef142f.49857 in_progress socket-flow (satisfied)] Output protocol connected
default	17:43:34.398401 +0100	NSLogger	nw_connection_report_state_with_handler_locked [C59] reporting state ready
default	17:43:34.398516 +0100	NSLogger	[C60 IPv4#819d78c4:49858 tcp, local: IPv4#bfdea447:60544, legacy-socket, server] start
default	17:43:34.398605 +0100	NSLogger	TCP Conn 0x600000d88540 event 1. err: 0
default	17:43:34.398821 +0100	NSLogger	TCP Conn 0x600000d88540 complete. fd: 96, err: 0
default	17:43:34.399158 +0100	NSLogger	TCP Conn 0x600000d88540 starting SSL negotiation
default	17:43:34.399285 +0100	NSLogger	nw_connection_report_state_with_handler_locked [C60] reporting state preparing
default	17:43:34.399384 +0100	NSLogger	nw_endpoint_flow_protocol_connected [C60 IPv4#819d78c4:49858 in_progress socket-flow (satisfied)] Output protocol connected
default	17:43:34.399904 +0100	NSLogger	nw_connection_report_state_with_handler_locked [C60] reporting state ready
default	17:43:34.400086 +0100	NSLogger	nw_socket_handle_socket_event [C60:1] Socket received READ_CLOSE event
default	17:43:34.400127 +0100	NSLogger	TCP Conn 0x600000dd8600 event 1. err: 0
default	17:43:34.400238 +0100	NSLogger	TCP Conn 0x600000dd8600 complete. fd: 97, err: 0
default	17:43:34.412278 +0100	NSLogger	TCP Conn 0x600000dd8600 starting SSL negotiation
default	17:43:34.412346 +0100	NSLogger	CFNetwork SSLHandshake failed (-9806)
error	17:43:34.412401 +0100	NSLogger	TCP Conn 0x600000dd8600 SSLHandshake failed (-9806)
default	17:43:34.412547 +0100	NSLogger	TCP Conn 0x600000dd8600 canceled
default	17:43:34.412585 +0100	NSLogger	[C60 IPv4#819d78c4:49858 tcp, local: IPv4#bfdea447:60544, legacy-socket, server] cancel
default	17:43:34.412740 +0100	NSLogger	[C60 IPv4#819d78c4:49858 tcp, local: IPv4#bfdea447:60544, legacy-socket, server] cancelled
	[C60 <private> 192.168.86.134:60544<->IPv4#819d78c4:49858]
	Connected Path: satisfied (Path is satisfied), interface: en0, scoped, ipv4, dns
	Duration: 0.014s, , TCP @0.000s took 0.002s
	bytes in/out: 0/0, packets in/out: 1/0, rtt: 0.006s, retransmitted packets: 0, out-of-order packets: 0
default	17:43:34.412792 +0100	NSLogger	0.000s [C60 <private> 192.168.86.134:60544<->IPv4#819d78c4:49858 socket-flow] path:start
default	17:43:34.412832 +0100	NSLogger	0.000s [C60 <private> 192.168.86.134:60544<->IPv4#819d78c4:49858 socket-flow] path:satisfied
default	17:43:34.412867 +0100	NSLogger	0.000s [C60 <private> 192.168.86.134:60544<->IPv4#819d78c4:49858 socket-flow] flow:start_connect
default	17:43:34.412900 +0100	NSLogger	0.001s [C60 <private> 192.168.86.134:60544<->IPv4#819d78c4:49858 socket-flow] flow:finish_connect
default	17:43:34.412936 +0100	NSLogger	0.001s [C60 <private> 192.168.86.134:60544<->IPv4#819d78c4:49858 socket-flow] flow:changed_viability
default	17:43:34.412967 +0100	NSLogger	0.014s [C60] path:cancel
default	17:43:34.413103 +0100	NSLogger	nw_endpoint_flow_protocol_disconnected [C60 IPv4#819d78c4:49858 cancelled socket-flow (null)] Output protocol disconnected
default	17:43:34.413153 +0100	NSLogger	nw_connection_report_state_with_handler_locked [C60] reporting state cancelled
default	17:43:34.421522 +0100	NSLogger	TCP Conn 0x600000d88540 SSL Handshake DONE
default	17:43:34.910507 +0100	NSLogger	nw_socket_handle_socket_event [C59:1] Socket received READ_CLOSE event