Add troubleshooting / debug information

[TomBoehm]

Due to the fact that the process consists of several steps, it is hard to find out what is broken: broadcast - upload - download.

Example: Status "no reports found" ...flashed 2x ESP32 - They can be found as bluetooth device(BT scanner), but do not provide any log info on the serial connection. ...installed the Mail.app plugin, but since I have no working device it is hard to verify if the plugin is retrieving correct.

Is it possible to have an indicator "Mail.app plugin connection OK" ? Is it possible to verify if a device is already known at Apple's Servers?

By now it is only possible to verify the console: (filtered by Process== OpenHaystack) Where that NSURLErrorDomain error can be found, but how to find out if that "Berlin" is OK - or should be "Vienna" in my case?

    standard    11:46:28.930936+0100    Requesting data for (
    "5le8H/6goDaqDDW9lAEmh1xw3LfO7wprwQ1lVf5PtAY="
)   OpenHaystack
    standard    11:46:28.931047+0100    Query : {
    search =     (
                {
            endDate = 1615459588930;
            ids =             (
                "5le8H/6goDaqDDW9lAEmh1xw3LfO7wprwQ1lVf5PtAY="
            );
            startDate = 1613645188930;
        }
    );
}   OpenHaystack
com.apple.securityd standard    11:46:28.932385+0100    UNIX error exception: 17    OpenHaystack
com.apple.securityd standard    11:46:28.935303+0100    UNIX error exception: 17    OpenHaystack
    standard    11:46:28.985368+0100    Headers:
{
    Accept = "application/json";
    Authorization = "Basic MTE0OTgzODE1OTk6RUFBSkFBQUFCTHdJQUFBQUFHQkk4bmtSRG1kekxtbGpiRzkxWkM1aGRYUm92UURiWmoxcG1pbGY5cFBXMlhUMW9kQ0dER3BhYm1hUnlwOGk5WlN4NDJNY0xBLWp1aVdlSTVEU0FENkNSNm4zcW1UWlZRVGdTYmdsbU1lTXNfc25XN2VqOUcxWEJyallDT2NIUDljNVpWcGR5UEF4NXZpQ3ZYZkpNZ1BjamxCZTVxWWozMEE1UU9JNWwxR09ZTFcyV1cwX2p0UTBPZ35+";
    "Content-Type" = "application/json";
    "X-Apple-I-Client-Time" = "2021-03-11T10:46:28Z";
    "X-Apple-I-MD" = "AAAABQAAABBjePJUpnnQ/EgLRmJlq8T2AAAAAQ==";
    "X-Apple-I-MD-M" = "dniIKdtJ9l01TbcG7rpxDfz18zdt4f9jop9faphccmhdPt819agG0tCFOTbBE/xaC3G1j4UcW3Uxq31F";
    "X-Apple-I-MD-RINFO" = 17106176;
    "X-Apple-I-TimeZone" = CET;
}   OpenHaystack
com.apple.CFNetwork standard    11:46:28.985872+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> {strength 1, tls 8, ct 0, sub 0, sig 0, ciphers 1, bundle 0, builtin 0} OpenHaystack
    standard    11:46:28.986140+0100    Connection 17: enabling TLS OpenHaystack
    standard    11:46:28.986160+0100    Connection 17: starting, TC(0x0)    OpenHaystack
com.apple.network   standard    11:46:28.986182+0100    [C17 F98C71D1-7DDC-4D5B-BCE2-505AC577778F gateway.icloud.com:443 tcp, url hash: 440ac18c, tls, context: com.apple.CFNetwork.NSURLSession.{2ED42E76-C3B9-4DE3-BC3C-774E8312E85A}{(null)}{Y}{2}, proc: 8EFF089C-D52A-3950-B598-8A3ADB7EF06C] start    OpenHaystack
com.apple.network   standard    11:46:28.986219+0100    [C17 gateway.icloud.com:443 initial path ((null))] event: path:start @0.000s    OpenHaystack
com.apple.network   standard    11:46:28.986366+0100    [C17 gateway.icloud.com:443 waiting path (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: path:satisfied @0.000s, uuid: AB6E1AAC-DCAE-4ABC-8212-6A885760EBCD  OpenHaystack
com.apple.network   standard    11:46:28.986435+0100    [C17 gateway.icloud.com:443 in_progress resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: resolver:start_dns @0.000s  OpenHaystack
com.apple.network   standard    11:46:28.986450+0100    nw_connection_report_state_with_handler_on_nw_queue [C17] reporting state preparing OpenHaystack
    standard    11:46:28.986531+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> setting up Connection 17    OpenHaystack
com.apple.network   standard    11:46:29.042970+0100    [C17 gateway.icloud.com:443 in_progress resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: resolver:receive_dns @0.056s    OpenHaystack
com.apple.network   standard    11:46:29.043111+0100    [C17.1 17.248.147.141:443 initial path ((null))] event: path:start @0.056s  OpenHaystack
com.apple.network   standard    11:46:29.043390+0100    [C17.1 17.248.147.141:443 waiting path (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: path:satisfied @0.057s, uuid: 9690C1B3-9DAC-4E33-A53C-24822AE7E97D    OpenHaystack
com.apple.network   standard    11:46:29.043842+0100    [C17.1 17.248.147.141:443 in_progress socket-flow (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: flow:start_connect @0.057s OpenHaystack
com.apple.network   standard    11:46:29.089670+0100    [C17 gateway.icloud.com:443 in_progress resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: resolver:receive_dns @0.103s    OpenHaystack
com.apple.network   standard    11:46:29.100735+0100    [C17 gateway.icloud.com:443 in_progress resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: resolver:receive_dns @0.114s    OpenHaystack
com.apple.network   standard    11:46:29.100771+0100    nw_socket_handle_socket_event [C17.1:3] Socket received CONNECTED event OpenHaystack
com.apple.network   standard    11:46:29.100841+0100    nw_flow_connected [C17.1 17.248.147.141:443 in_progress socket-flow (satisfied (Path is satisfied), viable, interface: en7, ipv4, dns)] Transport protocol connected    OpenHaystack
com.apple.network   standard    11:46:29.100903+0100    [C17.1 17.248.147.141:443 in_progress socket-flow (satisfied (Path is satisfied), viable, interface: en7, ipv4, dns)] event: flow:finish_transport @0.114s  OpenHaystack
com.apple.network   standard    11:46:29.100954+0100    [C17 gateway.icloud.com:443 in_progress resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: flow:finish_transport @0.114s   OpenHaystack
com.apple.network   standard    11:46:29.101550+0100    boringssl_session_apply_protocol_options_for_transport_block_invoke(1689) [C17.1:2][0x7fd9f37939d0] TLS configured [min_version(0x0303) max_version(0x0304) name(<private>) tickets(false) false_start(false) enforce_ev(false) enforce_ats(false)] OpenHaystack
com.apple.network   standard    11:46:29.101675+0100    boringssl_context_info_handler(1821) [C17.1:2][0x7fd9f37939d0] Client handshake started OpenHaystack
com.apple.network   standard    11:46:29.101785+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS client enter_early_data  OpenHaystack
com.apple.network   standard    11:46:29.101953+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS client read_server_hello OpenHaystack
com.apple.network   standard    11:46:29.146291+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_hello_retry_request  OpenHaystack
com.apple.network   standard    11:46:29.146353+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_server_hello OpenHaystack
com.apple.network   standard    11:46:29.146619+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_encrypted_extensions OpenHaystack
com.apple.network   standard    11:46:29.146914+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_certificate_request  OpenHaystack
com.apple.network   standard    11:46:29.158684+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_server_certificate   OpenHaystack
com.apple.network   standard    11:46:29.158844+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_server_certificate_verify    OpenHaystack
com.apple.network   standard    11:46:29.159559+0100    boringssl_context_evaluate_trust_async(1510) [C17.1:2][0x7fd9f37939d0] Performing external trust evaluation OpenHaystack
com.apple.network   standard    11:46:29.159710+0100    boringssl_context_evaluate_trust_async_external(1495) [C17.1:2][0x7fd9f37939d0] Asyncing for external verify block  OpenHaystack
    standard    11:46:29.159877+0100    Connection 17: asked to evaluate TLS Trust  OpenHaystack
    standard    11:46:29.166486+0100    System Trust Evaluation yielded status(0)   OpenHaystack
    standard    11:46:29.172389+0100    Connection 17: TLS Trust result 0   OpenHaystack
com.apple.network   standard    11:46:29.172410+0100    boringssl_context_evaluate_trust_async_external_block_invoke_3(1451) [C17.1:2][0x7fd9f37939d0] Returning from external verify block with result: true   OpenHaystack
com.apple.network   standard    11:46:29.172451+0100    boringssl_context_certificate_verify_callback(1609) [C17.1:2][0x7fd9f37939d0] Certificate verification result: OK   OpenHaystack
com.apple.network   standard    11:46:29.172741+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client read_server_finished  OpenHaystack
com.apple.network   standard    11:46:29.172878+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client send_end_of_early_data    OpenHaystack
com.apple.network   standard    11:46:29.172897+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client send_client_certificate   OpenHaystack
com.apple.network   standard    11:46:29.172911+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client complete_second_flight    OpenHaystack
com.apple.network   standard    11:46:29.172974+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS 1.3 client done  OpenHaystack
com.apple.network   standard    11:46:29.173074+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS client finish_client_handshake   OpenHaystack
com.apple.network   standard    11:46:29.173096+0100    boringssl_context_info_handler(1836) [C17.1:2][0x7fd9f37939d0] Client handshake state: TLS client done  OpenHaystack
com.apple.network   standard    11:46:29.173177+0100    boringssl_context_info_handler(1826) [C17.1:2][0x7fd9f37939d0] Client handshake done    OpenHaystack
com.apple.network   standard    11:46:29.173537+0100    nw_protocol_boringssl_signal_connected(734) [C17.1:2][0x7fd9f37939d0] TLS connected [version(0x0304) ciphersuite(TLS_AES_128_GCM_SHA256) group(0x001d) signature_alg(0x0403) alpn(http/1.1) resumed(0) offered_ticket(0) false_started(0) ocsp_received(1) sct_received(0) connect_time(72ms) flight_time(45ms) rtt(22ms) write_stalls(0) read_stalls(3)]   OpenHaystack
com.apple.network   standard    11:46:29.173656+0100    nw_flow_connected [C17.1 17.248.147.141:443 in_progress socket-flow (satisfied (Path is satisfied), viable, interface: en7, ipv4, dns)] Output protocol connected   OpenHaystack
com.apple.network   standard    11:46:29.173837+0100    [C17.1 17.248.147.141:443 ready socket-flow (satisfied (Path is satisfied), viable, interface: en7, ipv4, dns)] event: flow:finish_connect @0.187s  OpenHaystack
com.apple.network   standard    11:46:29.174016+0100    nw_connection_report_state_with_handler_on_nw_queue [C17] reporting state ready OpenHaystack
com.apple.network   standard    11:46:29.174082+0100    [C17 gateway.icloud.com:443 ready resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: flow:finish_connect @0.187s   OpenHaystack
com.apple.network   standard    11:46:29.174154+0100    [C17.1 17.248.147.141:443 ready socket-flow (satisfied (Path is satisfied), viable, interface: en7, ipv4, dns)] event: flow:changed_viability @0.187s   OpenHaystack
com.apple.network   standard    11:46:29.174181+0100    [C17 gateway.icloud.com:443 ready resolver (satisfied (Path is satisfied), interface: en7, ipv4, dns)] event: flow:changed_viability @0.187s    OpenHaystack
    standard    11:46:29.174249+0100    Connection 17: connected successfully   OpenHaystack
    standard    11:46:29.174278+0100    Connection 17: TLS handshake complete   OpenHaystack
    standard    11:46:29.174453+0100    Connection 17: ready C(N) E(N)  OpenHaystack
    standard    11:46:29.174613+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> now using Connection 17 OpenHaystack
    standard    11:46:29.174752+0100    Connection 17: received viability advisory(Y)   OpenHaystack
    standard    11:46:29.174999+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> sent request, body D 124    OpenHaystack
    standard    11:46:29.401104+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> received response, status 401 content K OpenHaystack
    standard    11:46:29.401552+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> done using Connection 17    OpenHaystack
com.apple.CFNetwork standard    11:46:29.401690+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> summary for auth challenge {transaction_duration_ms=416, response_status=401, connection=17, protocol="http/1.1", domain_lookup_duration_ms=56, connect_duration_ms=130, secure_connection_duration_ms=72, request_start_ms=189, request_duration_ms=0, response_start_ms=415, response_duration_ms=0, request_bytes=973, response_bytes=859, cache_hit=0}  OpenHaystack
    standard    11:46:29.401833+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> now using Connection 17 OpenHaystack
    standard    11:46:29.402108+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> sent request, body D 124    OpenHaystack
    standard    11:46:29.644777+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> received response, status 401 content K OpenHaystack
    standard    11:46:29.644907+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> response ended  OpenHaystack
    standard    11:46:29.644961+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> done using Connection 17    OpenHaystack
com.apple.CFNetwork standard    11:46:29.645076+0100    Task <B615A893-BC2C-4DBD-81DC-FE540D1C909D>.<0> summary for task success {transaction_duration_ms=243, response_status=401, connection=17, reused=1, request_start_ms=0, request_duration_ms=0, response_start_ms=242, response_duration_ms=0, request_bytes=973, response_bytes=859, cache_hit=0}  OpenHaystack
    standard    11:46:29.645342+0100    Error during request: 

Error Domain=NSURLErrorDomain Code=-1012 "(null)" UserInfo={NSErrorFailingURLStringKey=https://gateway.icloud.com/acsnservice/fetch, NSUnderlyingError=0x6000033225b0 {Error Domain=kCFErrorDomainCFNetwork Code=-1012 "(null)" UserInfo={_kCFURLErrorAuthFailedResponseKey=<NSHTTPURLResponse: 0x600003c99c40> { URL: https://gateway.icloud.com/acsnservice/fetch } { Status Code: 401, Headers {
    "Apple-Originating-System" =     (
        UnknownOriginatingSystem
    );
    Connection =     (
        "keep-alive"
    );
    "Content-Length" =     (
        0
    );
    Date =     (
        "Thu, 11 Mar 2021 10:46:29 GMT"
    );
    Server =     (
        "AppleHttpServer/4b0f4e40276cabbbae998f715d1fd1336e7478a2"
    );
    "Strict-Transport-Security" =     (
        "max-age=31536000; includeSubDomains;"
    );
    Via =     (
        "xrail:st53p00ic-qujn12070302.me.com:8301:20D277:grp60,631194250daa17e24277dea86cf30319:d7eedfa27549881027b210646fdd275e:Berlin"
    );
    "Www-Authenticate" =     (
        "   OpenHaystack

[schmittner]

You get some information already.

Is it possible to have an indicator "Mail.app plugin connection OK" ?

You will receive a pop-up if OpenHaystack is unable to connect to the mail plugin.

Is it possible to verify if a device is already known at Apple's Servers?

If you don't get any other error and, in fact, no report for your device has been submitted to Apple, the accessory is tagged with "no location found".

What would be nice though:

1. OpenHaystack could scan for advertisements and mark those accessories as "nearby" so you know that the device is correctly sending out the BLE advertisements
2. Display an error if the Mail plugin fails to connect to Apple's server @Sn0wfreezeDev: I'm not sure what info we already give back to the user.

[Sn0wfreezeDev]

OpenHaystack could scan for advertisements and mark those accessories as "nearby" so you know that the device is correctly sending out the BLE advertisements

That's definitely possible, but OpenHaystack will not be able to confirm if the device advertisement is 100% correct, because the MAC address is omitted in Apple's Bluetooth API.

Display an error if the Mail plugin fails to connect to Apple's server @Sn0wfreezeDev: I'm not sure what info we already give back to the user.

I think this error currently would also be that no reports have been found. Being more explicit here makes sense. I wanted to submit a PR later and I will include this.

@TomBoehm To ensure that your ESP32 is working correctly you can connect via a serial console and reset the esp. It will only log string during setup and not when it is already running. You can use the reset button for this. python -m serial.tools.miniterm --raw /dev/somePort 115200 Also on some ESP32 modules they need to be restarted after flashing. For mine this was the case.

[TomBoehm]

not working at all. I flashed the ESP32 new - verified the ESP via serial connection:

..... (no error) .....
I (1013) open_haystack: application initialized
I (1033) open_haystack: advertising has started.

restarted the ESP's, the Mac (does not complain about missing plugin), and all iOS devices - waited a day ... still nothing

=> might there be a regional restriction? (like we do not have HomePod's in Austria)

[schmittner]

@TomBoehm can you ensure that your accessory is correctly emitting the beacons using our latest version?

We are not aware of any regional restrictions of the Find My network.

[TomBoehm]

There is no regional restriction. • I have set up a clean macOS on a different hardware => working

on my Mac: • removed Mail plugin • upgraded to latest version • installed new Mail plugin (green indicator in the top right) • flashed new ESP32, restarted (green indicator at accessory) .... but still "no reports found"

I exported the accessory to a plist & imported it on the other device => working

although Mail plugin is installed the same way, there seem to be problems retrieving the published infos using my default Mac.

[schmittner]

Great that you got it working on your new machine.

On your old machine: can you verify that your iCloud keychain contains an item named com.apple.account.DeviceLocator.search-party-token (via the system's Keychain Access app)? Your error message indicates that there was an authentication issue.

[schoeberlt]

I also have some issues with esp32, since deployment by the app fails I copied the source code and entered the key myself. It is in fact broadcasting the public key and is recognized by BTLEMap as "Offline Finding" and as an (unknown) Apple Device. The Mail Plugin is also working, since I can get location reports from a RPi Setup, minutes after launching the HCI script. Still no reports for the esp32 tag. I suspect the iOS devices are not sending reports about the esp32 tags, for some reason. Maybe wrong advertising format? I did not find a way yet to capture the whole advertising package and analyse it and compare it with the expected format from your paper/Apples official docs. Location is also Vienna so no regional limits.

[schmittner]

@schoeberlt You can capture full BLE advertisements (including sender's MAC address) via Apple's PacketLogger (part of Additional Tools for Xcode package).

[schoeberlt]

@schmittner Thank you. Using the flash_esp32 script I managed to get it working properly. I had to change the baud rate to 115200 though, it might be specific to my use case, I am using a lolin32 lite clone with ESP32-D0WDQ6 (revision 1). Now I have to debug my own firmware, I copied the decoded key into a byte array, and used the same logic you have, but the final package could be different. PacketLogger is perfect for this case, thank you for the suggestion.

[TomBoehm]

The iCloud keychain contains com.apple.account.DeviceLocator.search-party-token and com.apple.account.DeviceLocator.token, but they look different from the entries at the "working" environment. They are 205 characters long ( working = 51 characters). Can I reset / delete them to start again? => maybe a "reset button" somewhere in the App might make sense, if others face such problems too.

A possible reason: I tried different methods to run OpenHaystack compiled myself to get it signed & downloaded the official release. Could that confuse keychain?

[schmittner]

The search-party-token is part of Apple's Find My implementation. We only read that token and never overwrite it, so it should not matter, which way you installed OpenHaystack. You can delete the tokens. New ones will be created when you open the Find My application. But I don't why this could help.