RC debugging works unreliably

cezarsignori commented 2 years ago

My integration setup

[x] Automatic integration using xcprepare integrate ...

Expected/desired behavior

Follow steps on Development.md to debug XCRemoteCache and have Xcode stop on breakpoints in the RC project.

Minimal reproduction of the problem with instructions

Step 1. Automatic integration using xcprepare integrate ... (from Release build) for all xcodeproj files in the workspace
Step 2. Pick one dependency (e.g. root project in the workspace) and follow instructions on Development.md to debug XCRemoteCache (from source code, same version tag)

Most of times my application finishes building and Xcode shows "Finished running" in the RC project instead of stopping in breakpoints there.

Environment

XCRemoteCache: 0.3.7
HTTP cache server: demo docker in localhost
Xcode: 13.2.1 (13C100)

Others

I am on an Apple M1 Max with macOS Monterey 12.2.1 (21D62).

I did also try to run xcprepare integrate from the locally built RC (building the Agreggated target) so all xcodeproj files are generated with all steps pointing to the locally built RC (instead of Release build), then select/run the xcpostbuild target and rebuild my application. Once, Xcode stopped in a breakpoint in the RC project (yay!), but then, it stopped for only one of the 70 projects, and finished running. Maybe that is expected behavior. But only got this to work once so far.

polac24 commented 2 years ago

Where do you put the sleep(1) mentioned in the tip? Do you observe that the postbuild takes an extra second to execute? Did you try longer sleeps like 3s? Did you try placing the sleep in other places, earlier/later in the flow? Did you set multiple breakpoints "just in case"?
It is expected that Xcode attaches to a single process per CMD+R.

cezarsignori commented 2 years ago

Hi!

I put the sleep(1) on the very first line XCPostbuild.main() and XCPrebuild.main().
I do observe the pre/postbuild steps take an extra second to execute.
Yes, I tried sleep(10) too.
Yes, also tried adding to XCPostbuild.init().
Yes, I have multiple breakpoints across init and main.

I noticed the Xcode instance with RC in "Waiting for execution" changes state to "Finished running" right after the other Xcode instance with the application open starts the build. By the time the postbuild step I changed to use the locally compiled version runs, RC's Xcode instance is no longer listening.

I see the same behavior if I try to do the same thing with the very first prebuild step run during the application build.

polac24 commented 2 years ago

I have 2 potential reasons: background indexing invokes the process or your LLDB source-map is too broad.

Close all Xcodes and call in a terminal defaults write com.apple.dt.Xcode IDEIndexDisable -bool YES. Note: After testing, remember to turn indexing on defaults delete com.apple.dt.Xcode IDEIndexDisable.
Close all Xcodes, open ~/.lldbinit, and comment out all lines starting with settings {set|apppend} target.source-map ..., save it and repeat the test. Do not call xcprepare integrate, if may modify that file again. 2b. In the project you want to build, It is a good practice to manually modify a single target that you want to debug (e.g. Network) to use a locally built binary (either xcprebuild or xcpostbuild) and all other targets should use the released version. If you use a locally built binary for all 70 targets - there will be a lot of noise. 2c. Tip: If having troubles, I often introduce a trivial change in the XCRemoteCache class (e.g. new line in XCPrebuild.swift) before running - as a result, Xcode relinks the app and invalidates the previous xcprebuild step.

cezarsignori commented 2 years ago

I'm still seeing the same behavior. Here is the test step by step:

With Xcode not running, I ran defaults write com.apple.dt.Xcode IDEIndexDisable -bool YES;
Then I ran xcprepare integrate with consumer mode and deleted the ~/.lldbinit file;
rm -rf ~/Library/Developer/Xcode/DerivedData and rm -rf ~/Library/Caches/XCRemoteCache ;
I opened the RC project in Xcode (Indexing did not take place) and I build xcprebuild (with sleep(1) in init and two breakpoints in the main method) and then run it set to Wait for execution;
I opened my project in Xcode and modified the root target's prebuild step input file to use the xcprebuild from DerivedData (Indexing did not take place, "Preparing editor" showed up and RC's Xcode was still "Waiting to attach");
I CMD+B my project and 3 seconds later, RC's Xcode changed status to "Finished running" and 8 seconds later my app successfully built;

polac24 commented 2 years ago

It sounds like an issue with the long LLDB attaching times on Big Sure and newer. It is a known issue and was reported to Apple many times (e.g. https://developer.apple.com/forums/thread/679098) - connecting the debugger for the very first time takes a lot of time (in the ballpark of 20s).

Hard to suggest something but you could try:

after 4., run xcprebuild via CMD+R and wait for the debugger to attach. If done, you can continue with 5. and 6.
experiment with extremely long sleeps (at least for the first time lldb attach)
if you run xcprebuild from CMD+R, verify that in the LLDB session settings show target.source-map prints an empty array

cezarsignori commented 2 years ago

Okay, so here is what I learned:

On step 6, RC's Xcode changed status to "Finished running" this shows up in the console:

Message from debugger: attach failed (Not allowed to attach to process.  Look in the console messages (Console.app), near the debugserver entries, when the attach failed.  The subsystem that denied the attach permission will likely have logged an informative message about why it was denied.)

Then looking at the Console.app near the debugserver entries when the attach failed:

error   17:04:05.775727+0100    authd   process: PID 74742 pidpathfailed 0
error   17:04:05.780951+0100    authd   process: PID 74742 failed to create code ref 100003
error   17:04:05.782593+0100    debugserver error: MachTask::StartExceptionThread (): task invalid, exception thread start failed.
error   17:04:05.782603+0100    debugserver error: [LaunchAttach] END (74660) MachProcess::AttachForDebug failed to start exception thread attaching to pid 74733: unable to start the exception thread
error   17:04:05.782622+0100    debugserver error: Attach failed
error   17:04:05.783174+0100    debugserver error: Attach failed: "Not allowed to attach to process.  Look in the console messages (Console.app), near the debugserver entries, when the attach failed.  The subsystem that denied the attach permission will likely have logged an informative message abo

And then looking waay up in the logs before the xcprebuild logs from my project building I see these:

error   17:04:01.176359+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd
error   17:04:01.176531+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.176558+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd
error   17:04:01.176707+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.177248+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd
error   17:04:01.177663+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd
error   17:04:01.176637+0100    AirPlayXPCHelper    send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x11e6ead80
error   17:04:01.177906+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.176652+0100    AirPlayXPCHelper    TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.178363+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.176808+0100    systemstats send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x142104590
error   17:04:01.176825+0100    systemstats TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.178226+0100    AirPlayXPCHelper    send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x11f50a270
error   17:04:01.178440+0100    AirPlayXPCHelper    TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.179372+0100    tccd    Refusing TCCAccessRequest for service kTCCServiceBluetoothAlways from client Sub:{/System/Library/PrivateFrameworks/MobileAccessoryUpdater.framework/Support/fud}Resp:{} in background session
error   17:04:01.178705+0100    systemstats send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x140f85bc0
error   17:04:01.178785+0100    systemstats TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.184752+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd
error   17:04:01.185168+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd
error   17:04:01.185337+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.185828+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.186862+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd
error   17:04:01.187427+0100    kernel  Sandbox: systemstats(374) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.185522+0100    systemstats send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x135910fe0
error   17:04:01.187484+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd
error   17:04:01.185535+0100    systemstats TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.186243+0100    AirPlayXPCHelper    send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x10e7460b0
error   17:04:01.186485+0100    AirPlayXPCHelper    TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.188476+0100    kernel  Sandbox: AirPlayXPCHelper(435) deny(1) mach-lookup com.apple.tccd.system
error   17:04:01.187011+0100    tccd    Refusing TCCAccessRequest for service kTCCServiceBluetoothAlways from client Sub:{/System/Library/PrivateFrameworks/MobileAccessoryUpdater.framework/Support/fud}Resp:{} in background session
error   17:04:01.188795+0100    AirPlayXPCHelper    send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x10e7460b0
error   17:04:01.188946+0100    AirPlayXPCHelper    TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.187779+0100    systemstats send_message_with_reply_sync(): XPC_ERROR_CONNECTION_INVALID for message 0x135911b10
error   17:04:01.187993+0100    systemstats TCCAccessRequest_block_invoke: Connection invalid
error   17:04:01.193895+0100    tccd    Refusing TCCAccessRequest for service kTCCServiceBluetoothAlways from client Sub:{/System/Library/PrivateFrameworks/MobileAccessoryUpdater.framework/Support/fud}Resp:{} in background session
error   17:04:01.195316+0100    tccd    Refusing TCCAccessRequest for service kTCCServiceBluetoothAlways from client Sub:{/System/Library/PrivateFrameworks/MobileAccessoryUpdater.framework/Support/fud}Resp:{} in background session
error   17:04:05.318068+0100    proactiveeventtrackerd  User passwd entry or home directory is not found
error   17:04:05.318120+0100    proactiveeventtrackerd  Failed to initialize PETEventTracker2.
fault   17:04:05.318140+0100    proactiveeventtrackerd  Failed to initialize the tracker
error   17:04:05.318165+0100    proactiveeventtrackerd  Failed to initialize PET service. Exiting...

Not sure yet what to do with this info.

By the way, I performed this last test with a 30s sleep in XCPrebuild.init and wasn't able to run settings show target.source-map as RC's Xcode never attaches.

Otherwise, I don't understand why you suspect about issue with the long LLDB attaching times on Big Sure and newer. In my case, RC's Xcode is waiting to attach because a build needs to take place (expected) and as soon as a build starts, Xcode changes to "Finished running". No long attaching times. Can you explain?

Thanks!

polac24 commented 2 years ago

I observed long times attaching into a simulator on BigSur+ and guessed that might be related - apparently there is something else.

I have never seen issues like that but that looks unrelated to XCRemoteCache - some machine-specific tool blocks the debugger, maybe an antivirus? Some links suggest that maybe you need to enable DevTools: https://developer.apple.com/forums/thread/120282?answerId=373436022#373436022. Worth trying.

polac24 commented 2 years ago

@cezarsignori, do you have any update on it? Does DevTools help?

xwlxwl commented 2 years ago

@cezarsignori, do you have any update on it? Does DevTools help? No,I'm also seeing the same behavior

xwlxwl commented 2 years ago

@cezarsignori, do you have any update on it? Does DevTools help? No,I'm also seeing the same behavior

my email is liwei920518@gmail.com

cezarsignori commented 2 years ago

Yes! sudo DevToolsSecurity -enable with

public init() {
    sleep(5)
}

makes it so the breakpoints are hit.

spotify / XCRemoteCache

RC debugging works unreliably #103