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 D mouse 756566 exceeded 10% #1079

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: W10DT714674/W10DT714674-D_gui_log_2024-11-23_17-44-58.txt
boxes: 6D
count: 1
text: Percentage of cross side lick intervals under 100 ms in Box D mouse 756566 exceeded 10%

GUI Log snippet (click for full log)

07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 1400743.708, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4032]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 1400743.708, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1400743.710496, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400743.823392, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400743.933696, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.052704, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.187008, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400744.316096, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.3272, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400744.381408, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.484352, '127.0.0.1', 4033]
07:24:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.649088, '127.0.0.1', 4033]
07:24:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.819104, '127.0.0.1', 4033]
07:24:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400745.01776, '127.0.0.1', 4033]
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.33%.
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 1.52%.
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.41%.
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 10.56%.
07:24:32 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 756566 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

05:44:58 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4661:Starting logfile!
05:44:58 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:58 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4689:Current git commit branch, hash: main, 1a7c9d3d1aa10284caed44ba9b223c6bfbb8ff5f
05:44:58 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4693:Current foraging_gui version: 1.6.10
05:44:58 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4703:local repository is clean
05:44:58 PM:INFO:Foraging:Foraging.py:<module>:line 4804:Setting QApplication attributes
05:44:58 PM:INFO:Foraging:Foraging.py:<module>:line 4812:Starting QApplication and Window
05:44:58 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
05:44:58 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1174:Loaded settings_box file
05:44:59 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1202:Loaded settings file
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
05:44: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
05:44: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\
05:44: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\
05:44: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
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box1), using default: 60
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box2), using default: 60
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box3), using default: 60
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box1), using default: 5000
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box2), using default: 5000
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box3), using default: 5000
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box4), using default: 5000
05:44: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
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (create_rig_metadata), using default: True
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (save_each_trial), using default: True
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (AutomaticUpload), using default: True
05:44: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
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (auto_engage), using default: True
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (clear_figure_after_save), using default: True
05:44:59 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (add_default_project_name), using default: True
05:44:59 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1100:Loaded behavior schedule
05:44:59 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:44:59 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-6-D_2024-11-19_11_21_56.json
05:44:59 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
05:44:59 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
05:44:59 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
05:44:59 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
05:44:59 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-D
05:44:59 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
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 1375:Could not connect: timed out
05:45:00 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1384:Starting Bonsai
05:45:00 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4776:BONSAI logging starting
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 1398:Could not connect, total waiting time 0.5 seconds: timed out
05:45:02 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:45:03 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.0 seconds: timed out
05:45:03 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:45:04 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1401:Connected to Bonsai after 1.5 seconds
05:45:04 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1402:Bonsai started successfully
05:45:04 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1281:Attempting to connect to Slims
05:45:05 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1298:Successfully connected to Slims
05:45:05 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 480:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_4.json
05:45:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
05:45:05 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 875:Scanning for newscale stages
05:45:05 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 885:Could not find any instances of NewScale Stage
05:45:05 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
05:45:05 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
05:45:05 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
05:45:05 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
05:45:05 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
05:45:05 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
05:45:05 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
05:45:05 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
05:45:05 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
05:45:05 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:05 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:05 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:05 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
05:45:05 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
05:45:05 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3428:Checking that photometry is not running
05:45:05 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3438:Photometry excitation stopped
05:45:05 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-6-D_2024-11-19_11_21_56.json
05:45:05 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:attempting to close bonsai connection
05:45:09 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 979:bonsai connection closed
05:45:09 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 981:attempting to restart bonsai
05:45:09 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
05:45:09 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
05:45:09 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1378:Connected to already running Bonsai
05:45:09 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1379:Bonsai started successfully
05:45:09 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
05:45:10 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:10 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:11 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:11 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:11 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:11 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:11 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2273:No entry found in df_training_manager for subject_id: 0
05:45:11 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=2
05:45:11 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: unknown training stage @unknown curriculum
05:46:58 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1213:Camera is on
05:49:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1395037.316, '127.0.0.1', 4033]
05:49:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1395037.319488, '127.0.0.1', 4033]
05:49:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1395042.357984, '127.0.0.1', 4033]
05:49:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1395042.36048, '127.0.0.1', 4033]
05:49:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1395043.381984, '127.0.0.1', 4033]
05:49:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1395043.385504, '127.0.0.1', 4033]
05:49:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1395048.757984, '127.0.0.1', 4033]
05:49:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1395048.759488, '127.0.0.1', 4033]
05:49:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1395054.29888, '127.0.0.1', 4033]
05:49:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1395054.298912, '127.0.0.1', 4033]
05:49:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1395054.308096, '127.0.0.1', 4033]
05:49:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1395054.30816, '127.0.0.1', 4033]
06:01:28 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
06:01:32 PM:INFO:Foraging:Foraging.py:_Open:line 2930:Quick load failed, user hit cancel or X
06:01:42 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
06:01:56 PM:INFO:Foraging:Foraging.py:_Open:line 2948:Quick load success: C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-22_15-33-16\behavior\756566_2024-11-22_15-33-16.json
06:01:56 PM:INFO:Foraging:Foraging.py:_NewSession:line 3491:New Session pressed
06:01:56 PM:INFO:Foraging:Foraging.py:_NewSession:line 3523:Resetting session run flag
06:01:56 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3428:Checking that photometry is not running
06:01:56 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3438:Photometry excitation stopped
06:01:56 PM:INFO:Foraging:Foraging.py:_NewSession:line 3561:New Session complete
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.026
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ID, 0.0 -> 756566.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.026
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.026
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.041
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
06:01:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
06:01:57 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:01:57 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 682:
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.028
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.028
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.041 -> 0.028
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_init_stage_pos_z, 12.0 -> 10.0
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y1, 0.0 -> 26.1975
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_z, 0.0 -> 19.5
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y2, 0.0 -> 26.1975
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_x, 0.0 -> 16.0825
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_step_size, 1.0 -> 0.1
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: SuggestedWater,  -> 1.3
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BaseWeight,  -> 27.53
06:01:57 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: TargetWeight,  -> 23.4
06:01:57 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2825:AutoTrain disengaged!
06:01:57 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'.
06:01:57 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=0
06:01:57 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'}
06:01:57 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'.
06:01:57 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
06:01:57 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
06:01:57 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'}
06:01:57 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'.
06:01:57 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2774:AutoTrain engaged! GRADUATED @ Uncoupled Baiting (v2.3@1.0)
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "training_stage" not found. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2897:Task is set to Uncoupled Baiting
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_url" not found. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_schema_version" not found. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "description" not found. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BaseRewardSum" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardFamily" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardPairsN" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:UncoupledReward is set to 0.1, 0.4, 0.7
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:Randomness is set to Exponential
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMin is set to 20
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMax is set to 35
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockBeta" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockMinReward" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMin is set to 1.0
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMax is set to 1.0
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayBeta is set to 0.0
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:RewardDelay is set to 0.0
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:AutoReward is set to False
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "AutoWaterType" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Multiplier" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Unrewarded" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Ignored" has been disabled by the GUI. skipped...
06:01:57 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMin is set to 1.0
_____SKIPPING_____
07:23:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400711.68016, '127.0.0.1', 4033], displaying at 0.5 Hz
07:23:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400713.278272, '127.0.0.1', 4033]
07:23:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400713.61488, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400713.73024, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400715.66496, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400715.730304, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1400716.102976, '127.0.0.1', 4032]
07:24:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400716.10448, '127.0.0.1', 4032]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1400717.085984, '127.0.0.1', 4032]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400717.08848, '127.0.0.1', 4032]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1400717.089312, 4, '127.0.0.1']
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400717.169696, '127.0.0.1', 4033]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1400717.168992, '127.0.0.1', 4032]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 1400717.168992, '127.0.0.1', 4033]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4032]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 1400717.168992, '127.0.0.1', 4033]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1400717.171488, '127.0.0.1', 4033]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400717.286656, '127.0.0.1', 4033]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400717.401184, '127.0.0.1', 4033]
07:24:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400717.5368, '127.0.0.1', 4033]
07:24:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400717.684384, '127.0.0.1', 4033]
07:24:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400717.715072, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400717.780384, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400717.851328, '127.0.0.1', 4033]
07:24:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400719.76512, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400719.830464, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1400720.185984, '127.0.0.1', 4032]
07:24:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400720.18848, '127.0.0.1', 4032]
07:24:06 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
07:24:06 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
07:24:06 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 415
07:24:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1400720.206976, '127.0.0.1', 4032]
07:24:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1400720.211488, '127.0.0.1', 4032]
07:24:06 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])

07:24:06 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
07:24:06 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-23_18-14-18
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400721.765216, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400721.880544, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1400722.02, '127.0.0.1', 4032]
07:24:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400722.021504, '127.0.0.1', 4032]
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1400723.002976, '127.0.0.1', 4032]
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1400723.005344, 4, '127.0.0.1']
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400723.005504, '127.0.0.1', 4032]
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400723.0792, '127.0.0.1', 4033]
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1400723.078976, '127.0.0.1', 4032]
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4032]
07:24:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400723.179904, '127.0.0.1', 4033]
07:24:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400723.815264, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400723.930624, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400725.865344, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400725.980704, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1400726.085984, '127.0.0.1', 4032]
07:24:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400726.08848, '127.0.0.1', 4032]
07:24:12 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
07:24:12 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
07:24:12 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 416
07:24:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1400726.102976, '127.0.0.1', 4032]
07:24:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1400726.106496, '127.0.0.1', 4032]
07:24:12 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])

07:24:12 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
07:24:12 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-23_18-14-18
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400727.915424, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400728.030784, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1400728.885984, '127.0.0.1', 4032]
07:24:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400728.88848, '127.0.0.1', 4032]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1400729.869984, '127.0.0.1', 4032]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400729.871488, '127.0.0.1', 4032]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1400729.872352, 4, '127.0.0.1']
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400729.965504, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.058912, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 1400730.057984, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1400730.057984, '127.0.0.1', 4032]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4032]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 1400730.057984, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1400730.06048, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400730.080864, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.18528, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.292704, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.425856, '127.0.0.1', 4033]
07:24:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.562752, '127.0.0.1', 4033]
07:24:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.720032, '127.0.0.1', 4033]
07:24:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400730.888448, '127.0.0.1', 4033]
07:24:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400732.015584, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400732.130912, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1400733.069984, '127.0.0.1', 4032]
07:24:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400733.071488, '127.0.0.1', 4032]
07:24:19 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
07:24:19 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
07:24:19 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 417
07:24:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1400733.090976, '127.0.0.1', 4032]
07:24:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1400733.094496, '127.0.0.1', 4032]
07:24:19 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])

07:24:19 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
07:24:19 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-23_18-14-18
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400734.065664, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400734.131008, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400736.115712, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400736.181088, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1400737.502976, '127.0.0.1', 4032]
07:24:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400737.50448, '127.0.0.1', 4032]
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400738.165824, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400738.231168, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1400738.485984, '127.0.0.1', 4032]
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400738.48848, '127.0.0.1', 4032]
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1400738.489376, 4, '127.0.0.1']
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400738.547424, '127.0.0.1', 4033]
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1400738.546976, '127.0.0.1', 4032]
07:24:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4032]
07:24:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400738.641536, '127.0.0.1', 4033]
07:24:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400739.043424, '127.0.0.1', 4033]
07:24:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400739.274624, '127.0.0.1', 4033]
07:24:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400740.215904, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400740.28128, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1400741.552992, '127.0.0.1', 4032]
07:24:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400741.554496, '127.0.0.1', 4032]
07:24:27 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
07:24:27 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
07:24:27 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 418
07:24:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1400741.569984, '127.0.0.1', 4032]
07:24:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1400741.573504, '127.0.0.1', 4032]
07:24:27 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])

07:24:28 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
07:24:28 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-23_18-14-18
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
07:24:28 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
07:24:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400742.265984, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400742.331328, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1400742.618976, '127.0.0.1', 4032]
07:24:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400742.621504, '127.0.0.1', 4032]
07:24:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1400743.602976, '127.0.0.1', 4032]
07:24:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1400743.605504, '127.0.0.1', 4032]
07:24:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1400743.606432, 4, '127.0.0.1']
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400743.7088, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1400743.708, '127.0.0.1', 4032]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 1400743.708, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4032]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 1400743.708, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1400743.710496, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400743.823392, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400743.933696, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.052704, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.187008, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1400744.316096, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.3272, '127.0.0.1', 4033]
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1400744.381408, '127.0.0.1', 4033], displaying at 0.5 Hz
07:24:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.484352, '127.0.0.1', 4033]
07:24:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.649088, '127.0.0.1', 4033]
07:24:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400744.819104, '127.0.0.1', 4033]
07:24:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1400745.01776, '127.0.0.1', 4033]
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.33%.
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 1.52%.
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.41%.
07:24:32 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 10.56%.
07:24:32 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 756566 exceeded 10%

alexpiet commented 4 days ago

This issue reoccurred:

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714674/W10DT714674-D_gui_log_2024-11-25_15-43-31.txt
boxes: 6D
count: 6
text: Percentage of cross side lick intervals under 100 ms in Box D mouse 756566 exceeded 10%

GUI Log snippet (click for full log)

04:32:20 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
04:32:20 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1755.62GB    Free space: 88.15GB
04:32:20 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-25_16-09-45
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 4.05%.
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 1.33%.
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.67%.
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 11.11%.
04:32:20 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 756566 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

03:43:31 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4661:Starting logfile!
03:43:31 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:43:31 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4689:Current git commit branch, hash: main, 1a7c9d3d1aa10284caed44ba9b223c6bfbb8ff5f
03:43:31 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4693:Current foraging_gui version: 1.6.10
03:43:31 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4703:local repository is clean
03:43:31 PM:INFO:Foraging:Foraging.py:<module>:line 4804:Setting QApplication attributes
03:43:31 PM:INFO:Foraging:Foraging.py:<module>:line 4812:Starting QApplication and Window
03:43:31 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
03:43:31 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1174:Loaded settings_box file
03:43:31 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1202:Loaded settings file
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
03:43:31 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:43:31 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:43:31 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:43:31 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:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box1), using default: 60
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box2), using default: 60
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box3), using default: 60
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box1), using default: 5000
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box2), using default: 5000
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box3), using default: 5000
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box4), using default: 5000
03:43:31 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:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (create_rig_metadata), using default: True
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (save_each_trial), using default: True
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (AutomaticUpload), using default: True
03:43:31 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:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (auto_engage), using default: True
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (clear_figure_after_save), using default: True
03:43:31 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (add_default_project_name), using default: True
03:43:31 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1100:Loaded behavior schedule
03:43:31 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
03:43:31 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-6-D_2024-11-25_12_10_20.json
03:43:31 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
03:43:31 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
03:43:31 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 42:differences with existing rig json: {'values_changed': {"root['daqs'][3]": {'new_value': {'device_type': 'Harp device', 'name': 'Harp sound amplifier', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': None, 'data_interface': 'USB', 'computer_name': 'W10DT714674', 'channels': [], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Input Expander', 'whoami': 1106}, 'core_version': '', 'tag_version': None, 'is_clock_generator': False}, 'old_value': {'device_type': 'Harp device', 'name': 'harp sound amplifier', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': None, 'data_interface': 'USB', 'computer_name': 'W10DT714674', 'channels': [], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Input Expander', 'whoami': 1106}, 'core_version': '', 'tag_version': None, 'is_clock_generator': False}}, "root['daqs'][0]": {'new_value': {'device_type': 'Harp device', 'name': 'Harp Behavior', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': 'Left lick spout and Right lick spout, as well as reward delivery solenoids are connected via ethernet cables', 'data_interface': 'Ethernet', 'computer_name': 'W10DT714674', 'channels': [{'channel_name': 'DI3', 'device_name': 'Photometry Clock', 'channel_type': 'Digital Input', 'port': None, 'channel_index': None, 'sample_rate': None, 'sample_rate_unit': 'hertz', 'event_based_sampling': None}], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Behavior', 'whoami': 1216}, 'core_version': '1.11', 'tag_version': None, 'is_clock_generator': False}, 'old_value': {'device_type': 'Harp device', 'name': 'harp behavior board', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': 'Left lick spout and Right lick spout, as well as reward delivery solenoids are connected via ethernet cables', 'data_interface': 'Ethernet', 'computer_name': 'W10DT714674', 'channels': [{'channel_name': 'DI3', 'device_name': 'Photometry Clock', 'channel_type': 'Digital Input', 'port': None, 'channel_index': None, 'sample_rate': None, 'sample_rate_unit': 'hertz', 'event_based_sampling': None}], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Behavior', 'whoami': 1216}, 'core_version': '1.11', 'tag_version': None, 'is_clock_generator': False}}, "root['daqs'][1]": {'new_value': {'device_type': 'Harp device', 'name': 'Harp Sound', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': None, 'data_interface': 'USB', 'computer_name': 'W10DT714674', 'channels': [], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Sound Card', 'whoami': 1280}, 'core_version': '1.4', 'tag_version': None, 'is_clock_generator': False}, 'old_value': {'device_type': 'Harp device', 'name': 'harp sound card', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': None, 'data_interface': 'USB', 'computer_name': 'W10DT714674', 'channels': [], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Sound Card', 'whoami': 1280}, 'core_version': '1.4', 'tag_version': None, 'is_clock_generator': False}}, "root['daqs'][2]": {'new_value': {'device_type': 'Harp device', 'name': 'Harp clock synchronization board', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': None, 'data_interface': 'USB', 'computer_name': 'W10DT714674', 'channels': [], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Clock Synchronizer', 'whoami': 1152}, 'core_version': '', 'tag_version': None, 'is_clock_generator': True}, 'old_value': {'device_type': 'Harp device', 'name': 'harp clock synchronization board', 'serial_number': None, 'manufacturer': {'name': 'Champalimaud Foundation', 'abbreviation': 'Champalimaud', 'registry': {'name': 'Research Organization Registry', 'abbreviation': 'ROR'}, 'registry_identifier': '03g001n57'}, 'model': None, 'path_to_cad': None, 'port_index': None, 'additional_settings': {}, 'notes': None, 'data_interface': 'USB', 'computer_name': 'W10DT714674', 'channels': [], 'firmware_version': None, 'hardware_version': None, 'harp_device_type': {'name': 'Clock Synchronizer', 'whoami': 1152}, 'core_version': '', 'tag_version': None, 'is_clock_generator': True}}}}
03:43:31 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 51:Saving new rig json: rig_446-6-D_2024-11-25_15_43_31.json
03:43:31 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
03:43:31 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-D
03:43:31 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
03:43:31 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:43:32 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1375:Could not connect: timed out
03:43:32 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1384:Starting Bonsai
03:43:32 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4776:BONSAI logging starting
03:43:32 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:43:33 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 0.5 seconds: timed out
03:43:34 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:43:35 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.0 seconds: timed out
03:43:35 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:43:36 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1401:Connected to Bonsai after 1.5 seconds
03:43:36 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1402:Bonsai started successfully
03:43:36 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1281:Attempting to connect to Slims
03:43:37 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1298:Successfully connected to Slims
03:43:37 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 480:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_4.json
03:43:37 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:43:37 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 875:Scanning for newscale stages
03:43:37 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 885:Could not find any instances of NewScale Stage
03:43:37 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
03:43:37 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
03:43:37 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
03:43:37 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
03:43:37 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
03:43:37 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
03:43:37 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
03:43:37 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
03:43:37 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
03:43:37 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
03:43:37 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
03:43:37 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
03:43:37 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
03:43:37 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
03:43:37 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3428:Checking that photometry is not running
03:43:37 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3438:Photometry excitation stopped
03:43:37 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_446-6-D_2024-11-25_15_43_31.json
03:43:37 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1735.28GB    Free space: 108.50GB
03:43:37 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:attempting to close bonsai connection
03:43:39 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 979:bonsai connection closed
03:43:39 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 981:attempting to restart bonsai
03:43:39 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
03:43:39 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
03:43:39 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1378:Connected to already running Bonsai
03:43:39 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1379:Bonsai started successfully
03:43:39 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
03:43:40 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:43:41 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:43:42 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:43:42 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:43:42 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:43:42 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:43:42 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2273:No entry found in df_training_manager for subject_id: 0
03:43:42 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=2
03:43:42 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: unknown training stage @unknown curriculum
03:44:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1560324.976, '127.0.0.1', 4033]
03:44:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1560324.979488, '127.0.0.1', 4033]
03:44:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1560329.996992, '127.0.0.1', 4033]
03:44:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1560329.999488, '127.0.0.1', 4033]
03:44:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1560330.833984, '127.0.0.1', 4033]
03:44:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1560330.837504, '127.0.0.1', 4033]
03:44:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1560335.124, '127.0.0.1', 4033]
03:44:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1560335.126496, '127.0.0.1', 4033]
03:55:01 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
03:55:18 PM:INFO:Foraging:Foraging.py:_Open:line 2948:Quick load success: C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-24_16-30-53\behavior\756566_2024-11-24_16-30-53.json
03:55:18 PM:INFO:Foraging:Foraging.py:_NewSession:line 3491:New Session pressed
03:55:18 PM:INFO:Foraging:Foraging.py:_NewSession:line 3523:Resetting session run flag
03:55:18 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3428:Checking that photometry is not running
03:55:18 PM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3438:Photometry excitation stopped
03:55:18 PM:INFO:Foraging:Foraging.py:_NewSession:line 3561:New Session complete
03:55:18 PM:INFO:Foraging:Foraging.py:_QComboBoxUpdate:line 1832:Field updated: Photometry:on
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.026
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ID, 0.0 -> 756566.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.041
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.026
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.026
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.041
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:55:18 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:55:18 PM:WARNING:Foraging:Foraging.py:_check_drop_frames:line 680:Error: bottom_camera.avi has 2369145 frames, but 2665377 triggers
Error: side_camera_right.avi has 2381100 frames, but 2665377 triggers

03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.028
03:55:18 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.041 -> 0.028
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.041 -> 0.028
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_init_stage_pos_z, 12.0 -> 10.0
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y1, 0.0 -> 25.4862
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_z, 0.0 -> 19.095
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_y2, 0.0 -> 25.4862
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_x, 0.0 -> 15.67
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: lineEdit_step_size, 1.0 -> 0.1
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: SuggestedWater,  -> 1.401
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BaseWeight,  -> 27.53
03:55:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: TargetWeight,  -> 23.4
03:55:19 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2825:AutoTrain disengaged!
03:55:19 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:55:19 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=0
03:55:19 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:55:19 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:55:19 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
03:55:19 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
03:55:19 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:55:19 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:55:19 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2774:AutoTrain engaged! GRADUATED @ Uncoupled Baiting (v2.3@1.0)
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "training_stage" not found. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2897:Task is set to Uncoupled Baiting
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_url" not found. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "task_schema_version" not found. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2905: Widget "description" not found. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BaseRewardSum" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardFamily" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "RewardPairsN" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:UncoupledReward is set to 0.1, 0.4, 0.7
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:Randomness is set to Exponential
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMin is set to 20
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:BlockMax is set to 35
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockBeta" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "BlockMinReward" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMin is set to 1.0
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayMax is set to 1.0
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:DelayBeta is set to 0.0
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:RewardDelay is set to 0.0
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:AutoReward is set to False
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "AutoWaterType" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Multiplier" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Unrewarded" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2917: Widget "Ignored" has been disabled by the GUI. skipped...
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMin is set to 1.0
03:55:19 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 2952:ITIMax is set to 30.0
_____SKIPPING_____
04:31:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:31:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:31:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:31:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563186.88416, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563186.949504, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563188.93424, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563188.999552, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1563190.26, '127.0.0.1', 4032]
04:31:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563190.261504, '127.0.0.1', 4032]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563190.984288, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563191.049664, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1563191.242976, '127.0.0.1', 4032]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563191.24448, '127.0.0.1', 4032]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1563191.245184, 4, '127.0.0.1']
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563191.342336, '127.0.0.1', 4033]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 1563191.341984, '127.0.0.1', 4033]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1563191.341984, '127.0.0.1', 4032]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4032]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 1563191.341984, '127.0.0.1', 4033]
04:31:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1563191.343488, '127.0.0.1', 4033]
04:31:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563191.458848, '127.0.0.1', 4033]
04:31:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563191.617568, '127.0.0.1', 4033]
04:31:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563191.776768, '127.0.0.1', 4033]
04:31:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563191.932768, '127.0.0.1', 4033]
04:31:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563192.102816, '127.0.0.1', 4033]
04:31:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563192.269504, '127.0.0.1', 4033]
04:31:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563192.438944, '127.0.0.1', 4033]
04:31:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563192.599072, '127.0.0.1', 4033]
04:31:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563192.8168, '127.0.0.1', 4033]
04:31:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563193.034368, '127.0.0.1', 4033], displaying at 0.5 Hz
04:31:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563193.099712, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:00 PM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
04:32:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1563194.342976, '127.0.0.1', 4032]
04:32:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563194.34448, '127.0.0.1', 4032]
04:32:00 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
04:32:00 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
04:32:00 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 62
04:32:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1563194.358976, '127.0.0.1', 4032]
04:32:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1563194.362496, '127.0.0.1', 4032]
04:32:00 PM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12136, 20400, 20400, 15440] to [12056, 20400, 20400, 15440]
04:32:01 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
04:32:01 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1755.32GB    Free space: 88.46GB
04:32:01 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-25_16-09-45
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:01 PM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
04:32:01 PM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12056, 20400, 20400, 15440] to [11976, 20400, 20400, 15440]
04:32:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563195.084448, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563195.149824, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1563195.376, '127.0.0.1', 4032]
04:32:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563195.378496, '127.0.0.1', 4032]
04:32:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1563196.36, '127.0.0.1', 4032]
04:32:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563196.361504, '127.0.0.1', 4032]
04:32:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1563196.36224, 4, '127.0.0.1']
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563196.575744, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1563196.574976, '127.0.0.1', 4032]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 1563196.574976, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4032]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 1563196.574976, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1563196.577504, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563196.7024, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563196.871008, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.018336, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563197.134528, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.172448, '127.0.0.1', 4033]
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563197.199872, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.342144, '127.0.0.1', 4033]
04:32:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.505824, '127.0.0.1', 4033]
04:32:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.660832, '127.0.0.1', 4033]
04:32:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.82496, '127.0.0.1', 4033]
04:32:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563197.99616, '127.0.0.1', 4033]
04:32:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563198.139264, '127.0.0.1', 4033]
04:32:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563198.3136, '127.0.0.1', 4033]
04:32:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563198.52192, '127.0.0.1', 4033]
04:32:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563199.184608, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563199.249984, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1563199.576, '127.0.0.1', 4032]
04:32:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563199.578496, '127.0.0.1', 4032]
04:32:06 PM:INFO:uncoupled_block:uncoupled_block.py:generate_next_block:line 94:--- 62: R is higher for 4 eff_blocks, force R to lowest ---

04:32:06 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:--- 62: R is higher for 4 eff_blocks, force R to lowest ---

04:32:06 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
04:32:06 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 63
04:32:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1563199.592992, '127.0.0.1', 4032]
04:32:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1563199.59648, '127.0.0.1', 4032]
04:32:06 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
04:32:06 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1755.40GB    Free space: 88.38GB
04:32:06 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-25_16-09-45
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:06 PM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 1 and 2
04:32:06 PM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11976, 20400, 20400, 15440] to [11976, 20480, 20480, 15440]
04:32:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563201.204928, '127.0.0.1', 4033]
04:32:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563201.234688, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1563201.292992, '127.0.0.1', 4032]
04:32:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563201.294496, '127.0.0.1', 4032]
04:32:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563201.300032, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1563202.276, '127.0.0.1', 4032]
04:32:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1563202.279264, 4, '127.0.0.1']
04:32:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563202.278496, '127.0.0.1', 4032]
04:32:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563202.365728, '127.0.0.1', 4033]
04:32:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1563202.364992, '127.0.0.1', 4032]
04:32:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4032]
04:32:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563202.519584, '127.0.0.1', 4033]
04:32:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563202.652448, '127.0.0.1', 4033]
04:32:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563203.234784, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563203.350144, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563205.234848, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563205.350208, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1563205.376, '127.0.0.1', 4032]
04:32:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563205.378496, '127.0.0.1', 4032]
04:32:11 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
04:32:11 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
04:32:11 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 64
04:32:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1563205.388, '127.0.0.1', 4032]
04:32:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1563205.391488, '127.0.0.1', 4032]
04:32:12 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
04:32:12 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1755.49GB    Free space: 88.28GB
04:32:12 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-25_16-09-45
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563207.284928, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563207.400288, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563207.949216, '127.0.0.1', 4033]
04:32:15 PM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
04:32:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563209.335008, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563209.450368, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:16 PM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11976, 20480, 20480, 15440] to [11896, 20480, 20480, 15440]
04:32:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1563209.609984, '127.0.0.1', 4032]
04:32:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563209.611488, '127.0.0.1', 4032]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1563210.592992, '127.0.0.1', 4032]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1563210.595296, 4, '127.0.0.1']
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563210.594496, '127.0.0.1', 4032]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563210.683968, '127.0.0.1', 4033]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1563210.682976, '127.0.0.1', 4032]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4032]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1563210.81152, '127.0.0.1', 4033]
04:32:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563211.385088, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563211.450464, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryRising', 1563213.435168, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 1563213.500512, '127.0.0.1', 4033], displaying at 0.5 Hz
04:32:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1563213.692992, '127.0.0.1', 4032]
04:32:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1563213.694496, '127.0.0.1', 4032]
04:32:20 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
04:32:20 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
04:32:20 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 65
04:32:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1563213.704, '127.0.0.1', 4032]
04:32:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1563213.707488, '127.0.0.1', 4032]
04:32:20 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
04:32:20 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1755.62GB    Free space: 88.15GB
04:32:20 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-D\756566\behavior_756566_2024-11-25_16-09-45
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
04:32:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 4.05%.
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 1.33%.
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.67%.
04:32:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 11.11%.
04:32:20 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 756566 exceeded 10%