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 7A mouse 745861 exceeded 10% #1013

Open alexpiet opened 1 week ago

alexpiet commented 1 week ago

This issue was automatically generated from GUI logs.

file: MyFunctions.py
function: calculate_inter_lick_intervals
line 957
logfile: W10DT714681/W10DT714681-A_gui_log_2024-11-13_12-43-48.txt
boxes: 7A
count: 3
text: Percentage of cross side lick intervals under 100 ms in Box A mouse 745861 exceeded 10%

GUI Log snippet (click for full log)

01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244431.107968, '127.0.0.1', 4003]
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244432.789632, '127.0.0.1', 4003]
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.30%.
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 0.00%.
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 0.30%.
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 12.50%.
01:30:52 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box A mouse 745861 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

12:43:48 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
12:43:48 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
12:43:49 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
12:43:49 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
12:43:49 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean
12:43:49 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
12:43:49 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
12:43:49 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
12:43:49 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
12:43:49 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
12:43:49 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
12:43:49 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
12:43:49 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
12:43:49 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-A_2024-11-12_13_29_06.json
12:43:49 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
12:43:49 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
12:43:49 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
12:43:49 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
12:43:49 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-A
12:43:49 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:43:49 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:50 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
12:43:50 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
12:43:50 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
12:43:50 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:51 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
12:43:52 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:53 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
12:43:53 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:43:54 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds
12:43:54 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
12:43:54 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
12:43:55 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
12:43:55 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
12:43:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
12:43:55 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
12:43:55 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage
12:43:55 PM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget
12:43:55 PM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
12:43:55 PM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
12:43:55 PM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
12:43:55 PM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
12:43:55 PM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130
12:43:55 PM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device
12:43:55 PM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
12:43:55 PM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
12:43:55 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
12:43:58 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
12:44:00 PM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
12:44:03 PM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
12:44:03 PM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
12:44:03 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-A_2024-11-12_13_29_06.json
12:44:03 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection
12:44:06 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed
12:44:06 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai
12:44:06 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
12:44:06 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
12:44:06 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai
12:44:06 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully
12:44:06 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
12:44:07 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5368
12:44:07 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3936
12:44:08 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
12:44:08 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
12:44:09 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
12:44:09 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
12:44:09 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
12:44:09 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
12:44:09 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
12:44:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241651.352992, '127.0.0.1', 4003]
12:44:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241651.355488, '127.0.0.1', 4003]
12:44:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241652.174976, '127.0.0.1', 4003]
12:44:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241652.177504, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241661.348, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241661.348, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241661.349504, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241661.350496, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241662.166976, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241662.168, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241662.169504, '127.0.0.1', 4003]
12:44:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241662.170496, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241671.352, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241671.352992, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241671.353504, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241671.354496, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241672.161984, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241672.161984, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241672.163488, '127.0.0.1', 4003]
12:44:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241672.16448, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241681.348, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241681.348992, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241681.349504, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241681.350496, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241682.168, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241682.168992, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241682.170496, '127.0.0.1', 4003]
12:45:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241682.171488, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241691.354976, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241691.354976, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241691.35648, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241691.357504, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241692.165984, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241692.166976, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241692.16848, '127.0.0.1', 4003]
12:45:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241692.169504, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241701.350976, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241701.352, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241701.35248, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241701.353504, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241702.170976, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241702.170976, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241702.17248, '127.0.0.1', 4003]
12:45:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241702.173504, '127.0.0.1', 4003]
12:45:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 16241709.353984, '127.0.0.1', 4003]
12:45:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16241709.355488, '127.0.0.1', 4003]
12:45:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241712.165984, '127.0.0.1', 4003]
12:45:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241712.165984, '127.0.0.1', 4003]
12:45:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241712.167488, '127.0.0.1', 4003]
12:45:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241712.16848, '127.0.0.1', 4003]
12:45:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 16241714.165984, '127.0.0.1', 4003]
12:45:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 16241714.167488, '127.0.0.1', 4003]
12:51:40 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
01:11:37 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
01:11:51 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-7-A\745861\behavior_745861_2024-11-12_13-53-17\behavior\745861_2024-11-12_13-53-17.json
01:11:51 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
01:11:51 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
01:11:51 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.5
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.5
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.039
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 745861.0
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 0.5
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.5
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.039
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.035
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.039
01:11:51 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 15.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 2.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 15.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 2.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:11:52 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

01:11:52 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.039 -> 0.026
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
01:11:52 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.039 -> 0.026
_____SKIPPING_____
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:15 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244396.28912, '127.0.0.1', 4003]
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 16244397.564992, '127.0.0.1', 4002]
01:30:17 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244397.566496, '127.0.0.1', 4002]
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 16244398.548, '127.0.0.1', 4002]
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244398.550496, '127.0.0.1', 4002]
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 16244398.551328, 4, '127.0.0.1']
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244398.72832, '127.0.0.1', 4003]
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 16244398.728, '127.0.0.1', 4002]
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
01:30:18 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244398.903328, '127.0.0.1', 4003]
01:30:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244401.410592, '127.0.0.1', 4003]
01:30:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 16244401.730976, '127.0.0.1', 4002]
01:30:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244401.733504, '127.0.0.1', 4002]
01:30:21 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:21 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:21 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 49
01:30:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 16244401.742976, '127.0.0.1', 4002]
01:30:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 16244401.746496, '127.0.0.1', 4002]
01:30:21 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:21 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-A\745861\behavior_745861_2024-11-13_13-20-51
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:21 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 16244405.197984, '127.0.0.1', 4002]
01:30:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244405.199488, '127.0.0.1', 4002]
01:30:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 16244406.180992, '127.0.0.1', 4002]
01:30:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244406.183488, '127.0.0.1', 4002]
01:30:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 16244406.184224, 4, '127.0.0.1']
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244406.439008, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 16244406.437984, '127.0.0.1', 4002]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 16244406.437984, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 16244406.437984, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16244406.44048, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244406.62336, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244406.740128, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244406.87152, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.023872, '127.0.0.1', 4003]
01:30:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.1848, '127.0.0.1', 4003]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.340352, '127.0.0.1', 4003]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.492448, '127.0.0.1', 4003]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.653888, '127.0.0.1', 4003]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.833088, '127.0.0.1', 4003]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244407.992672, '127.0.0.1', 4003]
01:30:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244408.1632, '127.0.0.1', 4003]
01:30:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 16244409.448, '127.0.0.1', 4002]
01:30:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244409.449504, '127.0.0.1', 4002]
01:30:29 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:29 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:29 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 50
01:30:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 16244409.464, '127.0.0.1', 4002]
01:30:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 16244409.467488, '127.0.0.1', 4002]
01:30:29 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:29 PM:INFO:bias_indicator:bias_indicator.py:calculate_bias:line 177:Can't calculate bias at trial count 49 because this solver needs samples of at least 2 classes in the data, but the data contains only one class: -1
01:30:29 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-A\745861\behavior_745861_2024-11-13_13-20-51
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:29 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244410.908864, '127.0.0.1', 4003]
01:30:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244411.069024, '127.0.0.1', 4003]
01:30:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 16244411.814976, '127.0.0.1', 4002]
01:30:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244411.81648, '127.0.0.1', 4002]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 16244412.797984, '127.0.0.1', 4002]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 16244412.800096, 4, '127.0.0.1']
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244412.799488, '127.0.0.1', 4002]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244412.927616, '127.0.0.1', 4003]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 16244412.926976, '127.0.0.1', 4002]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 16244412.926976, '127.0.0.1', 4003]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 16244412.926976, '127.0.0.1', 4003]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16244412.929504, '127.0.0.1', 4003]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.038912, '127.0.0.1', 4003]
01:30:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.198496, '127.0.0.1', 4003]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.343232, '127.0.0.1', 4003]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.499296, '127.0.0.1', 4003]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.66176, '127.0.0.1', 4003]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.80208, '127.0.0.1', 4003]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244413.973312, '127.0.0.1', 4003]
01:30:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244414.140256, '127.0.0.1', 4003]
01:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244414.301888, '127.0.0.1', 4003]
01:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244414.474272, '127.0.0.1', 4003]
01:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244414.669248, '127.0.0.1', 4003]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244415.46144, '127.0.0.1', 4003]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244415.637152, '127.0.0.1', 4003]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244415.827488, '127.0.0.1', 4003]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 16244415.930976, '127.0.0.1', 4002]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244415.933504, '127.0.0.1', 4002]
01:30:35 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
01:30:35 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:35 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 51
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 16244415.948, '127.0.0.1', 4002]
01:30:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 16244415.951488, '127.0.0.1', 4002]
01:30:35 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:35 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-A\745861\behavior_745861_2024-11-13_13-20-51
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:35 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244416.453472, '127.0.0.1', 4003]
01:30:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244417.715872, '127.0.0.1', 4003]
01:30:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244417.905312, '127.0.0.1', 4003]
01:30:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 16244421.097984, '127.0.0.1', 4002]
01:30:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244421.099488, '127.0.0.1', 4002]
01:30:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244421.582848, '127.0.0.1', 4003]
01:30:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244421.745504, '127.0.0.1', 4003]
01:30:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244423.459328, '127.0.0.1', 4003]
01:30:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244423.606848, '127.0.0.1', 4003]
01:30:45 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244426.117376, '127.0.0.1', 4003]
01:30:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 16244426.732, '127.0.0.1', 4002]
01:30:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244426.733504, '127.0.0.1', 4002]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 16244427.714976, '127.0.0.1', 4002]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 16244427.717248, 4, '127.0.0.1']
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244427.71648, '127.0.0.1', 4002]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244427.972384, '127.0.0.1', 4003]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 16244427.972, '127.0.0.1', 4002]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 16244427.972, '127.0.0.1', 4003]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 16244427.972, '127.0.0.1', 4003]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 16244427.973504, '127.0.0.1', 4003]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244428.15136, '127.0.0.1', 4003]
01:30:47 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244428.268672, '127.0.0.1', 4003]
01:30:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244428.426752, '127.0.0.1', 4003]
01:30:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244428.594464, '127.0.0.1', 4003]
01:30:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244428.750752, '127.0.0.1', 4003]
01:30:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244428.90576, '127.0.0.1', 4003]
01:30:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244429.053088, '127.0.0.1', 4003]
01:30:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244429.213088, '127.0.0.1', 4003]
01:30:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244429.375392, '127.0.0.1', 4003]
01:30:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244430.061088, '127.0.0.1', 4003]
01:30:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244430.19632, '127.0.0.1', 4003]
01:30:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 16244430.980992, '127.0.0.1', 4002]
01:30:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 16244430.983488, '127.0.0.1', 4002]
01:30:50 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:

01:30:50 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
01:30:50 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 52
01:30:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 16244430.997984, '127.0.0.1', 4002]
01:30:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 16244431.001504, '127.0.0.1', 4002]
01:30:50 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
01:30:50 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-A\745861\behavior_745861_2024-11-13_13-20-51
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244431.107968, '127.0.0.1', 4003]
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
01:30:50 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
01:30:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 16244432.789632, '127.0.0.1', 4003]
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.30%.
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 0.00%.
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 0.30%.
01:30:52 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 12.50%.
01:30:52 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box A mouse 745861 exceeded 10%