Print ios controller log if boot hangs

.github/workflows/ci.yml

@@ -3,10 +3,10 @@ name: CI
 on:
   workflow_dispatch:
   push:
-    branches: ["main"]
-  pull_request:
-    # The branches below must be a subset of the branches above
-    branches: ["main"]
+  #   branches: ["main"]
+  # pull_request:
+  #   # The branches below must be a subset of the branches above
+  #   branches: ["main"]
 
 # See https://docs.github.com/en/actions/using-jobs/using-concurrency#example-using-a-fallback-value
 concurrency:
@@ -20,58 +20,58 @@ jobs:
       fail-fast: false
       matrix:
         include:
-          # Release builds
-          - os: macos-26
-            config: "release"
-            # We want to test C++ and Swift only (in each direction)
-            cross_test_flags: "--all-cross --filter cpp --filter swift"
-            python_tests: true
-          - os: ubuntu-24.04
-            config: "release"
-            cross_test_flags: "--all-cross"
-          - os: ubuntu-24.04-arm
-            config: "release"
-            build_flags: "SKIP=csharp" # Skip C# on ARM as .NET compiler keeps crashing
-            test_flags: "--rfilter=csharp"
-            python_tests: true
-          - os: windows-2022
-            config: "release"
-            build_flags: "/p:Platform=x64"
-            test_flags: "--platform=x64"
-            python_tests: true
-          - os: windows-2022
-            config: "cpp-win32-release"
-            working_directory: "cpp"
-            build_flags: "/p:Platform=Win32"
-            msbuild_project: "msbuild/ice.proj"
-            test_flags: "--platform=Win32"
-            python_tests: true
-          - os: windows-2025
-            config: "release"
-            build_flags: "/p:Platform=x64"
-            test_flags: "--platform=x64"
-            python_tests: true
-
-          # Debug builds
-          - os: macos-26
-            config: "debug"
-            build_flags: "OPTIMIZE=no"
-            test_flags: "--swift-config=debug --csharp-config=Debug"
-            python_tests: true
-          - os: ubuntu-24.04
-            config: "debug"
-            build_flags: "OPTIMIZE=no"
-            test_flags: "--csharp-config=Debug"
-            python_tests: true
-
-          # TODO - figure out how to properly install debug Python
-          - os: windows-2022
-            config: "debug"
-            working_directory: "cpp"
-            build_flags: "/p:Platform=x64 /p:Configuration=Debug"
-            test_flags: "--platform=x64 --config=Debug"
-            msbuild_project: "msbuild/ice.proj"
-            python_tests: true
+          # # Release builds
+          # - os: macos-26
+          #   config: "release"
+          #   # We want to test C++ and Swift only (in each direction)
+          #   cross_test_flags: "--all-cross --filter cpp --filter swift"
+          #   python_tests: true
+          # - os: ubuntu-24.04
+          #   config: "release"
+          #   cross_test_flags: "--all-cross"
+          # - os: ubuntu-24.04-arm
+          #   config: "release"
+          #   build_flags: "SKIP=csharp" # Skip C# on ARM as .NET compiler keeps crashing
+          #   test_flags: "--rfilter=csharp"
+          #   python_tests: true
+          # - os: windows-2022
+          #   config: "release"
+          #   build_flags: "/p:Platform=x64"
+          #   test_flags: "--platform=x64"
+          #   python_tests: true
+          # - os: windows-2022
+          #   config: "cpp-win32-release"
+          #   working_directory: "cpp"
+          #   build_flags: "/p:Platform=Win32"
+          #   msbuild_project: "msbuild/ice.proj"
+          #   test_flags: "--platform=Win32"
+          #   python_tests: true
+          # - os: windows-2025
+          #   config: "release"
+          #   build_flags: "/p:Platform=x64"
+          #   test_flags: "--platform=x64"
+          #   python_tests: true
+
+          # # Debug builds
+          # - os: macos-26
+          #   config: "debug"
+          #   build_flags: "OPTIMIZE=no"
+          #   test_flags: "--swift-config=debug --csharp-config=Debug"
+          #   python_tests: true
+          # - os: ubuntu-24.04
+          #   config: "debug"
+          #   build_flags: "OPTIMIZE=no"
+          #   test_flags: "--csharp-config=Debug"
+          #   python_tests: true
+
+          # # TODO - figure out how to properly install debug Python
+          # - os: windows-2022
+          #   config: "debug"
+          #   working_directory: "cpp"
+          #   build_flags: "/p:Platform=x64 /p:Configuration=Debug"
+          #   test_flags: "--platform=x64 --config=Debug"
+          #   msbuild_project: "msbuild/ice.proj"
+          #   python_tests: true
 
           # iOS
           - os: macos-26
@@ -81,32 +81,32 @@ jobs:
             test_flags: "--languages='cpp,swift' --config=debug --platform=iphonesimulator --controller-app --rfilter=swift/Ice/udp"
             build_cpp_and_python: true
 
-          # Static builds
-          - os: ubuntu-24.04
-            config: "static"
-            build_flags: "CONFIGS=static"
-            test_flags: "--config=static --filter=Ice/ --filter=IceDiscovery/"
-            working_directory: "cpp"
-
-          # MATLAB
-          - os: ubuntu-24.04
-            config: "matlab"
-            working_directory: "matlab"
-            build_cpp_and_python: true
-          - os: windows-2022
-            config: "matlab"
-            working_directory: "matlab"
-            build_flags: "/p:Platform=x64"
-            msbuild_project: "msbuild/ice.proj"
-            test_flags: "--platform=x64"
-            build_cpp_and_python: true
-
-          - os: ubuntu-24.04
-            config: "android"
-            working_directory: "java"
-            test_flags: "--android --controller-app"
-            build_cpp_and_python: true
-            build_android_controller: true
+          # # Static builds
+          # - os: ubuntu-24.04
+          #   config: "static"
+          #   build_flags: "CONFIGS=static"
+          #   test_flags: "--config=static --filter=Ice/ --filter=IceDiscovery/"
+          #   working_directory: "cpp"
+
+          # # MATLAB
+          # - os: ubuntu-24.04
+          #   config: "matlab"
+          #   working_directory: "matlab"
+          #   build_cpp_and_python: true
+          # - os: windows-2022
+          #   config: "matlab"
+          #   working_directory: "matlab"
+          #   build_flags: "/p:Platform=x64"
+          #   msbuild_project: "msbuild/ice.proj"
+          #   test_flags: "--platform=x64"
+          #   build_cpp_and_python: true
+
+          # - os: ubuntu-24.04
+          #   config: "android"
+          #   working_directory: "java"
+          #   test_flags: "--android --controller-app"
+          #   build_cpp_and_python: true
+          #   build_android_controller: true
 
     runs-on: ${{ matrix.os }}
     steps:

scripts/Util.py

@@ -2819,17 +2819,42 @@ def startControllerApp(self, current, ident):
         run('xcrun simctl install "{0}" "{1}"'.format(self.device, appFullPath))
         print("ok")
 
+        logStreamProcess = subprocess.Popen(
+            [
+                "xcrun",
+                "simctl",
+                "spawn",
+                "booted",
+                "log",
+                "stream",
+                "--level",
+                "debug",
+                # "--predicate",
+                # f'subsystem contains "{ident.name}"',
+            ],
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT,
+        )
+
         sys.stdout.write("launching {0}... ".format(os.path.basename(appFullPath)))
         sys.stdout.flush()
         n = 0
         while n < 5:
             try:
-                subprocess.run(["xcrun", "simctl", "launch", self.device, ident.name], check=True, timeout=60)
+                subprocess.run(["xcrun", "simctl", "launch", self.device, ident.name], check=True, timeout=120)
                 break
             except subprocess.TimeoutExpired:
                 n += 1
-                sys.stdout.write(f"\nlaunch timeout, retrying {n}/5... ")
-                sys.stdout.flush()
+
+        print(f"ok ({n} retries)")
+        logStreamProcess.terminate()
+
+        if n == 5:
+            output = logStreamProcess.stdout.readlines()
+            with open("ios_simulator.log", "wb") as f:
+                for line in output:
+                    f.write(line)
+            raise RuntimeError("failed to launch the controller application")
         # No "ok" as the command prints its own output
 
     def restartControllerApp(self, current, ident):
@@ -2845,7 +2870,8 @@ def restartControllerApp(self, current, ident):
             except Exception:
                 time.sleep(1.0)
                 nRetry += 1
-        run('xcrun simctl launch "{0}" {1}'.format(self.device, ident.name))
+
+        subprocess.run(["xcrun", "simctl", "launch", self.device, ident.name], check=True, timeout=60)
 
     def stopControllerApp(self, ident):
         controllerBundleIdentifier = ident.name

swift/src/Ice/ObjectAdapterI.swift

@@ -234,6 +234,12 @@ final class ObjectAdapterI: LocalObject<ICEObjectAdapter>, ObjectAdapter, ICEDis
     ) {
         precondition(handle == adapter)
 
+
+        let logger = getCommunicator().getLogger()
+
+        logger.print(
+            "Swift Dispatch started: time=\(Date().formatted(.iso8601.year().month().day().time(includingFractionalSeconds: true))) identity=\(name) operation=\(operation) starting dispatch")
+
         let connection = con?.getSwiftObject(ConnectionI.self) { ConnectionI(handle: con!) }
         let encoding = EncodingVersion(major: encodingMajor, minor: encodingMinor)
 
@@ -255,17 +261,22 @@ final class ObjectAdapterI: LocalObject<ICEObjectAdapter>, ObjectAdapter, ICEDis
 
         let request = IncomingRequest(current: current, inputStream: istr)
 
+        logger.print(
+            "About to start Task: time=\(Date().formatted(.iso8601.year().month().day().time(includingFractionalSeconds: true))) identity=\(name) operation=\(operation) starting dispatch")
         Task {
             let response: OutgoingResponse
 
             // TODO: the request is in the Task capture and we need to send it. Is there a better syntax?
             nonisolated(unsafe) let request = request
             do {
+                logger.print(
+                    "Dispatching OA request: time=\(Date().formatted(.iso8601.year().month().day().time(includingFractionalSeconds: true))) identity=\(name) operation=\(operation) starting dispatch")
                 response = try await dispatchPipeline.dispatch(request)
             } catch {
                 response = current.makeOutgoingResponse(error: error)
             }
-
+            logger.print(
+                "Completed OA request: time=\(Date().formatted(.iso8601.year().month().day().time(includingFractionalSeconds: true))) identity=\(name) operation=\(operation) dispatch completed, sending response")
             response.outputStream.finished().withUnsafeBytes {
                 outgoingResponseHandler(
                     response.replyStatus,

swift/src/IceImpl/DispatchAdapter.mm

@@ -6,12 +6,39 @@
 #import "include/LocalExceptionFactory.h"
 #import "include/ObjectAdapter.h"
 
+#include <chrono>
+
+namespace
+{
+    std::string timePointToString(const std::chrono::system_clock::time_point& timePoint)
+    {
+        auto time = std::chrono::system_clock::to_time_t(timePoint);
+        struct tm tr;
+
+        localtime_r(&time, &tr);
+
+        char buf[32];
+        strftime(buf, sizeof(buf), "%x %H:%M:%S", &tr);
+
+        auto usec = std::chrono::duration_cast<std::chrono::microseconds>(timePoint.time_since_epoch());
+        return std::string(buf) + "." + std::to_string(usec.count() % 1000000 / 1000);
+    }
+}
+
 void
 CppDispatcher::dispatch(Ice::IncomingRequest& request, std::function<void(Ice::OutgoingResponse)> sendResponse)
 {
     // Captured as a const copy by the block according to https://clang.llvm.org/docs/BlockLanguageSpec.html
     Ice::Current current{request.current()};
 
+    auto logger = current.adapter->getCommunicator()->getLogger();
+
+    auto startTime = std::chrono::system_clock::now();
+
+    logger->print(
+        "C++ Dispatch into Swift: time=" + timePointToString(startTime) + " identity=" + current.id.name +
+        " operation=" + current.operation + " start time");
+
     int32_t sz;
     const std::byte* inEncaps;
     std::function<void()> cleanup;
@@ -49,6 +76,12 @@
 
     ICEOutgoingResponse outgoingResponse =
         ^(uint8_t replyStatus, NSString* exceptionId, NSString* exceptionDetails, const void* message, long count) {
+          auto endTime = std::chrono::system_clock::now();
+          logger->print(
+              "C++ Dispatch completed: time=" + timePointToString(endTime) + " identity=" + current.id.name +
+              " operation=" + current.operation + " duration=" +
+              std::to_string(std::chrono::duration_cast<std::chrono::milliseconds>(endTime - startTime).count()) +
+              " ms");
           cleanup();
 
           // We need to copy the message here as we don't own the memory and it can be sent asynchronously.
@@ -61,6 +94,9 @@
               fromNSString(exceptionDetails),
               std::move(ostr),
               current});
+          logger->print(
+              "Swift Dispatch: time=" + timePointToString(std::chrono::system_clock::now()) +
+              " identity=" + current.id.name + " operation=" + current.operation + " response sent");
         };
 
     ICEObjectAdapter* adapter = [ICEObjectAdapter getHandle:current.adapter];

swift/test/Ice/location/Server.swift

@@ -1,16 +1,33 @@
 // Copyright (c) ZeroC, Inc.
 
-import Dispatch
 import Ice
 import TestCommon
 
+
+struct DispatchWrapper: Dispatcher {
+    let dispatcher: Dispatcher
+
+    func dispatch(_ request: sending IncomingRequest) async throws -> OutgoingResponse {
+        let startTime = ContinuousClock.now
+        let response = try await dispatcher.dispatch(request)
+        let endTime = ContinuousClock.now
+        let elapsed = startTime.duration(to: endTime)
+
+        let logger = request.current.adapter.getCommunicator().getLogger()
+        logger.print("Swift Dispatch: identity=\(request.current.id) operation=\(request.current.operation) duration=\(Double(elapsed.components.attoseconds) / 1_000_000_000_000_000.0) ms")
+
+        return response
+    }
+}
+
 class Server: TestHelperI, @unchecked Sendable {
     override public func run(args: [String]) async throws {
         //
         // Register the server manager. The server manager creates a new
         // 'server'(a server isn't a different process, it's just a new
         // communicator and object adapter).
         //
+
         let properties = try createTestProperties(args)
         properties.setProperty(key: "Ice.ThreadPool.Server.Size", value: "2")
         let communicator = try initialize(Ice.InitializationData(properties: properties))
@@ -32,7 +49,7 @@ class Server: TestHelperI, @unchecked Sendable {
         // Make sure we use a separate copy of the properties as the servant modifies them.
         let object = ServerManagerI(registry: registry, properties: properties.clone(), helper: self)
 
-        try adapter.add(servant: object, id: Ice.stringToIdentity("ServerManager"))
+        try adapter.add(servant: DispatchWrapper(dispatcher: object), id: Ice.stringToIdentity("ServerManager"))
         try await registry.addObject(adapter.createProxy(Ice.stringToIdentity("ServerManager")))
 
         let registryPrx = try uncheckedCast(
@@ -42,7 +59,7 @@ class Server: TestHelperI, @unchecked Sendable {
             type: Ice.LocatorRegistryPrx.self)
 
         let locator = ServerLocator(registry: registry, registryPrx: registryPrx)
-        try adapter.add(servant: locator, id: Ice.stringToIdentity("locator"))
+        try adapter.add(servant: DispatchWrapper(dispatcher: locator), id: Ice.stringToIdentity("locator"))
 
         try adapter.activate()
         serverReady()