Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10% #1136

Open
alexpiet opened this issue Dec 9, 2024 · 1 comment
Open

Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10% #1136

alexpiet opened this issue Dec 9, 2024 · 1 comment
Labels
medium priority - auto-generated autogenerated issues that have occurred more than once in a month

Comments

@alexpiet
Copy link
Collaborator

alexpiet commented Dec 9, 2024

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-12-04_14-42-30.txt
boxes: ephys3
count: 10
text: Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10%

GUI Log snippet (click for full log)

05:15:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380288.654496, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8380289.634976, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380289.637536, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8380289.638656, 4, '127.0.0.1']
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380289.920672, '127.0.0.1', 4003]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 8380289.92, '127.0.0.1', 4003]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 8380289.92, '127.0.0.1', 4003]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8380289.92, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 8380289.923488, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.055168, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.215072, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.340544, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.4984, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.636512, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.78576, '127.0.0.1', 4003]
05:15:36 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 17.94%.
05:15:36 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 6.71%.
05:15:36 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 11.96%.
05:15:36 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10%
Full GUI log (first 200 and last 200 lines) 
02:42:30 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4661:Starting logfile!
02:42:30 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4672:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
02:42:30 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4689:Current git commit branch, hash: main, 1a7c9d3d1aa10284caed44ba9b223c6bfbb8ff5f
02:42:30 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4693:Current foraging_gui version: 1.6.10
02:42:30 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4703:local repository is clean
02:42:30 PM:INFO:Foraging:Foraging.py:<module>:line 4804:Setting QApplication attributes
02:42:30 PM:INFO:Foraging:Foraging.py:<module>:line 4812:Starting QApplication and Window
02:42:30 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
02:42:30 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1174:Loaded settings_box file
02:42:30 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1202:Loaded settings file
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_workflow_path), using default: 
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_settings), using default: C:\Users\svc_aind_ephys\Documents\FIPSettings
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsai_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.exe
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsaiworkflow_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\src\workflows\foraging.bonsai
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\metadata_dialog\
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\rig_metadata\
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (project_info_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\Project Name and Funding Source v2.csv
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box2), using default: 60
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box3), using default: 60
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box4), using default: 60
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box1), using default: 5000
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box2), using default: 5000
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box3), using default: 5000
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box4), using default: 5000
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\name_mapper.json
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (save_each_trial), using default: True
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (AutomaticUpload), using default: True
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_ephys\Documents\aind_watchdog_service\manifest
02:42:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (add_default_project_name), using default: True
02:42:30 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1100:Loaded behavior schedule
02:42:30 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
02:42:30 PM:INFO:Foraging:Foraging.py:_LoadRigJson:line 1544:Skipping rig metadata creation because create_rig_metadata=False
02:42:30 PM:INFO:Foraging:Foraging.py:_LoadUI:line 281:Using ForagingGUI_Ephys.ui interface
02:42:30 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 323_EPHYS3
02:42:30 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
02:42:30 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:31 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1375:Could not connect: timed out
02:42:31 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1384:Starting Bonsai
02:42:31 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4776:BONSAI logging starting
02:42:32 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:33 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 0.5 seconds: timed out
02:42:33 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:34 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.0 seconds: timed out
02:42:35 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:36 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.5 seconds: timed out
02:42:36 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:37 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 2.0 seconds: timed out
02:42:38 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:39 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 2.5 seconds: timed out
02:42:39 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:42:39 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1401:Connected to Bonsai after 3.0 seconds
02:42:39 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1402:Bonsai started successfully
02:42:39 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1281:Attempting to connect to Slims
02:42:40 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1298:Successfully connected to Slims
02:42:40 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 480:could not find water calibration parameters: C:\Users\svc_aind_ephys\Documents\ForagingSettings\WaterCalibrationPar_1.json
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:42:40 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 875:Scanning for newscale stages
02:42:40 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 890:found 1 newscale stages
02:42:40 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 914:Found the newscale stage from the settings file
02:42:40 PM:INFO:Foraging:Foraging.py:_connect_stage:line 941:Successfully connected to newscale stage: 46796
02:42:40 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 761:Checking stage connection
02:42:40 PM:INFO:Foraging:Foraging.py:_GetPositions:line 773:Grabbing current stage position
02:42:40 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_323_EPHYS3_2024-10-17.json
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.057
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.053
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.053
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.057
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.057
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.053
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.053
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.057
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionY,  -> 9316.5
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionX,  -> 6081.0
02:42:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionZ,  -> 9913.5
02:42:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:42:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:42:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:42:41 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
02:42:42 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) = 5833
02:42:43 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) = 4352
02:42:43 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/
02:42:44 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_ephys/capsule/scratch/saved_curriculums/
02:42:44 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/
02:42:44 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/
02:42:44 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2273:No entry found in df_training_manager for subject_id: 0
02:42:44 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=2
02:42:44 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: unknown training stage @unknown curriculum
02:42:53 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
02:43:00 PM:INFO:Foraging:Foraging.py:_Open:line 2948:Quick load success: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-03_13-43-26\behavior\764769_2024-12-03_13-43-26.json
02:43:00 PM:INFO:Foraging:Foraging.py:_NewSession:line 3491:New Session pressed
02:43:00 PM:INFO:Foraging:Foraging.py:_NewSession:line 3523:Resetting session run flag
02:43:00 PM:INFO:Foraging:Foraging.py:_NewSession:line 3561:New Session complete
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.057 -> 0.037
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.053 -> 0.035
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.053 -> 0.035
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.057 -> 0.037
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.057 -> 0.037
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.053 -> 0.035
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.053 -> 0.035
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.057 -> 0.037
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
02:43:00 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
02:43:00 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])

02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ID, 0.0 -> 764769.0
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BaseWeight,  -> 26.07
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: TargetWeight,  -> 22.16
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: SuggestedWater,  -> 0.52
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionY, 9316.5 -> 10112.0
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionX, 6081.0 -> 5233.5
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionZ, 9913.5 -> 9913.0
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:01 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:02 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 682:Correct: body_camera.avi has 2293526 frames and 2293526 triggers
Correct: bottom_camera.avi has 2293526 frames and 2293526 triggers
Correct: side_camera_left.avi has 2293526 frames and 2293526 triggers
Correct: side_camera_right.avi has 2293526 frames and 2293526 triggers

02:43:02 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:02 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2825:AutoTrain disengaged!
02:43:02 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'.
02:43:02 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=0
02:43:02 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
02:43:02 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'.
02:43:02 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting ([email protected])
02:43:02 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting ([email protected])
02:43:02 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
02:43:02 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'.
02:43:06 PM:INFO:Foraging:Foraging.py:_Start:line 3719:Start button pressed: starting trial loop
02:43:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:07 PM:INFO:Foraging:Foraging.py:_Start:line 3787:Starting session, with experimenter: Xinxin Yin
02:43:07 PM:INFO:Foraging:Foraging.py:_set_default_project:line 3656:Setting Project name: Behavior Platform
02:43:07 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:43:07 PM:INFO:Foraging:Foraging.py:_restartlogging:line 997:Restarting logging
02:43:07 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2734:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07
02:43:07 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2737:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07\metadata-dir
02:43:07 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2740:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07\behavior
02:43:07 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2743:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07\behavior\raw.harp
02:43:07 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2746:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07\behavior-videos
02:43:07 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2749:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07\fib
02:43:07 PM:INFO:Dialogs:Dialogs.py:_StartCamera:line 1241:Camera is turning on
02:43:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'D:\\BehaviorData\\323_EPHYS3\\764769\\behavior_764769_2024-12-04_14-43-07\\behavior\\raw.harp', '127.0.0.1', 4002]
02:43:12 PM:INFO:Dialogs:Dialogs.py:_StartCamera:line 1268:Camera is on!
02:43:12 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
02:43:12 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
02:43:12 PM:INFO:Foraging:Foraging.py:log_session:line 4103:Starting log file at D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-04_14-43-07\behavior
02:43:12 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4120:starting trial loop
02:43:12 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 1
02:43:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8371146.941984, '127.0.0.1', 4002]
02:43:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8371146.949504, '127.0.0.1', 4002]
02:43:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 8371146.949536, '127.0.0.1', 4003], displaying at 0.5 Hz
02:43:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 000001a29a73b340] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:43:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 000001d51db6e940] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:43:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 00000112ed7db340] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:43:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 000001cbdc49e940] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:43:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8371156.512992, '127.0.0.1', 4002]
02:43:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8371156.516512, '127.0.0.1', 4002]
02:43:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8371157.494976, '127.0.0.1', 4002]
02:43:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8371157.497504, '127.0.0.1', 4002]
02:43:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8371157.498336, 4, '127.0.0.1']
02:43:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8371158.089888, '127.0.0.1', 4003]
02:43:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8371158.088992, '127.0.0.1', 4002]
02:43:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
02:43:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8371158.170976, '127.0.0.1', 4003]
_____SKIPPING_____
05:14:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:14:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:14:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:14:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:14:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:14:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380251.538432, '127.0.0.1', 4003]
05:14:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380251.685952, '127.0.0.1', 4003]
05:14:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380251.873312, '127.0.0.1', 4003]
05:14:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8380252.384992, '127.0.0.1', 4002]
05:14:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380252.386496, '127.0.0.1', 4002]
05:14:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380252.881888, '127.0.0.1', 4003]
05:15:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8380254.117984, '127.0.0.1', 4002]
05:15:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380254.12048, '127.0.0.1', 4002]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8380255.101984, '127.0.0.1', 4002]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8380255.104096, 4, '127.0.0.1']
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380255.103488, '127.0.0.1', 4002]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380255.563232, '127.0.0.1', 4003]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8380255.562976, '127.0.0.1', 4002]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380255.698848, '127.0.0.1', 4003]
05:15:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380255.898208, '127.0.0.1', 4003]
05:15:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380256.076416, '127.0.0.1', 4003]
05:15:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380256.218464, '127.0.0.1', 4003]
05:15:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380256.381664, '127.0.0.1', 4003]
05:15:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8380258.568, '127.0.0.1', 4002]
05:15:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380258.570496, '127.0.0.1', 4002]
05:15:04 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
05:15:04 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:15:04 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 54
05:15:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8380258.648992, '127.0.0.1', 4002]
05:15:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8380258.65248, '127.0.0.1', 4002]
05:15:04 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])

05:15:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380258.80176, '127.0.0.1', 4003]
05:15:04 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:15:04 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-04_17-05-31
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380258.973056, '127.0.0.1', 4003]
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:15:04 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:15:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8380262.382976, '127.0.0.1', 4002]
05:15:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380262.390496, '127.0.0.1', 4002]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8380263.368, '127.0.0.1', 4002]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380263.370496, '127.0.0.1', 4002]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8380263.371328, 4, '127.0.0.1']
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380263.62144, '127.0.0.1', 4003]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8380263.620992, '127.0.0.1', 4002]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380263.676, '127.0.0.1', 4003]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380263.795744, '127.0.0.1', 4003]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380263.845984, '127.0.0.1', 4003]
05:15:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380263.95328, '127.0.0.1', 4003]
05:15:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8380264.135872, '127.0.0.1', 4003]
05:15:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380264.344928, '127.0.0.1', 4003]
05:15:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380264.514304, '127.0.0.1', 4003]
05:15:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380264.556672, '127.0.0.1', 4003]
05:15:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380265.296992, '127.0.0.1', 4003]
05:15:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380265.441408, '127.0.0.1', 4003]
05:15:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380265.626336, '127.0.0.1', 4003]
05:15:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8380266.633984, '127.0.0.1', 4002]
05:15:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380266.637504, '127.0.0.1', 4002]
05:15:12 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
05:15:12 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:15:12 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 55
05:15:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8380266.685984, '127.0.0.1', 4002]
05:15:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8380266.689504, '127.0.0.1', 4002]
05:15:12 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])

05:15:12 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:15:12 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-04_17-05-31
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:15:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:15:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8380274.417984, '127.0.0.1', 4002]
05:15:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380274.42048, '127.0.0.1', 4002]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8380275.401984, '127.0.0.1', 4002]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8380275.40416, 4, '127.0.0.1']
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380275.403488, '127.0.0.1', 4002]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380275.817376, '127.0.0.1', 4003]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 8380275.816992, '127.0.0.1', 4003]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 8380275.816992, '127.0.0.1', 4003]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8380275.816992, '127.0.0.1', 4002]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 8380275.819488, '127.0.0.1', 4003]
05:15:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380275.960864, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.116416, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.272384, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.415232, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.56688, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.707296, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.83696, '127.0.0.1', 4003]
05:15:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380276.975776, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.113728, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.245696, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.38896, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.517184, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.647008, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.773888, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.913696, '127.0.0.1', 4003]
05:15:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380277.961984, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.052448, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.18816, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.31968, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.45952, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.600192, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.752704, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.796, '127.0.0.1', 4003]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8380278.834976, '127.0.0.1', 4002]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380278.83648, '127.0.0.1', 4002]
05:15:24 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380278.908448, '127.0.0.1', 4003]
05:15:24 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:15:24 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 56
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8380278.922976, '127.0.0.1', 4002]
05:15:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8380278.926496, '127.0.0.1', 4002]
05:15: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])

05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.037952, '127.0.0.1', 4003]
05:15:25 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:15:25 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-04_17-05-31
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.187488, '127.0.0.1', 4003]
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:15:25 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.334976, '127.0.0.1', 4003]
05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.473664, '127.0.0.1', 4003]
05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.622176, '127.0.0.1', 4003]
05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.787776, '127.0.0.1', 4003]
05:15:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380279.926752, '127.0.0.1', 4003]
05:15:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380280.081696, '127.0.0.1', 4003]
05:15:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380280.222336, '127.0.0.1', 4003]
05:15:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380280.375072, '127.0.0.1', 4003]
05:15:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380280.526592, '127.0.0.1', 4003]
05:15:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380280.552032, '127.0.0.1', 4003]
05:15:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380280.989728, '127.0.0.1', 4003]
05:15:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380281.134752, '127.0.0.1', 4003]
05:15:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380281.279648, '127.0.0.1', 4003]
05:15:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380281.874976, '127.0.0.1', 4003]
05:15:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380282.006976, '127.0.0.1', 4003]
05:15:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380282.141696, '127.0.0.1', 4003]
05:15:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380282.315456, '127.0.0.1', 4003]
05:15:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380283.152512, '127.0.0.1', 4003]
05:15:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380283.318944, '127.0.0.1', 4003]
05:15:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8380288.652, '127.0.0.1', 4002]
05:15:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380288.654496, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8380289.634976, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8380289.637536, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8380289.638656, 4, '127.0.0.1']
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380289.920672, '127.0.0.1', 4003]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 8380289.92, '127.0.0.1', 4003]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 8380289.92, '127.0.0.1', 4003]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8380289.92, '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
05:15:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 8380289.923488, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.055168, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.215072, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.340544, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.4984, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.636512, '127.0.0.1', 4003]
05:15:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8380290.78576, '127.0.0.1', 4003]
05:15:36 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 17.94%.
05:15:36 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 6.71%.
05:15:36 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 11.96%.
05:15:36 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10%
@alexpiet alexpiet added the low priority - auto-generated autogenerated issues that have only occurred once label Dec 9, 2024
@alexpiet
Copy link
Collaborator Author

This issue reoccurred:

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 930
logfile: W10DT713883/W10DT713883-A_gui_log_2024-12-09_14-32-42.txt
boxes: ephys3
count: 7
text: Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10%

GUI Log snippet (click for full log)

05:34:18 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:34:18 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-09_17-24-15
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 27.31%.
05:34:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 6.77%.
05:34:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 15.68%.
05:34:20 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10%
Full GUI log (first 200 and last 200 lines) 
02:32:42 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4661:Starting logfile!
02:32:42 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4672:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
02:32:42 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4689:Current git commit branch, hash: main, 1a7c9d3d1aa10284caed44ba9b223c6bfbb8ff5f
02:32:42 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4693:Current foraging_gui version: 1.6.10
02:32:42 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4703:local repository is clean
02:32:42 PM:INFO:Foraging:Foraging.py:<module>:line 4804:Setting QApplication attributes
02:32:42 PM:INFO:Foraging:Foraging.py:<module>:line 4812:Starting QApplication and Window
02:32:42 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
02:32:42 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1174:Loaded settings_box file
02:32:42 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1202:Loaded settings file
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_workflow_path), using default: 
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (FIP_settings), using default: C:\Users\svc_aind_ephys\Documents\FIPSettings
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsai_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.exe
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (bonsaiworkflow_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\src\workflows\foraging.bonsai
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\metadata_dialog\
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\rig_metadata\
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (project_info_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\Project Name and Funding Source v2.csv
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box2), using default: 60
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box3), using default: 60
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (go_cue_decibel_box4), using default: 60
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box1), using default: 5000
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box2), using default: 5000
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box3), using default: 5000
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (lick_spout_distance_box4), using default: 5000
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\name_mapper.json
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (save_each_trial), using default: True
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (AutomaticUpload), using default: True
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_ephys\Documents\aind_watchdog_service\manifest
02:32:42 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1212:Missing setting (add_default_project_name), using default: True
02:32:42 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1100:Loaded behavior schedule
02:32:42 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
02:32:42 PM:INFO:Foraging:Foraging.py:_LoadRigJson:line 1544:Skipping rig metadata creation because create_rig_metadata=False
02:32:43 PM:INFO:Foraging:Foraging.py:_LoadUI:line 281:Using ForagingGUI_Ephys.ui interface
02:32:43 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 323_EPHYS3
02:32:43 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Trying to connect to already running Bonsai
02:32:43 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:44 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1375:Could not connect: timed out
02:32:44 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1384:Starting Bonsai
02:32:44 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4776:BONSAI logging starting
02:32:44 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:45 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 0.5 seconds: timed out
02:32:46 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:47 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.0 seconds: timed out
02:32:47 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 1.5 seconds: timed out
02:32:49 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:50 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 2.0 seconds: timed out
02:32:50 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:51 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1398:Could not connect, total waiting time 2.5 seconds: timed out
02:32:52 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1418:connecting to GUI and Bonsai through OSC
02:32:52 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1401:Connected to Bonsai after 3.0 seconds
02:32:52 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1402:Bonsai started successfully
02:32:52 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1281:Attempting to connect to Slims
02:32:52 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1298:Successfully connected to Slims
02:32:52 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 480:could not find water calibration parameters: C:\Users\svc_aind_ephys\Documents\ForagingSettings\WaterCalibrationPar_1.json
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:32:53 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 875:Scanning for newscale stages
02:32:53 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 890:found 1 newscale stages
02:32:53 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 914:Found the newscale stage from the settings file
02:32:53 PM:INFO:Foraging:Foraging.py:_connect_stage:line 941:Successfully connected to newscale stage: 46796
02:32:53 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 761:Checking stage connection
02:32:53 PM:INFO:Foraging:Foraging.py:_GetPositions:line 773:Grabbing current stage position
02:32:53 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1534:Found existing rig.json: rig_323_EPHYS3_2024-10-17.json
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.057
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.053
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.053
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.057
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.03 -> 0.057
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.03 -> 0.053
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.03 -> 0.053
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.03 -> 0.057
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionY,  -> 10112.0
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionX,  -> 4692.5
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionZ,  -> 9913.5
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:32:53 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:32:53 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
02:32:54 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) = 5932
02:32:54 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) = 4440
02:32:55 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/
02:32:55 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_ephys/capsule/scratch/saved_curriculums/
02:32:56 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/
02:32:56 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/
02:32:56 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2273:No entry found in df_training_manager for subject_id: 0
02:32:56 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=2
02:32:56 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: unknown training stage @unknown curriculum
02:32:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8802530.47824, '127.0.0.1', 4003]
02:32:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 8802530.47824, '127.0.0.1', 4003], displaying at 0.5 Hz
02:32:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8802530.689856, '127.0.0.1', 4003]
02:32:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8802530.861728, '127.0.0.1', 4003]
02:33:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8802534.09792, '127.0.0.1', 4003]
02:33:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8802534.288736, '127.0.0.1', 4003]
02:34:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8802621.44208, '127.0.0.1', 4003]
02:34:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8802621.442144, '127.0.0.1', 4003]
02:35:00 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3581:Stopping current trials
02:35:04 PM:INFO:Foraging:Foraging.py:_Open:line 2948:Quick load success: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-06_17-05-36\behavior\764769_2024-12-06_17-05-36.json
02:35:04 PM:INFO:Foraging:Foraging.py:_NewSession:line 3491:New Session pressed
02:35:04 PM:INFO:Foraging:Foraging.py:_NewSession:line 3523:Resetting session run flag
02:35:04 PM:INFO:Foraging:Foraging.py:_NewSession:line 3561:New Session complete
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.057 -> 0.037
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.053 -> 0.035
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.053 -> 0.035
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.057 -> 0.037
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BlockMax, 60.0 -> 35.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayBeta, 1.0 -> 0.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: DelayMin, 0.0 -> 1.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIBeta, 2.0 -> 3.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ITIMax, 8.0 -> 30.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Multiplier, 0.8 -> 0.5
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Unrewarded, 200.0 -> 10.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: Ignored, 100.0 -> 10.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: StopIgnores, 20.0 -> 25.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue, 0.057 -> 0.037
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue, 0.053 -> 0.035
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL, 0.053 -> 0.035
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR, 0.057 -> 0.037
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: MaxTime, 120.0 -> 75.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: RightValue_volume, 3.0 -> 2.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: LeftValue_volume, 3.0 -> 2.0
02:35:05 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])

02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: ID, 0.0 -> 764769.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: BaseWeight,  -> 26.07
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: TargetWeight,  -> 22.16
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: SuggestedWater,  -> 0.506
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionY, 10112.0 -> 10111.5
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionX, 4692.5 -> 4633.5
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1922:Changing parameter: PositionZ, 9913.5 -> 9914.0
02:35:05 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 682:Correct: body_camera.avi has 2259708 frames and 2259708 triggers
Correct: bottom_camera.avi has 2259708 frames and 2259708 triggers
Correct: side_camera_left.avi has 2259708 frames and 2259708 triggers
Correct: side_camera_right.avi has 2259708 frames and 2259708 triggers

02:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:06 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2825:AutoTrain disengaged!
02:35:06 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'.
02:35:06 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2621:Override stage clicked: state=0
02:35:06 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
02:35:06 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'.
02:35:06 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting ([email protected])
02:35:06 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2647:Current stage to apply: GRADUATED @Uncoupled Baiting ([email protected])
02:35:06 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2567:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
02:35:06 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'.
02:35:09 PM:INFO:Foraging:Foraging.py:_Start:line 3719:Start button pressed: starting trial loop
02:35:09 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:10 PM:INFO:Foraging:Foraging.py:_Start:line 3787:Starting session, with experimenter: Xinxin Yin
02:35:10 PM:INFO:Foraging:Foraging.py:_set_default_project:line 3656:Setting Project name: Behavior Platform
02:35:11 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1863:processing parameter changes
02:35:11 PM:INFO:Foraging:Foraging.py:_restartlogging:line 997:Restarting logging
02:35:11 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2734:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11
02:35:11 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2737:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11\metadata-dir
02:35:11 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2740:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11\behavior
02:35:11 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2743:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11\behavior\raw.harp
02:35:11 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2746:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11\behavior-videos
02:35:11 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2749:Created new folder: D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11\fib
02:35:11 PM:INFO:Dialogs:Dialogs.py:_StartCamera:line 1241:Camera is turning on
02:35:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'D:\\BehaviorData\\323_EPHYS3\\764769\\behavior_764769_2024-12-09_14-35-11\\behavior\\raw.harp', '127.0.0.1', 4002]
02:35:16 PM:INFO:Dialogs:Dialogs.py:_StartCamera:line 1268:Camera is on!
02:35:16 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
02:35:16 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
02:35:16 PM:INFO:Foraging:Foraging.py:log_session:line 4103:Starting log file at D:\BehaviorData\323_EPHYS3\764769\behavior_764769_2024-12-09_14-35-11\behavior
02:35:16 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4120:starting trial loop
02:35:16 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 1
02:35:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8802669.956992, '127.0.0.1', 4002]
02:35:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8802669.96048, '127.0.0.1', 4002]
02:35:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 0000016a9613b340] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:35:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 000002a423d9e940] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:35:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 00000168993eb340] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:35:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4782:BONSAI: [out#0/avi @ 000001b651d3e940] Codec AVOption crf (Select the quality for constant quality mode) has not been used for any stream. The most likely reason is either wrong type (e.g. a video option with no video streams) or that it is a private option of some encoder which was not actually used for any stream.
02:35:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8802671.868992, '127.0.0.1', 4002]
02:35:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8802671.87248, '127.0.0.1', 4002]
_____SKIPPING_____
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:33:36 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:33:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8813372.146368, '127.0.0.1', 4003]
05:33:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8813372.30144, '127.0.0.1', 4003]
05:33:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8813372.314976, '127.0.0.1', 4003]
05:33:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8813382.180992, '127.0.0.1', 4002]
05:33:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813382.183488, '127.0.0.1', 4002]
05:33:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8813383.164, '127.0.0.1', 4002]
05:33:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8813383.1672, 4, '127.0.0.1']
05:33:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813383.166496, '127.0.0.1', 4002]
05:33:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8813384.164992, '127.0.0.1', 4002]
05:33:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8813386.636512, '127.0.0.1', 4003]
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8813386.677984, '127.0.0.1', 4003]
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8813386.800576, '127.0.0.1', 4003]
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8813387.180992, '127.0.0.1', 4002]
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813387.183488, '127.0.0.1', 4002]
05:33:53 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
05:33:53 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:33:53 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 65
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8813387.258976, '127.0.0.1', 4002]
05:33:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8813387.263488, '127.0.0.1', 4002]
05:33:53 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:33:53 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-09_17-24-15
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:33:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:33:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8813392.730976, '127.0.0.1', 4002]
05:33:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813392.733504, '127.0.0.1', 4002]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8813393.713984, '127.0.0.1', 4002]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8813393.717088, 4, '127.0.0.1']
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813393.71648, '127.0.0.1', 4002]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813393.96976, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 8813393.968992, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8813393.968992, '127.0.0.1', 4002]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 8813393.968992, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 8813393.97248, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813394.155648, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813394.29584, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813394.446176, '127.0.0.1', 4003]
05:34:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813394.58736, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813394.728352, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813394.865184, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.011424, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.036032, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.155232, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.291008, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.440096, '127.0.0.1', 4003]
05:34:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.596608, '127.0.0.1', 4003]
05:34:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.73712, '127.0.0.1', 4003]
05:34:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813395.873888, '127.0.0.1', 4003]
05:34:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813396.03264, '127.0.0.1', 4003]
05:34:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813396.187456, '127.0.0.1', 4003]
05:34:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813396.36288, '127.0.0.1', 4003]
05:34:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813396.534144, '127.0.0.1', 4003]
05:34:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813396.698016, '127.0.0.1', 4003]
05:34:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8813396.980992, '127.0.0.1', 4002]
05:34:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813396.983488, '127.0.0.1', 4002]
05:34:03 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
05:34:03 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:34:03 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 66
05:34:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8813397.036, '127.0.0.1', 4002]
05:34:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8813397.037536, '127.0.0.1', 4002]
05:34:03 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:34:03 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-09_17-24-15
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:03 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813397.506208, '127.0.0.1', 4003]
05:34:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813397.6536, '127.0.0.1', 4003]
05:34:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813397.803008, '127.0.0.1', 4003]
05:34:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813398.648448, '127.0.0.1', 4003]
05:34:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813398.678048, '127.0.0.1', 4003]
05:34:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813398.802464, '127.0.0.1', 4003]
05:34:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8813400.280992, '127.0.0.1', 4002]
05:34:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813400.28352, '127.0.0.1', 4002]
05:34:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8813401.264, '127.0.0.1', 4002]
05:34:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8813401.267328, 4, '127.0.0.1']
05:34:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813401.26752, '127.0.0.1', 4002]
05:34:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813401.55232, '127.0.0.1', 4003]
05:34:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8813401.552, '127.0.0.1', 4002]
05:34:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813401.698336, '127.0.0.1', 4003]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813401.894912, '127.0.0.1', 4003]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.045024, '127.0.0.1', 4003]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.191328, '127.0.0.1', 4003]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.339072, '127.0.0.1', 4003]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.473664, '127.0.0.1', 4003]
05:34:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.620256, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.76016, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813402.913312, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.068128, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.203744, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.216032, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.365312, '127.0.0.1', 4003]
05:34:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.5208, '127.0.0.1', 4003]
05:34:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.667264, '127.0.0.1', 4003]
05:34:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813403.827904, '127.0.0.1', 4003]
05:34:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813404.292608, '127.0.0.1', 4003]
05:34:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813404.4896, '127.0.0.1', 4003]
05:34:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8813404.564, '127.0.0.1', 4002]
05:34:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813404.566496, '127.0.0.1', 4002]
05:34:11 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
05:34:11 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:34:11 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 67
05:34:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813404.644224, '127.0.0.1', 4003]
05:34:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8813404.641984, '127.0.0.1', 4002]
05:34:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8813404.64448, '127.0.0.1', 4002]
05:34:11 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:34:11 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-09_17-24-15
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813404.983456, '127.0.0.1', 4003]
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:11 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813405.961408, '127.0.0.1', 4003]
05:34:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813406.092096, '127.0.0.1', 4003]
05:34:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813406.645728, '127.0.0.1', 4003]
05:34:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813406.97824, '127.0.0.1', 4003]
05:34:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8813407.664, '127.0.0.1', 4002]
05:34:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813407.666496, '127.0.0.1', 4002]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8813408.648, '127.0.0.1', 4002]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813408.654496, '127.0.0.1', 4002]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8813408.655232, 4, '127.0.0.1']
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813408.802912, '127.0.0.1', 4003]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8813408.801984, '127.0.0.1', 4002]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813408.956704, '127.0.0.1', 4003]
05:34:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8813409.147776, '127.0.0.1', 4003]
05:34:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8813411.840992, '127.0.0.1', 4002]
05:34:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8813411.849504, '127.0.0.1', 4002]
05:34:18 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:

05:34:18 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
05:34:18 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4141:Current trial: 68
05:34:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 8813411.924992, '127.0.0.1', 4002]
05:34:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 8813411.929504, '127.0.0.1', 4002]
05:34:18 PM:INFO:Foraging:Foraging.py:_Save:line 2441:Saving current session, ForceSave=1
05:34:18 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1064:Loaded Water Calibration
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\BehaviorData\323_EPHYS3\753124\behavior_753124_2024-12-09_17-24-15
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_FindLatestCalibrationDate:line 1129:No dates found in the LaserCalibrationResults.
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
05:34:18 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
05:34:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 27.31%.
05:34:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 6.77%.
05:34:20 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 15.68%.
05:34:20 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 753124 exceeded 10%

@alexpiet alexpiet added medium priority - auto-generated autogenerated issues that have occurred more than once in a month and removed low priority - auto-generated autogenerated issues that have only occurred once labels Dec 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
medium priority - auto-generated autogenerated issues that have occurred more than once in a month
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@alexpiet