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 same side lick intervals under 100 ms in Box ephys3A mouse 744329 exceeded 10% #1021

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 930
logfile: W10DT713883/W10DT713883-A_gui_log_2024-11-13_12-40-13.txt
boxes: ephys3
count: 2
text: Percentage of same side lick intervals under 100 ms in Box A mouse 744329 exceeded 10%

GUI Log snippet (click for full log)

12:55:06 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
12:55:06 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744329\behavior_744329_2024-11-13_12-45-02
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:55:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 19.53%.
12:55:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 6.12%.
12:55:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 12.32%.
12:55:07 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 744329 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

12:40:13 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
12:40:13 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:40:13 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
12:40:13 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
12:40:13 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
12:40:13 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
12:40:13 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
12:40:13 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
12:40:13 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
12:40:13 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_ephys\Documents\FIPSettings
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.exe
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsaiworkflow_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\src\workflows\foraging.bonsai
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\metadata_dialog\
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\rig_metadata\
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\Project Name and Funding Source v2.csv
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\name_mapper.json
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_ephys\Documents\aind_watchdog_service\manifest
12:40:13 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
12:40:13 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
12:40:13 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:40:13 PM:INFO:Foraging:Foraging.py:_LoadRigJson:line 1536:Skipping rig metadata creation because create_rig_metadata=False
12:40:14 PM:INFO:Foraging:Foraging.py:_LoadUI:line 281:Using ForagingGUI_Ephys.ui interface
12:40:14 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 323_EPHYS3
12:40:14 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:40:14 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:40:15 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
12:40:15 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
12:40:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
12:40:15 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:40:16 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
12:40:17 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:40:18 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
12:40:18 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:40:19 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.5 seconds: timed out
12:40:20 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:40:21 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 2.0 seconds: timed out
12:40:21 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:40:21 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 2.5 seconds
12:40:21 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
12:40:21 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
12:40:22 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
12:40:22 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_ephys\Documents\ForagingSettings\WaterCalibrationPar_1.json
12:40:22 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:22 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
12:40:22 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 882:found 1 newscale stages
12:40:22 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 906:Found the newscale stage from the settings file
12:40:22 PM:INFO:Foraging:Foraging.py:_connect_stage:line 933:Successfully connected to newscale stage: 46796
12:40:22 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 753:Checking stage connection
12:40:22 PM:INFO:Foraging:Foraging.py:_GetPositions:line 765:Grabbing current stage position
12:40:23 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_323_EPHYS3_2024-10-17.json
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.057
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.053
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.053
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.057
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.057
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.053
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.053
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.057
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionY,  -> 10111.0
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionX,  -> 4493.0
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionZ,  -> 9913.5
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:23 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:23 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
12:40:24 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) = 5368
12:40:25 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) = 3936
12:40:26 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_ephys/capsule/scratch/saved_curriculums/
12:40:26 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_ephys/capsule/scratch/saved_curriculums/
12:40:26 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_ephys/.aind_auto_train/curriculum_manager/
12:40:26 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_ephys/.aind_auto_train/curriculum_manager/
12:40:26 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
12:40:26 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
12:40:26 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
12:40:30 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
12:40:38 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: D:\BehaviorData\323_EPHYS3\744329\behavior_744329_2024-10-31_13-58-00\behavior\744329_2024-10-31_13-58-00.json
12:40:38 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
12:40:38 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
12:40:38 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.057 -> 0.037
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.053 -> 0.035
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.057 -> 0.037
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.053 -> 0.035
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
12:40:39 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_ephys\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:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 744329.0
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 28.8
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 24.48
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: SuggestedWater,  -> 0.68
12:40:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionY, 10111.0 -> 10111.5
12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:WARNING:Foraging:Foraging.py:_check_drop_frames:line 672:Correct: body_camera.avi has 2308737 frames and 2308737 triggers
Error: bottom_camera.avi has 923152 frames, but 2308737 triggers
Error: side_camera_left.avi has 329820 frames, but 2308737 triggers
Correct: side_camera_right.avi has 2308737 frames and 2308737 triggers

12:40:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:40 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
12:40:40 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'.
12:40:40 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
12:40:40 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680: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'}
12:40:40 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'.
12:40:40 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
12:40:40 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
12:40:40 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680: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'}
12:40:40 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'.
12:40:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6549399.161184, '127.0.0.1', 4003]
12:40:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 6549399.161184, '127.0.0.1', 4003], displaying at 0.5 Hz
12:40:53 PM:ERROR:Dialogs:Dialogs.py:_Frequency:line 183:''
12:40:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:ERROR:Dialogs:Dialogs.py:_Frequency:line 183:''
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:40:58 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6549416.177984, '127.0.0.1', 4003]
12:41:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:10 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:10 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:10 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:10 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:12 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:12 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:12 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:15 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:31 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:41:31 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Probability_1, 0.25 -> 1.0
12:41:31 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Duration_1, 5.0 -> 50.0
12:41:47 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
_____SKIPPING_____
12:54:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6550237.537984, '127.0.0.1', 4002]
12:54:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
12:54:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 6550237.542496, '127.0.0.1', 4003]
12:54:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550237.669632, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550237.815584, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550237.936384, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.077056, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.224608, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.350912, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.398976, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.486944, '127.0.0.1', 4003]
12:54:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.623136, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.7608, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550238.895424, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.033728, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.085024, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.175968, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.311008, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.361984, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.442016, '127.0.0.1', 4003]
12:54:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.576224, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.725664, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550239.874304, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550240.026368, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550240.183648, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550240.366432, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550240.520832, '127.0.0.1', 4003]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6550240.545984, '127.0.0.1', 4002]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550240.54848, '127.0.0.1', 4002]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550240.579008, '127.0.0.1', 4003]
12:54:44 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
12:54:44 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
12:54:44 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 68
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6550240.633984, '127.0.0.1', 4002]
12:54:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6550240.637504, '127.0.0.1', 4002]
12:54:44 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_ephys\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:54:45 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
12:54:45 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744329\behavior_744329_2024-11-13_12-45-02
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:54:45 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:54:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550241.872896, '127.0.0.1', 4003]
12:54:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550242.006336, '127.0.0.1', 4003]
12:54:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 6550242.112, '127.0.0.1', 4002]
12:54:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550242.119488, '127.0.0.1', 4002]
12:54:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550242.164736, '127.0.0.1', 4003]
12:54:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 6550243.645984, '127.0.0.1', 4002]
12:54:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550243.647488, '127.0.0.1', 4002]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 6550244.628992, '127.0.0.1', 4002]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550244.631488, '127.0.0.1', 4002]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 6550244.632416, 4, '127.0.0.1']
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550244.720448, '127.0.0.1', 4003]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 6550244.72, '127.0.0.1', 4003]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 6550244.72, '127.0.0.1', 4003]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6550244.72, '127.0.0.1', 4002]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
12:54:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 6550244.723488, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550244.895296, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.026656, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.17168, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.320576, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.494592, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.542016, '127.0.0.1', 4003]
12:54:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.64432, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.780576, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550245.914112, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.04832, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.175104, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.300896, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.444992, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.575968, '127.0.0.1', 4003]
12:54:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.701216, '127.0.0.1', 4003]
12:54:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550246.82896, '127.0.0.1', 4003]
12:54:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550247.005728, '127.0.0.1', 4003]
12:54:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550247.167808, '127.0.0.1', 4003]
12:54:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550247.338016, '127.0.0.1', 4003]
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6550247.728, '127.0.0.1', 4002]
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550247.731488, '127.0.0.1', 4002]
12:54:52 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
12:54:52 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
12:54:52 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 69
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6550247.812992, '127.0.0.1', 4002]
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6550247.81648, '127.0.0.1', 4002]
12:54:52 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_ephys\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:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550247.854528, '127.0.0.1', 4003]
12:54:52 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
12:54:52 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744329\behavior_744329_2024-11-13_12-45-02
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550248.007072, '127.0.0.1', 4003]
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550248.065984, '127.0.0.1', 4003]
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:54:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:54:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550248.189344, '127.0.0.1', 4003]
12:54:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 6550249.178976, '127.0.0.1', 4002]
12:54:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550249.181504, '127.0.0.1', 4002]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 6550250.162976, '127.0.0.1', 4002]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550250.16448, '127.0.0.1', 4002]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 6550250.165344, 4, '127.0.0.1']
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6550250.654272, '127.0.0.1', 4003]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 6550250.653984, '127.0.0.1', 4003]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 6550250.653984, '127.0.0.1', 4003]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6550250.653984, '127.0.0.1', 4002]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
12:54:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 6550250.657504, '127.0.0.1', 4003]
12:54:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550251.957888, '127.0.0.1', 4003]
12:54:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550252.11392, '127.0.0.1', 4003]
12:54:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6550253.662976, '127.0.0.1', 4002]
12:54:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550253.66448, '127.0.0.1', 4002]
12:54:58 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
12:54:58 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
12:54:58 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 70
12:54:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6550253.748, '127.0.0.1', 4002]
12:54:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6550253.750496, '127.0.0.1', 4002]
12:54:58 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_ephys\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:54:58 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
12:54:58 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744329\behavior_744329_2024-11-13_12-45-02
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:54:58 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:54:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550255.099712, '127.0.0.1', 4003]
12:54:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550255.258976, '127.0.0.1', 4003]
12:54:59 PM:INFO:bias_indicator:bias_indicator.py:calculate_bias:line 139:Bias: 9.919568642033842e-05 Trial Count: 69
12:55:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 6550257.896, '127.0.0.1', 4002]
12:55:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550257.897504, '127.0.0.1', 4002]
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 6550258.878976, '127.0.0.1', 4002]
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 6550258.882272, 4, '127.0.0.1']
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550258.881504, '127.0.0.1', 4002]
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550258.970656, '127.0.0.1', 4003]
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6550258.969984, '127.0.0.1', 4002]
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
12:55:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6550259.137408, '127.0.0.1', 4003]
12:55:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6550261.978976, '127.0.0.1', 4002]
12:55:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6550261.981504, '127.0.0.1', 4002]
12:55:06 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
12:55:06 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
12:55:06 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 71
12:55:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6550262.064992, '127.0.0.1', 4002]
12:55:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6550262.067488, '127.0.0.1', 4002]
12:55:06 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_ephys\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:55:06 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
12:55:06 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744329\behavior_744329_2024-11-13_12-45-02
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
12:55:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
12:55:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 19.53%.
12:55:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 6.12%.
12:55:07 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 12.32%.
12:55:07 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 744329 exceeded 10%