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 7C mouse 744899 exceeded 10% #1017

Open alexpiet opened 1 week ago

alexpiet commented 1 week ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714683/W10DT714683-C_gui_log_2024-11-15_13-08-35.txt
boxes: 7C
count: 4
text: Percentage of cross side lick intervals under 100 ms in Box C mouse 744899 exceeded 10%

GUI Log snippet (click for full log)

01:30:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821099.585536, '127.0.0.1', 4023]
01:30:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821099.748, '127.0.0.1', 4022]
01:30:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821099.751488, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11821100.730976, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821100.734496, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11821100.7352, 4, '127.0.0.1']
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821100.860768, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11821100.86, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 11821100.86, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 11821100.86, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11821100.863488, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821101.037408, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821101.164224, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821101.365472, '127.0.0.1', 4023]
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.30%.
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 0.00%.
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 0.29%.
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 50.00%.
01:30:42 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 744899 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

01:08:35 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
01:08:35 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
01:08:35 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
01:08:35 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
01:08:35 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
01:08:35 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
01:08:35 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
01:08:35 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
01:08:35 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
01:08:35 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
01:08:35 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
01:08:35 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
01:08:35 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:08:35 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-C_2024-11-12_13_28_18.json
01:08:35 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
01:08:35 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
01:08:35 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
01:08:36 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
01:08:36 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-C
01:08:36 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
01:08:36 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
01:08:37 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
01:08:37 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
01:08:37 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
01:08:37 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
01:08:38 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
01:08:39 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
01:08:40 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
01:08:40 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
01:08:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 11819779.873536, '127.0.0.1', 4023], displaying at 0.5 Hz
01:08:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11819779.881504, '127.0.0.1', 4022]
01:08:41 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
01:08:41 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
01:08:41 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
01:08:41 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
01:08:42 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_3.json
01:08:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:08:42 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
01:08:42 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
01:08:42 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
01:08:42 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
01:08:42 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
01:08:42 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
01:08:42 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
01:08:42 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
01:08:42 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
01:08:42 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
01:08:42 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
01:08:42 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
01:08:45 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
01:08:52 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
01:08:54 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
01:08:54 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
01:08:54 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-C_2024-11-12_13_28_18.json
01:08:54 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
01:08:57 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
01:08:57 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
01:08:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
01:08:57 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
01:08:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
01:08:57 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
01:08:57 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
01:08:58 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5433
01:08:58 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3993
01:08:59 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
01:08:59 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
01:09:00 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
01:09:00 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
01:09:00 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
01:09:00 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
01:09:00 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
01:10:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819893.797984, '127.0.0.1', 4023]
01:10:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819893.803488, '127.0.0.1', 4023]
01:10:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819894.296992, '127.0.0.1', 4023]
01:10:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819894.301504, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819903.785984, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819903.786976, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819903.789504, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819903.790496, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819904.285984, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819904.285984, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819904.289504, '127.0.0.1', 4023]
01:10:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819904.290496, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819913.776992, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819913.776992, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819913.78048, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819913.781504, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819914.276992, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819914.277984, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819914.28048, '127.0.0.1', 4023]
01:10:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819914.281504, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819923.785984, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819923.786976, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819923.78848, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819923.789504, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819924.284992, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819924.285984, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819924.28848, '127.0.0.1', 4023]
01:11:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819924.290496, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819933.778976, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819933.778976, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819933.782496, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819933.783488, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819934.278976, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819934.28, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819934.282496, '127.0.0.1', 4023]
01:11:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819934.283488, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819943.781984, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819943.781984, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819943.785504, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819943.786496, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819944.281984, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819944.282976, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819944.285504, '127.0.0.1', 4023]
01:11:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819944.286496, '127.0.0.1', 4023]
01:11:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11819948.784, '127.0.0.1', 4023]
01:11:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11819948.787488, '127.0.0.1', 4023]
01:11:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819954.277984, '127.0.0.1', 4023]
01:11:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819954.278976, '127.0.0.1', 4023]
01:11:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819954.281504, '127.0.0.1', 4023]
01:11:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819954.282496, '127.0.0.1', 4023]
01:11:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819964.282976, '127.0.0.1', 4023]
01:11:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819964.284, '127.0.0.1', 4023]
01:11:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819964.286496, '127.0.0.1', 4023]
01:11:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819964.287488, '127.0.0.1', 4023]
01:11:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11819966.284, '127.0.0.1', 4023]
01:11:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11819966.287488, '127.0.0.1', 4023]
01:15:02 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
01:15:13 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-14_13-10-26\behavior\744899_2024-11-14_13-10-26.json
01:15:13 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
01:15:13 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
01:15:13 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 744899.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.035
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.041
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:15:13 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:15:13 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

01:15:14 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.027
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.027
01:15:14 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023
_____SKIPPING_____
01:30:06 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 54
01:30:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11821065.078976, '127.0.0.1', 4022]
01:30:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11821065.081504, '127.0.0.1', 4022]
01:30:06 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:06 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-15_13-20-42
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:06 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821065.388768, '127.0.0.1', 4023]
01:30:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821065.564864, '127.0.0.1', 4023]
01:30:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821066.681984, '127.0.0.1', 4022]
01:30:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821066.68448, '127.0.0.1', 4022]
01:30:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11821067.664992, '127.0.0.1', 4022]
01:30:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821067.66848, '127.0.0.1', 4022]
01:30:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11821067.668288, 4, '127.0.0.1']
01:30:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821067.7856, '127.0.0.1', 4023]
01:30:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11821067.784992, '127.0.0.1', 4022]
01:30:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4022]
01:30:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821067.947424, '127.0.0.1', 4023]
01:30:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11821070.797984, '127.0.0.1', 4022]
01:30:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821070.801504, '127.0.0.1', 4022]
01:30:12 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:12 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:12 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 55
01:30:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11821070.812, '127.0.0.1', 4022]
01:30:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11821070.815488, '127.0.0.1', 4022]
01:30:12 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:12 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-15_13-20-42
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821070.90176, '127.0.0.1', 4023]
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:12 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821072.014976, '127.0.0.1', 4022]
01:30:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821072.017504, '127.0.0.1', 4022]
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11821072.997984, '127.0.0.1', 4022]
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11821073.002336, 4, '127.0.0.1']
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821073.002496, '127.0.0.1', 4022]
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821073.104, '127.0.0.1', 4023]
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11821073.102976, '127.0.0.1', 4022]
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4022]
01:30:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821073.251936, '127.0.0.1', 4023]
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11821076.114976, '127.0.0.1', 4022]
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821076.117504, '127.0.0.1', 4022]
01:30:17 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:17 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:17 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 56
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11821076.128, '127.0.0.1', 4022]
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11821076.131488, '127.0.0.1', 4022]
01:30:17 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:17 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-15_13-20-42
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:17 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821076.639328, '127.0.0.1', 4023]
01:30:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821078.532, '127.0.0.1', 4022]
01:30:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821078.534496, '127.0.0.1', 4022]
01:30:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821079.49568, '127.0.0.1', 4023]
01:30:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821080.661728, '127.0.0.1', 4023]
01:30:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821081.898976, '127.0.0.1', 4022]
01:30:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821081.901504, '127.0.0.1', 4022]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11821082.881984, '127.0.0.1', 4022]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11821082.885088, 4, '127.0.0.1']
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821082.885504, '127.0.0.1', 4022]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821083.009088, '127.0.0.1', 4023]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11821083.008992, '127.0.0.1', 4022]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4022]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821083.182368, '127.0.0.1', 4023]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11821086.013984, '127.0.0.1', 4022]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821086.017504, '127.0.0.1', 4022]
01:30:27 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:27 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:27 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 57
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11821086.028992, '127.0.0.1', 4022]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11821086.03248, '127.0.0.1', 4022]
01:30:27 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:27 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-15_13-20-42
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:27 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821087.114976, '127.0.0.1', 4022]
01:30:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821087.117504, '127.0.0.1', 4022]
01:30:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821087.21024, '127.0.0.1', 4023]
01:30:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821088.297984, '127.0.0.1', 4022]
01:30:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821088.301504, '127.0.0.1', 4022]
01:30:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821089.132544, '127.0.0.1', 4023]
01:30:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821090.230976, '127.0.0.1', 4022]
01:30:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821090.234496, '127.0.0.1', 4022]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11821091.213984, '127.0.0.1', 4022]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821091.218496, '127.0.0.1', 4022]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11821091.218112, 4, '127.0.0.1']
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821091.365376, '127.0.0.1', 4023]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11821091.364992, '127.0.0.1', 4022]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 11821091.364992, '127.0.0.1', 4023]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 11821091.364992, '127.0.0.1', 4023]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11821091.36848, '127.0.0.1', 4023]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821091.576928, '127.0.0.1', 4023]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821091.751264, '127.0.0.1', 4023]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821091.909632, '127.0.0.1', 4023]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821092.073312, '127.0.0.1', 4023]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821092.247744, '127.0.0.1', 4023]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821092.39984, '127.0.0.1', 4023]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821092.60736, '127.0.0.1', 4023]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821093.961792, '127.0.0.1', 4023]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821094.110208, '127.0.0.1', 4023]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821094.303808, '127.0.0.1', 4023]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11821094.381984, '127.0.0.1', 4022]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821094.384512, '127.0.0.1', 4022]
01:30:35 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:35 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:35 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 58
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11821094.4, '127.0.0.1', 4022]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11821094.403488, '127.0.0.1', 4022]
01:30:35 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:35 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-15_13-20-42
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821094.491936, '127.0.0.1', 4023]
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821096.210144, '127.0.0.1', 4023]
01:30:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821096.404256, '127.0.0.1', 4023]
01:30:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821096.732, '127.0.0.1', 4022]
01:30:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821096.734496, '127.0.0.1', 4022]
01:30:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821097.416032, '127.0.0.1', 4023]
01:30:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821098.615296, '127.0.0.1', 4023]
01:30:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821099.585536, '127.0.0.1', 4023]
01:30:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11821099.748, '127.0.0.1', 4022]
01:30:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821099.751488, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11821100.730976, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11821100.734496, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11821100.7352, 4, '127.0.0.1']
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821100.860768, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11821100.86, '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 11821100.86, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 11821100.86, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11821100.863488, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821101.037408, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821101.164224, '127.0.0.1', 4023]
01:30:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11821101.365472, '127.0.0.1', 4023]
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.30%.
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 0.00%.
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 0.29%.
01:30:42 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 50.00%.
01:30:42 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 744899 exceeded 10%

alexpiet commented 1 week ago

This issue reoccurred:

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714683/W10DT714683-C_gui_log_2024-11-18_12-55-52.txt
boxes: 7C
count: 5
text: Percentage of cross side lick intervals under 100 ms in Box C mouse 744899 exceeded 10%

GUI Log snippet (click for full log)

01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079591.596992, '127.0.0.1', 4022]
01:18:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079591.60048, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12079592.58, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079592.58448, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12079592.584192, 4, '127.0.0.1']
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079592.701536, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12079592.700992, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 12079592.700992, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 12079592.700992, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12079592.70448, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079592.872576, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079593.011008, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079593.15072, '127.0.0.1', 4023]
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.74%.
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 1.99%.
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.87%.
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 30.91%.
01:18:54 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 744899 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

12:55:52 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
12:55:52 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
12:55:52 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
12:55:52 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
12:55:52 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
12:55:52 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
12:55:52 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
12:55:52 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
12:55:52 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
12:55:52 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
12:55:52 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
12:55:52 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
12:55:52 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:55:52 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-C_2024-11-12_13_28_18.json
12:55:52 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
12:55:52 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
12:55:52 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
12:55:52 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
12:55:52 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-C
12:55:52 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:55:52 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:53 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
12:55:53 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
12:55:53 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
12:55:54 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:55 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
12:55:55 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:56 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
12:55:57 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:58 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
12:55:58 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
12:55:58 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
12:55:58 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
12:55:58 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_3.json
12:55:58 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:55:58 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
12:55:58 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
12:55:58 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
12:55:58 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
12:55:58 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
12:55:58 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
12:55:58 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
12:55:59 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
12:55:59 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
12:55:59 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
12:55:59 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
12:55:59 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
12:56:02 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
12:56:08 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
12:56:11 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
12:56:11 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
12:56:11 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-C_2024-11-12_13_28_18.json
12:56:11 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
12:56:13 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
12:56:13 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
12:56:13 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:56:13 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:56:13 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
12:56:13 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
12:56:13 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
12:56:14 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5495
12:56:15 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 4054
12:56:16 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
12:56:16 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
12:56:17 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
12:56:17 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
12:56:17 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
12:56:17 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
12:56:17 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
12:57:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078308.613984, '127.0.0.1', 4023]
12:57:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078308.618496, '127.0.0.1', 4023]
12:57:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078309.248, '127.0.0.1', 4023]
12:57:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078309.251488, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078318.612992, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078318.614976, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078318.61648, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078318.617504, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078319.254976, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078319.256, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078319.257504, '127.0.0.1', 4023]
12:57:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078319.258496, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078328.612992, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078328.613984, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078328.61648, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078328.617504, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078329.249984, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078329.250976, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078329.253504, '127.0.0.1', 4023]
12:57:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078329.254496, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078338.621984, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078338.621984, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078338.62448, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078338.625504, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078339.252992, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078339.253984, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078339.25648, '127.0.0.1', 4023]
12:58:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078339.257504, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078348.620992, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078348.620992, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078348.623488, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078348.62448, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078349.272, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078349.272, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078349.275488, '127.0.0.1', 4023]
12:58:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078349.27648, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078358.632992, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078358.632992, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078358.635488, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078358.63648, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078359.273984, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078359.273984, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078359.27648, '127.0.0.1', 4023]
12:58:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078359.277504, '127.0.0.1', 4023]
12:58:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 12078363.632, '127.0.0.1', 4023]
12:58:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 12078363.635488, '127.0.0.1', 4023]
12:58:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078369.265984, '127.0.0.1', 4023]
12:58:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078369.266976, '127.0.0.1', 4023]
12:58:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078369.26848, '127.0.0.1', 4023]
12:58:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078369.269504, '127.0.0.1', 4023]
12:58:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078379.266976, '127.0.0.1', 4023]
12:58:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078379.268, '127.0.0.1', 4023]
12:58:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078379.269504, '127.0.0.1', 4023]
12:58:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078379.270496, '127.0.0.1', 4023]
12:58:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 12078381.238976, '127.0.0.1', 4023]
12:58:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12078381.241504, '127.0.0.1', 4023]
01:03:34 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
01:03:41 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-15_13-20-42\behavior\744899_2024-11-15_13-20-42.json
01:03:41 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
01:03:41 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
01:03:41 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 744899.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.035
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.041
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:03:42 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

01:03:42 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.027
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.027
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
01:03:42 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
_____SKIPPING_____
01:18:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:18:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079542.58, '127.0.0.1', 4022]
01:18:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079542.583488, '127.0.0.1', 4022]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12079543.564, '127.0.0.1', 4022]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12079543.567168, 4, '127.0.0.1']
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079543.567488, '127.0.0.1', 4022]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079543.780096, '127.0.0.1', 4023]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12079543.78, '127.0.0.1', 4022]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079543.956576, '127.0.0.1', 4023]
01:18:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079544.203584, '127.0.0.1', 4023]
01:18:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12079546.78, '127.0.0.1', 4022]
01:18:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079546.783488, '127.0.0.1', 4022]
01:18:08 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:18:08 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:18:08 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 48
01:18:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12079546.793984, '127.0.0.1', 4022]
01:18:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12079546.797504, '127.0.0.1', 4022]
01:18:08 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:18:08 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-18_13-08-54
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:08 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079549.230976, '127.0.0.1', 4022]
01:18:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079549.233504, '127.0.0.1', 4022]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12079550.213984, '127.0.0.1', 4022]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12079550.217216, 4, '127.0.0.1']
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079550.217504, '127.0.0.1', 4022]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079550.349376, '127.0.0.1', 4023]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 12079550.348992, '127.0.0.1', 4023]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12079550.348992, '127.0.0.1', 4022]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 12079550.348992, '127.0.0.1', 4023]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12079550.351488, '127.0.0.1', 4023]
01:18:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079550.50272, '127.0.0.1', 4023]
01:18:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079550.686368, '127.0.0.1', 4023]
01:18:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079550.846112, '127.0.0.1', 4023]
01:18:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.004608, '127.0.0.1', 4023]
01:18:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.184384, '127.0.0.1', 4023]
01:18:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.325856, '127.0.0.1', 4023]
01:18:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.466464, '127.0.0.1', 4023]
01:18:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.637472, '127.0.0.1', 4023]
01:18:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.779136, '127.0.0.1', 4023]
01:18:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079551.963936, '127.0.0.1', 4023]
01:18:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12079553.362976, '127.0.0.1', 4022]
01:18:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079553.366496, '127.0.0.1', 4022]
01:18:14 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:18:14 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:18:14 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 49
01:18:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12079553.382976, '127.0.0.1', 4022]
01:18:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12079553.385504, '127.0.0.1', 4022]
01:18:14 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:18:14 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-18_13-08-54
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:14 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079554.031104, '127.0.0.1', 4023]
01:18:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079554.168832, '127.0.0.1', 4023]
01:18:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079554.33808, '127.0.0.1', 4023]
01:18:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079554.535936, '127.0.0.1', 4023]
01:18:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079555.787776, '127.0.0.1', 4023]
01:18:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079555.962272, '127.0.0.1', 4023]
01:18:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079557.289792, '127.0.0.1', 4023]
01:18:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079557.445696, '127.0.0.1', 4023]
01:18:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079557.628992, '127.0.0.1', 4023]
01:18:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079558.637664, '127.0.0.1', 4023]
01:18:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079559.574368, '127.0.0.1', 4023]
01:18:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079560.580992, '127.0.0.1', 4022]
01:18:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079560.583488, '127.0.0.1', 4022]
01:18:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079561.276, '127.0.0.1', 4023]
01:18:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079561.414528, '127.0.0.1', 4023]
01:18:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079563.81536, '127.0.0.1', 4023]
01:18:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12079563.986624, '127.0.0.1', 4023]
01:18:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079565.803104, '127.0.0.1', 4023]
01:18:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079568.464, '127.0.0.1', 4022]
01:18:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079568.466496, '127.0.0.1', 4022]
01:18:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12079569.000544, '127.0.0.1', 4023]
01:18:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079571.946592, '127.0.0.1', 4023]
01:18:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079575.427392, '127.0.0.1', 4023]
01:18:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079576.196992, '127.0.0.1', 4022]
01:18:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079576.20048, '127.0.0.1', 4022]
01:18:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12079577.18, '127.0.0.1', 4022]
01:18:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079577.18448, '127.0.0.1', 4022]
01:18:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12079577.184096, 4, '127.0.0.1']
01:18:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079577.523008, '127.0.0.1', 4023]
01:18:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12079577.521984, '127.0.0.1', 4022]
01:18:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:18:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079577.702496, '127.0.0.1', 4023]
01:18:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079577.863648, '127.0.0.1', 4023]
01:18:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079578.048288, '127.0.0.1', 4023]
01:18:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079578.199136, '127.0.0.1', 4023]
01:18:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12079578.425344, '127.0.0.1', 4023]
01:18:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12079580.479936, '127.0.0.1', 4023]
01:18:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12079580.530976, '127.0.0.1', 4022]
01:18:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079580.533504, '127.0.0.1', 4022]
01:18:42 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:18:42 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:18:42 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 50
01:18:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12079580.544, '127.0.0.1', 4022]
01:18:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12079580.546496, '127.0.0.1', 4022]
01:18:42 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:18:42 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-18_13-08-54
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:42 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:42 PM:INFO:bias_indicator:bias_indicator.py:calculate_bias:line 177:Can't calculate bias at trial count 49 because this solver needs samples of at least 2 classes in the data, but the data contains only one class: 1
01:18:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12079582.85152, '127.0.0.1', 4023]
01:18:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 12079583.877856, '127.0.0.1', 4023]
01:18:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079584.013984, '127.0.0.1', 4022]
01:18:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079584.017504, '127.0.0.1', 4022]
01:18:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12079584.997984, '127.0.0.1', 4022]
01:18:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12079585.001152, 4, '127.0.0.1']
01:18:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079585.001504, '127.0.0.1', 4022]
01:18:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079585.17616, '127.0.0.1', 4023]
01:18:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12079585.176, '127.0.0.1', 4022]
01:18:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022]
01:18:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079585.553184, '127.0.0.1', 4023]
01:18:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079585.712032, '127.0.0.1', 4023]
01:18:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079585.940224, '127.0.0.1', 4023]
01:18:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079586.159328, '127.0.0.1', 4023]
01:18:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 12079588.18, '127.0.0.1', 4022]
01:18:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079588.183488, '127.0.0.1', 4022]
01:18:49 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:18:49 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:18:49 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 51
01:18:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 12079588.194976, '127.0.0.1', 4022]
01:18:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 12079588.197504, '127.0.0.1', 4022]
01:18:49 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:18:49 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\744899\behavior_744899_2024-11-18_13-08-54
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:18:49 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:18:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 12079591.596992, '127.0.0.1', 4022]
01:18:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079591.60048, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 12079592.58, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 12079592.58448, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 12079592.584192, 4, '127.0.0.1']
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079592.701536, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 12079592.700992, '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 12079592.700992, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 12079592.700992, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 12079592.70448, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079592.872576, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079593.011008, '127.0.0.1', 4023]
01:18:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 12079593.15072, '127.0.0.1', 4023]
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 1.74%.
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 1.99%.
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 1.87%.
01:18:54 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 30.91%.
01:18:54 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box C mouse 744899 exceeded 10%