search

fpillet / NSLogger

A modern, flexible logging tool
Other
5k stars 573 forks source link

LoggerFlush hanging in UnitTest #285

Open DanielAsher opened 5 years ago

DanielAsher commented 5 years ago

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.

https://github.com/fpillet/NSLogger/blob/7c3255dac0a2e160de3672e731d3829ab6f71ae4/Client/iOS/LoggerClient.m#L598

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