search

AllenNeuralDynamics / dynamic-foraging-task

Bonsai/Harp workflow for Dynamic Foraging with Python GUI for visualization and control
MIT License
5 stars 4 forks source link

Percentage of cross side lick intervals under 100 ms in Box 7D mouse 749624 exceeded 10% #1020

Open alexpiet opened 4 days ago

alexpiet commented 4 days ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714684/W10DT714684-D_gui_log_2024-11-15_09-58-18.txt
boxes: 7D
count: 8
text: Percentage of cross side lick intervals under 100 ms in Box D mouse 749624 exceeded 10%

GUI Log snippet (click for full log)

10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541374.867136, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.049792, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.488672, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.659136, '127.0.0.1', 4033]
10:19:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.84512, '127.0.0.1', 4033]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10541376.878976, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541376.881504, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10541377.128992, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541377.131488, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10541377.132288, 4, '127.0.0.1']
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541377.26448, '127.0.0.1', 4033]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10541377.264, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541377.3256, '127.0.0.1', 4033]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541377.441568, '127.0.0.1', 4033]
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.93%.
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 3.24%.
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 2.69%.
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 13.68%.
10:19:30 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 749624 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

09:58:18 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
09:58:18 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:58:18 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
09:58:18 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
09:58:18 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
09:58:18 AM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
09:58:18 AM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
09:58:18 AM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
09:58:18 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
09:58:18 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
09:58:18 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
09:58:18 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
09:58:18 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:58:18 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-D_2024-11-12_11_02_35.json
09:58:18 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:58:18 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:58:18 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:58:18 AM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
09:58:18 AM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-D
09:58:18 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
09:58:18 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:58:19 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
09:58:19 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
09:58:19 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
09:58:20 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:58:21 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
09:58:21 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:58:22 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
09:58:23 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:58:23 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
09:58:23 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
09:58:23 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
09:58:24 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
09:58:24 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_4.json
09:58:24 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:24 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
09:58:24 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
09:58:24 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
09:58:24 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:58:24 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:58:24 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:58:24 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:58:25 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
09:58:25 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
09:58:25 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:58:25 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:58:25 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:58:25 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:58:25 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:58:25 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:58:25 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:58:25 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3446:Checking that photometry is not running
09:58:25 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3456:Photometry excitation stopped
09:58:25 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-D_2024-11-12_11_02_35.json
09:58:25 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
09:58:28 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
09:58:28 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
09:58:28 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
09:58:28 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:58:28 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
09:58:28 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
09:58:28 AM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
09:58:29 AM: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) = 5433
09:58:30 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3963
09:58:31 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:58:31 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:58:32 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:58:32 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:58:32 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
09:58:32 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
09:58:32 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
09:58:38 AM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
09:58:40 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
09:58:52 AM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-14_09-06-22\behavior\749624_2024-11-14_09-06-22.json
09:58:52 AM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
09:58:52 AM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
09:58:52 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3446:Checking that photometry is not running
09:58:52 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3456:Photometry excitation stopped
09:58:52 AM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.04
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.038
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 749624.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.04
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.038
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.038
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.04
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:52 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:58:53 AM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.04 -> 0.027
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.038 -> 0.025
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.04 -> 0.027
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.038 -> 0.025
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y1, 0.0 -> 23.5
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 0.0 -> 17.6
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 0.0 -> 23.5
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_x, 0.0 -> 16.1988
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_step_size, 1.0 -> 0.2
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: SuggestedWater,  -> 1.178
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 30.68
09:58:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 26.078
09:58:53 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
09:58:53 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:58:53 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
09:58:53 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:58:53 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:58:53 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_2 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:58:53 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_2 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:58:53 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:58:53 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:58:53 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! STAGE_2 @ Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Coupled Without Baiting
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BaseRewardSum is set to 0.8
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardFamily is set to 1
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardPairsN is set to 1
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "UncoupledReward" has been disabled by the GUI. skipped...
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 20
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMax is set to 35
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockBeta is set to 10
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMinReward is set to 0
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMin is set to 0.25
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMax is set to 0.25
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayBeta is set to 0.0
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardDelay is set to 0.1
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoReward is set to True
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoWaterType is set to Natural
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Multiplier is set to 0.5
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Unrewarded is set to 7
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Ignored is set to 7
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMin is set to 1.0
09:58:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMax is set to 10.0
_____SKIPPING_____
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10541344.845984, '127.0.0.1', 4032]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541344.847488, '127.0.0.1', 4032]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10541344.848416, 4, '127.0.0.1']
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.04384, '127.0.0.1', 4033]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10541345.042976, '127.0.0.1', 4032]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4032]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.199072, '127.0.0.1', 4033]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.33136, '127.0.0.1', 4033]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.477984, '127.0.0.1', 4033]
10:18:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.64992, '127.0.0.1', 4033]
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.818848, '127.0.0.1', 4033]
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541345.993536, '127.0.0.1', 4033]
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10541346.028992, '127.0.0.1', 4032]
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541346.031488, '127.0.0.1', 4032]
10:18:59 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:18:59 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 174
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10541346.042976, '127.0.0.1', 4032]
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10541346.046496, '127.0.0.1', 4032]
10:18:59 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:18:59 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:18:59 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-15_09-59-30
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:18:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541346.166592, '127.0.0.1', 4033]
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:18:59 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541346.8664, '127.0.0.1', 4033]
10:19:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541347.096672, '127.0.0.1', 4033]
10:19:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541348.033664, '127.0.0.1', 4033]
10:19:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541348.225376, '127.0.0.1', 4033]
10:19:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541350.0872, '127.0.0.1', 4033]
10:19:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541350.251648, '127.0.0.1', 4033]
10:19:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541350.694112, '127.0.0.1', 4033]
10:19:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541350.871712, '127.0.0.1', 4033]
10:19:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541353.603104, '127.0.0.1', 4033]
10:19:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541353.780128, '127.0.0.1', 4033]
10:19:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541354.309152, '127.0.0.1', 4033]
10:19:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541354.876224, '127.0.0.1', 4033]
10:19:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541355.028672, '127.0.0.1', 4033]
10:19:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10541355.678976, '127.0.0.1', 4032]
10:19:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541355.681504, '127.0.0.1', 4032]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10541355.928992, '127.0.0.1', 4032]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10541355.932128, 4, '127.0.0.1']
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541355.931488, '127.0.0.1', 4032]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541356.088576, '127.0.0.1', 4033]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10541356.088, '127.0.0.1', 4032]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4032]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541356.267904, '127.0.0.1', 4033]
10:19:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541356.41408, '127.0.0.1', 4033]
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541356.897376, '127.0.0.1', 4033]
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10541357.078976, '127.0.0.1', 4032]
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541357.081504, '127.0.0.1', 4032]
10:19:10 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:19:10 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 175
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10541357.092992, '127.0.0.1', 4032]
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10541357.09648, '127.0.0.1', 4032]
10:19:10 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:19:10 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:19:10 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-15_09-59-30
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541357.256128, '127.0.0.1', 4033]
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:19:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541357.439168, '127.0.0.1', 4033]
10:19:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541358.203712, '127.0.0.1', 4033]
10:19:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541358.395744, '127.0.0.1', 4033]
10:19:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541358.58032, '127.0.0.1', 4033]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541358.74112, '127.0.0.1', 4033]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10541358.945984, '127.0.0.1', 4032]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541358.947488, '127.0.0.1', 4032]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10541359.196, '127.0.0.1', 4032]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10541359.198144, 4, '127.0.0.1']
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541359.197504, '127.0.0.1', 4032]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541359.51728, '127.0.0.1', 4033]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10541359.516992, '127.0.0.1', 4032]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4032]
10:19:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541359.702496, '127.0.0.1', 4033]
10:19:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541359.857792, '127.0.0.1', 4033]
10:19:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10541360.512992, '127.0.0.1', 4032]
10:19:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541360.514496, '127.0.0.1', 4032]
10:19:13 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:19:13 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 176
10:19:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10541360.525984, '127.0.0.1', 4032]
10:19:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10541360.529504, '127.0.0.1', 4032]
10:19:13 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:19:13 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:19:13 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-15_09-59-30
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:19:13 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541362.659552, '127.0.0.1', 4033]
10:19:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541362.784384, '127.0.0.1', 4033]
10:19:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541362.965664, '127.0.0.1', 4033]
10:19:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541364.557664, '127.0.0.1', 4033]
10:19:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541364.696256, '127.0.0.1', 4033]
10:19:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10541365.496, '127.0.0.1', 4032]
10:19:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541365.497504, '127.0.0.1', 4032]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10541365.745984, '127.0.0.1', 4032]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10541365.748192, 4, '127.0.0.1']
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541365.747488, '127.0.0.1', 4032]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541365.873792, '127.0.0.1', 4033]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10541365.872992, '127.0.0.1', 4032]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 10541365.872992, '127.0.0.1', 4033]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4032]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 10541365.978976, '127.0.0.1', 4033]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 10541365.981504, '127.0.0.1', 4033]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541366.050304, '127.0.0.1', 4033]
10:19:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10541366.218432, '127.0.0.1', 4033]
10:19:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10541366.862976, '127.0.0.1', 4032]
10:19:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541366.86448, '127.0.0.1', 4032]
10:19:20 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:19:20 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 177
10:19:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10541366.880992, '127.0.0.1', 4032]
10:19:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10541366.88448, '127.0.0.1', 4032]
10:19:20 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:19:20 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:19:20 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-15_09-59-30
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:19:20 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541370.972896, '127.0.0.1', 4033]
10:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541371.113568, '127.0.0.1', 4033]
10:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541371.23984, '127.0.0.1', 4033]
10:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541371.418528, '127.0.0.1', 4033]
10:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541371.545696, '127.0.0.1', 4033]
10:19:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541372.127296, '127.0.0.1', 4033]
10:19:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541374.380992, '127.0.0.1', 4033]
10:19:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541374.529504, '127.0.0.1', 4033]
10:19:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541374.706912, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541374.867136, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.049792, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.488672, '127.0.0.1', 4033]
10:19:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.659136, '127.0.0.1', 4033]
10:19:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541375.84512, '127.0.0.1', 4033]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10541376.878976, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541376.881504, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10541377.128992, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10541377.131488, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10541377.132288, 4, '127.0.0.1']
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541377.26448, '127.0.0.1', 4033]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10541377.264, '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4032]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541377.3256, '127.0.0.1', 4033]
10:19:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10541377.441568, '127.0.0.1', 4033]
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.93%.
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 3.24%.
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 2.69%.
10:19:30 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 13.68%.
10:19:30 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 749624 exceeded 10%

alexpiet commented 3 days ago

This issue reoccurred:

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714684/W10DT714684-D_gui_log_2024-11-18_09-32-12.txt
boxes: 7D
count: 6
text: Percentage of cross side lick intervals under 100 ms in Box D mouse 749624 exceeded 10%

GUI Log snippet (click for full log)

10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799522.393888, '127.0.0.1', 4033]
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799522.517376, '127.0.0.1', 4033]
10:01:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799524.448512, '127.0.0.1', 4033]
10:01:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799524.540096, '127.0.0.1', 4033]
10:01:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799524.709344, '127.0.0.1', 4033]
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 2.41%.
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 5.80%.
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 3.52%.
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 11.76%.
10:01:58 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 749624 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

09:32:12 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
09:32:12 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:32:12 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
09:32:12 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
09:32:12 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
09:32:12 AM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
09:32:12 AM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
09:32:12 AM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
09:32:12 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
09:32:12 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
09:32:12 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
09:32:12 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
09:32:12 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:32:12 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-D_2024-11-12_11_02_35.json
09:32:12 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:32:12 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:32:12 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:32:13 AM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
09:32:13 AM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-D
09:32:13 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
09:32:13 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:32:14 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
09:32:14 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
09:32:14 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
09:32:14 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:32:15 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
09:32:16 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:32:17 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
09:32:17 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:32:18 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.5 seconds: timed out
09:32:19 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:32:19 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 2.0 seconds
09:32:19 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
09:32:19 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
09:32:19 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
09:32:20 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_4.json
09:32:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:32:20 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
09:32:20 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
09:32:20 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
09:32:20 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:32:20 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:32:20 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:32:20 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:32:20 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
09:32:20 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
09:32:20 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:32:20 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:32:20 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:32:20 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:32:20 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:32:20 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:32:20 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:32:20 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3446:Checking that photometry is not running
09:32:20 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3456:Photometry excitation stopped
09:32:20 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-D_2024-11-12_11_02_35.json
09:32:20 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
09:32:24 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
09:32:24 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
09:32:24 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
09:32:24 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:32:24 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
09:32:24 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
09:32:24 AM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
09:32:25 AM: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) = 5495
09:32:25 AM: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) = 4054
09:32:27 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:32:27 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:32:28 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:32:28 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:32:28 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
09:32:28 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
09:32:28 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
09:32:49 AM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
09:33:00 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
09:33:31 AM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-15_09-59-30\behavior\749624_2024-11-15_09-59-30.json
09:33:31 AM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
09:33:31 AM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
09:33:31 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3446:Checking that photometry is not running
09:33:31 AM:INFO:Foraging:Foraging.py:_StopPhotometry:line 3456:Photometry excitation stopped
09:33:31 AM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.04
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.038
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 749624.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.04
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.038
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.038
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.04
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:33:31 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:33:31 AM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.04 -> 0.027
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.038 -> 0.025
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.04 -> 0.027
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.038 -> 0.025
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
09:33:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y1, 0.0 -> 23.5
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 0.0 -> 17.6
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 0.0 -> 23.5
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_x, 0.0 -> 16.3975
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_step_size, 1.0 -> 0.2
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: SuggestedWater,  -> 1.478
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 30.68
09:33:32 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 26.078
09:33:32 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
09:33:32 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:33:32 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
09:33:32 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:33:32 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:33:32 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_2 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:33:32 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_2 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:33:32 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:33:32 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
09:33:32 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! STAGE_2 @ Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Coupled Without Baiting
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BaseRewardSum is set to 0.8
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardFamily is set to 1
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardPairsN is set to 1
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "UncoupledReward" has been disabled by the GUI. skipped...
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 20
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMax is set to 35
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockBeta is set to 10
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMinReward is set to 0
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMin is set to 0.25
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMax is set to 0.25
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayBeta is set to 0.0
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardDelay is set to 0.1
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoReward is set to True
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoWaterType is set to Natural
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Multiplier is set to 0.5
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Unrewarded is set to 7
09:33:32 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Ignored is set to 7
_____SKIPPING_____
10:01:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10799505.634496, '127.0.0.1', 4033]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799505.687104, '127.0.0.1', 4033]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799505.828544, '127.0.0.1', 4033]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799505.989088, '127.0.0.1', 4033]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799506.13696, '127.0.0.1', 4033]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10799506.516, '127.0.0.1', 4032]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799506.517504, '127.0.0.1', 4032]
10:01:39 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:01:39 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 80
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10799506.532, '127.0.0.1', 4032]
10:01:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10799506.535488, '127.0.0.1', 4032]
10:01:39 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:01:39 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:01:39 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-18_09-51-58
10:01:39 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:01:39 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:39 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:40 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:40 AM:INFO:bias_indicator:bias_indicator.py:calculate_bias:line 139:Bias: -0.06084754652143703 Trial Count: 79
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10799507.832992, '127.0.0.1', 4032]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799507.834496, '127.0.0.1', 4032]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10799508.082976, '127.0.0.1', 4032]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799508.08448, '127.0.0.1', 4032]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10799508.085344, 4, '127.0.0.1']
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799508.101888, '127.0.0.1', 4033]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10799508.100992, '127.0.0.1', 4032]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4032]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799508.246336, '127.0.0.1', 4033]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799508.394752, '127.0.0.1', 4033]
10:01:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799508.589312, '127.0.0.1', 4033]
10:01:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10799509.1, '127.0.0.1', 4032]
10:01:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799509.101504, '127.0.0.1', 4032]
10:01:42 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:01:42 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 81
10:01:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10799509.110976, '127.0.0.1', 4032]
10:01:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10799509.115488, '127.0.0.1', 4032]
10:01:42 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:01:42 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-18_09-51-58
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:42 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799509.965184, '127.0.0.1', 4033]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799510.092352, '127.0.0.1', 4033]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799510.271744, '127.0.0.1', 4033]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10799510.282976, '127.0.0.1', 4032]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799510.28448, '127.0.0.1', 4032]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10799510.532992, '127.0.0.1', 4032]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799510.534496, '127.0.0.1', 4032]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10799510.53536, 4, '127.0.0.1']
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799510.631616, '127.0.0.1', 4033]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10799510.630976, '127.0.0.1', 4032]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 10799510.630976, '127.0.0.1', 4033]
10:01:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4032]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 10799510.732992, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10799510.734496, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799510.780064, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799510.95664, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799511.09376, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799511.24448, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799511.42112, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799511.572256, '127.0.0.1', 4033]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10799511.616, '127.0.0.1', 4032]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799511.617504, '127.0.0.1', 4032]
10:01:44 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:01:44 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 82
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10799511.632, '127.0.0.1', 4032]
10:01:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10799511.635488, '127.0.0.1', 4032]
10:01:45 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:01:45 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-18_09-51-58
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799511.787808, '127.0.0.1', 4033]
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:45 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799512.140224, '127.0.0.1', 4033]
10:01:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799512.269696, '127.0.0.1', 4033]
10:01:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799512.894336, '127.0.0.1', 4033]
10:01:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799513.045536, '127.0.0.1', 4033]
10:01:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799513.8952, '127.0.0.1', 4033]
10:01:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799514.01248, '127.0.0.1', 4033]
10:01:48 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799515.302976, '127.0.0.1', 4033]
10:01:48 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799515.380512, '127.0.0.1', 4033]
10:01:48 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799515.481792, '127.0.0.1', 4033]
10:01:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799515.704352, '127.0.0.1', 4033]
10:01:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799515.887136, '127.0.0.1', 4033]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10799517.116, '127.0.0.1', 4032]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799517.117504, '127.0.0.1', 4032]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10799517.365984, '127.0.0.1', 4032]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10799517.368416, 4, '127.0.0.1']
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799517.36848, '127.0.0.1', 4032]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799517.460928, '127.0.0.1', 4033]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10799517.46, '127.0.0.1', 4032]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 10799517.46, '127.0.0.1', 4033]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4032]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 10799517.565984, '127.0.0.1', 4033]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10799517.567488, '127.0.0.1', 4033]
10:01:50 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799517.62192, '127.0.0.1', 4033]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799517.834624, '127.0.0.1', 4033]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799517.94064, '127.0.0.1', 4033]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799518.09488, '127.0.0.1', 4033]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799518.248352, '127.0.0.1', 4033]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10799518.449984, '127.0.0.1', 4032]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799518.451488, '127.0.0.1', 4032]
10:01:51 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:01:51 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 83
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10799518.465984, '127.0.0.1', 4032]
10:01:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10799518.469504, '127.0.0.1', 4032]
10:01:51 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:01:51 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-18_09-51-58
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:51 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799519.899872, '127.0.0.1', 4033]
10:01:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799519.986112, '127.0.0.1', 4033]
10:01:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799520.08208, '127.0.0.1', 4033]
10:01:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799520.253568, '127.0.0.1', 4033]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10799520.716, '127.0.0.1', 4032]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799520.718496, '127.0.0.1', 4032]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10799520.965984, '127.0.0.1', 4032]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10799520.968416, 4, '127.0.0.1']
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799520.96848, '127.0.0.1', 4032]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799521.0576, '127.0.0.1', 4033]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10799521.056992, '127.0.0.1', 4032]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4032]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799521.227552, '127.0.0.1', 4033]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799521.405504, '127.0.0.1', 4033]
10:01:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799521.572928, '127.0.0.1', 4033]
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10799522.049984, '127.0.0.1', 4032]
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10799522.051488, '127.0.0.1', 4032]
10:01:55 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
10:01:55 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 84
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10799522.060992, '127.0.0.1', 4032]
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10799522.065504, '127.0.0.1', 4032]
10:01:55 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
10:01:55 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-D\749624\behavior_749624_2024-11-18_09-51-58
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
10:01:55 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799522.393888, '127.0.0.1', 4033]
10:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799522.517376, '127.0.0.1', 4033]
10:01:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799524.448512, '127.0.0.1', 4033]
10:01:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799524.540096, '127.0.0.1', 4033]
10:01:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10799524.709344, '127.0.0.1', 4033]
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 2.41%.
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 5.80%.
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 3.52%.
10:01:58 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 11.76%.
10:01:58 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box D mouse 749624 exceeded 10%