trial stalled 5 minutes, user stopped trials. ANewTrial:0,Start:True,finish_Timer:1

[alexpiet]

This issue was automatically generated from GUI logs.

file: Foraging.py
function: _StartTrialLoop
line 4105
logfile: W10DT714033/W10DT714033-B_gui_log_2024-09-27_09-40-49.txt
boxes: 1B
count: 2
text: trial stalled 5 minutes, user stopped trials. ANewTrial:0,Start:True,finish_Timer:1


Log context

09:41:37 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3034:warmup is set to off
09:41:37 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1761:processing parameter changes
09:41:37 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2484:Auto engage successful for mouse 744744
09:43:11 AM:INFO:Foraging:Foraging.py:_Start:line 3615:Start button pressed: starting trial loop
09:43:11 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1761:processing parameter changes
09:43:12 AM:INFO:Foraging:Foraging.py:_Start:line 3681:Starting session, with experimenter: Huy Nguyen
09:43:12 AM:INFO:Foraging:Foraging.py:_Start:line 3771:Setting IACUC Protocol: 2109.0
09:43:12 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1761:processing parameter changes
09:43:12 AM:INFO:Foraging:Foraging.py:_Start:line 3805:Setting Project name: Behavior Platform
09:43:12 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1761:processing parameter changes
09:43:12 AM:INFO:Foraging:Foraging.py:_restartlogging:line 942:Restarting logging
09:43:12 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2624:Created new folder: C:\behavior_data\447-1-B\744744\behavior_744744_2024-09-27_09-43-12
09:43:12 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2627:Created new folder: C:\behavior_data\447-1-B\744744\behavior_744744_2024-09-27_09-43-12\metadata-dir
09:43:12 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2630:Created new folder: C:\behavior_data\447-1-B\744744\behavior_744744_2024-09-27_09-43-12\behavior
09:43:12 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2633:Created new folder: C:\behavior_data\447-1-B\744744\behavior_744744_2024-09-27_09-43-12\behavior\raw.harp
09:43:12 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2636:Created new folder: C:\behavior_data\447-1-B\744744\behavior_744744_2024-09-27_09-43-12\behavior-videos
09:43:12 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2639:Created new folder: C:\behavior_data\447-1-B\744744\behavior_744744_2024-09-27_09-43-12\fib
09:43:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\behavior_data\\447-1-B\\744744\\behavior_744744_2024-09-27_09-43-12\\behavior\\raw.harp', '127.0.0.1', 4012]
09:43:12 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 3984:starting trial loop
09:43:12 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4005:Current trial: 1
09:43:12 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 49 TimestampedU16@22710993.67549 Length:1.
09:43:12 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 50 TimestampedU16@22710993.67648 Length:1.
09:43:12 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 56 TimestampedU16@22710993.68448 Length:1.
09:43:12 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 36 TimestampedU16@22710993.6865 Length:1.
09:43:19 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 36 TimestampedU16@22711000.4185 Length:1.
09:43:20 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 36 TimestampedU16@22711001.40048 Length:1.
09:43:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 22711001.40112, 4, '127.0.0.1']
09:43:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
09:43:24 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 36 TimestampedU16@22711005.4175 Length:1.
09:48:38 AM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4105:trial stalled 5 minutes, user stopped trials. ANewTrial:0,Start:True,finish_Timer:1

[alexpiet]

Bonsai has a problem with harp data timestamps

[XX-Yin]

Can we repeat this issue? I have no idea from the information provided.

[alexpiet]

Do you know what this means?

09:43:12 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4601:BONSAI: Unexpected Harp data frame before operation control: Write 49 TimestampedU16@22710993.67549 Length:1.

[XX-Yin]

@alexpiet What day it was? I can take a look

[alexpiet]

All the information available is in the top comment:

logfile: W10DT714033/W10DT714033-B_gui_log_2024-09-27_09-40-49.txt

[XX-Yin]

I have no idea for this issue. There are some timestamps (e.g. ITI start, delay start) missing. It seems that the previous session is not fully closed.