2023-05-26 09:25:38.512 - INFO 6812 --- [http-nio-7777-exec-6] o.c.s.a.websockets.IOSTerminalWSServer : IOSTerminalWSServer-919e475fab4b27f70ba8a7bdfc1917052f1f3543 : quit.
2023-05-26 09:25:38.513 - INFO 6812 --- [Thread-654] o.cloud.sonic.agent.bridge.ios.SibTool : orientation watcher done.
2023-05-26 09:25:38.543 - INFO 6812 --- [http-nio-7777-exec-3] o.c.sonic.agent.websockets.IOSWSServer : IOSWSServer-919e475fab4b27f70ba8a7bdfc1917052f1f3543 : quit.
2023-05-26 09:25:38.544 - INFO 6812 --- [http-nio-7777-exec-3] o.c.sonic.agent.websockets.IOSWSServer : ios unlock udId：919e475fab4b27f70ba8a7bdfc1917052f1f3543
2023-05-26 09:25:45.660 - INFO 6812 --- [http-nio-7777-exec-2] o.c.sonic.agent.websockets.IOSWSServer : ios lock udId：919e475fab4b27f70ba8a7bdfc1917052f1f3543
2023-05-26 09:25:48.659 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:48.741034+0800 WebDriverAgentRunner-Runner[22942:2746955] Running tests...
2023-05-26 09:25:50.148 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : Test Suite 'All tests' started at 2023-05-26 09:25:50.254
2023-05-26 09:25:50.149 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : XCTestOutputBarrierTest Suite 'WebDriverAgentRunner.xctest' started at 2023-05-26 09:25:50.256
2023-05-26 09:25:50.149 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : XCTestOutputBarrierTest Suite 'UITestingUITests' started at 2023-05-26 09:25:50.256
2023-05-26 09:25:50.150 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : XCTestOutputBarrier t = nans Suite Set Up
2023-05-26 09:25:50.186 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.292912+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.186 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : KeyboardAutocorrection
2023-05-26 09:25:50.186 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.186 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.293769+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.186 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : "KeyboardAutocorrection_changedAt"
2023-05-26 09:25:50.186 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.187 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.294545+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.187 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : "KeyboardAutocorrection_buildAtChange"
2023-05-26 09:25:50.187 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.188 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.295201+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.188 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : "KeyboardAutocorrection_previousValue"
2023-05-26 09:25:50.188 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.188 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.295888+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.189 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : "KeyboardAutocorrection_analyzedAt"
2023-05-26 09:25:50.189 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.215 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.322859+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.216 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : KeyboardPrediction
2023-05-26 09:25:50.216 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.216 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.323781+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.216 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : KeyboardShowPredictionBar
2023-05-26 09:25:50.216 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.217 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.324790+0800 WebDriverAgentRunner-Runner[22942:2746955] [User Defaults] Couldn't write values for keys (
2023-05-26 09:25:50.218 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : DidShowGestureKeyboardIntroduction
2023-05-26 09:25:50.218 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : ) in CFPrefsPlistSource<0x2836c8780> (Domain: com.apple.keyboard.preferences, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No): setting preferences outside an application's container requires user-preference-write or file-write-data sandbox access
2023-05-26 09:25:50.224 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : Test Case '-[UITestingUITests testRunner]' started.
2023-05-26 09:25:50.226 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : XCTestOutputBarrier t = 0.00s Start Test at 2023-05-26 09:25:50.333
2023-05-26 09:25:50.228 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 0.00s Set Up
2023-05-26 09:25:50.230 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.336977+0800 WebDriverAgentRunner-Runner[22942:2746955] Built at Apr 11 2023 11:15:29
2023-05-26 09:25:50.248 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.355191+0800 WebDriverAgentRunner-Runner[22942:2746955] ServerURLHere->http://169.254.59.11:8100<-ServerURLHere
2023-05-26 09:25:50.248 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : WebDriverAgent server start successful
2023-05-26 09:25:51.254 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:50.356215+0800 WebDriverAgentRunner-Runner[22942:2746961] Using singleton test manager
2023-05-26 09:25:51.479 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : accept 127.0.0.1:59416
2023-05-26 09:25:51.512 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:51.607560+0800 WebDriverAgentRunner-Runner[22942:2746955] Getting the most recent active application (out of 1 total items)
2023-05-26 09:25:51.532 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 1.30s Find the Application 'com.tospur.houseaide'
2023-05-26 09:25:51.540 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 1.31s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:51.646 - INFO 6812 --- [Thread-657] o.cloud.sonic.agent.bridge.ios.SibTool : orientation: 1
2023-05-26 09:25:52.562 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 2.33s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:53.582 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 3.35s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:54.605 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 4.37s Find the Application 'com.tospur.houseaide' (retry 1)
2023-05-26 09:25:54.606 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 4.37s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:55.633 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 5.39s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:56.652 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 6.42s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:57.670 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 7.44s Find the Application 'com.tospur.houseaide' (retry 2)
2023-05-26 09:25:57.684 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 7.45s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:58.202 -ERROR 6812 --- [http-nio-7777-exec-7] o.a.t.websocket.pojo.PojoEndpointBase : Failed to call onClose method of POJO end point for POJO of type [org.cloud.sonic.agent.websockets.IOSScreenWSServer]
java.lang.reflect.InvocationTargetException: null
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
at org.apache.tomcat.websocket.pojo.PojoEndpointBase.onClose(PojoEndpointBase.java:107) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.WsSession.fireEndpointOnClose(WsSession.java:674) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.WsSession.onClose(WsSession.java:655) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.WsFrameBase.processDataControl(WsFrameBase.java:367) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:296) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:133) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:85) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.server.WsFrameServer.doOnDataAvailable(WsFrameServer.java:185) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.server.WsFrameServer.notifyDataAvailable(WsFrameServer.java:164) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler.upgradeDispatch(WsHttpUpgradeHandler.java:157) ~[tomcat-embed-websocket-10.1.7.jar!/:na]
at org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:60) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1741) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-10.1.7.jar!/:na]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-10.1.7.jar!/:na]
at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: java.lang.NullPointerException: Cannot invoke "java.util.concurrent.ScheduledFuture.cancel(boolean)" because "future" is null
at org.cloud.sonic.agent.websockets.IOSScreenWSServer.exit(IOSScreenWSServer.java:162) ~[classes!/:2.5.0]
at org.cloud.sonic.agent.websockets.IOSScreenWSServer.onClose(IOSScreenWSServer.java:151) ~[classes!/:2.5.0]
... 23 common frames omitted
2023-05-26 09:25:58.203 -ERROR 6812 --- [http-nio-7777-exec-7] o.c.s.a.websockets.IOSScreenWSServer : null
2023-05-26 09:25:58.710 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 8.47s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:59.731 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 9.50s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:59.750 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 9.52s Collecting extra data to assist test failure triage
2023-05-26 09:25:59.754 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 9.52s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:59.764 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 9.54s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:25:59.776 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:59.881397+0800 WebDriverAgentRunner-Runner[22942:2746955] Issue type: 0
2023-05-26 09:25:59.776 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:59.881585+0800 WebDriverAgentRunner-Runner[22942:2746955] Enqueue Failure: Failed to get matching snapshot: Error getting main window kAXErrorServerNotFound ((null)) (null) 0 0
[sonic-driver-core] 2023-05-26 09:25:59 [INFO] start session successful!
[sonic-driver-core] 2023-05-26 09:25:59 [INFO] session : 0480A5FE-0BB8-4A69-AE00-BFC888D3A35B
[sonic-driver-core] 2023-05-26 09:25:59 [INFO] session capabilities : Capabilities(device=iphone, browserName=null, sdkVersion=15.6.1, CFBundleIdentifier=com.tospur.houseaide)
2023-05-26 09:25:59.781 - INFO 6812 --- [pool-4-thread-6] org.cloud.sonic.agent.tests.LogUtil : {"msg":"step","des":"连接 WebDriverAgent 成功","log":"","rid":0,"udId":"919e475fab4b27f70ba8a7bdfc1917052f1f3543","status":2,"cid":0}
[sonic-driver-core] 2023-05-26 09:25:59 [INFO] set appium settings {"snapshotMaxDepth":30}.
2023-05-26 09:25:59.799 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : 2023-05-26 09:25:59.904684+0800 WebDriverAgentRunner-Runner[22942:2746955] Getting the most recent active application (out of 1 total items)
2023-05-26 09:25:59.804 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 9.58s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:26:00.822 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 10.59s Requesting snapshot of accessibility hierarchy for app with pid 98876
2023-05-26 09:26:01.845 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : t = 11.61s Requesting snapshot of accessibility hierarchy for app with pid 98876
[sonic-driver-core] 2023-05-26 09:26:01 [ERROR] get window size failed.
2023-05-26 09:26:01.866 -ERROR 6812 --- [pool-4-thread-6] o.c.sonic.agent.websockets.IOSWSServer : The previously found element "Application 'com.tospur.houseaide'" is not present in the current view anymore. Make sure the application UI has the expected state. Original error: Error getting main window kAXErrorServerNotFound
[sonic-driver-core] 2023-05-26 09:26:01 [INFO] close session successful!
2023-05-26 09:26:01.871 - INFO 6812 --- [pool-4-thread-6] org.cloud.sonic.agent.tests.LogUtil : {"msg":"step","des":"退出连接设备","log":"","rid":0,"udId":"919e475fab4b27f70ba8a7bdfc1917052f1f3543","status":2,"cid":0}
2023-05-26 09:26:01.877 - INFO 6812 --- [Thread-656] o.cloud.sonic.agent.bridge.ios.SibTool : WebDriverAgent print thread shutdown.`
