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 6A mouse 729678 exceeded 10% #1034

Open alexpiet opened 3 days ago

alexpiet commented 3 days ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714671/W10DT714671-A_gui_log_2024-11-18_09-12-39.txt
boxes: 6A
count: 6
text: Percentage of cross side lick intervals under 100 ms in Box A mouse 729678 exceeded 10%

GUI Log snippet (click for full log)

09:39:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377098.728992, '127.0.0.1', 4002]
09:39:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377098.731488, '127.0.0.1', 4002]
09:39:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377098.801408, '127.0.0.1', 4003]
09:39:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377099.006272, '127.0.0.1', 4003]
09:39:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377099.17376, '127.0.0.1', 4003]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377101.212992, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377101.214496, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15377101.312, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377101.314496, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15377101.315392, 4, '127.0.0.1']
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377101.568736, '127.0.0.1', 4003]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15377101.568, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
09:39:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377101.883008, '127.0.0.1', 4003]
09:39:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377102.018176, '127.0.0.1', 4003]
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 8.00%.
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 2.80%.
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.80%.
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 17.74%.
09:39:38 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box A mouse 729678 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

09:12:39 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
09:12:39 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:12:39 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
09:12:39 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
09:12:39 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
09:12:39 AM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
09:12:39 AM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
09:12:39 AM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
09:12:39 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
09:12:39 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
09:12:39 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
09:12:39 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
09:12:39 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:12:39 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-A_2024-11-12_13_29_11.json
09:12:40 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:12:40 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:12:40 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:12:40 AM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
09:12:40 AM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-A
09:12:40 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
09:12:40 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:12:41 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
09:12:41 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
09:12:41 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
09:12:41 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:12:42 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
09:12:43 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:12:44 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
09:12:44 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:12:45 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.5 seconds: timed out
09:12:46 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:12:46 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 2.0 seconds
09:12:46 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
09:12:46 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
09:12:47 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
09:12:47 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
09:12:47 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:12:47 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
09:12:47 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
09:12:47 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
09:12:47 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:12:47 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:12:47 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:12:47 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:12:47 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
09:12:47 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
09:12:47 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:12:47 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:12:47 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:12:50 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:12:52 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:12:55 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:12:55 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:12:55 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-6-A_2024-11-12_13_29_11.json
09:12:55 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
09:12:55 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
09:12:55 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
09:12:55 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
09:12:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
09:12:55 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
09:12:55 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
09:12:55 AM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
09:12:57 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5495
09:12:57 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 4054
09:12:58 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:12:58 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:12:59 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:12:59 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:12:59 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
09:12:59 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
09:12:59 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
09:18:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375829.408992, '127.0.0.1', 4003]
09:18:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375829.411488, '127.0.0.1', 4003]
09:18:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375830.016992, '127.0.0.1', 4003]
09:18:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375830.02048, '127.0.0.1', 4003]
09:18:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375839.412992, '127.0.0.1', 4003]
09:18:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375839.412992, '127.0.0.1', 4003]
09:18:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375839.414496, '127.0.0.1', 4003]
09:18:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375839.415488, '127.0.0.1', 4003]
09:18:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375840.016, '127.0.0.1', 4003]
09:18:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375840.016, '127.0.0.1', 4003]
09:18:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375840.017504, '127.0.0.1', 4003]
09:18:36 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375840.018496, '127.0.0.1', 4003]
09:18:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375849.405984, '127.0.0.1', 4003]
09:18:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375849.405984, '127.0.0.1', 4003]
09:18:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375849.40848, '127.0.0.1', 4003]
09:18:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375849.409504, '127.0.0.1', 4003]
09:18:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375850.016, '127.0.0.1', 4003]
09:18:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375850.016, '127.0.0.1', 4003]
09:18:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375850.017504, '127.0.0.1', 4003]
09:18:46 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375850.018496, '127.0.0.1', 4003]
09:18:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375859.408992, '127.0.0.1', 4003]
09:18:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375859.409984, '127.0.0.1', 4003]
09:18:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375859.410496, '127.0.0.1', 4003]
09:18:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375859.411488, '127.0.0.1', 4003]
09:18:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375860.012992, '127.0.0.1', 4003]
09:18:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375860.012992, '127.0.0.1', 4003]
09:18:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375860.014496, '127.0.0.1', 4003]
09:18:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375860.015488, '127.0.0.1', 4003]
09:19:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375869.418976, '127.0.0.1', 4003]
09:19:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375869.418976, '127.0.0.1', 4003]
09:19:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375869.42048, '127.0.0.1', 4003]
09:19:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375869.421504, '127.0.0.1', 4003]
09:19:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375870.008, '127.0.0.1', 4003]
09:19:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375870.008, '127.0.0.1', 4003]
09:19:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375870.010496, '127.0.0.1', 4003]
09:19:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375870.011488, '127.0.0.1', 4003]
09:19:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375879.421984, '127.0.0.1', 4003]
09:19:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375879.422976, '127.0.0.1', 4003]
09:19:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375879.42448, '127.0.0.1', 4003]
09:19:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375879.425504, '127.0.0.1', 4003]
09:19:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375880.013984, '127.0.0.1', 4003]
09:19:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375880.013984, '127.0.0.1', 4003]
09:19:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375880.015488, '127.0.0.1', 4003]
09:19:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375880.01648, '127.0.0.1', 4003]
09:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15375888.016992, '127.0.0.1', 4003]
09:19:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15375888.018496, '127.0.0.1', 4003]
09:19:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375889.416992, '127.0.0.1', 4003]
09:19:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375889.417984, '127.0.0.1', 4003]
09:19:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375889.419488, '127.0.0.1', 4003]
09:19:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375889.42048, '127.0.0.1', 4003]
09:19:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15375895.398976, '127.0.0.1', 4003]
09:19:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15375895.401504, '127.0.0.1', 4003]
09:20:22 AM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
09:21:24 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 729678
09:21:31 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
09:21:40 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:21:40 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
09:21:40 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:21:40 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
09:21:51 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Dialogs.py:2778: FutureWarning: The behavior of DataFrame concatenation with empty or all-NA entries is deprecated. In a future version, this will no longer exclude empty or all-NA columns when determining the result dtypes. To retain the old behavior, exclude the relevant entries before the concat operation.
  self.df_training_manager = pd.concat(

09:21:51 AM:INFO:Dialogs:Dialogs.py:_apply_curriculum:line 2801:Added a dummy session 0 for mouse 729678 
09:21:51 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
09:21:51 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:21:51 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
09:21:51 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
09:21:51 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_1_WARMUP @Uncoupled Without Baiting (v2.3@1.0)
09:21:51 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_1_WARMUP @Uncoupled Without Baiting (v2.3@1.0)
09:21:51 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
09:21:51 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3_schema_v1.0.json'.
09:21:53 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! STAGE_1_WARMUP @ Uncoupled Without Baiting (v2.3@1.0)
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Coupled Baiting
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BaseRewardSum is set to 0.8
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardFamily is set to 3
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardPairsN is set to 1
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "UncoupledReward" has been disabled by the GUI. skipped...
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 10
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMax is set to 30
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockBeta is set to 10
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMinReward is set to 0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMin is set to 0.1
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMax is set to 0.1
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayBeta is set to 0.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardDelay is set to 0.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoReward is set to True
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoWaterType is set to Natural
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Multiplier is set to 0.5
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Unrewarded is set to 3
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Ignored is set to 3
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMin is set to 1.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMax is set to 7.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIBeta is set to 3.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "ITIIncrease" has been disabled by the GUI. skipped...
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ResponseTime is set to 5.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardConsumeTime is set to 1.0
09:21:53 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:StopIgnores is set to 20000
09:21:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
09:21:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.1
09:21:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
09:21:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.1
09:21:53 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 30.0
_____SKIPPING_____
09:39:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377074.17328, '127.0.0.1', 4003]
09:39:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377074.377696, '127.0.0.1', 4003]
09:39:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377074.411072, '127.0.0.1', 4003]
09:39:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377074.588672, '127.0.0.1', 4003]
09:39:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377075.276032, '127.0.0.1', 4003]
09:39:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377075.451488, '127.0.0.1', 4003]
09:39:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15377075.728672, '127.0.0.1', 4003]
09:39:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15377075.88224, '127.0.0.1', 4003]
09:39:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377076.045632, '127.0.0.1', 4003]
09:39:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15377076.312192, '127.0.0.1', 4003]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377077.878976, '127.0.0.1', 4002]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377077.881504, '127.0.0.1', 4002]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15377077.978976, '127.0.0.1', 4002]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15377077.982272, 4, '127.0.0.1']
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377077.981504, '127.0.0.1', 4002]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377078.349248, '127.0.0.1', 4003]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15377078.348992, '127.0.0.1', 4002]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 15377078.348992, '127.0.0.1', 4003]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 15377078.348992, '127.0.0.1', 4003]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15377078.350496, '127.0.0.1', 4003]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377078.533984, '127.0.0.1', 4003]
09:39:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377078.705664, '127.0.0.1', 4003]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377078.824864, '127.0.0.1', 4003]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377078.955712, '127.0.0.1', 4003]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377079.102528, '127.0.0.1', 4003]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15377079.314912, '127.0.0.1', 4003]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15377079.345984, '127.0.0.1', 4002]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377079.347488, '127.0.0.1', 4002]
09:39:15 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
09:39:15 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 92
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15377079.362976, '127.0.0.1', 4002]
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15377079.367488, '127.0.0.1', 4002]
09:39:15 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377079.456512, '127.0.0.1', 4003]
09:39:15 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
09:39:15 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\729678\behavior_729678_2024-11-18_09-29-38
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15377079.50976, '127.0.0.1', 4003]
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:15 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377080.701216, '127.0.0.1', 4003]
09:39:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377080.848224, '127.0.0.1', 4003]
09:39:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377081.018688, '127.0.0.1', 4003]
09:39:17 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377081.208672, '127.0.0.1', 4003]
09:39:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377082.38256, '127.0.0.1', 4003]
09:39:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377082.596288, '127.0.0.1', 4003]
09:39:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377082.76224, '127.0.0.1', 4003]
09:39:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377082.980096, '127.0.0.1', 4003]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377086.378976, '127.0.0.1', 4002]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377086.381504, '127.0.0.1', 4002]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15377086.48, '127.0.0.1', 4002]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15377086.482208, 4, '127.0.0.1']
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377086.481504, '127.0.0.1', 4002]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377086.603904, '127.0.0.1', 4003]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15377086.602976, '127.0.0.1', 4002]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
09:39:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377086.722912, '127.0.0.1', 4003]
09:39:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377087.033696, '127.0.0.1', 4003]
09:39:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15377087.596, '127.0.0.1', 4002]
09:39:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377087.597504, '127.0.0.1', 4002]
09:39:23 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
09:39:23 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 93
09:39:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15377087.608, '127.0.0.1', 4002]
09:39:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15377087.61248, '127.0.0.1', 4002]
09:39:23 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:39:23 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
09:39:23 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:39:23 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\729678\behavior_729678_2024-11-18_09-29-38
09:39:23 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
09:39:23 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:23 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:24 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377091.445984, '127.0.0.1', 4002]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377091.447488, '127.0.0.1', 4002]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15377091.545984, '127.0.0.1', 4002]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377091.54848, '127.0.0.1', 4002]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15377091.549152, 4, '127.0.0.1']
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377091.665408, '127.0.0.1', 4003]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 15377091.664992, '127.0.0.1', 4003]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 15377091.664992, '127.0.0.1', 4003]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15377091.664992, '127.0.0.1', 4002]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4002]
09:39:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15377091.666496, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377091.783456, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377091.92608, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377092.033824, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377092.3216, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377092.52256, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377092.6512, '127.0.0.1', 4003]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15377092.662976, '127.0.0.1', 4002]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377092.66448, '127.0.0.1', 4002]
09:39:28 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
09:39:28 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 94
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15377092.68, '127.0.0.1', 4002]
09:39:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15377092.68448, '127.0.0.1', 4002]
09:39:28 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:39:29 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
09:39:29 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\729678\behavior_729678_2024-11-18_09-29-38
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377092.821888, '127.0.0.1', 4003]
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:29 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377092.970656, '127.0.0.1', 4003]
09:39:29 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377093.120928, '127.0.0.1', 4003]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377095.112992, '127.0.0.1', 4002]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377095.114496, '127.0.0.1', 4002]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15377095.212992, '127.0.0.1', 4002]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377095.214496, '127.0.0.1', 4002]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15377095.215104, 4, '127.0.0.1']
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377095.327072, '127.0.0.1', 4003]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15377095.326976, '127.0.0.1', 4002]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
09:39:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377095.620128, '127.0.0.1', 4003]
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377095.806688, '127.0.0.1', 4003]
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377095.996928, '127.0.0.1', 4003]
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377096.164896, '127.0.0.1', 4003]
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15377096.312992, '127.0.0.1', 4002]
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377096.314496, '127.0.0.1', 4002]
09:39:32 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
09:39:32 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 95
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15377096.325984, '127.0.0.1', 4002]
09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15377096.329504, '127.0.0.1', 4002]
09:39:32 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

09:39:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377096.364512, '127.0.0.1', 4003]
09:39:32 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
09:39:32 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\729678\behavior_729678_2024-11-18_09-29-38
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
09:39:32 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
09:39:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377098.728992, '127.0.0.1', 4002]
09:39:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377098.731488, '127.0.0.1', 4002]
09:39:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377098.801408, '127.0.0.1', 4003]
09:39:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377099.006272, '127.0.0.1', 4003]
09:39:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377099.17376, '127.0.0.1', 4003]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15377101.212992, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377101.214496, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15377101.312, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15377101.314496, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15377101.315392, 4, '127.0.0.1']
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377101.568736, '127.0.0.1', 4003]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15377101.568, '127.0.0.1', 4002]
09:39:37 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4002]
09:39:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377101.883008, '127.0.0.1', 4003]
09:39:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 15377102.018176, '127.0.0.1', 4003]
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 8.00%.
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 2.80%.
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 4.80%.
09:39:38 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 17.74%.
09:39:38 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box A mouse 729678 exceeded 10%