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 ephys1A mouse 728570 exceeded 10% #1011

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: W10DT713669/W10DT713669-A_gui_log_2024-11-13_15-27-46.txt
boxes: ephys1
count: 11
text: Percentage of cross side lick intervals under 100 ms in Box A mouse 728570 exceeded 10%

GUI Log snippet (click for full log)

03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30927 fps= 50 q=26.0 size=  382208kB time=00:01:01.85 bitrate=50620.0kbits/s speed= 0.1x
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30925 fps= 50 q=20.0 size=  381952kB time=00:01:01.85 bitrate=50589.3kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=309555 fps=501 q=23.0 size= 3801611kB time=00:10:19.11 bitrate=50302.5kbits/s speed=   1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30951 fps= 50 q=19.0 size=  382208kB time=00:01:01.90 bitrate=50580.7kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30953 fps= 50 q=24.0 size=  382464kB time=00:01:01.90 bitrate=50611.3kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=309819 fps=501 q=24.0 size= 3804427kB time=00:10:19.63 bitrate=50296.9kbits/s speed=   1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30977 fps= 50 q=20.0 size=  382464kB time=00:01:01.95 bitrate=50572.1kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30979 fps= 50 q=23.0 size=  382464kB time=00:01:01.95 bitrate=50568.9kbits/s speed= 0.1x
03:46:23 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=31003 fps= 50 q=19.0 size=  382976kB time=00:01:02.00 bitrate=50597.4kbits/s speed= 0.1x
03:46:23 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=310077 fps=501 q=24.0 size= 3806987kB time=00:10:20.15 bitrate=50288.9kbits/s speed=   1x
03:46:23 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=31005 fps= 50 q=24.0 size=  382976kB time=00:01:02.01 bitrate=50594.1kbits/s speed= 0.1x
03:46:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10628.5, '127.0.0.1', 4002]
03:46:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10628.502496, '127.0.0.1', 4002]
03:46:23 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:46:23 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.00%.
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 0.00%.
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 0.00%.
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 22.58%.
03:46:23 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box A mouse 728570 exceeded 10%

 Full GUI log (first 200 and last 200 lines)

03:27:46 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile!
03:27:46 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)]
03:27:47 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43
03:27:47 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9
03:27:47 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4718:local repository has untracked changes to the following files: src/workflows/foraging.bonsai, src/workflows/foraging.bonsai.layout
03:27:47 PM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes
03:27:47 PM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window
03:27:47 PM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window
03:27:47 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file
03:27:47 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_ephys\Documents\FIPSettings
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_ephys\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\metadata_dialog\
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\rig_metadata\
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\Project Name and Funding Source v2.csv
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box3), using default: 60
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_ephys\Documents\ForagingSettings\name_mapper.json
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_ephys\Documents\aind_watchdog_service\manifest
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True
03:27:47 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True
03:27:47 PM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule
03:27:47 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:27:47 PM:INFO:Foraging:Foraging.py:_LoadRigJson:line 1536:Skipping rig metadata creation because create_rig_metadata=False
03:27:47 PM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface
03:27:47 PM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 323_EPHYS1
03:27:47 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai
03:27:47 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
03:27:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out
03:27:48 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai
03:27:48 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting
03:27:48 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
03:27:49 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out
03:27:50 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
03:27:51 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out
03:27:51 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
03:27:52 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.5 seconds: timed out
03:27:53 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC
03:27:53 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: Not able to parse a Harp Data Frame (03:27:53 PM)!
03:27:53 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: Raw Harp Data Frame: 01:E4:03:0B:20:FF:11:DB:22:00:00:B0:31:00:1C:03:0B:20:FF:11:DF:22:00:00:D7:72:01:89:03:0B:20:FF:11:DF:22:00:00:06:79:00:BE:03:0B:20:FF:11:E3:22:00:00:E8:06:01:32:03:0B:20:FF:11:E3:22:00:00:7A:0E:00:CB:03:0B:20:FF:11:E3:22:00:00:3F:1A:01:9D:03:0B:20:FF:11:E3:22:00:00:29:25:00:91:03:0B:20:FF:11:FA:22:00:00:2A:75:01:FA:03:0B:20:FF:11:FB:22:00:00:93:00:00:EE:03:0B:20:FF:11:00:23:00:00:87:4B:01:34:03:0B:20:FF:11:00:23:00:00:F6:4F:00:A6:03:0B:20:FF:11:4F:23:00:00:93:45:01:89:03:0B:20:FF:11:4F:23:00:00:CB:4C:00:C7:03:0B:20:FF:11:D4:23:00:00:A8:19:01:F7:03:0B:20:FF:11:D4:23:00:00:6B:1E:00:BE:03:0B:20:FF:11:1D:24:00:00:87:65:01:6C:03:0B:20:FF:11:1D:24:00:00:2B:6A:00:14:03:0B:20:FF:11:1E:24
03:27:53 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: Not able to parse a Harp Data Frame (03:27:53 PM)!
03:27:53 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: Raw Harp Data Frame: 01:C3:03:0B:20:FF:11:B1:22:00:00:40:54:00:A5:03:0B:20:FF:11:E6:22:00:00:7C:57:01:1A:03:0B:20:FF:11:E6:22:00:00:D9:5D:00:7C:03:0B:20:FF:11:E6:22:00:00:76:6E:01:2B:03:0B:20:FF:11:E6:22:00:00:E1:74:00:9B:03:0B:20:FF:11:1C:23:00:00:2C:49:01:F3:03:0B:20:FF:11:1C:23:00:00:4C:50:00:19:03:0B:20:FF:11:1C:23:00:00:A1:63:01:82:03:0B:20:FF:11:1C:23:00:00:97:68:00:7C:03:0B:20:FF:11:4D:23:00:00:4B:3D:01:37:03:0B:20:FF:11:4D:23:00:00:59:48:00:4F:03:0B:20:FF:11:BE:23:00:00:04:41:01:65:03:0B:20:FF:11:BE:23:00:00:F9:48:00:60:03:0B:20:FF:11:BE:23:00:00:FC:52:01:6E:03:0B:20:FF:11:BE:23:00:00:93:5B:00:0D
03:27:53 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 2.0 seconds
03:27:53 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully
03:27:53 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims
03:27:54 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims
03:27:54 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_ephys\Documents\ForagingSettings\WaterCalibrationPar_1.json
03:27:54 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:27:55 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages
03:27:55 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 882:found 3 newscale stages
03:27:55 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 906:Found the newscale stage from the settings file
03:27:55 PM:INFO:Foraging:Foraging.py:_connect_stage:line 933:Successfully connected to newscale stage: 46809
03:27:55 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 753:Checking stage connection
03:27:55 PM:INFO:Foraging:Foraging.py:_GetPositions:line 765:Grabbing current stage position
03:27:55 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_323_EPHYS1_2024-06-17.json
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.036
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.04
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.036
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.04
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.04
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.036
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionZ,  -> 6534.5
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionY,  -> 11599.0
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionX,  -> 6946.0
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:27:55 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:27:55 PM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete
03:27:57 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
03:27:57 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
03:27:58 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_ephys/capsule/scratch/saved_curriculums/
03:27:58 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_ephys/capsule/scratch/saved_curriculums/
03:27:59 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_ephys/.aind_auto_train/curriculum_manager/
03:27:59 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_ephys/.aind_auto_train/curriculum_manager/
03:27:59 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0
03:27:59 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2
03:27:59 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum
03:29:05 PM:INFO:Dialogs:Dialogs.py:_start_preview:line 1326:Camera is on
03:29:26 PM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials
03:29:39 PM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: D:\dynamic-foraging\323_EPHYS1\728570\behavior_728570_2024-11-11_15-23-12\behavior\728570_2024-11-11_15-23-12.json
03:29:39 PM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed
03:29:39 PM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag
03:29:39 PM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.04 -> 0.028
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 728570.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMin, 0.0 -> 1.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.04 -> 0.028
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0
03:29:39 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:39 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_ephys\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])

03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.036 -> 0.024
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 35.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 30.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 10.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 25.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.036 -> 0.024
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 10.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.04 -> 0.028
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.036 -> 0.024
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL_volume, 3.0 -> 2.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR_volume, 3.0 -> 2.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionZ, 6534.5 -> 7127.5
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionY, 11599.0 -> 11629.5
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: PositionX, 6946.0 -> 6695.5
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Step, 200.0 -> 50.0
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: SuggestedWater,  -> 0.488
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BaseWeight,  -> 26.77
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: TargetWeight,  -> 22.754
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:40 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:41 PM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674:
03:29:41 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes
03:29:41 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2938:AutoTrain disengaged!
03:29:41 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
03:29:41 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
03:29:41 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
03:29:41 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
03:29:41 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: GRADUATED @Uncoupled Baiting (v2.3@1.0)
03:29:41 PM:INFO:Dialogs:Dialogs.py:_update_curriculum_diagrams:line 2680:Selected curriculum: {'curriculum_name': 'Uncoupled Baiting', 'curriculum_version': '2.3', 'curriculum_schema_version': '1.0', 'curriculum_description': '2024-08-16 max_len = 75 mins; decrease finished trial criterion'}
03:29:41 PM:INFO:curriculum_manager:curriculum_manager.py:get_curriculum:line 131:Loaded a DynamicForagingCurriculum model from 'Uncoupled Baiting_curriculum_v2.3_schema_v1.0.json'.
03:29:41 PM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2887:AutoTrain engaged! GRADUATED @ Uncoupled Baiting (v2.3@1.0)
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "training_stage" not found. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3010:Task is set to Uncoupled Baiting
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_url" not found. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "task_schema_version" not found. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3018: Widget "description" not found. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "BaseRewardSum" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "RewardFamily" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "RewardPairsN" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:UncoupledReward is set to 0.1, 0.4, 0.7
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:Randomness is set to Exponential
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMin is set to 20
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:BlockMax is set to 35
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "BlockBeta" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "BlockMinReward" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMin is set to 1.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayMax is set to 1.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:DelayBeta is set to 0.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardDelay is set to 0.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:AutoReward is set to False
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "AutoWaterType" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "Multiplier" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "Unrewarded" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "Ignored" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMin is set to 1.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIMax is set to 30.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ITIBeta is set to 3.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "ITIIncrease" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:ResponseTime is set to 1.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RewardConsumeTime is set to 3.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:StopIgnores is set to 25
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "AdvancedBlockAuto" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "SwitchThr" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "PointsInARow" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:MaxTrial is set to 1000
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:MaxTime is set to 75
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:RightValue_volume is set to 2.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3065:LeftValue_volume is set to 2.0
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_min_trial" has been disabled by the GUI. skipped...
03:29:41 PM:INFO:Dialogs:Dialogs.py:_set_training_parameters:line 3030: Widget "warm_max_choice_ratio_bias" has been disabled by the GUI. skipped...
_____SKIPPING_____
03:46:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10610.321088, '127.0.0.1', 4003]
03:46:05 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=301048 fps=501 q=24.0 size= 3697675kB time=00:10:02.09 bitrate=50309.8kbits/s speed=   1x
03:46:05 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30102 fps= 50 q=28.0 size=  371712kB time=00:01:00.20 bitrate=50579.1kbits/s speed= 0.1x
03:46:05 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30100 fps= 50 q=20.0 size=  371968kB time=00:01:00.20 bitrate=50617.3kbits/s speed= 0.1x
03:46:05 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=301305 fps=501 q=24.0 size= 3701003kB time=00:10:02.61 bitrate=50312.2kbits/s speed=   1x
03:46:05 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30128 fps= 50 q=28.0 size=  372224kB time=00:01:00.25 bitrate=50605.1kbits/s speed= 0.1x
03:46:05 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30126 fps= 50 q=20.0 size=  372224kB time=00:01:00.25 bitrate=50608.4kbits/s speed= 0.1x
03:46:06 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=301568 fps=501 q=23.0 size= 3703563kB time=00:10:03.13 bitrate=50303.1kbits/s speed=   1x
03:46:06 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30152 fps= 50 q=19.0 size=  372480kB time=00:01:00.30 bitrate=50599.6kbits/s speed= 0.1x
03:46:06 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30154 fps= 50 q=25.0 size=  372480kB time=00:01:00.30 bitrate=50596.2kbits/s speed= 0.1x
03:46:06 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=301825 fps=501 q=24.0 size= 3706123kB time=00:10:03.65 bitrate=50295.0kbits/s speed=   1x
03:46:06 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30178 fps= 50 q=20.0 size=  372736kB time=00:01:00.35 bitrate=50590.7kbits/s speed= 0.1x
03:46:06 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30180 fps= 50 q=24.0 size=  372736kB time=00:01:00.36 bitrate=50587.4kbits/s speed= 0.1x
03:46:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10612.282976, '127.0.0.1', 4002]
03:46:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10612.285504, '127.0.0.1', 4002]
03:46:07 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:46:07 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:46:07 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 65
03:46:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10612.357984, '127.0.0.1', 4002]
03:46:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10612.361504, '127.0.0.1', 4002]
03:46:07 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=302082 fps=501 q=24.0 size= 3708939kB time=00:10:04.16 bitrate=50290.4kbits/s speed=   1x
03:46:07 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30205 fps= 50 q=25.0 size=  372736kB time=00:01:00.41 bitrate=50545.5kbits/s speed= 0.1x
03:46:07 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30204 fps= 50 q=19.0 size=  372992kB time=00:01:00.40 bitrate=50581.9kbits/s speed= 0.1x
03:46:07 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
03:46:07 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\dynamic-foraging\323_EPHYS1\728570\behavior_728570_2024-11-13_15-35-58
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:46:07 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
03:46:07 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=302341 fps=501 q=23.0 size= 3711499kB time=00:10:04.68 bitrate=50282.0kbits/s speed=   1x
03:46:07 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30229 fps= 50 q=20.0 size=  373248kB time=00:01:00.45 bitrate=50574.7kbits/s speed= 0.1x
03:46:07 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30231 fps= 50 q=24.0 size=  372992kB time=00:01:00.46 bitrate=50536.7kbits/s speed= 0.1x
03:46:08 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=302598 fps=501 q=23.0 size= 3714571kB time=00:10:05.19 bitrate=50280.8kbits/s speed=   1x
03:46:08 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30257 fps= 50 q=23.0 size=  373248kB time=00:01:00.51 bitrate=50527.9kbits/s speed= 0.1x
03:46:08 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30255 fps= 50 q=20.0 size=  373760kB time=00:01:00.51 bitrate=50600.6kbits/s speed= 0.1x
03:46:08 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=302854 fps=501 q=23.0 size= 3717387kB time=00:10:05.70 bitrate=50276.4kbits/s speed=   1x
03:46:08 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30281 fps= 50 q=19.0 size=  374016kB time=00:01:00.56 bitrate=50591.8kbits/s speed= 0.1x
03:46:08 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30283 fps= 50 q=24.0 size=  373504kB time=00:01:00.56 bitrate=50519.2kbits/s speed= 0.1x
03:46:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 10614.337184, '127.0.0.1', 4003]
03:46:09 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=303112 fps=501 q=24.0 size= 3720971kB time=00:10:06.22 bitrate=50282.1kbits/s speed=   1x
03:46:09 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30307 fps= 50 q=20.0 size=  374272kB time=00:01:00.61 bitrate=50583.0kbits/s speed= 0.1x
03:46:09 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30308 fps= 50 q=28.0 size=  374016kB time=00:01:00.61 bitrate=50546.7kbits/s speed= 0.1x
03:46:10 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=303368 fps=501 q=23.0 size= 3724299kB time=00:10:06.73 bitrate=50284.6kbits/s speed=   1x
03:46:10 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30332 fps= 50 q=20.0 size=  374784kB time=00:01:00.66 bitrate=50610.4kbits/s speed= 0.1x
03:46:10 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30334 fps= 50 q=27.0 size=  374272kB time=00:01:00.66 bitrate=50537.9kbits/s speed= 0.1x
03:46:10 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=303625 fps=501 q=23.0 size= 3727115kB time=00:10:07.25 bitrate=50280.0kbits/s speed=   1x
03:46:10 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30358 fps= 50 q=19.0 size=  375040kB time=00:01:00.71 bitrate=50601.6kbits/s speed= 0.1x
03:46:10 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30360 fps= 50 q=25.0 size=  374528kB time=00:01:00.72 bitrate=50529.2kbits/s speed= 0.1x
03:46:11 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=303883 fps=501 q=23.0 size= 3730187kB time=00:10:07.76 bitrate=50278.7kbits/s speed=   1x
03:46:11 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30384 fps= 50 q=19.0 size=  375296kB time=00:01:00.76 bitrate=50592.8kbits/s speed= 0.1x
03:46:11 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30386 fps= 50 q=23.0 size=  374784kB time=00:01:00.77 bitrate=50520.5kbits/s speed= 0.1x
03:46:11 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=304146 fps=501 q=23.0 size= 3733003kB time=00:10:08.29 bitrate=50273.2kbits/s speed=   1x
03:46:11 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30410 fps= 50 q=20.0 size=  375552kB time=00:01:00.82 bitrate=50584.1kbits/s speed= 0.1x
03:46:11 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30412 fps= 50 q=25.0 size=  374784kB time=00:01:00.82 bitrate=50477.3kbits/s speed= 0.1x
03:46:12 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=304403 fps=501 q=23.0 size= 3736075kB time=00:10:08.80 bitrate=50272.1kbits/s speed=   1x
03:46:12 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30438 fps= 50 q=25.0 size=  375040kB time=00:01:00.87 bitrate=50468.6kbits/s speed= 0.1x
03:46:12 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30436 fps= 50 q=20.0 size=  375808kB time=00:01:00.87 bitrate=50575.3kbits/s speed= 0.1x
03:46:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10617.366976, '127.0.0.1', 4002]
03:46:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10617.36848, '127.0.0.1', 4002]
03:46:12 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=304660 fps=501 q=23.0 size= 3739403kB time=00:10:09.32 bitrate=50274.4kbits/s speed=   1x
03:46:12 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30463 fps= 50 q=27.0 size=  375552kB time=00:01:00.92 bitrate=50496.0kbits/s speed= 0.1x
03:46:12 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30461 fps= 50 q=19.0 size=  376064kB time=00:01:00.92 bitrate=50568.2kbits/s speed= 0.1x
03:46:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=304917 fps=501 q=23.0 size= 3742475kB time=00:10:09.83 bitrate=50273.3kbits/s speed=   1x
03:46:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30489 fps= 50 q=27.0 size=  375808kB time=00:01:00.97 bitrate=50487.4kbits/s speed= 0.1x
03:46:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30487 fps= 50 q=19.0 size=  376576kB time=00:01:00.97 bitrate=50593.9kbits/s speed= 0.1x
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10618.349984, '127.0.0.1', 4002]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10618.352288, 4, '127.0.0.1']
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10618.351488, '127.0.0.1', 4002]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10618.460736, '127.0.0.1', 4003]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 10618.46, '127.0.0.1', 4003]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10618.46, '127.0.0.1', 4002]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 10618.46, '127.0.0.1', 4003]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 10618.462496, '127.0.0.1', 4003]
03:46:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=305175 fps=501 q=24.0 size= 3746315kB time=00:10:10.35 bitrate=50282.3kbits/s speed=   1x
03:46:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30513 fps= 50 q=20.0 size=  376832kB time=00:01:01.02 bitrate=50585.1kbits/s speed= 0.1x
03:46:13 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30515 fps= 50 q=28.0 size=  376320kB time=00:01:01.03 bitrate=50513.1kbits/s speed= 0.1x
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10618.599776, '127.0.0.1', 4003]
03:46:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10618.786944, '127.0.0.1', 4003]
03:46:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10618.967424, '127.0.0.1', 4003]
03:46:14 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=305432 fps=501 q=24.0 size= 3750667kB time=00:10:10.86 bitrate=50298.4kbits/s speed=   1x
03:46:14 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30540 fps= 50 q=28.0 size=  376832kB time=00:01:01.08 bitrate=50540.4kbits/s speed= 0.1x
03:46:14 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30538 fps= 50 q=20.0 size=  377088kB time=00:01:01.07 bitrate=50578.0kbits/s speed= 0.1x
03:46:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10619.13232, '127.0.0.1', 4003]
03:46:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10619.338336, '127.0.0.1', 4003]
03:46:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10619.50928, '127.0.0.1', 4003]
03:46:14 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=305689 fps=501 q=25.0 size= 3754507kB time=00:10:11.37 bitrate=50307.5kbits/s speed=   1x
03:46:14 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30564 fps= 50 q=20.0 size=  377600kB time=00:01:01.12 bitrate=50603.6kbits/s speed= 0.1x
03:46:14 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30566 fps= 50 q=28.0 size=  377344kB time=00:01:01.13 bitrate=50566.0kbits/s speed= 0.1x
03:46:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10619.678688, '127.0.0.1', 4003]
03:46:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10619.890912, '127.0.0.1', 4003]
03:46:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10620.067648, '127.0.0.1', 4003]
03:46:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=305948 fps=501 q=24.0 size= 3758091kB time=00:10:11.89 bitrate=50312.9kbits/s speed=   1x
03:46:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30590 fps= 50 q=20.0 size=  377856kB time=00:01:01.18 bitrate=50594.9kbits/s speed= 0.1x
03:46:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30592 fps= 50 q=28.0 size=  377600kB time=00:01:01.18 bitrate=50557.3kbits/s speed= 0.1x
03:46:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10620.261504, '127.0.0.1', 4003]
03:46:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10620.428608, '127.0.0.1', 4003]
03:46:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=306205 fps=501 q=24.0 size= 3761419kB time=00:10:12.40 bitrate=50315.4kbits/s speed=   1x
03:46:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30618 fps= 50 q=28.0 size=  378112kB time=00:01:01.23 bitrate=50582.9kbits/s speed= 0.1x
03:46:15 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30616 fps= 50 q=20.0 size=  378112kB time=00:01:01.23 bitrate=50586.2kbits/s speed= 0.1x
03:46:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10620.66352, '127.0.0.1', 4003]
03:46:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10620.884384, '127.0.0.1', 4003]
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10621.08384, '127.0.0.1', 4003]
03:46:16 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=306462 fps=501 q=24.0 size= 3764747kB time=00:10:12.92 bitrate=50317.5kbits/s speed=   1x
03:46:16 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30642 fps= 50 q=19.0 size=  378368kB time=00:01:01.28 bitrate=50577.5kbits/s speed= 0.1x
03:46:16 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30643 fps= 50 q=28.0 size=  378368kB time=00:01:01.28 bitrate=50575.8kbits/s speed= 0.1x
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10621.284448, '127.0.0.1', 4003]
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10621.466976, '127.0.0.1', 4002]
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10621.46848, '127.0.0.1', 4002]
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10621.521312, '127.0.0.1', 4003]
03:46:16 PM:INFO:uncoupled_block:uncoupled_block.py:auto_shape_perseverance:line 137:persev at side = L, added 4 trials to both sides
03:46:16 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:persev at side = L, added 4 trials to both sides
03:46:16 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:46:16 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 66
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 10621.545984, '127.0.0.1', 4002]
03:46:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 10621.549504, '127.0.0.1', 4002]
03:46:16 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1
03:46:16 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:D:\dynamic-foraging\323_EPHYS1\728570\behavior_728570_2024-11-13_15-35-58
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields
03:46:16 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=306726 fps=501 q=25.0 size= 3768075kB time=00:10:13.45 bitrate=50318.6kbits/s speed=   1x
03:46:16 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30668 fps= 50 q=20.0 size=  378880kB time=00:01:01.33 bitrate=50603.0kbits/s speed= 0.1x
03:46:16 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30670 fps= 50 q=28.0 size=  378880kB time=00:01:01.34 bitrate=50599.7kbits/s speed= 0.1x
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected!
03:46:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected!
03:46:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=306984 fps=501 q=23.0 size= 3770891kB time=00:10:13.96 bitrate=50313.9kbits/s speed=   1x
03:46:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30696 fps= 50 q=25.0 size=  379136kB time=00:01:01.39 bitrate=50591.0kbits/s speed= 0.1x
03:46:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30694 fps= 50 q=20.0 size=  379136kB time=00:01:01.38 bitrate=50594.3kbits/s speed= 0.1x
03:46:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=307241 fps=501 q=24.0 size= 3773451kB time=00:10:14.48 bitrate=50306.0kbits/s speed=   1x
03:46:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30719 fps= 50 q=19.0 size=  379392kB time=00:01:01.43 bitrate=50587.2kbits/s speed= 0.1x
03:46:17 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30721 fps= 50 q=25.0 size=  379136kB time=00:01:01.44 bitrate=50549.8kbits/s speed= 0.1x
03:46:18 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=307498 fps=501 q=24.0 size= 3776011kB time=00:10:14.99 bitrate=50298.0kbits/s speed=   1x
03:46:18 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30745 fps= 50 q=20.0 size=  379648kB time=00:01:01.49 bitrate=50578.6kbits/s speed= 0.1x
03:46:18 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30747 fps= 50 q=23.0 size=  379392kB time=00:01:01.49 bitrate=50541.2kbits/s speed= 0.1x
03:46:18 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=307756 fps=501 q=24.0 size= 3779083kB time=00:10:15.51 bitrate=50296.7kbits/s speed=   1x
03:46:18 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30773 fps= 50 q=27.0 size=  379904kB time=00:01:01.54 bitrate=50566.6kbits/s speed= 0.1x
03:46:18 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30771 fps= 50 q=20.0 size=  380160kB time=00:01:01.54 bitrate=50604.0kbits/s speed= 0.1x
03:46:19 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=308012 fps=501 q=24.0 size= 3782411kB time=00:10:16.02 bitrate=50299.2kbits/s speed=   1x
03:46:19 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30796 fps= 50 q=19.0 size=  380416kB time=00:01:01.59 bitrate=50597.0kbits/s speed= 0.1x
03:46:19 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30798 fps= 50 q=28.0 size=  380160kB time=00:01:01.59 bitrate=50559.6kbits/s speed= 0.1x
03:46:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 10624.4, '127.0.0.1', 4002]
03:46:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10624.401504, '127.0.0.1', 4002]
03:46:19 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=308269 fps=501 q=24.0 size= 3785995kB time=00:10:16.53 bitrate=50304.9kbits/s speed=   1x
03:46:19 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30824 fps= 50 q=28.0 size=  380672kB time=00:01:01.64 bitrate=50585.0kbits/s speed= 0.1x
03:46:19 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30822 fps= 50 q=19.0 size=  380672kB time=00:01:01.64 bitrate=50588.3kbits/s speed= 0.1x
03:46:20 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=308526 fps=501 q=24.0 size= 3789067kB time=00:10:17.05 bitrate=50303.8kbits/s speed=   1x
03:46:20 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30848 fps= 50 q=20.0 size=  380928kB time=00:01:01.69 bitrate=50579.7kbits/s speed= 0.1x
03:46:20 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30850 fps= 50 q=27.0 size=  380928kB time=00:01:01.70 bitrate=50576.4kbits/s speed= 0.1x
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 10625.384, '127.0.0.1', 4002]
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10625.385504, '127.0.0.1', 4002]
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 10625.386176, 4, '127.0.0.1']
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10625.485376, '127.0.0.1', 4003]
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 10625.484992, '127.0.0.1', 4002]
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10625.631296, '127.0.0.1', 4003]
03:46:20 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=308783 fps=501 q=24.0 size= 3792395kB time=00:10:17.56 bitrate=50306.0kbits/s speed=   1x
03:46:20 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30876 fps= 50 q=28.0 size=  381440kB time=00:01:01.75 bitrate=50601.7kbits/s speed= 0.1x
03:46:20 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30874 fps= 50 q=20.0 size=  381440kB time=00:01:01.74 bitrate=50605.0kbits/s speed= 0.1x
03:46:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10625.853056, '127.0.0.1', 4003]
03:46:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 10626.078752, '127.0.0.1', 4003]
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=309041 fps=501 q=24.0 size= 3795979kB time=00:10:18.08 bitrate=50311.7kbits/s speed=   1x
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30899 fps= 50 q=19.0 size=  381696kB time=00:01:01.79 bitrate=50598.0kbits/s speed= 0.1x
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30901 fps= 50 q=28.0 size=  381952kB time=00:01:01.80 bitrate=50628.6kbits/s speed= 0.1x
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=309298 fps=501 q=24.0 size= 3798795kB time=00:10:18.59 bitrate=50307.0kbits/s speed=   1x
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30927 fps= 50 q=26.0 size=  382208kB time=00:01:01.85 bitrate=50620.0kbits/s speed= 0.1x
03:46:21 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30925 fps= 50 q=20.0 size=  381952kB time=00:01:01.85 bitrate=50589.3kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=309555 fps=501 q=23.0 size= 3801611kB time=00:10:19.11 bitrate=50302.5kbits/s speed=   1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30951 fps= 50 q=19.0 size=  382208kB time=00:01:01.90 bitrate=50580.7kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30953 fps= 50 q=24.0 size=  382464kB time=00:01:01.90 bitrate=50611.3kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=309819 fps=501 q=24.0 size= 3804427kB time=00:10:19.63 bitrate=50296.9kbits/s speed=   1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30977 fps= 50 q=20.0 size=  382464kB time=00:01:01.95 bitrate=50572.1kbits/s speed= 0.1x
03:46:22 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=30979 fps= 50 q=23.0 size=  382464kB time=00:01:01.95 bitrate=50568.9kbits/s speed= 0.1x
03:46:23 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=31003 fps= 50 q=19.0 size=  382976kB time=00:01:02.00 bitrate=50597.4kbits/s speed= 0.1x
03:46:23 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=310077 fps=501 q=24.0 size= 3806987kB time=00:10:20.15 bitrate=50288.9kbits/s speed=   1x
03:46:23 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4800:BONSAI: frame=31005 fps= 50 q=24.0 size=  382976kB time=00:01:02.01 bitrate=50594.1kbits/s speed= 0.1x
03:46:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 10628.5, '127.0.0.1', 4002]
03:46:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 10628.502496, '127.0.0.1', 4002]
03:46:23 PM:WARNING:MyFunctions:MyFunctions.py:_GenerateATrial:line 172:
03:46:23 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 0.00%.
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 0.00%.
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 0.00%.
03:46:23 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 22.58%.
03:46:23 PM:ERROR:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 957:Percentage of cross side lick intervals under 100 ms in Box A mouse 728570 exceeded 10%