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

ValueError: invalid literal for int() with base 10: '' #958

Open alexpiet opened 1 day ago

alexpiet commented 1 day ago

This issue was automatically generated from GUI logs.

file: Foraging.py
function: _CheckFormat
line 2028
logfile: DT300178/DT300178-A_gui_log_2024-11-07_09-30-52.txt
boxes: 9D
count: 40
text: ValueError: invalid literal for int() with base 10: ''

GUI Log snippet (click for full log)

10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:47:45 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 0.0
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 10.0 -> 0.0
10:47:47 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 8000, 12800] to [11200, 0, 0, 12800]
10:53:34 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
10:53:37 AM:ERROR:Foraging:Foraging.py:_CheckFormat:line 2018:Traceback (most recent call last):
  File "c:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Foraging.py", line 2014, in _CheckFormat
    if int(self.RewardPairsN.text())>len(self.RewardFamilies[int(self.RewardFamily.text())-1]):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: invalid literal for int() with base 10: ''

Full GUI log (first 400 lines)

09:30:52 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile!
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4718:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8
09:30:52 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window
09:30:52 AM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_workflow_path), using default: 
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (create_rig_metadata), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1082:Loaded behavior schedule
09:30:53 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:30:53 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface
09:30:53 AM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 428-9-D
09:30:53 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
09:30:53 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai
09:30:54 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting
09:30:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out
09:30:56 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:57 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out
09:30:58 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.5 seconds: timed out
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 2.0 seconds
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims
09:31:00 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims
09:31:00 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
09:31:00 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:403: UserWarning: No artists with labels found to put in legend.  Note that artists whose label start with an underscore are ignored when legend() is called with no argument.
  self.ax1.legend(loc='lower right', fontsize=8)

09:31:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:00 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages
09:31:00 AM:WARNING:Foraging:Foraging.py:_InitializeMotorStage:line 867:Could not find any instances of NewScale Stage
09:31:00 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 239:Inserting Stage Widget
09:31:00 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:31:00 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:31:00 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:31:00 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 61:Connected to COM5, device id: 1130
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 142:Getting available registers on device
09:31:01 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:31:01 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:31:03 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:31:05 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:31:05 AM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5243
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3814
09:31:07 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:07 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:08 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0
09:31:08 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2
09:31:08 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
09:31:23 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:23 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 16.0
09:31:27 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [0, 0, 0, 12800]
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:31 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 12.0
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 0.0 -> 12.0
09:31:33 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 12800] to [9600, 0, 0, 12800]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164332.802976, '127.0.0.1', 4003]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164332.80848, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164334.189984, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164334.191488, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164335.241984, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164335.24448, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164336.784, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164336.785504, '127.0.0.1', 4003]
09:32:00 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:32:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:_Start:line 3846:Starting session, with experimenter: the ghost in the shell
09:32:01 AM:INFO:Foraging:Foraging.py:_set_default_project:line 3715:Setting Project name: Behavior Platform
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:02 AM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\metadata-dir
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\raw.harp
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior-videos
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\fib
09:32:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\Users\\svc_aind_behavior\\Documents\\behavior_data\\428-9-D\\0\\behavior_0_2024-11-07_09-32-02\\behavior\\raw.harp', '127.0.0.1', 4002]
09:32:08 AM:INFO:Foraging:Foraging.py:log_session:line 4159:Starting log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4176:starting trial loop
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 1
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164362.133984, '127.0.0.1', 4002]
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164362.13648, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164363.492, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164363.495488, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164364.474976, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164364.477504, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164626.9912, 4, '127.0.0.1']
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164365.484992, '127.0.0.1', 4002]
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164368.490976, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164368.494496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 2
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164368.513984, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164368.518496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:14 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 415:No laser calibration file for session metadata
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164372.290976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.293504, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164372.474976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.47648, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164634.990368, 4, '127.0.0.1']
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164373.474976, '127.0.0.1', 4002]
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164376.490976, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164376.493504, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4198:Skipping Automatic Upload based on ForagingSettings.json
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 3
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164376.504, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164376.507488, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:22 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:24 AM:INFO:Foraging:Foraging.py:_Start:line 3968:Start button pressed: ending trial loop
09:32:24 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4178:ending trial loop
09:32:26 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164380.274976, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.27648, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164380.657984, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164643.173184, 4, '127.0.0.1']
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.659488, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164381.657984, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:28 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
09:32:28 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:28 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164384.673984, '127.0.0.1', 4002]
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164384.67648, '127.0.0.1', 4002]
09:32:33 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:32:33 AM:INFO:Foraging:Foraging.py:end_session_log:line 4167:Closing log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\python_gui_log.txt
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:34:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 164484.586656, '127.0.0.1', 4003], displaying at 0.5 Hz
09:35:06 AM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\metadata-dir
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\behavior
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\behavior\raw.harp
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\behavior-videos
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\fib
09:35:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\Users\\svc_aind_behavior\\Documents\\behavior_data\\428-9-D\\0\\behavior_0_2024-11-07_09-35-06\\behavior\\raw.harp', '127.0.0.1', 4002]
09:35:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164564.608992, '127.0.0.1', 4003]
09:35:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164564.611488, '127.0.0.1', 4003]
09:35:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164565.208992, '127.0.0.1', 4003]
09:35:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164565.210496, '127.0.0.1', 4003]
09:35:47 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
09:35:48 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
09:35:48 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:35:48 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:35:48 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:03:27 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:28 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [9600, 0, 0, 12800] to [10400, 0, 0, 12800]
10:03:28 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:28 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [10400, 0, 0, 12800] to [11200, 0, 0, 12800]
10:03:28 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:29 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 0, 12800] to [12000, 0, 0, 12800]
10:03:30 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:30 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 0, 0, 12800] to [12800, 0, 0, 12800]
10:03:42 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2949:AutoTrain disengaged!
10:03:42 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0750101
10:03:42 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
10:03:42 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2526:Auto engage successful for mouse 0750101
10:03:42 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:42 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:42 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: StopIgnores, 20.0 -> 200.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: StopIgnores, 20.0 -> 200.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:33 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0

alexpiet commented 1 day ago

This issue reoccurred:

file: Foraging.py
function: _ShowRewardPairs
line 2240
logfile: DT300178/DT300178-A_gui_log_2024-11-07_09-30-52.txt
boxes: 9D
count: 40
text: ValueError: invalid literal for int() with base 10: ''

GUI Log snippet (click for full log)

10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:47:45 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 0.0
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 10.0 -> 0.0
10:47:47 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 8000, 12800] to [11200, 0, 0, 12800]
10:53:34 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
10:53:37 AM:ERROR:Foraging:Foraging.py:_CheckFormat:line 2018:Traceback (most recent call last):
  File "c:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Foraging.py", line 2014, in _CheckFormat
    if int(self.RewardPairsN.text())>len(self.RewardFamilies[int(self.RewardFamily.text())-1]):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: invalid literal for int() with base 10: ''

Full GUI log (first 400 lines)

09:30:52 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile!
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4718:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8
09:30:52 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window
09:30:52 AM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_workflow_path), using default: 
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (create_rig_metadata), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1082:Loaded behavior schedule
09:30:53 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:30:53 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface
09:30:53 AM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 428-9-D
09:30:53 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
09:30:53 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai
09:30:54 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting
09:30:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out
09:30:56 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:57 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out
09:30:58 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.5 seconds: timed out
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 2.0 seconds
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims
09:31:00 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims
09:31:00 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
09:31:00 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:403: UserWarning: No artists with labels found to put in legend.  Note that artists whose label start with an underscore are ignored when legend() is called with no argument.
  self.ax1.legend(loc='lower right', fontsize=8)

09:31:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:00 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages
09:31:00 AM:WARNING:Foraging:Foraging.py:_InitializeMotorStage:line 867:Could not find any instances of NewScale Stage
09:31:00 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 239:Inserting Stage Widget
09:31:00 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:31:00 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:31:00 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:31:00 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 61:Connected to COM5, device id: 1130
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 142:Getting available registers on device
09:31:01 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:31:01 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:31:03 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:31:05 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:31:05 AM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5243
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3814
09:31:07 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:07 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:08 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0
09:31:08 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2
09:31:08 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
09:31:23 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:23 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 16.0
09:31:27 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [0, 0, 0, 12800]
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:31 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 12.0
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 0.0 -> 12.0
09:31:33 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 12800] to [9600, 0, 0, 12800]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164332.802976, '127.0.0.1', 4003]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164332.80848, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164334.189984, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164334.191488, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164335.241984, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164335.24448, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164336.784, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164336.785504, '127.0.0.1', 4003]
09:32:00 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:32:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:_Start:line 3846:Starting session, with experimenter: the ghost in the shell
09:32:01 AM:INFO:Foraging:Foraging.py:_set_default_project:line 3715:Setting Project name: Behavior Platform
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:02 AM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\metadata-dir
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\raw.harp
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior-videos
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\fib
09:32:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\Users\\svc_aind_behavior\\Documents\\behavior_data\\428-9-D\\0\\behavior_0_2024-11-07_09-32-02\\behavior\\raw.harp', '127.0.0.1', 4002]
09:32:08 AM:INFO:Foraging:Foraging.py:log_session:line 4159:Starting log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4176:starting trial loop
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 1
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164362.133984, '127.0.0.1', 4002]
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164362.13648, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164363.492, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164363.495488, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164364.474976, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164364.477504, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164626.9912, 4, '127.0.0.1']
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164365.484992, '127.0.0.1', 4002]
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164368.490976, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164368.494496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 2
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164368.513984, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164368.518496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:14 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 415:No laser calibration file for session metadata
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164372.290976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.293504, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164372.474976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.47648, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164634.990368, 4, '127.0.0.1']
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164373.474976, '127.0.0.1', 4002]
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164376.490976, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164376.493504, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4198:Skipping Automatic Upload based on ForagingSettings.json
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 3
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164376.504, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164376.507488, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:22 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:24 AM:INFO:Foraging:Foraging.py:_Start:line 3968:Start button pressed: ending trial loop
09:32:24 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4178:ending trial loop
09:32:26 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164380.274976, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.27648, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164380.657984, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164643.173184, 4, '127.0.0.1']
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.659488, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164381.657984, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:28 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
09:32:28 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:28 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164384.673984, '127.0.0.1', 4002]
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164384.67648, '127.0.0.1', 4002]
09:32:33 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:32:33 AM:INFO:Foraging:Foraging.py:end_session_log:line 4167:Closing log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\python_gui_log.txt
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:34:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 164484.586656, '127.0.0.1', 4003], displaying at 0.5 Hz
09:35:06 AM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\metadata-dir
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\behavior
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\behavior\raw.harp
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\behavior-videos
09:35:06 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06\fib
09:35:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\Users\\svc_aind_behavior\\Documents\\behavior_data\\428-9-D\\0\\behavior_0_2024-11-07_09-35-06\\behavior\\raw.harp', '127.0.0.1', 4002]
09:35:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164564.608992, '127.0.0.1', 4003]
09:35:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164564.611488, '127.0.0.1', 4003]
09:35:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164565.208992, '127.0.0.1', 4003]
09:35:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164565.210496, '127.0.0.1', 4003]
09:35:47 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
09:35:48 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
09:35:48 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:35:48 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:35:48 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:48 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-35-06
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:35:53 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:03:27 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:28 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [9600, 0, 0, 12800] to [10400, 0, 0, 12800]
10:03:28 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:28 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [10400, 0, 0, 12800] to [11200, 0, 0, 12800]
10:03:28 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:29 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 0, 12800] to [12000, 0, 0, 12800]
10:03:30 AM:INFO:move_worker:move_worker.py:axis_motion:line 94:(axis motion): Moving motor 0
10:03:30 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [12000, 0, 0, 12800] to [12800, 0, 0, 12800]
10:03:42 AM:INFO:Dialogs:Dialogs.py:update_auto_train_lock:line 2949:AutoTrain disengaged!
10:03:42 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0750101
10:03:42 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
10:03:42 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2526:Auto engage successful for mouse 0750101
10:03:42 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:42 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:42 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:46 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:52 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:55 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:03:58 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:04 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:06 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:10 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:13 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:16 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: StopIgnores, 20.0 -> 200.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:19 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ID, 0.0 -> 750101.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 12.0 -> 16.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: StopIgnores, 20.0 -> 200.0
10:04:20 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RewardFamily, 1.0 -> 3.0
10:04:33 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMin, 1.0 -> 2.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayBeta, 1.0 -> 0.5
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: DelayMax, 1.0 -> 0.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMax, 60.0 -> 500.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIMax, 8.0 -> 15.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ITIBeta, 2.0 -> 3.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: ResponseTime, 1.0 -> 3.0
10:04:33 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: BlockMin, 20.0 -> 400.0

alexpiet commented 1 day ago

This issue reoccurred:

file: Foraging.py
function: _CheckFormat
line 2028
logfile: DT300178/DT300178-A_gui_log_2024-11-07_09-30-52.txt
boxes: 9D
count: 40
text: ValueError: invalid literal for int() with base 10: ''

GUI Log snippet (click for full log)

10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:47:45 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 0.0
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 10.0 -> 0.0
10:47:47 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 8000, 12800] to [11200, 0, 0, 12800]
10:53:34 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
10:53:37 AM:ERROR:Foraging:Foraging.py:_CheckFormat:line 2018:Traceback (most recent call last):
  File "c:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Foraging.py", line 2014, in _CheckFormat
    if int(self.RewardPairsN.text())>len(self.RewardFamilies[int(self.RewardFamily.text())-1]):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: invalid literal for int() with base 10: ''

Full GUI log (first 200 and last 200 lines)

09:30:52 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile!
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4718:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8
09:30:52 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window
09:30:52 AM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_workflow_path), using default: 
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (create_rig_metadata), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1082:Loaded behavior schedule
09:30:53 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:30:53 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface
09:30:53 AM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 428-9-D
09:30:53 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
09:30:53 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai
09:30:54 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting
09:30:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out
09:30:56 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:57 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out
09:30:58 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.5 seconds: timed out
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 2.0 seconds
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims
09:31:00 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims
09:31:00 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
09:31:00 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:403: UserWarning: No artists with labels found to put in legend.  Note that artists whose label start with an underscore are ignored when legend() is called with no argument.
  self.ax1.legend(loc='lower right', fontsize=8)

09:31:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:00 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages
09:31:00 AM:WARNING:Foraging:Foraging.py:_InitializeMotorStage:line 867:Could not find any instances of NewScale Stage
09:31:00 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 239:Inserting Stage Widget
09:31:00 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:31:00 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:31:00 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:31:00 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 61:Connected to COM5, device id: 1130
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 142:Getting available registers on device
09:31:01 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:31:01 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:31:03 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:31:05 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:31:05 AM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5243
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3814
09:31:07 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:07 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:08 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0
09:31:08 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2
09:31:08 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
09:31:23 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:23 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 16.0
09:31:27 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [0, 0, 0, 12800]
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:31 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 12.0
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 0.0 -> 12.0
09:31:33 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 12800] to [9600, 0, 0, 12800]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164332.802976, '127.0.0.1', 4003]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164332.80848, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164334.189984, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164334.191488, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164335.241984, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164335.24448, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164336.784, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164336.785504, '127.0.0.1', 4003]
09:32:00 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:32:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:_Start:line 3846:Starting session, with experimenter: the ghost in the shell
09:32:01 AM:INFO:Foraging:Foraging.py:_set_default_project:line 3715:Setting Project name: Behavior Platform
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:02 AM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\metadata-dir
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\raw.harp
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior-videos
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\fib
09:32:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\Users\\svc_aind_behavior\\Documents\\behavior_data\\428-9-D\\0\\behavior_0_2024-11-07_09-32-02\\behavior\\raw.harp', '127.0.0.1', 4002]
09:32:08 AM:INFO:Foraging:Foraging.py:log_session:line 4159:Starting log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4176:starting trial loop
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 1
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164362.133984, '127.0.0.1', 4002]
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164362.13648, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164363.492, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164363.495488, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164364.474976, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164364.477504, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164626.9912, 4, '127.0.0.1']
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164365.484992, '127.0.0.1', 4002]
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164368.490976, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164368.494496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 2
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164368.513984, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164368.518496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:14 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 415:No laser calibration file for session metadata
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164372.290976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.293504, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164372.474976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.47648, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164634.990368, 4, '127.0.0.1']
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164373.474976, '127.0.0.1', 4002]
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164376.490976, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164376.493504, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4198:Skipping Automatic Upload based on ForagingSettings.json
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 3
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164376.504, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164376.507488, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:22 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:24 AM:INFO:Foraging:Foraging.py:_Start:line 3968:Start button pressed: ending trial loop
09:32:24 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4178:ending trial loop
09:32:26 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164380.274976, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.27648, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164380.657984, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164643.173184, 4, '127.0.0.1']
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.659488, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164381.657984, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:28 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
09:32:28 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:28 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164384.673984, '127.0.0.1', 4002]
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164384.67648, '127.0.0.1', 4002]
09:32:33 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:32:33 AM:INFO:Foraging:Foraging.py:end_session_log:line 4167:Closing log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\python_gui_log.txt
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:34:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 164484.586656, '127.0.0.1', 4003], displaying at 0.5 Hz
_____SKIPPING_____
10:46:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169073.337184, 4, '127.0.0.1']
10:46:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168810.785504, '127.0.0.1', 4002]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168812.220864, '127.0.0.1', 4003]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168812.22, '127.0.0.1', 4002]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168812.385792, '127.0.0.1', 4003]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168812.592608, '127.0.0.1', 4003]
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168815.233984, '127.0.0.1', 4002]
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168815.235488, '127.0.0.1', 4002]
10:46:21 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 261
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168815.248992, '127.0.0.1', 4002]
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168815.253504, '127.0.0.1', 4002]
10:46:21 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:21 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:21 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168817.284, '127.0.0.1', 4002]
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168817.285504, '127.0.0.1', 4002]
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168817.316992, '127.0.0.1', 4002]
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169079.870336, 4, '127.0.0.1']
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168817.318496, '127.0.0.1', 4002]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168818.832224, '127.0.0.1', 4003]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 168818.832, '127.0.0.1', 4003]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 168818.832, '127.0.0.1', 4003]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168818.832, '127.0.0.1', 4002]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 168818.834496, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.001856, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.123648, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.151584, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.30608, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.606144, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.625632, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.655072, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.667168, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.77632, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.944224, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.08768, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.24144, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.3696, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.532096, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.068, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.2736, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.444128, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168821.833984, '127.0.0.1', 4002]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168821.835488, '127.0.0.1', 4002]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.839264, '127.0.0.1', 4003]
10:46:27 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 262
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168821.86, '127.0.0.1', 4002]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168821.863488, '127.0.0.1', 4002]
10:46:27 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.889088, '127.0.0.1', 4003]
10:46:28 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:28 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168822.041664, '127.0.0.1', 4003]
10:46:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168827.396928, '127.0.0.1', 4003]
10:46:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168827.795136, '127.0.0.1', 4003]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168829.384, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168829.385504, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168829.416992, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168829.418496, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169091.97024, 4, '127.0.0.1']
10:46:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168832.433984, '127.0.0.1', 4002]
10:46:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168835.402816, '127.0.0.1', 4003]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168835.449984, '127.0.0.1', 4002]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168835.45248, '127.0.0.1', 4002]
10:46:41 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 263
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168835.466976, '127.0.0.1', 4002]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168835.471488, '127.0.0.1', 4002]
10:46:41 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:41 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:41 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168835.610432, '127.0.0.1', 4003]
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168835.756544, '127.0.0.1', 4003]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168841.916992, '127.0.0.1', 4002]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168841.918496, '127.0.0.1', 4002]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168841.949984, '127.0.0.1', 4002]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169104.504128, 4, '127.0.0.1']
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168841.95248, '127.0.0.1', 4002]
10:46:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168844.966976, '127.0.0.1', 4002]
10:46:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168847.984, '127.0.0.1', 4002]
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168847.985504, '127.0.0.1', 4002]
10:46:54 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 264
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168848.0, '127.0.0.1', 4002]
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168848.003488, '127.0.0.1', 4002]
10:46:54 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:54 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:54 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168852.216992, '127.0.0.1', 4002]
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168852.218496, '127.0.0.1', 4002]
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168852.249984, '127.0.0.1', 4002]
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169114.804352, 4, '127.0.0.1']
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168852.25248, '127.0.0.1', 4002]
10:47:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168855.266976, '127.0.0.1', 4002]
10:47:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168858.284, '127.0.0.1', 4002]
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168858.285504, '127.0.0.1', 4002]
10:47:04 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 265
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168858.298976, '127.0.0.1', 4002]
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168858.303488, '127.0.0.1', 4002]
10:47:04 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168858.342112, '127.0.0.1', 4003]
10:47:04 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:47:04 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168861.300992, '127.0.0.1', 4002]
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168861.302496, '127.0.0.1', 4002]
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168861.333984, '127.0.0.1', 4002]
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169123.888192, 4, '127.0.0.1']
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168861.33648, '127.0.0.1', 4002]
10:47:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168864.350976, '127.0.0.1', 4002]
10:47:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:47:12 AM:INFO:Foraging:Foraging.py:_Start:line 3968:Start button pressed: ending trial loop
10:47:12 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4178:ending trial loop
10:47:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168867.366976, '127.0.0.1', 4002]
10:47:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168867.369504, '127.0.0.1', 4002]
10:47:21 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
10:47:22 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
10:47:22 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:47:22 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
10:47:28 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
10:47:28 AM:INFO:Foraging:Foraging.py:end_session_log:line 4167:Closing log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09\behavior\python_gui_log.txt
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:47:45 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 0.0
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 10.0 -> 0.0
10:47:47 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 8000, 12800] to [11200, 0, 0, 12800]
10:53:34 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
10:53:37 AM:ERROR:Foraging:Foraging.py:_CheckFormat:line 2018:Traceback (most recent call last):
  File "c:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Foraging.py", line 2014, in _CheckFormat
    if int(self.RewardPairsN.text())>len(self.RewardFamilies[int(self.RewardFamily.text())-1]):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: invalid literal for int() with base 10: ''

alexpiet commented 1 day ago

This issue reoccurred:

file: Foraging.py
function: _ShowRewardPairs
line 2240
logfile: DT300178/DT300178-A_gui_log_2024-11-07_09-30-52.txt
boxes: 9D
count: 40
text: ValueError: invalid literal for int() with base 10: ''

GUI Log snippet (click for full log)

10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:47:45 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 0.0
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 10.0 -> 0.0
10:47:47 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 8000, 12800] to [11200, 0, 0, 12800]
10:53:34 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
10:53:37 AM:ERROR:Foraging:Foraging.py:_CheckFormat:line 2018:Traceback (most recent call last):
  File "c:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Foraging.py", line 2014, in _CheckFormat
    if int(self.RewardPairsN.text())>len(self.RewardFamilies[int(self.RewardFamily.text())-1]):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: invalid literal for int() with base 10: ''

Full GUI log (first 200 and last 200 lines)

09:30:52 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile!
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4718:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)]
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61
09:30:52 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8
09:30:52 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes
09:30:52 AM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window
09:30:52 AM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file
09:30:52 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_workflow_path), using default: 
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (create_rig_metadata), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True
09:30:52 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1082:Loaded behavior schedule
09:30:53 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:30:53 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
09:30:53 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
09:30:53 AM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface
09:30:53 AM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 428-9-D
09:30:53 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
09:30:53 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out
09:30:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai
09:30:54 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting
09:30:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out
09:30:56 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:57 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out
09:30:58 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.5 seconds: timed out
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 2.0 seconds
09:30:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully
09:30:59 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims
09:31:00 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims
09:31:00 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_1.json
09:31:00 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:403: UserWarning: No artists with labels found to put in legend.  Note that artists whose label start with an underscore are ignored when legend() is called with no argument.
  self.ax1.legend(loc='lower right', fontsize=8)

09:31:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:00 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages
09:31:00 AM:WARNING:Foraging:Foraging.py:_InitializeMotorStage:line 867:Could not find any instances of NewScale Stage
09:31:00 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 239:Inserting Stage Widget
09:31:00 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False
09:31:00 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED
09:31:00 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181
09:31:00 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 61:Connected to COM5, device id: 1130
09:31:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 142:Getting available registers on device
09:31:01 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file)
09:31:01 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0]
09:31:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0]
09:31:03 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200]
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions
09:31:05 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device
#############################################################
09:31:05 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_428-9-D_2024-10-28_11_36_22.json
09:31:05 AM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5243
09:31:06 AM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3814
09:31:07 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:07 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
09:31:08 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
09:31:08 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0
09:31:08 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2
09:31:08 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
09:31:23 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:23 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 3 to 16.0
09:31:27 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 0] to [0, 0, 0, 12800]
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:31:31 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 0 to 12.0
09:31:31 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_x, 0.0 -> 12.0
09:31:33 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [0, 0, 0, 12800] to [9600, 0, 0, 12800]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164332.802976, '127.0.0.1', 4003]
09:31:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164332.80848, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 164334.189984, '127.0.0.1', 4003]
09:31:40 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 164334.191488, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164335.241984, '127.0.0.1', 4003]
09:31:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164335.24448, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 164336.784, '127.0.0.1', 4003]
09:31:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 164336.785504, '127.0.0.1', 4003]
09:32:00 AM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
09:32:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:_Start:line 3846:Starting session, with experimenter: the ghost in the shell
09:32:01 AM:INFO:Foraging:Foraging.py:_set_default_project:line 3715:Setting Project name: Behavior Platform
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:01 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
09:32:02 AM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\metadata-dir
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\raw.harp
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior-videos
09:32:02 AM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\fib
09:32:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\Users\\svc_aind_behavior\\Documents\\behavior_data\\428-9-D\\0\\behavior_0_2024-11-07_09-32-02\\behavior\\raw.harp', '127.0.0.1', 4002]
09:32:08 AM:INFO:Foraging:Foraging.py:log_session:line 4159:Starting log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4176:starting trial loop
09:32:08 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 1
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164362.133984, '127.0.0.1', 4002]
09:32:08 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164362.13648, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164363.492, '127.0.0.1', 4002]
09:32:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164363.495488, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164364.474976, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164364.477504, '127.0.0.1', 4002]
09:32:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164626.9912, 4, '127.0.0.1']
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164365.484992, '127.0.0.1', 4002]
09:32:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164368.490976, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164368.494496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 2
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164368.513984, '127.0.0.1', 4002]
09:32:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164368.518496, '127.0.0.1', 4002]
09:32:14 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:14 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 415:No laser calibration file for session metadata
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:14 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164372.290976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.293504, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164372.474976, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164372.47648, '127.0.0.1', 4002]
09:32:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164634.990368, 4, '127.0.0.1']
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164373.474976, '127.0.0.1', 4002]
09:32:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164376.490976, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164376.493504, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4198:Skipping Automatic Upload based on ForagingSettings.json
09:32:22 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 3
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 164376.504, '127.0.0.1', 4002]
09:32:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 164376.507488, '127.0.0.1', 4002]
09:32:22 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
09:32:22 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:22 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:32:24 AM:INFO:Foraging:Foraging.py:_Start:line 3968:Start button pressed: ending trial loop
09:32:24 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4178:ending trial loop
09:32:26 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 164380.274976, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.27648, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 164380.657984, '127.0.0.1', 4002]
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 164643.173184, 4, '127.0.0.1']
09:32:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164380.659488, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 164381.657984, '127.0.0.1', 4002]
09:32:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
09:32:28 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
09:32:28 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
09:32:28 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 164384.673984, '127.0.0.1', 4002]
09:32:30 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 164384.67648, '127.0.0.1', 4002]
09:32:33 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
09:32:33 AM:INFO:Foraging:Foraging.py:end_session_log:line 4167:Closing log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02\behavior\python_gui_log.txt
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:33 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0\behavior_0_2024-11-07_09-32-02
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
09:32:38 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
09:34:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 52:['/PhotometryFalling', 164484.586656, '127.0.0.1', 4003], displaying at 0.5 Hz
_____SKIPPING_____
10:46:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169073.337184, 4, '127.0.0.1']
10:46:16 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168810.785504, '127.0.0.1', 4002]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168812.220864, '127.0.0.1', 4003]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168812.22, '127.0.0.1', 4002]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168812.385792, '127.0.0.1', 4003]
10:46:18 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168812.592608, '127.0.0.1', 4003]
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168815.233984, '127.0.0.1', 4002]
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168815.235488, '127.0.0.1', 4002]
10:46:21 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 261
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168815.248992, '127.0.0.1', 4002]
10:46:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168815.253504, '127.0.0.1', 4002]
10:46:21 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:21 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:21 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:21 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168817.284, '127.0.0.1', 4002]
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168817.285504, '127.0.0.1', 4002]
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168817.316992, '127.0.0.1', 4002]
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169079.870336, 4, '127.0.0.1']
10:46:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168817.318496, '127.0.0.1', 4002]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168818.832224, '127.0.0.1', 4003]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 168818.832, '127.0.0.1', 4003]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 168818.832, '127.0.0.1', 4003]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168818.832, '127.0.0.1', 4002]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4002]
10:46:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 168818.834496, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.001856, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.123648, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.151584, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.30608, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.606144, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.625632, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.655072, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.667168, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.77632, '127.0.0.1', 4003]
10:46:25 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168819.944224, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.08768, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.24144, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.3696, '127.0.0.1', 4003]
10:46:26 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168820.532096, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.068, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.2736, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.444128, '127.0.0.1', 4003]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168821.833984, '127.0.0.1', 4002]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168821.835488, '127.0.0.1', 4002]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.839264, '127.0.0.1', 4003]
10:46:27 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 262
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168821.86, '127.0.0.1', 4002]
10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168821.863488, '127.0.0.1', 4002]
10:46:27 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:27 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168821.889088, '127.0.0.1', 4003]
10:46:28 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:28 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:28 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:28 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168822.041664, '127.0.0.1', 4003]
10:46:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168827.396928, '127.0.0.1', 4003]
10:46:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168827.795136, '127.0.0.1', 4003]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168829.384, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168829.385504, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168829.416992, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168829.418496, '127.0.0.1', 4002]
10:46:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169091.97024, 4, '127.0.0.1']
10:46:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168832.433984, '127.0.0.1', 4002]
10:46:38 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168835.402816, '127.0.0.1', 4003]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168835.449984, '127.0.0.1', 4002]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168835.45248, '127.0.0.1', 4002]
10:46:41 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 263
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168835.466976, '127.0.0.1', 4002]
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168835.471488, '127.0.0.1', 4002]
10:46:41 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:41 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:41 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168835.610432, '127.0.0.1', 4003]
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:41 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168835.756544, '127.0.0.1', 4003]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168841.916992, '127.0.0.1', 4002]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168841.918496, '127.0.0.1', 4002]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168841.949984, '127.0.0.1', 4002]
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169104.504128, 4, '127.0.0.1']
10:46:47 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168841.95248, '127.0.0.1', 4002]
10:46:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168844.966976, '127.0.0.1', 4002]
10:46:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168847.984, '127.0.0.1', 4002]
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168847.985504, '127.0.0.1', 4002]
10:46:54 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 264
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168848.0, '127.0.0.1', 4002]
10:46:54 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168848.003488, '127.0.0.1', 4002]
10:46:54 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:46:54 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:46:54 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:46:54 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168852.216992, '127.0.0.1', 4002]
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168852.218496, '127.0.0.1', 4002]
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168852.249984, '127.0.0.1', 4002]
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169114.804352, 4, '127.0.0.1']
10:46:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168852.25248, '127.0.0.1', 4002]
10:47:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168855.266976, '127.0.0.1', 4002]
10:47:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168858.284, '127.0.0.1', 4002]
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168858.285504, '127.0.0.1', 4002]
10:47:04 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 265
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 168858.298976, '127.0.0.1', 4002]
10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 168858.303488, '127.0.0.1', 4002]
10:47:04 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice
  RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1])

10:47:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 168858.342112, '127.0.0.1', 4003]
10:47:04 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
10:47:04 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:04 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 168861.300992, '127.0.0.1', 4002]
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168861.302496, '127.0.0.1', 4002]
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 168861.333984, '127.0.0.1', 4002]
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 169123.888192, 4, '127.0.0.1']
10:47:07 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168861.33648, '127.0.0.1', 4002]
10:47:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 168864.350976, '127.0.0.1', 4002]
10:47:10 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4002]
10:47:12 AM:INFO:Foraging:Foraging.py:_Start:line 3968:Start button pressed: ending trial loop
10:47:12 AM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4178:ending trial loop
10:47:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 168867.366976, '127.0.0.1', 4002]
10:47:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 168867.369504, '127.0.0.1', 4002]
10:47:21 AM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=True
10:47:22 AM:INFO:Foraging:Foraging.py:_Save:line 2463:saving without weight or extra water
10:47:22 AM:WARNING:Foraging:Foraging.py:_GetWaterCalibration:line 1050:Did not find a recent water calibration file
10:47:22 AM:INFO:Foraging:Foraging.py:_NewSession:line 3538:New Session pressed
10:47:28 AM:INFO:Foraging:Foraging.py:_NewSession:line 3612:New Session complete
10:47:28 AM:INFO:Foraging:Foraging.py:end_session_log:line 4167:Closing log file at C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09\behavior\python_gui_log.txt
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:28 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4828:BONSAI: 
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\Users\svc_aind_behavior\Documents\behavior_data\428-9-D\0750101\behavior_0750101_2024-11-07_10-05-09
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
10:47:33 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
10:47:45 AM:INFO:move_worker:move_worker.py:move_to_position:line 145:(move to position): Moving motor 2 to 0.0
10:47:45 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: lineEdit_y2, 10.0 -> 0.0
10:47:47 AM:INFO:move_worker:move_worker.py:move_absolute:line 306:(move absolute): Moved motors from [11200, 0, 8000, 12800] to [11200, 0, 0, 12800]
10:53:34 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3632:Stopping current trials
10:53:37 AM:ERROR:Foraging:Foraging.py:_CheckFormat:line 2018:Traceback (most recent call last):
  File "c:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Foraging.py", line 2014, in _CheckFormat
    if int(self.RewardPairsN.text())>len(self.RewardFamilies[int(self.RewardFamily.text())-1]):
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: invalid literal for int() with base 10: ''