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 6B mouse 744495 exceeded 10% #1015

Open alexpiet opened 4 days ago

alexpiet commented 4 days ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714672/W10DT714672-B_gui_log_2024-11-13_12-43-50.txt
boxes: 6B
count: 24
text: Percentage of cross side lick intervals under 100 ms in Box B mouse 744495 exceeded 10%

GUI Log snippet (click for full log)

01:36:13 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-13_13-26-14
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 5.45%.
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 3.20%.
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.31%.
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 22.03%.
01:36:14 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box B mouse 744495 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

12:43:50 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
12:43:50 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:43:50 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
12:43:50 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
12:43:50 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
12:43:50 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
12:43:50 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
12:43:50 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
12:43:50 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
12:43:50 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
12:43:50 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:43:50 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:43:50 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:43:50 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:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
12:43:50 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:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
12:43:50 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:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
12:43:50 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
12:43:50 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
12:43:50 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:43:50 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-B_2024-11-12_13_28_26.json
12:43:50 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
12:43:50 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
12:43:50 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
12:43:50 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
12:43:50 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-B
12:43:50 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:43:50 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:51 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
12:43:51 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
12:43:51 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
12:43:52 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:53 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
12:43:53 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:54 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
12:43:55 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:55 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
12:43:55 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
12:43:55 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
12:43:56 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
12:43:56 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_2.json
12:43:56 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:43:56 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
12:43:56 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
12:43:56 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
12:43:56 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
12:43:56 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
12:43:56 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
12:43:56 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
12:43:57 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
12:43:57 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
12:43:57 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
12:43:57 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
12:43:57 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
12:44:00 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
12:44:02 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
12:44:04 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
12:44:04 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
12:44:04 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-B_2024-11-12_13_28_26.json
12:44:04 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
12:44:07 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
12:44:07 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
12:44:07 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:44:07 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:44:07 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
12:44:07 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
12:44:07 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
12:44:08 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5368
12:44:09 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3936
12:44:09 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:44:09 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:44:10 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:44:10 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:44:10 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
12:44:10 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
12:44:10 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
12:44:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245469.729984, '127.0.0.1', 4013]
12:44:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245469.733504, '127.0.0.1', 4013]
12:44:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245470.518976, '127.0.0.1', 4013]
12:44:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245470.522496, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245479.724, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245479.724, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245479.725504, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245479.726496, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245480.524992, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245480.524992, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245480.526496, '127.0.0.1', 4013]
12:44:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245480.527488, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245489.726976, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245489.726976, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245489.72848, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245489.729504, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245490.525984, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245490.525984, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245490.527488, '127.0.0.1', 4013]
12:44:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245490.52848, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245499.728, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245499.728, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245499.729504, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245499.730496, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245500.536992, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245500.537984, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245500.539488, '127.0.0.1', 4013]
12:45:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245500.54048, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245509.725984, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245509.725984, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245509.727488, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245509.72848, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245510.536992, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245510.537984, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245510.539488, '127.0.0.1', 4013]
12:45:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245510.54048, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245519.728992, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245519.728992, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245519.730496, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245519.731488, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245520.54, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245520.54, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245520.541504, '127.0.0.1', 4013]
12:45:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245520.542496, '127.0.0.1', 4013]
12:45:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245529.728992, '127.0.0.1', 4013]
12:45:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245529.729984, '127.0.0.1', 4013]
12:45:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245529.731488, '127.0.0.1', 4013]
12:45:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245529.73248, '127.0.0.1', 4013]
12:45:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18245530.528992, '127.0.0.1', 4013]
12:45:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18245530.530496, '127.0.0.1', 4013]
12:45:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18245530.724992, '127.0.0.1', 4013]
12:45:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18245530.727488, '127.0.0.1', 4013]
12:51:28 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
01:13:06 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
01:13:19 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-12_14-00-45\behavior\744495_2024-11-12_14-00-45.json
01:13:19 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
01:13:19 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
01:13:19 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.037
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.032
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 744495.0
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.037
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.032
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.032
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.037
01:13:19 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:13:20 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:13:20 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.037 -> 0.025
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.032 -> 0.02
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
01:13:20 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
_____SKIPPING_____
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248543.8968, '127.0.0.1', 4013]
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248544.068864, '127.0.0.1', 4013]
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248544.244448, '127.0.0.1', 4013]
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18248544.248992, '127.0.0.1', 4012]
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248544.250496, '127.0.0.1', 4012]
01:35:52 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:35:52 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 81
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18248544.264992, '127.0.0.1', 4012]
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18248544.26848, '127.0.0.1', 4012]
01:35:52 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:35:52 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:35:52 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-13_13-26-14
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248544.401792, '127.0.0.1', 4013]
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248544.442272, '127.0.0.1', 4013]
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248544.442304, '127.0.0.1', 4013]
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:35:52 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248544.634848, '127.0.0.1', 4013]
01:35:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248546.004352, '127.0.0.1', 4013]
01:35:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248546.166208, '127.0.0.1', 4013]
01:35:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248546.196128, '127.0.0.1', 4013]
01:35:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248546.352544, '127.0.0.1', 4013]
01:35:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248547.078272, '127.0.0.1', 4013]
01:35:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248547.229632, '127.0.0.1', 4013]
01:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18248547.998976, '127.0.0.1', 4012]
01:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248548.00048, '127.0.0.1', 4012]
01:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248548.18992, '127.0.0.1', 4013]
01:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248548.345504, '127.0.0.1', 4013]
01:35:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248549.212512, '127.0.0.1', 4013]
01:35:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248549.373952, '127.0.0.1', 4013]
01:35:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248549.54768, '127.0.0.1', 4013]
01:35:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248550.10176, '127.0.0.1', 4013]
01:35:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248550.276768, '127.0.0.1', 4013]
01:35:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248551.35136, '127.0.0.1', 4013]
01:35:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248551.519872, '127.0.0.1', 4013]
01:35:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248551.68528, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248551.863456, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18248551.932, '127.0.0.1', 4012]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248551.934496, '127.0.0.1', 4012]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18248552.181984, '127.0.0.1', 4012]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18248552.185184, 4, '127.0.0.1']
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248552.18448, '127.0.0.1', 4012]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248552.23792, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18248552.236992, '127.0.0.1', 4012]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 18248552.236992, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4012]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248552.26416, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 18248552.348992, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18248552.350496, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248552.523424, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248552.540288, '127.0.0.1', 4013]
01:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248552.659744, '127.0.0.1', 4013]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248552.780416, '127.0.0.1', 4013]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248552.911328, '127.0.0.1', 4013]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248553.069696, '127.0.0.1', 4013]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18248553.232, '127.0.0.1', 4012]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248553.234496, '127.0.0.1', 4012]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248553.23776, '127.0.0.1', 4013]
01:36:01 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:36:01 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 82
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18248553.248992, '127.0.0.1', 4012]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18248553.253504, '127.0.0.1', 4012]
01:36:01 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:36:01 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248553.347744, '127.0.0.1', 4013]
01:36:01 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-13_13-26-14
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248553.492416, '127.0.0.1', 4013]
01:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248553.677216, '127.0.0.1', 4013]
01:36:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248554.586176, '127.0.0.1', 4013]
01:36:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18248555.548992, '127.0.0.1', 4012]
01:36:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248555.550496, '127.0.0.1', 4012]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18248555.798976, '127.0.0.1', 4012]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248555.80048, '127.0.0.1', 4012]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18248555.80112, 4, '127.0.0.1']
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248555.878752, '127.0.0.1', 4013]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18248555.877984, '127.0.0.1', 4012]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4012]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248556.079648, '127.0.0.1', 4013]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248556.247136, '127.0.0.1', 4013]
01:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248556.461088, '127.0.0.1', 4013]
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248556.862624, '127.0.0.1', 4013]
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248556.864192, '127.0.0.1', 4013]
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18248556.865984, '127.0.0.1', 4012]
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248556.867488, '127.0.0.1', 4012]
01:36:05 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:36:05 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 83
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18248556.876992, '127.0.0.1', 4012]
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18248556.881504, '127.0.0.1', 4012]
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248556.894208, '127.0.0.1', 4013]
01:36:05 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:36:05 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:36:05 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-13_13-26-14
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248557.046912, '127.0.0.1', 4013]
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248557.745184, '127.0.0.1', 4013]
01:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248557.919616, '127.0.0.1', 4013]
01:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248558.24448, '127.0.0.1', 4013]
01:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248558.482752, '127.0.0.1', 4013]
01:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18248559.232, '127.0.0.1', 4012]
01:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248559.234496, '127.0.0.1', 4012]
01:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248559.241344, '127.0.0.1', 4013]
01:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248559.286784, '127.0.0.1', 4013]
01:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248559.29104, '127.0.0.1', 4013]
01:36:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248559.44, '127.0.0.1', 4013]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248561.095168, '127.0.0.1', 4013]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248561.289088, '127.0.0.1', 4013]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248561.358208, '127.0.0.1', 4013]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248561.502816, '127.0.0.1', 4013]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18248561.598976, '127.0.0.1', 4012]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248561.60048, '127.0.0.1', 4012]
01:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248561.684928, '127.0.0.1', 4013]
01:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248562.874784, '127.0.0.1', 4013]
01:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248563.048224, '127.0.0.1', 4013]
01:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248563.246496, '127.0.0.1', 4013]
01:36:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18248563.630816, '127.0.0.1', 4013]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18248564.048992, '127.0.0.1', 4012]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248564.050496, '127.0.0.1', 4012]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18248564.298976, '127.0.0.1', 4012]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248564.30048, '127.0.0.1', 4012]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18248564.301344, 4, '127.0.0.1']
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248564.318976, '127.0.0.1', 4013]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18248564.317984, '127.0.0.1', 4012]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4012]
01:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248564.524832, '127.0.0.1', 4013]
01:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18248564.708672, '127.0.0.1', 4013]
01:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18248565.316, '127.0.0.1', 4012]
01:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18248565.317504, '127.0.0.1', 4012]
01:36:13 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:36:13 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 84
01:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18248565.326976, '127.0.0.1', 4012]
01:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18248565.331488, '127.0.0.1', 4012]
01:36: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:36:13 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:36:13 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-13_13-26-14
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:36:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 5.45%.
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 3.20%.
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.31%.
01:36:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 22.03%.
01:36:14 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box B mouse 744495 exceeded 10%

alexpiet commented 3 days ago

This issue reoccurred:

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714672/W10DT714672-B_gui_log_2024-11-18_12-55-30.txt
boxes: 6B
count: 8
text: Percentage of cross side lick intervals under 100 ms in Box B mouse 744495 exceeded 10%

GUI Log snippet (click for full log)

01:48:13 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-18_13-38-14
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 3.62%.
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 7.26%.
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.71%.
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 25.00%.
01:48:14 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box B mouse 744495 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

12:55:30 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
12:55:30 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:30 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
12:55:30 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
12:55:30 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
12:55:30 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
12:55:30 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
12:55:30 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
12:55:30 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
12:55:30 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
12:55:30 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:30 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:30 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:30 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:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
12:55:30 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:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
12:55:30 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:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
12:55:30 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
12:55:30 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
12:55:30 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:55:30 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-B_2024-11-12_13_28_26.json
12:55:30 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
12:55:30 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
12:55:30 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
12:55:31 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
12:55:31 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-B
12:55:31 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:55:31 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:32 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
12:55:32 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
12:55:32 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
12:55:32 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:33 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
12:55:34 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:35 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
12:55:35 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:36 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
12:55:36 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
12:55:36 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
12:55:36 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
12:55:36 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_2.json
12:55:37 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:55:37 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
12:55:37 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
12:55:37 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
12:55:37 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
12:55:37 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
12:55:37 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
12:55:37 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
12:55:37 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
12:55:37 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
12:55:37 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
12:55:37 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
12:55:37 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
12:55:40 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
12:55:42 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
12:55:45 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
12:55:45 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
12:55:45 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-B_2024-11-12_13_28_26.json
12:55:45 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
12:55:48 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
12:55:48 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
12:55:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:55:48 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:55:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
12:55:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
12:55:48 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
12:55:49 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:55:49 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:55:50 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:55:50 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:55:51 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:55:51 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:55:51 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
12:55:51 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
12:55:51 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
12:55:55 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
12:56:35 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1338:Camera is off
12:56:36 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
12:57:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678259.764992, '127.0.0.1', 4013]
12:57:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678259.76848, '127.0.0.1', 4013]
12:57:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678260.368, '127.0.0.1', 4013]
12:57:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678260.371488, '127.0.0.1', 4013]
12:57:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678269.772, '127.0.0.1', 4013]
12:57:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678269.772, '127.0.0.1', 4013]
12:57:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678269.773504, '127.0.0.1', 4013]
12:57:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678269.774496, '127.0.0.1', 4013]
12:57:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678270.373984, '127.0.0.1', 4013]
12:57:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678270.373984, '127.0.0.1', 4013]
12:57:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678270.375488, '127.0.0.1', 4013]
12:57:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678270.37648, '127.0.0.1', 4013]
12:58:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678279.768, '127.0.0.1', 4013]
12:58:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678279.768, '127.0.0.1', 4013]
12:58:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678279.770496, '127.0.0.1', 4013]
12:58:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678279.771488, '127.0.0.1', 4013]
12:58:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678280.377984, '127.0.0.1', 4013]
12:58:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678280.377984, '127.0.0.1', 4013]
12:58:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678280.379488, '127.0.0.1', 4013]
12:58:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678280.38048, '127.0.0.1', 4013]
12:58:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678289.769984, '127.0.0.1', 4013]
12:58:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678289.770976, '127.0.0.1', 4013]
12:58:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678289.77248, '127.0.0.1', 4013]
12:58:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678289.773504, '127.0.0.1', 4013]
12:58:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678290.38, '127.0.0.1', 4013]
12:58:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678290.380992, '127.0.0.1', 4013]
12:58:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678290.382496, '127.0.0.1', 4013]
12:58:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678290.383488, '127.0.0.1', 4013]
12:58:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678299.770976, '127.0.0.1', 4013]
12:58:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678299.770976, '127.0.0.1', 4013]
12:58:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678299.773504, '127.0.0.1', 4013]
12:58:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678299.774496, '127.0.0.1', 4013]
12:58:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678300.380992, '127.0.0.1', 4013]
12:58:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678300.380992, '127.0.0.1', 4013]
12:58:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678300.382496, '127.0.0.1', 4013]
12:58:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678300.383488, '127.0.0.1', 4013]
12:58:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678309.768, '127.0.0.1', 4013]
12:58:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678309.768, '127.0.0.1', 4013]
12:58:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678309.769504, '127.0.0.1', 4013]
12:58:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678309.770496, '127.0.0.1', 4013]
12:58:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678310.376992, '127.0.0.1', 4013]
12:58:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678310.377984, '127.0.0.1', 4013]
12:58:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678310.379488, '127.0.0.1', 4013]
12:58:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678310.38048, '127.0.0.1', 4013]
12:58:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678319.769984, '127.0.0.1', 4013]
12:58:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678319.769984, '127.0.0.1', 4013]
12:58:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678319.771488, '127.0.0.1', 4013]
12:58:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678319.77248, '127.0.0.1', 4013]
12:58:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 18678320.369984, '127.0.0.1', 4013]
12:58:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18678320.371488, '127.0.0.1', 4013]
12:58:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 18678320.78, '127.0.0.1', 4013]
12:58:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 18678320.782496, '127.0.0.1', 4013]
01:04:37 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
01:04:49 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-15_13-35-40\behavior\744495_2024-11-15_13-35-40.json
01:04:49 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
01:04:49 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
01:04:49 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 30.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 7.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 5.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.037
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.032
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 744495.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 30.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 7.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 5.0
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.037
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.032
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.032
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.037
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:04:49 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:04:50 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:04:50 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 5.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMin, 20.0 -> 10.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 20000.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardFamily, 1.0 -> 3.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.037 -> 0.025
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.032 -> 0.02
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 5.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 5.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMin, 20.0 -> 10.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 20000.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:04:50 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
_____SKIPPING_____
01:47:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681260.582848, '127.0.0.1', 4013]
01:47:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18681261.168992, '127.0.0.1', 4012]
01:47:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681261.171488, '127.0.0.1', 4012]
01:47:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18681261.418976, '127.0.0.1', 4012]
01:47:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681261.421504, '127.0.0.1', 4012]
01:47:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18681261.4224, 4, '127.0.0.1']
01:47:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681261.87136, '127.0.0.1', 4013]
01:47:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18681261.870976, '127.0.0.1', 4012]
01:47:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4012]
01:47:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18681262.868992, '127.0.0.1', 4012]
01:47:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681262.871488, '127.0.0.1', 4012]
01:47:51 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:47:51 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 92
01:47:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18681262.880992, '127.0.0.1', 4012]
01:47:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18681262.88448, '127.0.0.1', 4012]
01:47:51 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:47:51 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:47:51 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-18_13-38-14
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:47:51 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:47:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681263.139648, '127.0.0.1', 4013]
01:47:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681263.395776, '127.0.0.1', 4013]
01:47:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681264.499424, '127.0.0.1', 4013]
01:47:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681266.041024, '127.0.0.1', 4013]
01:47:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18681266.836, '127.0.0.1', 4012]
01:47:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681266.837504, '127.0.0.1', 4012]
01:47:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18681267.085984, '127.0.0.1', 4012]
01:47:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681267.087488, '127.0.0.1', 4012]
01:47:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18681267.08832, 4, '127.0.0.1']
01:47:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681267.513568, '127.0.0.1', 4013]
01:47:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18681267.512992, '127.0.0.1', 4012]
01:47:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4012]
01:47:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681267.949632, '127.0.0.1', 4013]
01:47:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681267.980672, '127.0.0.1', 4013]
01:47:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681268.251808, '127.0.0.1', 4013]
01:47:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18681268.501984, '127.0.0.1', 4012]
01:47:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681268.50448, '127.0.0.1', 4012]
01:47:57 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:47:57 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 93
01:47:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18681268.513984, '127.0.0.1', 4012]
01:47:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18681268.518496, '127.0.0.1', 4012]
01:47:57 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:47:57 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:47:57 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-18_13-38-14
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:47:57 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:47:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18681268.844032, '127.0.0.1', 4013]
01:47:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681269.048896, '127.0.0.1', 4013]
01:47:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681270.075648, '127.0.0.1', 4013]
01:47:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681270.2784, '127.0.0.1', 4013]
01:47:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18681271.085984, '127.0.0.1', 4012]
01:47:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681271.087488, '127.0.0.1', 4012]
01:48:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18681271.336, '127.0.0.1', 4012]
01:48:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18681271.338272, 4, '127.0.0.1']
01:48:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681271.337504, '127.0.0.1', 4012]
01:48:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681271.748448, '127.0.0.1', 4013]
01:48:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18681271.748, '127.0.0.1', 4012]
01:48:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4012]
01:48:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681272.652544, '127.0.0.1', 4013]
01:48:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18681272.736, '127.0.0.1', 4012]
01:48:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681272.737504, '127.0.0.1', 4012]
01:48:01 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:48:01 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 94
01:48:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18681272.746976, '127.0.0.1', 4012]
01:48:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18681272.750496, '127.0.0.1', 4012]
01:48:01 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:48:01 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:48:01 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-18_13-38-14
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681272.935296, '127.0.0.1', 4013]
01:48:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681274.193344, '127.0.0.1', 4013]
01:48:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681274.455392, '127.0.0.1', 4013]
01:48:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681275.701664, '127.0.0.1', 4013]
01:48:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681275.924896, '127.0.0.1', 4013]
01:48:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681277.032128, '127.0.0.1', 4013]
01:48:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681277.30816, '127.0.0.1', 4013]
01:48:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681278.582528, '127.0.0.1', 4013]
01:48:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18681279.185984, '127.0.0.1', 4012]
01:48:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681279.187488, '127.0.0.1', 4012]
01:48:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18681279.436, '127.0.0.1', 4012]
01:48:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18681279.438144, 4, '127.0.0.1']
01:48:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681279.437504, '127.0.0.1', 4012]
01:48:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681279.860512, '127.0.0.1', 4013]
01:48:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18681279.86, '127.0.0.1', 4012]
01:48:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4012]
01:48:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681280.441856, '127.0.0.1', 4013]
01:48:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18681280.852992, '127.0.0.1', 4012]
01:48:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681280.854496, '127.0.0.1', 4012]
01:48:09 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:48:09 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 95
01:48:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18681280.864, '127.0.0.1', 4012]
01:48:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18681280.86848, '127.0.0.1', 4012]
01:48:09 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:48:09 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:48:09 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-18_13-38-14
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681282.444832, '127.0.0.1', 4013]
01:48:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681282.712256, '127.0.0.1', 4013]
01:48:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 18681283.068992, '127.0.0.1', 4012]
01:48:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681283.071488, '127.0.0.1', 4012]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 18681283.318976, '127.0.0.1', 4012]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681283.321504, '127.0.0.1', 4012]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 18681283.322432, 4, '127.0.0.1']
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18681283.537088, '127.0.0.1', 4013]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 18681283.536992, '127.0.0.1', 4012]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 18681283.536992, '127.0.0.1', 4013]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4012]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 18681283.652992, '127.0.0.1', 4013]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 18681283.654496, '127.0.0.1', 4013]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18681283.726752, '127.0.0.1', 4013]
01:48:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 18681283.90688, '127.0.0.1', 4013]
01:48:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 18681284.33472, '127.0.0.1', 4013]
01:48:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 18681284.536, '127.0.0.1', 4012]
01:48:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 18681284.537504, '127.0.0.1', 4012]
01:48:13 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:48:13 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 96
01:48:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 18681284.552, '127.0.0.1', 4012]
01:48:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 18681284.555488, '127.0.0.1', 4012]
01:48: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:48:13 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:48:13 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-B\744495\behavior_744495_2024-11-18_13-38-14
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:48:13 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 3.62%.
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 7.26%.
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.71%.
01:48:14 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 25.00%.
01:48:14 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box B mouse 744495 exceeded 10%