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

Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10% #1075

Open alexpiet opened 5 days ago

alexpiet commented 5 days ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714683/W10DT714683-C_gui_log_2024-11-23_17-44-55.txt
boxes: 7C
count: 1
text: Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10%

GUI Log snippet (click for full log)

10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544474.406976, '127.0.0.1', 4022]
10:26:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544474.409504, '127.0.0.1', 4022]
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.89%.
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 2.81%.
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.56%.
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 12.50%.
10:26:56 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

05:44:55 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4661:Starting logfile!
05:44:55 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4672:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
05:44:55 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4689:Current git commit branch, hash: main, 1a7c9d3d1aa10284caed44ba9b223c6bfbb8ff5f
05:44:55 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4693:Current foraging_gui version: 1.6.10
05:44:55 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4703:local repository is clean
05:44:55 PM:INFO:Foraging:Foraging.py:<module>:line 4804:Setting QApplication attributes
05:44:55 PM:INFO:Foraging:Foraging.py:<module>:line 4812:Starting QApplication and Window
05:44:55 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
05:44:55 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1174:Loaded settings_box file
05:44:55 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1202:Loaded settings file
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_workflow_path), using default: 
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box1), using default: 60
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box2), using default: 60
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box4), using default: 60
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box1), using default: 5000
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box2), using default: 5000
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box3), using default: 5000
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box4), using default: 5000
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (create_rig_metadata), using default: True
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (save_each_trial), using default: True
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (AutomaticUpload), using default: True
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (auto_engage), using default: True
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (clear_figure_after_save), using default: True
05:44:55 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (add_default_project_name), using default: True
05:44:55 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1100:Loaded behavior schedule
05:44:55 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:44:55 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-7-C_2024-11-19_12_59_08.json
05:44:55 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
05:44:55 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
05:44:56 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
05:44:56 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
05:44:56 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-C
05:44:56 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
05:44:56 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:44:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1375:Could not connect: timed out
05:44:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1384:Starting Bonsai
05:44:57 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4776:BONSAI logging starting
05:44:57 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:44:58 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 0.5 seconds: timed out
05:44:59 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:45:00 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.0 seconds: timed out
05:45:00 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:45:01 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1401:Connected to Bonsai after 1.5 seconds
05:45:01 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1402:Bonsai started successfully
05:45:01 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1281:Attempting to connect to Slims
05:45:02 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1298:Successfully connected to Slims
05:45:02 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 480:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_3.json
05:45:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
05:45:02 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 875:Scanning for newscale stages
05:45:02 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 885:Could not find any instances of NewScale Stage
05:45:02 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
05:45:02 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
05:45:02 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
05:45:02 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
05:45:02 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
05:45:02 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
05:45:02 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
05:45:02 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
05:45:02 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
05:45:02 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
05:45:06 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
05:45:12 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
05:45:15 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
05:45:15 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
05:45:15 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-7-C_2024-11-19_12_59_08.json
05:45:15 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:attempting to close bonsai connection
05:45:17 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 979:bonsai connection closed
05:45:17 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 981:attempting to restart bonsai
05:45:17 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
05:45:17 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:45:17 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1378:Connected to already running Bonsai
05:45:17 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1379:Bonsai started successfully
05:45:17 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
05:45:18 PM: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) = 5621
05:45:18 PM: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) = 4165
05:45:19 PM: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/
05:45:19 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
05:45:20 PM: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/
05:45:20 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
05:45:20 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2273:No entry found in df_training_manager for subject_id: 0
05:45:20 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=2
05:45:20 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: unknown training stage @unknown curriculum
05:46:26 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1213:Camera is on
05:48:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12527790.676992, '127.0.0.1', 4023]
05:48:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12527790.681504, '127.0.0.1', 4023]
05:48:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12527796.064, '127.0.0.1', 4023]
05:48:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12527796.067488, '127.0.0.1', 4023]
05:48:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12527796.672992, '127.0.0.1', 4023]
05:48:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12527796.682496, '127.0.0.1', 4023]
05:49:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12527801.792, '127.0.0.1', 4023]
05:49:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12527801.795488, '127.0.0.1', 4023]
05:59:30 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
05:59:40 PM:INFO:Foraging:Foraging.py:_Open:line 2948:Quick load success: C:\behavior_data\446-7-C\756346\behavior_756346_2024-11-22_15-30-02\behavior\756346_2024-11-22_15-30-02.json
05:59:40 PM:INFO:Foraging:Foraging.py:_NewSession:line 3491:New Session pressed
05:59:40 PM:INFO:Foraging:Foraging.py:_NewSession:line 3523:Resetting session run flag
05:59:40 PM:INFO:Foraging:Foraging.py:_NewSession:line 3561:New Session complete
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.023
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ID, 0.0 -> 756346.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.023
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.023
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.041
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
05:59:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
05:59:40 PM: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])

05:59:41 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 682:
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.027
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.027
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.041 -> 0.027
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y1, 0.0 -> 26.295
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_z, 0.0 -> 20.1
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y2, 0.0 -> 26.295
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_x, 0.0 -> 15.3
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_step_size, 1.0 -> 0.1
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: SuggestedWater,  -> 0.586
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BaseWeight,  -> 22.77
05:59:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: TargetWeight,  -> 19.354
05:59:41 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2825:AutoTrain disengaged!
05:59:41 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
05:59:41 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
05:59:41 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
05:59:41 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: STAGE_FINAL @Uncoupled Baiting (v2.3@1.0)
05:59:41 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: STAGE_FINAL @Uncoupled Baiting (v2.3@1.0)
05:59:41 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
05:59:41 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
05:59:41 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2774:AutoTrain engaged! STAGE_FINAL @ Uncoupled Baiting (v2.3@1.0)
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "training_stage" not found. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2897:Task is set to Uncoupled Baiting
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_url" not found. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_schema_version" not found. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "description" not found. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BaseRewardSum" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardFamily" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardPairsN" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:UncoupledReward is set to 0.1, 0.4, 0.7
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:Randomness is set to Exponential
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMin is set to 20
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMax is set to 35
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockBeta" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockMinReward" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMin is set to 1.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMax is set to 1.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayBeta is set to 0.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:RewardDelay is set to 0.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:AutoReward is set to False
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "AutoWaterType" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Multiplier" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Unrewarded" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Ignored" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMin is set to 1.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMax is set to 30.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIBeta is set to 3.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "ITIIncrease" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ResponseTime is set to 1.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:RewardConsumeTime is set to 3.0
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:StopIgnores is set to 25
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "AdvancedBlockAuto" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "SwitchThr" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "PointsInARow" has been disabled by the GUI. skipped...
05:59:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:MaxTrial is set to 1000
_____SKIPPING_____
10:26:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
10:26:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12544432.305984, '127.0.0.1', 4022]
10:26:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544432.309504, '127.0.0.1', 4022]
10:26:13 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
10:26:13 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:26:13 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 188
10:26:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12544432.322976, '127.0.0.1', 4022]
10:26:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12544432.326496, '127.0.0.1', 4022]
10:26:14 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
10:26:14 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-23_21-56-56
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544435.722976, '127.0.0.1', 4022]
10:26:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544435.725504, '127.0.0.1', 4022]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12544436.705984, '127.0.0.1', 4022]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544436.709504, '127.0.0.1', 4022]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12544436.710304, 4, '127.0.0.1']
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544436.8784, '127.0.0.1', 4023]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 12544436.877984, '127.0.0.1', 4023]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12544436.877984, '127.0.0.1', 4022]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 12544436.877984, '127.0.0.1', 4023]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12544436.88048, '127.0.0.1', 4023]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544437.028512, '127.0.0.1', 4023]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544437.160768, '127.0.0.1', 4023]
10:26:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544437.309184, '127.0.0.1', 4023]
10:26:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12544439.889984, '127.0.0.1', 4022]
10:26:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544439.89248, '127.0.0.1', 4022]
10:26:21 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
10:26:21 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:26:21 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 189
10:26:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12544439.912, '127.0.0.1', 4022]
10:26:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12544439.914496, '127.0.0.1', 4022]
10:26:21 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
10:26:21 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-23_21-56-56
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544441.305984, '127.0.0.1', 4022]
10:26:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544441.309504, '127.0.0.1', 4022]
10:26:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12544442.288992, '127.0.0.1', 4022]
10:26:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544442.29248, '127.0.0.1', 4022]
10:26:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12544442.293344, 4, '127.0.0.1']
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544442.436576, '127.0.0.1', 4023]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 12544442.436, '127.0.0.1', 4023]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12544442.436, '127.0.0.1', 4022]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 12544442.436, '127.0.0.1', 4023]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12544442.438496, '127.0.0.1', 4023]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544442.59536, '127.0.0.1', 4023]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544442.743328, '127.0.0.1', 4023]
10:26:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544442.928384, '127.0.0.1', 4023]
10:26:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12544445.44, '127.0.0.1', 4022]
10:26:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544445.442496, '127.0.0.1', 4022]
10:26:27 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
10:26:27 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:26:27 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 190
10:26:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12544445.461984, '127.0.0.1', 4022]
10:26:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12544445.46448, '127.0.0.1', 4022]
10:26:27 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
10:26:27 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-23_21-56-56
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:27 PM:INFO:bias_indicator:bias_indicator.py:calculate_bias:line 139:Bias: -0.22395765873075835 Trial Count: 189
10:26:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544446.856, '127.0.0.1', 4022]
10:26:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544446.859488, '127.0.0.1', 4022]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12544447.838976, '127.0.0.1', 4022]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544447.842496, '127.0.0.1', 4022]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12544447.843392, 4, '127.0.0.1']
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544447.977824, '127.0.0.1', 4023]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12544447.976992, '127.0.0.1', 4022]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4022]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544448.129344, '127.0.0.1', 4023]
10:26:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544448.302848, '127.0.0.1', 4023]
10:26:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12544450.989984, '127.0.0.1', 4022]
10:26:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544450.99248, '127.0.0.1', 4022]
10:26:32 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
10:26:32 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:26:32 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 191
10:26:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12544451.005984, '127.0.0.1', 4022]
10:26:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12544451.00848, '127.0.0.1', 4022]
10:26:32 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
10:26:32 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-23_21-56-56
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544453.638976, '127.0.0.1', 4022]
10:26:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544453.642496, '127.0.0.1', 4022]
10:26:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12544454.622976, '127.0.0.1', 4022]
10:26:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12544454.626112, 4, '127.0.0.1']
10:26:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544454.626496, '127.0.0.1', 4022]
10:26:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12544455.622976, '127.0.0.1', 4022]
10:26:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4022]
10:26:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12544458.638976, '127.0.0.1', 4022]
10:26:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544458.642496, '127.0.0.1', 4022]
10:26:40 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
10:26:40 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:26:40 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 192
10:26:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12544458.656, '127.0.0.1', 4022]
10:26:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12544458.659488, '127.0.0.1', 4022]
10:26:40 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
10:26:40 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-23_21-56-56
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544465.522976, '127.0.0.1', 4022]
10:26:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544465.526496, '127.0.0.1', 4022]
10:26:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12544466.505984, '127.0.0.1', 4022]
10:26:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544466.509504, '127.0.0.1', 4022]
10:26:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12544466.510176, 4, '127.0.0.1']
10:26:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12544467.505984, '127.0.0.1', 4022]
10:26:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4022]
10:26:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12544469.340928, '127.0.0.1', 4023]
10:26:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12544470.522976, '127.0.0.1', 4022]
10:26:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544470.525504, '127.0.0.1', 4022]
10:26:52 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
10:26:52 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:26:52 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 193
10:26:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12544470.54, '127.0.0.1', 4022]
10:26:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12544470.542496, '127.0.0.1', 4022]
10:26:52 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
10:26:52 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-23_21-56-56
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:26:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:26:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12544474.406976, '127.0.0.1', 4022]
10:26:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12544474.409504, '127.0.0.1', 4022]
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.89%.
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 2.81%.
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.56%.
10:26:56 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 12.50%.
10:26:56 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10%

alexpiet commented 4 days ago

This issue reoccurred:

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714683/W10DT714683-C_gui_log_2024-11-25_15-35-59.txt
boxes: 7C
count: 1
text: Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10%

GUI Log snippet (click for full log)

06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.573536, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 12703543.572992, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12703543.572992, '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 12703543.572992, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12703543.57648, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.731584, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.8544, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.978208, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.11024, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.24976, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.39344, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.5304, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.674272, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.821824, '127.0.0.1', 4023]
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.14%.
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 2.00%.
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.48%.
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 14.55%.
06:38:07 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

03:35:59 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4661:Starting logfile!
03:35:59 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4672:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
03:35:59 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4689:Current git commit branch, hash: main, 1a7c9d3d1aa10284caed44ba9b223c6bfbb8ff5f
03:35:59 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4693:Current foraging_gui version: 1.6.10
03:35:59 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4703:local repository is clean
03:35:59 PM:INFO:Foraging:Foraging.py:<module>:line 4804:Setting QApplication attributes
03:35:59 PM:INFO:Foraging:Foraging.py:<module>:line 4812:Starting QApplication and Window
03:35:59 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
03:35:59 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1174:Loaded settings_box file
03:35:59 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1202:Loaded settings file
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_workflow_path), using default: 
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box1), using default: 60
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box2), using default: 60
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box4), using default: 60
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box1), using default: 5000
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box2), using default: 5000
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box3), using default: 5000
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box4), using default: 5000
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (create_rig_metadata), using default: True
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (save_each_trial), using default: True
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (AutomaticUpload), using default: True
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (auto_engage), using default: True
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (clear_figure_after_save), using default: True
03:35:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (add_default_project_name), using default: True
03:35:59 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1100:Loaded behavior schedule
03:35:59 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
03:35:59 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-7-C_2024-11-19_12_59_08.json
03:35:59 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
03:35:59 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
03:35:59 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
03:35:59 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
03:35:59 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-C
03:35:59 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
03:35:59 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:36:00 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1375:Could not connect: timed out
03:36:00 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1384:Starting Bonsai
03:36:00 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4776:BONSAI logging starting
03:36:01 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:36:02 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 0.5 seconds: timed out
03:36:02 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:36:03 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.0 seconds: timed out
03:36:04 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:36:04 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1401:Connected to Bonsai after 1.5 seconds
03:36:04 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1402:Bonsai started successfully
03:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12692622.809504, '127.0.0.1', 4023]
03:36:04 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1281:Attempting to connect to Slims
03:36:05 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1298:Successfully connected to Slims
03:36:05 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 480:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_3.json
03:36:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:36:05 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 875:Scanning for newscale stages
03:36:05 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 885:Could not find any instances of NewScale Stage
03:36:05 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
03:36:05 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
03:36:05 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
03:36:05 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
03:36:05 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
03:36:06 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
03:36:06 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
03:36:06 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
03:36:06 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
03:36:06 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
03:36:06 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
03:36:12 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
03:36:12 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
03:36:12 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
03:36:12 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-7-C_2024-11-19_12_59_08.json
03:36:12 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:attempting to close bonsai connection
03:36:16 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 979:bonsai connection closed
03:36:16 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 981:attempting to restart bonsai
03:36:16 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
03:36:16 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:36:16 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1378:Connected to already running Bonsai
03:36:16 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1379:Bonsai started successfully
03:36:16 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
03:36:18 PM: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) = 5669
03:36:18 PM: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) = 4210
03:36:19 PM: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/
03:36:19 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
03:36:20 PM: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/
03:36:20 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
03:36:20 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2273:No entry found in df_training_manager for subject_id: 0
03:36:20 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=2
03:36:20 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: unknown training stage @unknown curriculum
03:37:00 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1213:Camera is on
03:41:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12692966.245984, '127.0.0.1', 4023]
03:41:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12692966.250496, '127.0.0.1', 4023]
03:41:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12692970.624, '127.0.0.1', 4023]
03:41:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12692970.626496, '127.0.0.1', 4023]
03:41:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12692971.284992, '127.0.0.1', 4023]
03:41:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12692971.294496, '127.0.0.1', 4023]
03:41:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12692975.381984, '127.0.0.1', 4023]
03:41:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12692975.38448, '127.0.0.1', 4023]
03:51:57 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
03:52:12 PM:INFO:Foraging:Foraging.py:_Open:line 2936:User entered the ID for a mouse with no data: 756346.
03:52:14 PM:INFO:Foraging:Foraging.py:_OpenNewMouse:line 2884:User declines to start new mouse: 756346.
03:52:16 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
03:52:19 PM:INFO:Foraging:Foraging.py:_Open:line 2948:Quick load success: C:\behavior_data\446-7-C\756346\behavior_756346_2024-11-23_18-01-16\behavior\756346_2024-11-23_18-01-16.json
03:52:19 PM:INFO:Foraging:Foraging.py:_NewSession:line 3491:New Session pressed
03:52:19 PM:INFO:Foraging:Foraging.py:_NewSession:line 3523:Resetting session run flag
03:52:19 PM:INFO:Foraging:Foraging.py:_NewSession:line 3561:New Session complete
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.023
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ID, 0.0 -> 756346.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.023
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.023
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.041
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
03:52:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:52:20 PM: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])

03:52:20 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 682:
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.027
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.027
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.041 -> 0.027
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y1, 0.0 -> 26.3
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_z, 0.0 -> 20.1
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y2, 0.0 -> 26.3
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_x, 0.0 -> 15.0
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_step_size, 1.0 -> 0.1
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: SuggestedWater,  -> 0.544
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BaseWeight,  -> 22.77
03:52:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: TargetWeight,  -> 19.354
03:52:20 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2825:AutoTrain disengaged!
03:52:20 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
03:52:20 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
03:52:20 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
03:52:20 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: STAGE_FINAL @Uncoupled Baiting (v2.3@1.0)
03:52:20 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: STAGE_FINAL @Uncoupled Baiting (v2.3@1.0)
03:52:20 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
03:52:20 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
03:52:20 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2774:AutoTrain engaged! STAGE_FINAL @ Uncoupled Baiting (v2.3@1.0)
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "training_stage" not found. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2897:Task is set to Uncoupled Baiting
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_url" not found. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_schema_version" not found. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "description" not found. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BaseRewardSum" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardFamily" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardPairsN" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:UncoupledReward is set to 0.1, 0.4, 0.7
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:Randomness is set to Exponential
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMin is set to 20
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMax is set to 35
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockBeta" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockMinReward" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMin is set to 1.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMax is set to 1.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayBeta is set to 0.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:RewardDelay is set to 0.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:AutoReward is set to False
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "AutoWaterType" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Multiplier" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Unrewarded" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Ignored" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMin is set to 1.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMax is set to 30.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIBeta is set to 3.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "ITIIncrease" has been disabled by the GUI. skipped...
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ResponseTime is set to 1.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:RewardConsumeTime is set to 3.0
03:52:20 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:StopIgnores is set to 25
_____SKIPPING_____

06:37:26 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
06:37:26 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-25_17-28-07
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12703506.156352, '127.0.0.1', 4023]
06:37:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12703507.136992, '127.0.0.1', 4022]
06:37:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703507.14048, '127.0.0.1', 4022]
06:37:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12703508.120992, '127.0.0.1', 4022]
06:37:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703508.123488, '127.0.0.1', 4022]
06:37:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12703508.124256, 4, '127.0.0.1']
06:37:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12703508.227488, '127.0.0.1', 4023]
06:37:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12703508.226976, '127.0.0.1', 4022]
06:37:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4022]
06:37:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12703508.354176, '127.0.0.1', 4023]
06:37:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12703511.236992, '127.0.0.1', 4022]
06:37:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703511.24048, '127.0.0.1', 4022]
06:37:32 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
06:37:32 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
06:37:32 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 462
06:37:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12703511.258976, '127.0.0.1', 4022]
06:37:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12703511.262496, '127.0.0.1', 4022]
06:37:32 PM: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])

06:37:33 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
06:37:33 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-25_17-28-07
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12703515.086976, '127.0.0.1', 4022]
06:37:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703515.090496, '127.0.0.1', 4022]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12703516.069984, '127.0.0.1', 4022]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703516.073504, '127.0.0.1', 4022]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12703516.074304, 4, '127.0.0.1']
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703516.231648, '127.0.0.1', 4023]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 12703516.230976, '127.0.0.1', 4023]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12703516.230976, '127.0.0.1', 4022]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 12703516.230976, '127.0.0.1', 4023]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022]
06:37:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12703516.234496, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703516.404576, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703516.530848, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703516.668768, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703516.808768, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703516.956512, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703517.106528, '127.0.0.1', 4023]
06:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703517.262976, '127.0.0.1', 4023]
06:37:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703517.426784, '127.0.0.1', 4023]
06:37:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703517.585152, '127.0.0.1', 4023]
06:37:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703517.740768, '127.0.0.1', 4023]
06:37:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703517.911968, '127.0.0.1', 4023]
06:37:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12703519.236992, '127.0.0.1', 4022]
06:37:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703519.24048, '127.0.0.1', 4022]
06:37:40 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
06:37:40 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
06:37:40 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 463
06:37:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12703519.264, '127.0.0.1', 4022]
06:37:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12703519.267488, '127.0.0.1', 4022]
06:37:41 PM: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])

06:37:41 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
06:37:41 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-25_17-28-07
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:41 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12703524.136992, '127.0.0.1', 4022]
06:37:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703524.14048, '127.0.0.1', 4022]
06:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12703525.12, '127.0.0.1', 4022]
06:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12703525.124384, 4, '127.0.0.1']
06:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703525.12448, '127.0.0.1', 4022]
06:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703525.266656, '127.0.0.1', 4023]
06:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12703525.265984, '127.0.0.1', 4022]
06:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
06:37:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703525.40576, '127.0.0.1', 4023]
06:37:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12703528.270976, '127.0.0.1', 4022]
06:37:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703528.273504, '127.0.0.1', 4022]
06:37:49 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
06:37:49 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
06:37:49 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 464
06:37:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12703528.292992, '127.0.0.1', 4022]
06:37:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12703528.295488, '127.0.0.1', 4022]
06:37:50 PM: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])

06:37:50 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
06:37:50 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-25_17-28-07
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:37:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12703533.720992, '127.0.0.1', 4022]
06:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703533.723488, '127.0.0.1', 4022]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12703534.704, '127.0.0.1', 4022]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12703534.707136, 4, '127.0.0.1']
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703534.707488, '127.0.0.1', 4022]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12703534.943936, '127.0.0.1', 4023]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 12703534.942976, '127.0.0.1', 4023]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12703534.942976, '127.0.0.1', 4022]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 12703534.942976, '127.0.0.1', 4023]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12703534.946528, '127.0.0.1', 4023]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12703535.088096, '127.0.0.1', 4023]
06:37:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12703535.233792, '127.0.0.1', 4023]
06:37:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12703537.953984, '127.0.0.1', 4022]
06:37:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703537.95648, '127.0.0.1', 4022]
06:37:59 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
06:37:59 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
06:37:59 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 465
06:37:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12703537.980992, '127.0.0.1', 4022]
06:37:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12703537.983488, '127.0.0.1', 4022]
06:37:59 PM: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])

06:38:00 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
06:38:00 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\757212\behavior_757212_2024-11-25_17-28-07
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
06:38:00 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
06:38:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12703542.452992, '127.0.0.1', 4022]
06:38:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703542.45648, '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12703543.437984, '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12703543.441184, 4, '127.0.0.1']
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12703543.441504, '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.573536, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 12703543.572992, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12703543.572992, '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 12703543.572992, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12703543.57648, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.731584, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.8544, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703543.978208, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.11024, '127.0.0.1', 4023]
06:38:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.24976, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.39344, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.5304, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.674272, '127.0.0.1', 4023]
06:38:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12703544.821824, '127.0.0.1', 4023]
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.14%.
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 2.00%.
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.48%.
06:38:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 14.55%.
06:38:07 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 757212 exceeded 10%