夜風のMixedReality

xRと出会って変わった人生と出会った技術を書き残すためのGeekなHoloRangerの居場所

Editorでは問題ないのに実機でアプリがクラッシュする際のログ取得と問題の特定方法　HoloLensアドベントカレンダー2023　3日目

Events HoloLensのいろは

本日はHoloLensのデバッグを行います。

本来は別の内容を紹介する予定だったのですが筆者自身が通信回りがまだ勉強中で、UnityEditor上では正常に動いてくれているのですが、HoloLens側で実行したところ通信でデータを受け取った際にクラッシュする問題がありました。

今回はHoloLens実機のログを取得していきます。

〇HoloLensアドベントカレンダー2023とは？

HoloLensアドベントカレンダーとは毎年12月に私の師である、がちもとさんを中心に開催されているアドベントカレンダー企画になります。

qiita.com

〇実機上のログ

アドベントカレンダー1日目ではiPhoneでHoloLensのログを出力しました。

この手法は非常に有用なのですが今回のようにクラッシュした場合はログそのものが送信されません。

このような場合Unityアプリケーションログを確認することで原因を特定することができる可能性があります。

このログはデバイスポータルを使用することでアクセスできます。

redhologerbera.hatenablog.com

redhologerbera.hatenablog.com

①デバイスポータル接続後Systemを開きます。

②FileExplorerを開きます。

③LocalAppDataを開きます。

④ログを取り出したいアプリを開きます。

⑤TempState内のUnityPlayer.logをダウンロードします。

このログがアプリケーションのログになります。

次のようなログが取得できます。

[MRTKLifecycleManager] Starting MixedReality.Toolkit.Speech.Windows.WindowsTextToSpeechSubsystem
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
MixedReality.Toolkit.Subsystems.MRTKLifecycleManager:OnEnable()

NullReferenceException: Object reference not set to an instance of an object.
  at LogMessageListener.HandleLog (System.String logString, System.String stackTrace, UnityEngine.LogType type) [0x00000] in <00000000000000000000000000000000>:0 
  at UnityEngine.Application.CallLogCallback (System.String logString, System.String stackTrace, UnityEngine.LogType type, System.Boolean invokedOnMainThread) [0x00000] in <00000000000000000000000000000000>:0 
  at UnityEngine.DebugLogHandler.LogFormat (UnityEngine.LogType logType, UnityEngine.Object context, System.String format, System.Object[] args) [0x00000] in <00000000000000000000000000000000>:0 
  at UnityEngine.Logger.Log (UnityEngine.LogType logType, System.Object message) [0x00000] in <00000000000000000000000000000000>:0 
  at UnityEngine.Debug.Log (System.Object message) [0x00000] in <00000000000000000000000000000000>:0 
  at MixedReality.Toolkit.Input.UnboundedTrackingMode.EnsureUnboundedModeSetIfSupported () [0x00000] in <00000000000000000000000000000000>:0 
  at MixedReality.Toolkit.Input.UnboundedTrackingMode.OnEnable () [0x00000] in <00000000000000000000000000000000>:0 
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
MixedReality.Toolkit.Input.UnboundedTrackingMode:EnsureUnboundedModeSetIfSupported()
MixedReality.Toolkit.Input.UnboundedTrackingMode:OnEnable()

UnboundedTrackingMode: TrySetTrackingOriginMode to Unbounded
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
MixedReality.Toolkit.Input.UnboundedTrackingMode:EnsureUnboundedModeSetIfSupported()
MixedReality.Toolkit.Input.UnboundedTrackingMode:OnEnable()

[XR] [MROpenXR][Info   ][21:51:46.087746][tid:1b0] SetSceneOriginSpace oldSpace=3 newSpace=5
[XR] [MROpenXR][Info   ][21:51:46.087746][tid:1b0] SetSceneOriginSpace oldSpace=3 newSpace=5
Button Pressed!0.01736026
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
LogSample:SampleLog()
UnityEngine.Events.InvokableCall:Invoke()
UnityEngine.Events.UnityEvent:Invoke()
MixedReality.Toolkit.StatefulInteractable:OnLastSelectExited(SelectExitEventArgs)
UnityEngine.Events.InvokableCall`1:Invoke(T1)
UnityEngine.Events.UnityEvent`1:Invoke(T0)
UnityEngine.XR.Interaction.Toolkit.XRBaseInteractable:OnSelectExited(SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExit(IXRSelectInteractor, IXRSelectInteractable, SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExitInternal(IXRSelectInteractor, IXRSelectInteractable, SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExit(IXRSelectInteractor, IXRSelectInteractable)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExitInternal(IXRSelectInteractor, IXRSelectInteractable)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:ClearInteractorSelection(IXRSelectInteractor, List`1)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:ClearInteractorSelectionInternal(IXRSelectInteractor, List`1)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:Update()

Button Pressed!0.0176275
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
LogSample:SampleLog()
UnityEngine.Events.InvokableCall:Invoke()
UnityEngine.Events.UnityEvent:Invoke()
MixedReality.Toolkit.StatefulInteractable:OnLastSelectExited(SelectExitEventArgs)
UnityEngine.Events.InvokableCall`1:Invoke(T1)
UnityEngine.Events.UnityEvent`1:Invoke(T0)
UnityEngine.XR.Interaction.Toolkit.XRBaseInteractable:OnSelectExited(SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExit(IXRSelectInteractor, IXRSelectInteractable, SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExitInternal(IXRSelectInteractor, IXRSelectInteractable, SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExit(IXRSelectInteractor, IXRSelectInteractable)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExitInternal(IXRSelectInteractor, IXRSelectInteractable)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:ClearInteractorSelection(IXRSelectInteractor, List`1)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:ClearInteractorSelectionInternal(IXRSelectInteractor, List`1)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:Update()

Button Pressed!0.01637724
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
LogSample:SampleLog()
UnityEngine.Events.InvokableCall:Invoke()
UnityEngine.Events.UnityEvent:Invoke()
MixedReality.Toolkit.StatefulInteractable:OnLastSelectExited(SelectExitEventArgs)
UnityEngine.Events.InvokableCall`1:Invoke(T1)
UnityEngine.Events.UnityEvent`1:Invoke(T0)
UnityEngine.XR.Interaction.Toolkit.XRBaseInteractable:OnSelectExited(SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExit(IXRSelectInteractor, IXRSelectInteractable, SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExitInternal(IXRSelectInteractor, IXRSelectInteractable, SelectExitEventArgs)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExit(IXRSelectInteractor, IXRSelectInteractable)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:SelectExitInternal(IXRSelectInteractor, IXRSelectInteractable)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:ClearInteractorSelection(IXRSelectInteractor, List`1)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:ClearInteractorSelectionInternal(IXRSelectInteractor, List`1)
UnityEngine.XR.Interaction.Toolkit.XRInteractionManager:Update()

FUN
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
Client:ProcessReceivedData(Byte[], Int32)
Client:<StartConnection>b__7_0()
System.Threading.ThreadHelper:ThreadStart_Context(Object)
System.Threading.ExecutionContext:RunInternal(ExecutionContext, ContextCallback, Object, Boolean)
System.Threading.ExecutionContext:Run(ExecutionContext, ContextCallback, Object)
System.Threading.ThreadHelper:ThreadStart()

ここから開発において必要なログのみを残します。

Button Pressed!0.01736026


Button Pressed!0.0176275

Button Pressed!0.01637724

FUN

これはDebug.Logで出力させたログになります。　つまり筆者が仕込んだDebug.Logのログになります。

今回はHoloLens側からButton Pressed!xxでボタンが押された時間を出力し、データを受け取った際にFUNというログが出るようにしていました。

また一つのログに注目するとDebug.Logの次の行にどこで呼ばれたというような詳細ログが出力されています。

FUN
UnityEngine.DebugLogHandler:LogFormat(LogType, Object, String, Object[])
UnityEngine.Logger:Log(LogType, Object)
UnityEngine.Debug:Log(Object)
Client:ProcessReceivedData(Byte[], Int32)
Client:<StartConnection>b__7_0()
System.Threading.ThreadHelper:ThreadStart_Context(Object)
System.Threading.ExecutionContext:RunInternal(ExecutionContext, ContextCallback, Object, Boolean)
System.Threading.ExecutionContext:Run(ExecutionContext, ContextCallback, Object)
System.Threading.ThreadHelper:ThreadStart()

これを見るとSystem.Threading.ThreadHelper:ThreadStart()が最後のログになります。

Unityではサブスレッドからメインスレッドにアクセスする際に一部のAPIが禁止されていることがあります。

今回は最後のログからこの現象が発生していると結論付けることができました。

このように実機上での挙動を確認したためUnityEditorでは問題がない場合でも問題を推察しやすくなっています。

本日は以上です。