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 same side lick intervals under 100 ms in Box 6A mouse 749472 exceeded 10% #1041

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 930
logfile: W10DT714671/W10DT714671-A_gui_log_2024-11-18_10-59-24.txt
boxes: 6A
count: 5
text: Percentage of same side lick intervals under 100 ms in Box A mouse 749472 exceeded 10%

GUI Log snippet (click for full log)

11:53:10 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
11:53:10 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\749472\behavior_749472_2024-11-18_11-23-12
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:53:12 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 11.16%.
11:53:12 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 9.74%.
11:53:12 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 10.58%.
11:53:12 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 749472 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

10:59:24 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
10:59:24 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)]
10:59:24 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
10:59:24 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
10:59:24 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
10:59:24 AM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
10:59:24 AM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
10:59:24 AM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
10:59:24 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
10:59:24 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
10:59:24 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
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
10:59:24 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
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
10:59:24 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
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
10:59:24 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
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
10:59:24 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
10:59:24 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
10:59:24 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
10:59:24 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
10:59:24 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
10:59:24 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
10:59:24 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
10:59:24 AM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
10:59:24 AM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-6-A
10:59:24 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
10:59:24 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
10:59:25 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
10:59:25 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
10:59:25 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
10:59:26 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
10:59:27 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
10:59:27 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
10:59:28 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
10:59:29 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
10:59:29 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
10:59:29 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
10:59:29 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
10:59:30 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
10:59:30 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
10:59:30 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
10:59:30 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
10:59:30 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
10:59:30 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
10:59:30 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
10:59:30 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
10:59:30 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
10:59:30 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
10:59:31 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
10:59:31 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
10:59:31 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
10:59:31 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
10:59:31 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
10:59:33 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
10:59:35 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
10:59:38 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
10:59:38 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
10:59:38 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
10:59:38 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
10:59:41 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
10:59:41 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
10:59:41 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
10:59:41 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
10:59:41 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
10:59:41 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
10:59:41 AM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
10:59:42 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
10:59:43 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
10:59:43 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/
10:59:43 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
10:59:44 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/
10:59:44 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/
10:59:44 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
10:59:44 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
10:59:44 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
11:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15382039.237984, '127.0.0.1', 4003]
11:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15382039.241504, '127.0.0.1', 4003]
11:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15382039.652, '127.0.0.1', 4003]
11:01:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15382039.654496, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15382049.238976, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15382049.238976, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15382049.24048, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15382049.241504, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15382049.638976, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15382049.64, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15382049.64048, '127.0.0.1', 4003]
11:02:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15382049.641504, '127.0.0.1', 4003]
11:02:10 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15382059.232992, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 15382059.233984, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15382059.235488, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15382059.23648, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15382059.642976, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 15382059.642976, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15382059.645504, '127.0.0.1', 4003]
11:02:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 15382059.646496, '127.0.0.1', 4003]
11:02:19 AM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-6-A\749472\behavior_749472_2024-11-15_11-19-48\behavior\749472_2024-11-15_11-19-48.json
11:02:19 AM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
11:02:19 AM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
11:02:19 AM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.037
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.045
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 749472.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.25
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.25
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.037
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.045
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.045
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.037
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 10.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 1.5
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:02:19 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])

11:02:19 AM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.037 -> 0.025
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.045 -> 0.031
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 7.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.037 -> 0.025
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.045 -> 0.031
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 7.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y1, 0.0 -> 21.4
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_z, 0.0 -> 17.2
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_y2, 0.0 -> 21.4
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_x, 0.0 -> 15.7912
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: lineEdit_step_size, 1.0 -> 0.2
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: SuggestedWater,  -> 0.243
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 29.1
11:02:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 24.735
11:02:20 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
11:02:20 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
11:02:20 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
11:02:20 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
11:02:20 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
11:02:20 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_3 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
11:02:20 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: STAGE_3 @Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
11:02:20 AM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Without Baiting', 'curriculum_version': '2.3.1rwdDelay159', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
11:02:20 AM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Without Baiting_curriculum_v2.3.1rwdDelay159_schema_v1.0.json'.
11:02:20 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! STAGE_3 @ Uncoupled Without Baiting (v2.3.1rwdDelay159@1.0)
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Coupled Without Baiting
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BaseRewardSum is set to 0.8
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardFamily is set to 1
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardPairsN is set to 1
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "UncoupledReward" has been disabled by the GUI. skipped...
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
11:02:20 AM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 20
_____SKIPPING_____
11:52:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385084.950496, '127.0.0.1', 4003]
11:52:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15385085.980992, '127.0.0.1', 4002]
11:52:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385085.982496, '127.0.0.1', 4002]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15385086.964, '127.0.0.1', 4002]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385086.966496, '127.0.0.1', 4002]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15385086.967264, 4, '127.0.0.1']
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.071872, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15385087.070976, '127.0.0.1', 4002]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 15385087.070976, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.148096, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 15385087.180992, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15385087.182496, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.261376, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.452992, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.518752, '127.0.0.1', 4003]
11:52:43 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.602048, '127.0.0.1', 4003]
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.823424, '127.0.0.1', 4003]
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385087.965824, '127.0.0.1', 4003]
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15385088.064, '127.0.0.1', 4002]
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385088.065504, '127.0.0.1', 4002]
11:52:44 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
11:52:44 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 189
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15385088.081984, '127.0.0.1', 4002]
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15385088.086496, '127.0.0.1', 4002]
11:52:44 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])

11:52:44 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
11:52:44 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\749472\behavior_749472_2024-11-18_11-23-12
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:44 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:44 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385088.357248, '127.0.0.1', 4003]
11:52:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385091.737536, '127.0.0.1', 4003]
11:52:48 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385091.91952, '127.0.0.1', 4003]
11:52:48 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385092.064, '127.0.0.1', 4003]
11:52:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385095.634752, '127.0.0.1', 4003]
11:52:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385095.79984, '127.0.0.1', 4003]
11:52:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15385096.364, '127.0.0.1', 4002]
11:52:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385096.365504, '127.0.0.1', 4002]
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15385097.348, '127.0.0.1', 4002]
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15385097.350144, 4, '127.0.0.1']
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385097.349504, '127.0.0.1', 4002]
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385097.475456, '127.0.0.1', 4003]
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15385097.474976, '127.0.0.1', 4002]
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
11:52:53 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385097.56672, '127.0.0.1', 4003]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385097.74176, '127.0.0.1', 4003]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385097.869088, '127.0.0.1', 4003]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385097.884992, '127.0.0.1', 4003]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15385098.464, '127.0.0.1', 4002]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385098.465504, '127.0.0.1', 4002]
11:52:54 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
11:52:54 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 190
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15385098.476992, '127.0.0.1', 4002]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15385098.481504, '127.0.0.1', 4002]
11:52:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385098.484192, '127.0.0.1', 4003]
11:52:54 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])

11:52:54 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
11:52:54 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\749472\behavior_749472_2024-11-18_11-23-12
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:55 AM:INFO:bias_indicator:bias_indicator.py:calculate_bias:line 139:Bias: 0.011984364513974591 Trial Count: 189
11:52:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15385099.930976, '127.0.0.1', 4002]
11:52:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385099.93248, '127.0.0.1', 4002]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15385100.913984, '127.0.0.1', 4002]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15385100.91712, 4, '127.0.0.1']
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385100.91648, '127.0.0.1', 4002]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385101.057952, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15385101.056992, '127.0.0.1', 4002]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 15385101.056992, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385101.075232, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 15385101.164, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 15385101.166496, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385101.227296, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385101.366176, '127.0.0.1', 4003]
11:52:57 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385101.665024, '127.0.0.1', 4003]
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15385102.048, '127.0.0.1', 4002]
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385102.049504, '127.0.0.1', 4002]
11:52:58 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
11:52:58 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 191
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15385102.065984, '127.0.0.1', 4002]
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15385102.070496, '127.0.0.1', 4002]
11:52:58 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])

11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.122624, '127.0.0.1', 4003]
11:52:58 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.177728, '127.0.0.1', 4003]
11:52:58 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\749472\behavior_749472_2024-11-18_11-23-12
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:52:58 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.310176, '127.0.0.1', 4003]
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.460352, '127.0.0.1', 4003]
11:52:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.60512, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.756896, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385102.940608, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.279552, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.405504, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.424672, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.563776, '127.0.0.1', 4003]
11:52:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.736512, '127.0.0.1', 4003]
11:53:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.914656, '127.0.0.1', 4003]
11:53:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385103.935392, '127.0.0.1', 4003]
11:53:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385104.09488, '127.0.0.1', 4003]
11:53:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385104.285696, '127.0.0.1', 4003]
11:53:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385104.47248, '127.0.0.1', 4003]
11:53:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385106.263648, '127.0.0.1', 4003]
11:53:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385106.46384, '127.0.0.1', 4003]
11:53:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15385106.630976, '127.0.0.1', 4002]
11:53:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385106.63248, '127.0.0.1', 4002]
11:53:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385107.379008, '127.0.0.1', 4003]
11:53:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385107.601184, '127.0.0.1', 4003]
11:53:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385107.621728, '127.0.0.1', 4003]
11:53:05 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385108.8024, '127.0.0.1', 4003]
11:53:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385110.99008, '127.0.0.1', 4003]
11:53:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385111.214944, '127.0.0.1', 4003]
11:53:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 15385111.930976, '127.0.0.1', 4002]
11:53:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385111.93248, '127.0.0.1', 4002]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 15385112.913984, '127.0.0.1', 4002]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385112.91648, '127.0.0.1', 4002]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 15385112.917344, 4, '127.0.0.1']
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385113.011968, '127.0.0.1', 4003]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 15385113.010976, '127.0.0.1', 4002]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385113.144608, '127.0.0.1', 4003]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385113.208096, '127.0.0.1', 4003]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385113.247072, '127.0.0.1', 4003]
11:53:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 15385113.355616, '127.0.0.1', 4003]
11:53:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 15385113.997984, '127.0.0.1', 4002]
11:53:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 15385113.999488, '127.0.0.1', 4002]
11:53:10 AM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
11:53:10 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 192
11:53:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 15385114.010976, '127.0.0.1', 4002]
11:53:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 15385114.014496, '127.0.0.1', 4002]
11:53:10 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

11:53:10 AM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
11:53:10 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-6-A\749472\behavior_749472_2024-11-18_11-23-12
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
11:53:10 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
11:53:12 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 11.16%.
11:53:12 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 9.74%.
11:53:12 AM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 10.58%.
11:53:12 AM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 930:Percentage of same side lick intervals under 100 ms in Box A mouse 749472 exceeded 10%