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 3C mouse 754372 exceeded 10% #1018

Open alexpiet opened 4 days ago

alexpiet commented 4 days ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714030/W10DT714030-C_gui_log_2024-11-14_12-01-48.txt
boxes: 3C
count: 1
text: Percentage of cross side lick intervals under 100 ms in Box C mouse 754372 exceeded 10%

GUI Log snippet (click for full log)

01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370728.657984, '127.0.0.1', 4022]
01:51:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370728.659488, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370729.640992, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370729.643488, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370729.644352, 4, '127.0.0.1']
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370729.921088, '127.0.0.1', 4023]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370729.920992, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.80%.
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 5.16%.
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.21%.
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 10.29%.
01:51:55 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 754372 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

12:01:48 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
12:01:48 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
12:01:48 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
12:01:48 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
12:01:48 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
12:01:48 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
12:01:48 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
12:01:48 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
12:01:48 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
12:01:48 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (open_ephys_machine_ip_address), using default: 
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
12:01:48 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
12:01:48 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
12:01:48 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:01:48 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_447-3-C_2024-11-12_13_12_42.json
12:01:48 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
12:01:48 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
12:01:48 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
12:01:48 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
12:01:48 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 447-3-C
12:01:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:01:48 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:01:49 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
12:01:49 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
12:01:49 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
12:01:50 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:01:51 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
12:01:51 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:01:52 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.0 seconds
12:01:52 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
12:01:52 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
12:01:53 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
12:01:53 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_3.json
12:01:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:01:53 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
12:01:53 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 882:found 2 newscale stages
12:01:53 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 906:Found the newscale stage from the settings file
12:01:53 PM:INFO:Foraging:Foraging.py:_connect_stage:line 933:Successfully connected to newscale stage: 46808
12:01:53 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 753:Checking stage connection
12:01:53 PM:INFO:Foraging:Foraging.py:_GetPositions:line 765:Grabbing current stage position
12:01:53 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_447-3-C_2024-11-12_13_12_42.json
12:01:53 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
12:01:57 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
12:01:57 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
12:01:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:01:57 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:01:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
12:01:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
12:01:57 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
12:01:58 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) = 5403
12:01:58 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) = 3963
12:01:59 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/
12:01:59 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
12:02:00 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/
12:02:00 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
12:02:00 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
12:02:00 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
12:02:00 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
12:03:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1364243.142976, '127.0.0.1', 4023]
12:03:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1364243.146496, '127.0.0.1', 4023]
12:03:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1364243.609984, '127.0.0.1', 4023]
12:03:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1364243.613504, '127.0.0.1', 4023]
12:03:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1364253.132, '127.0.0.1', 4023]
12:03:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1364253.132992, '127.0.0.1', 4023]
12:03:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1364253.134496, '127.0.0.1', 4023]
12:03:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1364253.135488, '127.0.0.1', 4023]
12:03:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1364253.620992, '127.0.0.1', 4023]
12:03:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1364253.620992, '127.0.0.1', 4023]
12:03:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1364253.622496, '127.0.0.1', 4023]
12:03:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1364253.623488, '127.0.0.1', 4023]
12:04:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1364263.130976, '127.0.0.1', 4023]
12:04:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 1364263.130976, '127.0.0.1', 4023]
12:04:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1364263.133504, '127.0.0.1', 4023]
12:04:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1364263.134496, '127.0.0.1', 4023]
12:04:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1364263.620992, '127.0.0.1', 4023]
12:04:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 1364263.621984, '127.0.0.1', 4023]
12:04:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1364263.623488, '127.0.0.1', 4023]
12:04:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 1364263.62448, '127.0.0.1', 4023]
12:04:10 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
12:04:16 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\447-3-C\754372\behavior_754372_2024-11-13_13-37-02\behavior\754372_2024-11-13_13-37-02.json
12:04:16 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
12:04:16 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
12:04:16 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.038
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.038
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 754372.0
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.038
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.038
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.038
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.038
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionZ,  -> 4369.5
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionY,  -> 6679.5
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionX,  -> 7652.5
12:04:16 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:04:16 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])

12:04:17 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.038 -> 0.027
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.038 -> 0.026
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.038 -> 0.027
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.038 -> 0.026
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionZ, 4369.5 -> 4370.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionX, 7652.5 -> 7652.0
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: SuggestedWater,  -> 0.637
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 30.22
12:04:17 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 25.687
12:04:17 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
12:04:17 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
12:04:17 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
12:04:17 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
12:04:17 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_FINAL @Uncoupled Without Baiting (v2.3@1.0)
12:04:17 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_FINAL @Uncoupled Without Baiting (v2.3@1.0)
12:04:17 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
12:04:17 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
12:04:17 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! STAGE_FINAL @ Uncoupled Without Baiting (v2.3@1.0)
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Uncoupled Without Baiting
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "BaseRewardSum" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "RewardFamily" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "RewardPairsN" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:UncoupledReward is set to 0.1, 0.4, 0.7
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 20
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMax is set to 35
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "BlockBeta" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "BlockMinReward" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMin is set to 1.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMax is set to 1.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayBeta is set to 0.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardDelay is set to 0.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoReward is set to False
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "AutoWaterType" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "Multiplier" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "Unrewarded" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "Ignored" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMin is set to 1.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMax is set to 30.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIBeta is set to 3.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "ITIIncrease" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ResponseTime is set to 1.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardConsumeTime is set to 3.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:StopIgnores is set to 25
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "AdvancedBlockAuto" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "SwitchThr" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "PointsInARow" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:MaxTrial is set to 1000
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:MaxTime is set to 75
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RightValue_volume is set to 2.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:LeftValue_volume is set to 2.0
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_min_trial" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_max_choice_ratio_bias" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_min_finish_ratio" has been disabled by the GUI. skipped...
12:04:17 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_windowsize" has been disabled by the GUI. skipped...
_____SKIPPING_____
01:51:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370680.290976, '127.0.0.1', 4022]
01:51:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370680.29248, '127.0.0.1', 4022]
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370681.273984, '127.0.0.1', 4022]
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370681.27648, '127.0.0.1', 4022]
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370681.277344, 4, '127.0.0.1']
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370681.782624, '127.0.0.1', 4023]
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370681.781984, '127.0.0.1', 4022]
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:51:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370682.012256, '127.0.0.1', 4023]
01:51:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370682.209856, '127.0.0.1', 4023]
01:51:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1370684.790976, '127.0.0.1', 4022]
01:51:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370684.79248, '127.0.0.1', 4022]
01:51:08 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:51:08 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:51:08 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 414
01:51:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1370684.865984, '127.0.0.1', 4022]
01:51:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1370684.869504, '127.0.0.1', 4022]
01:51:08 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])

01:51:08 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:51:08 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\447-3-C\754372\behavior_754372_2024-11-14_12-51-55
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370689.608, '127.0.0.1', 4022]
01:51:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370689.609504, '127.0.0.1', 4022]
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370690.590976, '127.0.0.1', 4022]
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370690.59248, '127.0.0.1', 4022]
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370690.593344, 4, '127.0.0.1']
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370690.923168, '127.0.0.1', 4023]
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370690.922976, '127.0.0.1', 4022]
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:51:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370691.08368, '127.0.0.1', 4023]
01:51:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1370693.924, '127.0.0.1', 4022]
01:51:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370693.926496, '127.0.0.1', 4022]
01:51:17 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:51:17 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:51:17 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 415
01:51:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1370693.998976, '127.0.0.1', 4022]
01:51:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1370694.002496, '127.0.0.1', 4022]
01:51:17 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])

01:51:17 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:51:17 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:51:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\447-3-C\754372\behavior_754372_2024-11-14_12-51-55
01:51:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:51:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370696.690976, '127.0.0.1', 4022]
01:51:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370696.69248, '127.0.0.1', 4022]
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370697.673984, '127.0.0.1', 4022]
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370697.677344, 4, '127.0.0.1']
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370697.67648, '127.0.0.1', 4022]
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370697.96048, '127.0.0.1', 4023]
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370697.96, '127.0.0.1', 4022]
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:51:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370698.130592, '127.0.0.1', 4023]
01:51:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1370700.974976, '127.0.0.1', 4022]
01:51:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370700.97648, '127.0.0.1', 4022]
01:51:24 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:51:24 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:51:24 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 416
01:51:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1370701.048992, '127.0.0.1', 4022]
01:51:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1370701.05248, '127.0.0.1', 4022]
01:51:24 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])

01:51:25 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:51:25 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\447-3-C\754372\behavior_754372_2024-11-14_12-51-55
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370702.708, '127.0.0.1', 4022]
01:51:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370702.709504, '127.0.0.1', 4022]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370703.18672, '127.0.0.1', 4023]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370703.280864, '127.0.0.1', 4023]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370703.30448, '127.0.0.1', 4023]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370703.458304, '127.0.0.1', 4023]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370703.643872, '127.0.0.1', 4023]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370703.66848, '127.0.0.1', 4023]
01:51:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370703.991008, '127.0.0.1', 4023]
01:51:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370704.205952, '127.0.0.1', 4023]
01:51:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370704.24064, '127.0.0.1', 4023]
01:51:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370704.840992, '127.0.0.1', 4022]
01:51:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370704.842496, '127.0.0.1', 4022]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370705.824992, '127.0.0.1', 4022]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370705.826496, '127.0.0.1', 4022]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370705.827328, 4, '127.0.0.1']
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370705.89088, '127.0.0.1', 4023]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 1370705.889984, '127.0.0.1', 4023]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370705.889984, '127.0.0.1', 4022]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 1370705.889984, '127.0.0.1', 4023]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 1370705.89248, '127.0.0.1', 4023]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370705.940096, '127.0.0.1', 4023]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370705.967008, '127.0.0.1', 4023]
01:51:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1370705.974816, '127.0.0.1', 4023]
01:51:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1370708.890976, '127.0.0.1', 4022]
01:51:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370708.893504, '127.0.0.1', 4022]
01:51:32 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:51:32 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:51:32 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 417
01:51:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1370708.969984, '127.0.0.1', 4022]
01:51:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1370708.973504, '127.0.0.1', 4022]
01:51:32 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

01:51:32 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:51:32 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\447-3-C\754372\behavior_754372_2024-11-14_12-51-55
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:51:32 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:33 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370718.39168, '127.0.0.1', 4023]
01:51:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370721.890976, '127.0.0.1', 4022]
01:51:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370721.893504, '127.0.0.1', 4022]
01:51:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370722.874976, '127.0.0.1', 4022]
01:51:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370722.87648, '127.0.0.1', 4022]
01:51:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370722.877344, 4, '127.0.0.1']
01:51:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370723.358688, '127.0.0.1', 4023]
01:51:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370723.357984, '127.0.0.1', 4022]
01:51:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:51:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370723.54208, '127.0.0.1', 4023]
01:51:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370724.216288, '127.0.0.1', 4023]
01:51:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 1370726.374976, '127.0.0.1', 4022]
01:51:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370726.37648, '127.0.0.1', 4022]
01:51:50 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:51:50 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:51:50 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 418
01:51:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 1370726.448992, '127.0.0.1', 4022]
01:51:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 1370726.45248, '127.0.0.1', 4022]
01:51:50 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

01:51:50 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:51:50 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\447-3-C\754372\behavior_754372_2024-11-14_12-51-55
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:51:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:51:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 1370728.657984, '127.0.0.1', 4022]
01:51:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370728.659488, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 1370729.640992, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 1370729.643488, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 1370729.644352, 4, '127.0.0.1']
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 1370729.921088, '127.0.0.1', 4023]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 1370729.920992, '127.0.0.1', 4022]
01:51:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.80%.
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 5.16%.
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.21%.
01:51:55 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 10.29%.
01:51:55 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 754372 exceeded 10%