search

AllenNeuralDynamics / dynamic-foraging-task

Bonsai/Harp workflow for Dynamic Foraging with Python GUI for visualization and control
MIT License
5 stars 4 forks source link

Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon #856

Closed alexpiet closed 1 day ago

alexpiet commented 2 weeks ago

This issue was automatically generated from GUI logs.

file: Foraging.py
function: _Start
line 3816
logfile: W10DT714674/W10DT714674-D_gui_log_2024-10-28_09-34-45.txt
boxes: 6D, 7D
count: 4
text: Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon


Log context

09:37:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9333722.158496, '127.0.0.1', 4033]
09:37:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333722.576992, '127.0.0.1', 4033]
09:37:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333722.576992, '127.0.0.1', 4033]
09:37:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333722.578496, '127.0.0.1', 4033]
09:37:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333722.579488, '127.0.0.1', 4033]
09:37:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 9333732.153984, '127.0.0.1', 4033]
09:37:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 9333732.153984, '127.0.0.1', 4033]
09:37:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9333732.155488, '127.0.0.1', 4033]
09:37:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9333732.15648, '127.0.0.1', 4033]
09:37:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333732.576, '127.0.0.1', 4033]
09:37:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333732.576, '127.0.0.1', 4033]
09:37:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333732.577504, '127.0.0.1', 4033]
09:37:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333732.578496, '127.0.0.1', 4033]
09:38:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 9333742.152992, '127.0.0.1', 4033]
09:38:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 9333742.152992, '127.0.0.1', 4033]
09:38:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9333742.154496, '127.0.0.1', 4033]
09:38:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9333742.15552, '127.0.0.1', 4033]
09:38:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333742.572992, '127.0.0.1', 4033]
09:38:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333742.573984, '127.0.0.1', 4033]
09:38:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333742.574496, '127.0.0.1', 4033]
09:38:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333742.57552, '127.0.0.1', 4033]
09:38:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 9333743.152992, '127.0.0.1', 4033]
09:38:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9333743.154496, '127.0.0.1', 4033]
09:38:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9333746.568992, '127.0.0.1', 4033]
09:38:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9333746.570496, '127.0.0.1', 4033]
09:40:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 9333883.109248, '127.0.0.1', 4033]
09:40:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9333883.109344, '127.0.0.1', 4033]
09:43:57 AM:INFO:Foraging:Foraging.py:_Start:line 3784:Start button pressed: starting trial loop
09:43:57 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1884:processing parameter changes
09:43:58 AM:ERROR:Foraging:Foraging.py:_Start:line 3816:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon
ellahiltonvano commented 2 weeks ago

Sue added to smartsheet notes: Please don't start photometry before 'FINAL' stage. Can use either normal behavior or FP box.

alexpiet commented 1 week ago

This issue reoccurred:

file: Foraging.py
function: _Start
line 3851
logfile: W10DT714674/W10DT714674-D_gui_log_2024-10-31_08-57-08.txt
boxes: 6D
count: 2
text: Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon


Log context

09:08:49 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [11838, 0, 0, 0]
09:09:43 AM:INFO:move_worker:move_worker.py:move_to_preset_position:line 177:(move to preset position): Moving stage to preset initialize with coordinates [15, 16, 16, 10]
09:09:46 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11838, 0, 0, 0] to [11838, 12800, 12800, 0]
09:09:46 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11838, 12800, 12800, 0] to [12000, 12800, 12800, 0]
09:09:49 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 12800, 12800, 0] to [12000, 12800, 12800, 8000]
09:10:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1919:processing parameter changes
09:10:03 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 18.0
09:10:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_y1, 21.6 -> 16.0
09:10:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_z, 18.9962 -> 18.0
09:10:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_y2, 21.6 -> 16.0
09:10:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_x, 14.7975 -> 15.0
09:10:05 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 12800, 12800, 8000] to [12000, 12800, 12800, 14400]
09:10:11 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1919:processing parameter changes
09:10:11 AM:INFO:move_worker:move_worker.py:update_step_size:line 260:(update step size): Setting step size to 2.0
09:10:11 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_step_size, 0.2 -> 2.0
09:10:12 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 1 and 2
09:10:13 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 12800, 12800, 14400] to [12000, 14400, 14400, 14400]
09:10:14 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 1 and 2
09:10:15 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 14400, 14400, 14400] to [12000, 16000, 16000, 14400]
09:10:16 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 1 and 2
09:10:17 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16000, 16000, 14400] to [12000, 17600, 17600, 14400]
09:10:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1919:processing parameter changes
09:10:21 AM:INFO:move_worker:move_worker.py:update_step_size:line 260:(update step size): Setting step size to 0.2
09:10:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_y1, 16.0 -> 22.0
09:10:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_y2, 16.0 -> 22.0
09:10:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1978:Changing parameter: lineEdit_step_size, 2.0 -> 0.2
09:11:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9591343.480864, '127.0.0.1', 4033]
09:15:48 AM:INFO:Foraging:Foraging.py:_Start:line 3819:Start button pressed: starting trial loop
09:15:48 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1919:processing parameter changes
09:15:50 AM:ERROR:Foraging:Foraging.py:_Start:line 3851:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon
ellahiltonvano commented 1 week ago

Henry reported that he forgot to start FIP for this mouse on 11/1 but knows he was supposed to

alexpiet commented 1 week ago

This issue reoccurred:

file: Foraging.py
function: _Start
line 3812
logfile: W10DT714674/W10DT714674-D_gui_log_2024-11-04_09-45-46.txt
boxes: 6D
count: 1
text: Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon


Log context

09:51:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9942944.665504, '127.0.0.1', 4033]
09:51:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 9942950.304, '127.0.0.1', 4033]
09:51:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9942950.306496, '127.0.0.1', 4033]
09:51:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9942954.664992, '127.0.0.1', 4033]
09:51:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9942954.664992, '127.0.0.1', 4033]
09:51:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9942954.666496, '127.0.0.1', 4033]
09:51:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9942954.667488, '127.0.0.1', 4033]
09:51:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 9942959.656992, '127.0.0.1', 4033]
09:51:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 9942959.658496, '127.0.0.1', 4033]
09:51:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 9942964.715488, '127.0.0.1', 4033]
09:54:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:54:03 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 15.0
09:54:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y1, 21.2 -> 0.0
09:54:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 14.9975 -> 15.0
09:54:06 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [12000, 0, 0, 0]
09:54:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:54:09 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 1 to 21.2
09:54:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y1, 0.0 -> 21.2
09:54:13 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 0, 0, 0] to [12000, 16960, 0, 0]
09:54:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:54:16 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 21.2
09:54:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 0.0 -> 21.2
09:54:20 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16960, 0, 0] to [12000, 16960, 16960, 0]
09:54:22 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:54:22 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 17.6
09:54:22 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_z, 0.0 -> 17.6
09:54:26 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16960, 16960, 0] to [12000, 16960, 16960, 14080]
09:58:52 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:58:53 AM:ERROR:Foraging:Foraging.py:_Start:line 3812:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon
ellahiltonvano commented 1 week ago

This mouse is on stage 2

alexpiet commented 3 days ago

This issue reoccurred:

file: Foraging.py
function: _Start
line 3812
logfile: W10DT714674/W10DT714674-D_gui_log_2024-11-07_09-38-55.txt
boxes: 6D
count: 2
text: Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon

GUI Log snippet (click for full log)

09:49:02 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_z, 0.0 -> 17.6
09:49:06 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12158, 16960, 16960, 0] to [12158, 16960, 16960, 14080]
09:50:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.080128, '127.0.0.1', 4033]
09:50:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.186176, '127.0.0.1', 4033]
09:50:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.293472, '127.0.0.1', 4033]
09:50:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.42672, '127.0.0.1', 4033]
09:50:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.045024, '127.0.0.1', 4033]
09:50:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.167616, '127.0.0.1', 4033]
09:50:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.299008, '127.0.0.1', 4033]
09:50:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.465088, '127.0.0.1', 4033]
09:50:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.570432, '127.0.0.1', 4033]
09:50:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202081.142336, '127.0.0.1', 4033]
09:50:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202081.302528, '127.0.0.1', 4033]
09:50:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202083.621792, '127.0.0.1', 4033]
09:50:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202083.7944, '127.0.0.1', 4033]
09:50:27 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:50:27 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:50:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202085.663872, '127.0.0.1', 4033]
09:50:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202086.21696, '127.0.0.1', 4033]
09:50:28 AM:ERROR:Foraging:Foraging.py:_Start:line 3812:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon

 Full GUI log (first 400 lines)

09:38:55 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile!
09:38:55 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4718:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:38:55 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61
09:38:55 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8
09:38:55 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean
09:38:55 AM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes
09:38:55 AM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window
09:38:55 AM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window
09:38:55 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file
09:38:55 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (go_cue_decibel_box1), using default: 60
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (go_cue_decibel_box2), using default: 60
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (go_cue_decibel_box3), using default: 60
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (create_rig_metadata), using default: True
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (AutomaticUpload), using default: True
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True
09:38:55 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True
09:38:55 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1082:Loaded behavior schedule
09:38:55 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
09:38:55 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_446-6-D_2024-11-05_11_08_20.json
09:38:55 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:38:55 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:38:55 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:38:55 AM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface
09:38:55 AM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 446-6-D
09:38:55 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
09:38:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:38:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out
09:38:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai
09:38:56 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting
09:38:57 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:38:58 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out
09:38:58 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:38:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out
09:39:00 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:39:00 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 1.5 seconds
09:39:00 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully
09:39:00 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims
09:39:01 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims
09:39:01 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_4.json
09:39:02 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:39:02 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages
09:39:02 AM:WARNING:Foraging:Foraging.py:_InitializeMotorStage:line 867:Could not find any instances of NewScale Stage
09:39:02 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 239:Inserting Stage Widget
09:39:02 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:39:02 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:39:02 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:39:02 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:39:02 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 61:Connected to COM6, device id: 1130
09:39:02 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 142:Getting available registers on device
09:39:02 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:39:02 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:39:02 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:39:02 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:39:02 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:39:02 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:39:02 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:39:02 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3472:Checking that photometry is not running
09:39:02 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3482:Photometry excitation stopped
09:39:02 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_446-6-D_2024-11-05_11_08_20.json
09:39:02 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 953:attempting to close bonsai connection
09:39:06 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 961:bonsai connection closed
09:39:06 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to restart bonsai
09:39:06 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
09:39:06 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:39:06 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1360:Connected to already running Bonsai
09:39:06 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1361:Bonsai started successfully
09:39:06 AM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete
09:39:07 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5243
09:39:07 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3814
09:39:08 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:39:08 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:39:09 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:39:09 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:39:09 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0
09:39:09 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2
09:39:09 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
09:39:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201437.612992, '127.0.0.1', 4033]
09:39:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201437.61648, '127.0.0.1', 4033]
09:39:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201438.048, '127.0.0.1', 4033]
09:39:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201438.050496, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201447.605984, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201447.605984, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201447.607488, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201447.60848, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201448.036, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201448.036992, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201448.037504, '127.0.0.1', 4033]
09:39:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201448.038496, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201457.6, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201457.6, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201457.601504, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201457.602496, '127.0.0.1', 4033]
09:39:59 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201458.037984, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201458.037984, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201458.039488, '127.0.0.1', 4033]
09:39:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201458.04048, '127.0.0.1', 4033]
09:40:03 AM:INFO:Foraging:Foraging.py:_Open:line 2974:Quick load success: C:\behavior_data\446-6-D\743986\behavior_743986_2024-11-06_09-51-35\behavior\743986_2024-11-06_09-51-35.json
09:40:03 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:40:03 AM:INFO:Foraging:Foraging.py:_NewSession:line 3570:Resetting session run flag
09:40:03 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3472:Checking that photometry is not running
09:40:03 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3482:Photometry excitation stopped
09:40:03 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMin, 0.0 -> 1.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.03 -> 0.041
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.03 -> 0.037
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 743986.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMin, 0.0 -> 1.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.03 -> 0.041
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.03 -> 0.037
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: GiveWaterL, 0.03 -> 0.037
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: GiveWaterR, 0.03 -> 0.041
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 35.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardDelay, 0.0 -> 0.1
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 10.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 1.5
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 35.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardDelay, 0.0 -> 0.1
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 10.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
09:40:03 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 1.5
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:04 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: Ignored, 100.0 -> 10.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockBeta, 20.0 -> 10.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: StopIgnores, 20.0 -> 25.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: MaxTime, 120.0 -> 75.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: Multiplier, 0.8 -> 0.5
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue_volume, 3.0 -> 2.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.041 -> 0.028
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.037 -> 0.026
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: Unrewarded, 200.0 -> 10.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue_volume, 3.0 -> 2.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: warm_min_trial, 60.0 -> 50.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: Ignored, 100.0 -> 10.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockBeta, 20.0 -> 10.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: StopIgnores, 20.0 -> 25.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: MaxTime, 120.0 -> 75.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: Multiplier, 0.8 -> 0.5
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue_volume, 3.0 -> 2.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.041 -> 0.028
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.037 -> 0.026
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: Unrewarded, 200.0 -> 10.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue_volume, 3.0 -> 2.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: warm_min_trial, 60.0 -> 50.0
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y1, 0.0 -> 21.2
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_z, 0.0 -> 17.6
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 0.0 -> 21.2
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 0.0 -> 15.1975
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_step_size, 1.0 -> 0.2
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: SuggestedWater,  -> 0.59
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BaseWeight,  -> 31.4
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: TargetWeight,  -> 26.69
09:40:04 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2949:AutoTrain disengaged!
09:40:04 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:40:04 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2691:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:40:04 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:40:04 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: STAGE_3 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:40:04 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: STAGE_3 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:40:04 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2691:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:40:04 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:40:04 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2898:AutoTrain engaged! STAGE_3 @ Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3029: Widget "training_stage" not found. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3021:Task is set to Coupled Without Baiting
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3029: Widget "task_url" not found. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3029: Widget "task_schema_version" not found. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3029: Widget "description" not found. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:BaseRewardSum is set to 0.8
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:RewardFamily is set to 1
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:RewardPairsN is set to 1
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3041: Widget "UncoupledReward" has been disabled by the GUI. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:Randomness is set to Exponential
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:BlockMin is set to 20
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:BlockMax is set to 35
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:BlockBeta is set to 10
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:BlockMinReward is set to 0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:DelayMin is set to 1.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:DelayMax is set to 1.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:DelayBeta is set to 0.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:RewardDelay is set to 0.1
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:AutoReward is set to True
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:AutoWaterType is set to Natural
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:Multiplier is set to 0.5
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:Unrewarded is set to 10
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:Ignored is set to 10
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:ITIMin is set to 1.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:ITIMax is set to 10.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:ITIBeta is set to 3.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3041: Widget "ITIIncrease" has been disabled by the GUI. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:ResponseTime is set to 1.5
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:RewardConsumeTime is set to 1.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:StopIgnores is set to 25
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:AdvancedBlockAuto is set to now
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:SwitchThr is set to 0.5
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:PointsInARow is set to 5
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:MaxTrial is set to 1000
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:MaxTime is set to 75
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:RightValue_volume is set to 2.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:LeftValue_volume is set to 2.0
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3041: Widget "warm_min_trial" has been disabled by the GUI. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3041: Widget "warm_max_choice_ratio_bias" has been disabled by the GUI. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3041: Widget "warm_min_finish_ratio" has been disabled by the GUI. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3041: Widget "warm_windowsize" has been disabled by the GUI. skipped...
09:40:04 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3076:warmup is set to off
09:40:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:40:04 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2526:Auto engage successful for mouse 743986
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201467.605984, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201467.606976, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201467.60848, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201467.609504, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201468.036, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201468.036992, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201468.038496, '127.0.0.1', 4033]
09:40:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201468.039488, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201477.597984, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201477.597984, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201477.60048, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201477.601504, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201478.037984, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201478.037984, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201478.04048, '127.0.0.1', 4033]
09:40:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201478.041504, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201487.605984, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201487.605984, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201487.608512, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201487.609504, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201488.036, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201488.036, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201488.037504, '127.0.0.1', 4033]
09:40:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201488.038528, '127.0.0.1', 4033]
09:40:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 10201493.601984, '127.0.0.1', 4033]
09:40:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10201493.603488, '127.0.0.1', 4033]
09:40:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201498.033984, '127.0.0.1', 4033]
09:40:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201498.034976, '127.0.0.1', 4033]
09:40:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201498.03648, '127.0.0.1', 4033]
09:40:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201498.037504, '127.0.0.1', 4033]
09:40:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 10201503.034976, '127.0.0.1', 4033]
09:40:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10201503.03648, '127.0.0.1', 4033]
09:42:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10201622.352256, '127.0.0.1', 4033]
09:43:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10201662.64, '127.0.0.1', 4033]
09:48:15 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:48:15 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 15.1975
09:48:19 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [12158, 0, 0, 0]
09:48:43 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:48:43 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 1 to 21.2
09:48:43 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_z, 17.6 -> 0.0
09:48:43 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 21.2 -> 0.0
09:48:48 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12158, 0, 0, 0] to [12158, 16960, 0, 0]
09:48:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:48:50 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 21.2
09:48:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 0.0 -> 21.2
09:48:54 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12158, 16960, 0, 0] to [12158, 16960, 16960, 0]
09:49:02 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:49:02 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 17.6
09:49:02 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_z, 0.0 -> 17.6
09:49:06 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12158, 16960, 16960, 0] to [12158, 16960, 16960, 14080]
09:50:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.080128, '127.0.0.1', 4033]
09:50:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.186176, '127.0.0.1', 4033]
09:50:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.293472, '127.0.0.1', 4033]
09:50:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202074.42672, '127.0.0.1', 4033]
09:50:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.045024, '127.0.0.1', 4033]
09:50:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.167616, '127.0.0.1', 4033]
09:50:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.299008, '127.0.0.1', 4033]
09:50:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.465088, '127.0.0.1', 4033]
09:50:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202076.570432, '127.0.0.1', 4033]
09:50:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202081.142336, '127.0.0.1', 4033]
09:50:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202081.302528, '127.0.0.1', 4033]
09:50:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202083.621792, '127.0.0.1', 4033]
09:50:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202083.7944, '127.0.0.1', 4033]
09:50:27 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:50:27 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:50:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10202085.663872, '127.0.0.1', 4033]
09:50:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10202086.21696, '127.0.0.1', 4033]
09:50:28 AM:ERROR:Foraging:Foraging.py:_Start:line 3812:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon

alexpiet commented 2 days ago

This issue reoccurred:

file: Foraging.py
function: _Start
line 3769
logfile: W10DT714674/W10DT714674-D_gui_log_2024-11-11_11-04-33.txt
boxes: 6D
count: 2
text: Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon

GUI Log snippet (click for full log)

11:25:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:25:21 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 21.0
11:25:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 0.0 -> 21.0
11:25:25 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16800, 0, 0] to [12000, 16800, 16800, 0]
11:25:29 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:25:29 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 18.4
11:25:29 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 0.0 -> 18.4
11:25:32 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16800, 16800, 0] to [12000, 16800, 16800, 14719]
11:28:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335376.70848, '127.0.0.1', 4033]
11:28:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335376.817312, '127.0.0.1', 4033]
11:28:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335376.956544, '127.0.0.1', 4033]
11:28:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335385.65856, '127.0.0.1', 4033]
11:28:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335399.294976, '127.0.0.1', 4033]
11:28:44 AM:INFO:Foraging:Foraging.py:_Start:line 3737:Start button pressed: starting trial loop
11:28:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:28:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 18.4 -> 18.3987
11:28:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335401.7944, '127.0.0.1', 4033]
11:28:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335401.966368, '127.0.0.1', 4033]
11:28:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335402.285312, '127.0.0.1', 4033]
11:28:47 AM:ERROR:Foraging:Foraging.py:_Start:line 3769:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon

 Full GUI log 

11:04:33 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
11:04:33 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
11:04:33 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: production_testing, 5df16b6537b77543ebec6d65af6967bf5ef7671b
11:04:33 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.6
11:04:33 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
11:04:33 AM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
11:04:33 AM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
11:04:34 AM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
11:04:34 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
11:04:34 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
11:04:34 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
11:04:34 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
11:04:34 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
11:04:34 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-D_2024-11-05_11_08_20.json
11:04:34 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
11:04:34 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
11:04:34 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
11:04:34 AM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
11:04:34 AM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-D
11:04:34 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
11:04:34 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
11:04:35 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
11:04:35 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
11:04:35 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
11:04:35 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
11:04:36 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
11:04:37 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
11:04:38 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
11:04:38 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
11:04:39 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
11:04:39 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
11:04:39 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
11:04:40 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
11:04:40 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_4.json
11:04:40 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:04:40 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
11:04:40 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
11:04:40 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
11:04:40 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
11:04:40 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
11:04:40 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
11:04:40 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
11:04:40 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 61:Connected to COM6, device id: 1130
11:04:40 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 142:Getting available registers on device
11:04:40 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
11:04:40 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
11:04:40 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
11:04:40 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
11:04:40 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
11:04:40 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
11:04:40 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
11:04:40 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3446:Checking that photometry is not running
11:04:40 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3456:Photometry excitation stopped
11:04:40 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-D_2024-11-05_11_08_20.json
11:04:40 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
11:04:44 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
11:04:44 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
11:04:44 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
11:04:44 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
11:04:44 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
11:04:44 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
11:04:44 AM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
11:04:46 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5323
11:04:46 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3892
11:04:47 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
11:04:47 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
11:04:47 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
11:04:47 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
11:04:47 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
11:04:47 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
11:04:47 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
11:05:41 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
11:05:50 AM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-6-D\743986\behavior_743986_2024-11-07_09-50-29\behavior\743986_2024-11-07_09-50-29.json
11:05:50 AM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
11:05:50 AM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
11:05:50 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3446:Checking that photometry is not running
11:05:50 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3456:Photometry excitation stopped
11:05:50 AM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.037
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 743986.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.037
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.037
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.041
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:50 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:50 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

11:05:56 AM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.028
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.037 -> 0.026
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.028
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.037 -> 0.026
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y1, 0.0 -> 21.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 0.0 -> 18.3987
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 0.0 -> 21.0
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_x, 0.0 -> 14.795
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_step_size, 1.0 -> 0.2
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 31.4
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 26.69
11:05:56 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
11:05:56 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
11:05:56 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
11:05:56 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
11:05:56 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_3 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
11:05:56 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_3 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
11:05:56 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
11:05:56 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
11:05:56 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! STAGE_3 @ Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Coupled Without Baiting
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BaseRewardSum is set to 0.8
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardFamily is set to 1
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardPairsN is set to 1
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "UncoupledReward" has been disabled by the GUI. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 20
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMax is set to 35
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockBeta is set to 10
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMinReward is set to 0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMin is set to 1.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMax is set to 1.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayBeta is set to 0.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardDelay is set to 0.1
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoReward is set to True
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoWaterType is set to Natural
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Multiplier is set to 0.5
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Unrewarded is set to 10
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Ignored is set to 10
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMin is set to 1.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMax is set to 10.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIBeta is set to 3.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "ITIIncrease" has been disabled by the GUI. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ResponseTime is set to 1.5
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardConsumeTime is set to 1.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:StopIgnores is set to 25
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AdvancedBlockAuto is set to now
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:SwitchThr is set to 0.5
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:PointsInARow is set to 5
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:MaxTrial is set to 1000
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:MaxTime is set to 75
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RightValue_volume is set to 2.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:LeftValue_volume is set to 2.0
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_min_trial" has been disabled by the GUI. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_max_choice_ratio_bias" has been disabled by the GUI. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_min_finish_ratio" has been disabled by the GUI. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_windowsize" has been disabled by the GUI. skipped...
11:05:56 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:warmup is set to off
11:05:56 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:05:56 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2515:Auto engage successful for mouse 743986
11:07:14 AM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
11:08:05 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:08:05 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 14.795
11:08:09 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [11836, 0, 0, 0]
11:08:11 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
11:08:11 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
11:08:11 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
11:08:13 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
11:16:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334651.297984, '127.0.0.1', 4033]
11:16:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334651.301504, '127.0.0.1', 4033]
11:16:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334651.782976, '127.0.0.1', 4033]
11:16:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334651.785504, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334661.284, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334661.284, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334661.285504, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334661.286496, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334661.773984, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334661.774976, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334661.775488, '127.0.0.1', 4033]
11:16:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334661.77648, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334671.292, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334671.292992, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334671.294496, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334671.295488, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334671.772, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334671.772992, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334671.774496, '127.0.0.1', 4033]
11:16:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334671.775488, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334681.285984, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334681.285984, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334681.287488, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334681.28848, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334681.776, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334681.776, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334681.777504, '127.0.0.1', 4033]
11:16:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334681.778496, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334691.292992, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334691.292992, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334691.294528, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334691.295488, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334691.772992, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334691.772992, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334691.774528, '127.0.0.1', 4033]
11:16:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334691.775488, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334701.292, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334701.292, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334701.293504, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334701.294496, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334701.768, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334701.768992, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334701.770496, '127.0.0.1', 4033]
11:17:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334701.771488, '127.0.0.1', 4033]
11:17:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 334707.290976, '127.0.0.1', 4033]
11:17:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 334707.29248, '127.0.0.1', 4033]
11:17:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334711.772, '127.0.0.1', 4033]
11:17:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334711.772992, '127.0.0.1', 4033]
11:17:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334711.774496, '127.0.0.1', 4033]
11:17:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334711.775488, '127.0.0.1', 4033]
11:17:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 334716.773984, '127.0.0.1', 4033]
11:17:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 334716.775488, '127.0.0.1', 4033]
11:18:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 334812.342976, '127.0.0.1', 4033]
11:23:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:23:44 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 15.0
11:23:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y1, 21.0 -> 0.0
11:23:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 18.3987 -> 0.0
11:23:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 21.0 -> 0.0
11:23:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_x, 14.795 -> 15.0
11:23:48 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [12000, 0, 0, 0]
11:24:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:24:01 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 1 to 21.0
11:24:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y1, 0.0 -> 21.0
11:24:05 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 0, 0, 0] to [12000, 16800, 0, 0]
11:25:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:25:21 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 21.0
11:25:21 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 0.0 -> 21.0
11:25:25 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16800, 0, 0] to [12000, 16800, 16800, 0]
11:25:29 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:25:29 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 18.4
11:25:29 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 0.0 -> 18.4
11:25:32 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 16800, 16800, 0] to [12000, 16800, 16800, 14719]
11:28:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335376.70848, '127.0.0.1', 4033]
11:28:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335376.817312, '127.0.0.1', 4033]
11:28:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335376.956544, '127.0.0.1', 4033]
11:28:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335385.65856, '127.0.0.1', 4033]
11:28:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335399.294976, '127.0.0.1', 4033]
11:28:44 AM:INFO:Foraging:Foraging.py:_Start:line 3737:Start button pressed: starting trial loop
11:28:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:28:44 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 18.4 -> 18.3987
11:28:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335401.7944, '127.0.0.1', 4033]
11:28:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 335401.966368, '127.0.0.1', 4033]
11:28:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 335402.285312, '127.0.0.1', 4033]
11:28:47 AM:ERROR:Foraging:Foraging.py:_Start:line 3769:Starting session with conflicting FIP information: mouse 743986, FIP off, but schedule lists FIP Axon

ellahiltonvano commented 1 day ago

This mouse is on stage 3