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 744331 exceeded 10% #1023

Open alexpiet opened 1 week ago

alexpiet commented 1 week 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: 11
text: Percentage of same side lick intervals under 100 ms in Box A mouse 744331 exceeded 10%

GUI Log snippet (click for full log)

03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559941.613792, '127.0.0.1', 4003]
03:36:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559941.806688, '127.0.0.1', 4003]
03:36:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559942.725536, '127.0.0.1', 4003]
03:36:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559943.567136, '127.0.0.1', 4003]
03:36:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559944.634528, '127.0.0.1', 4003]
03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559946.135488, '127.0.0.1', 4003]
03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559946.306592, '127.0.0.1', 4003]
03:36:31 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 16.91%.
03:36:31 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 8.49%.
03:36:31 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 12.20%.
03:36:31 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 744331 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_____
03:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6559919.956, '127.0.0.1', 4002]
03:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
03:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559920.117152, '127.0.0.1', 4003]
03:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559922.476608, '127.0.0.1', 4003]
03:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6559922.968992, '127.0.0.1', 4002]
03:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559922.971488, '127.0.0.1', 4002]
03:36:07 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:36:07 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:36:07 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 83
03:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6559923.045984, '127.0.0.1', 4002]
03:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6559923.050496, '127.0.0.1', 4002]
03:36:07 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])

03:36:07 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
03:36:07 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1752.15GB    Free space: 110.86GB
03:36:07 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744331\behavior_744331_2024-11-13_15-26-26
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559923.274176, '127.0.0.1', 4003]
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559924.582944, '127.0.0.1', 4003]
03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559924.763424, '127.0.0.1', 4003]
03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559925.732576, '127.0.0.1', 4003]
03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559925.776992, '127.0.0.1', 4003]
03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559925.919936, '127.0.0.1', 4003]
03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559925.954976, '127.0.0.1', 4003]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 6559926.86, '127.0.0.1', 4002]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559926.862496, '127.0.0.1', 4002]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 6559926.86336, 4, '127.0.0.1']
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559926.958688, '127.0.0.1', 4003]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 6559926.957984, '127.0.0.1', 4003]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6559926.957984, '127.0.0.1', 4002]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 6559926.957984, '127.0.0.1', 4003]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 6559926.961504, '127.0.0.1', 4003]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559927.103584, '127.0.0.1', 4003]
03:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559927.280448, '127.0.0.1', 4003]
03:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559928.489472, '127.0.0.1', 4003]
03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6559929.968992, '127.0.0.1', 4002]
03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559929.971488, '127.0.0.1', 4002]
03:36:14 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:36:14 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:36:14 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 84
03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6559930.064, '127.0.0.1', 4002]
03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6559930.066496, '127.0.0.1', 4002]
03:36:14 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])

03:36:14 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
03:36:14 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1752.33GB    Free space: 110.69GB
03:36:14 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744331\behavior_744331_2024-11-13_15-26-26
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559930.681888, '127.0.0.1', 4003]
03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559931.047968, '127.0.0.1', 4003]
03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559931.230944, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559931.77664, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559931.923808, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.069024, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.2024, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.250976, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.333856, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 6559932.344992, '127.0.0.1', 4002]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 6559932.34928, 4, '127.0.0.1']
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559932.34848, '127.0.0.1', 4002]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.48896, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 6559932.488, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 6559932.488, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6559932.488, '127.0.0.1', 4002]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 6559932.49248, '127.0.0.1', 4003]
03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.607616, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.753952, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559932.86432, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.003936, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.138912, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.271168, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.416192, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.554016, '127.0.0.1', 4003]
03:36:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.707136, '127.0.0.1', 4003]
03:36:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.835424, '127.0.0.1', 4003]
03:36:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559933.981632, '127.0.0.1', 4003]
03:36:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559934.12368, '127.0.0.1', 4003]
03:36:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559934.274144, '127.0.0.1', 4003]
03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559935.203104, '127.0.0.1', 4003]
03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559935.36192, '127.0.0.1', 4003]
03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6559935.501984, '127.0.0.1', 4002]
03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559935.50448, '127.0.0.1', 4002]
03:36:19 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:36:19 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:36:19 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 85
03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6559935.596, '127.0.0.1', 4002]
03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6559935.599488, '127.0.0.1', 4002]
03:36:19 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])

03:36:20 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
03:36:20 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1752.47GB    Free space: 110.55GB
03:36:20 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744331\behavior_744331_2024-11-13_15-26-26
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:20 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 6559936.772, '127.0.0.1', 4002]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 6559936.77424, 4, '127.0.0.1']
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559936.773504, '127.0.0.1', 4002]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559936.891456, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 6559936.890976, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 6559936.890976, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 6559936.890976, '127.0.0.1', 4002]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 6559936.894496, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559937.255584, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559937.419104, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559937.456992, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559937.538464, '127.0.0.1', 4003]
03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559937.667584, '127.0.0.1', 4003]
03:36:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559937.803072, '127.0.0.1', 4003]
03:36:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559938.109824, '127.0.0.1', 4003]
03:36:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559938.249696, '127.0.0.1', 4003]
03:36:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559938.412352, '127.0.0.1', 4003]
03:36:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559938.564128, '127.0.0.1', 4003]
03:36:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559938.694816, '127.0.0.1', 4003]
03:36:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559938.861344, '127.0.0.1', 4003]
03:36:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559939.007616, '127.0.0.1', 4003]
03:36:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559939.144384, '127.0.0.1', 4003]
03:36:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559939.287424, '127.0.0.1', 4003]
03:36:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559939.443296, '127.0.0.1', 4003]
03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 6559939.901984, '127.0.0.1', 4002]
03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 6559939.90448, '127.0.0.1', 4002]
03:36:24 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:36:24 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:36:24 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 86
03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 6559939.994976, '127.0.0.1', 4002]
03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 6559939.998496, '127.0.0.1', 4002]
03:36:24 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])

03:36:24 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
03:36:24 PM:WARNING:Foraging:Foraging.py:_show_disk_space:line 235:Low disk space  Used space: 1752.56GB    Free space: 110.45GB
03:36:24 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\744331\behavior_744331_2024-11-13_15-26-26
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:36:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559941.613792, '127.0.0.1', 4003]
03:36:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559941.806688, '127.0.0.1', 4003]
03:36:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559942.725536, '127.0.0.1', 4003]
03:36:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559943.567136, '127.0.0.1', 4003]
03:36:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 6559944.634528, '127.0.0.1', 4003]
03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559946.135488, '127.0.0.1', 4003]
03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 6559946.306592, '127.0.0.1', 4003]
03:36:31 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 16.91%.
03:36:31 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 8.49%.
03:36:31 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 12.20%.
03:36:31 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 744331 exceeded 10%