trial stalled 5 minutes, user continued trials

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

10:34:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11488817.066176, '127.0.0.1', 4003] 10:34:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11488817.094848, '127.0.0.1', 4003] 10:34:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11488817.28208, '127.0.0.1', 4003] 10:34:49 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11488817.488224, '127.0.0.1', 4003] 10:35:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11488833.674528, '127.0.0.1', 4003] 10:35:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11488833.93664, '127.0.0.1', 4003] 10:36:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11488939.718784, '127.0.0.1', 4003] 10:36:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11488939.912288, '127.0.0.1', 4003] 10:37:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11488962.198944, '127.0.0.1', 4003] 10:38:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489020.053376, '127.0.0.1', 4003] 10:38:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11489020.24608, '127.0.0.1', 4003] 10:38:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11489020.462816, '127.0.0.1', 4003] 10:40:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489147.858592, '127.0.0.1', 4003] 10:40:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489148.055264, '127.0.0.1', 4003] 10:40:20 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489148.251488, '127.0.0.1', 4003] 10:40:23 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489150.713408, '127.0.0.1', 4003] 10:40:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489172.93056, '127.0.0.1', 4003] 10:40:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489173.148, '127.0.0.1', 4003] 10:40:45 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489173.359168, '127.0.0.1', 4003] 10:41:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11489200.24736, '127.0.0.1', 4003] 10:41:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489200.48048, '127.0.0.1', 4003] 10:41:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489200.705664, '127.0.0.1', 4003] 10:41:13 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489200.712992, '127.0.0.1', 4003] 10:41:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489206.966592, '127.0.0.1', 4003] 10:41:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489207.342976, '127.0.0.1', 4003] 10:41:19 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489207.364352, '127.0.0.1', 4003] 10:43:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489317.435744, '127.0.0.1', 4003] 10:43:09 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489317.622944, '127.0.0.1', 4003] 10:43:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11489320.454464, '127.0.0.1', 4003] 10:45:11 AM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4263:trial stalled 5 minutes, user continued trials

09:59:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 8694460.362976, '127.0.0.1', 4022] 09:59:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8694460.366496, '127.0.0.1', 4022] 10:00:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 8694461.345984, '127.0.0.1', 4022] 10:00:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 8694461.346208, 4, '127.0.0.1'] 10:00:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8694461.350496, '127.0.0.1', 4022] 10:00:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694461.46912, '127.0.0.1', 4023] 10:00:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 8694461.468992, '127.0.0.1', 4022] 10:00:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4022] 10:00:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694461.59344, '127.0.0.1', 4023] 10:00:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694461.750528, '127.0.0.1', 4023] 10:00:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694461.915648, '127.0.0.1', 4023] 10:00:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 8694464.48, '127.0.0.1', 4022] 10:00:04 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 8694464.482496, '127.0.0.1', 4022] 10:00:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694466.758976, '127.0.0.1', 4023] 10:00:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694466.897632, '127.0.0.1', 4023] 10:00:06 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694467.047296, '127.0.0.1', 4023] 10:00:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694484.45328, '127.0.0.1', 4023] 10:00:24 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694484.656736, '127.0.0.1', 4023] 10:02:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8694635.65152, '127.0.0.1', 4023] 10:02:55 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8694635.8776, '127.0.0.1', 4023] 10:02:58 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694639.30512, '127.0.0.1', 4023] 10:06:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694852.407968, '127.0.0.1', 4023] 10:06:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 8694852.408032, '127.0.0.1', 4023] 10:06:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694852.602368, '127.0.0.1', 4023] 10:06:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694852.787616, '127.0.0.1', 4023] 10:06:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694852.956384, '127.0.0.1', 4023] 10:06:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694860.016672, '127.0.0.1', 4023] 10:06:39 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 8694860.197984, '127.0.0.1', 4023] 10:06:43 AM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4282:trial stalled 5 minutes, user continued trials

10:27:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 9300911.818496, '127.0.0.1', 4022] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 9300912.798976, '127.0.0.1', 4022] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 9300912.802304, 4, '127.0.0.1'] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 9300912.802496, '127.0.0.1', 4022] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300912.947872, '127.0.0.1', 4023] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTime', 9300912.946976, '127.0.0.1', 4023] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 9300912.946976, '127.0.0.1', 4022] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedLeftWaterStartTime', 9300912.946976, '127.0.0.1', 4023] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardLeft', '127.0.0.1', 4022] 10:27:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 9300912.950496, '127.0.0.1', 4023] 10:27:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300913.04096, '127.0.0.1', 4023] 10:27:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300913.315712, '127.0.0.1', 4023] 10:27:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300913.436672, '127.0.0.1', 4023] 10:27:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300913.564768, '127.0.0.1', 4023] 10:27:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300913.696032, '127.0.0.1', 4023] 10:27:33 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300913.850688, '127.0.0.1', 4023] 10:27:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300914.119232, '127.0.0.1', 4023] 10:27:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300914.27728, '127.0.0.1', 4023] 10:27:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300914.408256, '127.0.0.1', 4023] 10:27:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300914.711392, '127.0.0.1', 4023] 10:27:34 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300914.868288, '127.0.0.1', 4023] 10:27:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300915.79472, '127.0.0.1', 4023] 10:27:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 9300915.948992, '127.0.0.1', 4022] 10:27:35 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 9300915.951488, '127.0.0.1', 4022] 10:27:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300932.087552, '127.0.0.1', 4023] 10:27:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300932.247296, '127.0.0.1', 4023] 10:27:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300932.391392, '127.0.0.1', 4023] 10:27:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300932.56224, '127.0.0.1', 4023] 10:27:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 9300932.702336, '127.0.0.1', 4023] 10:34:16 AM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4282:trial stalled 5 minutes, user continued trials

04:59:58 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=249724 fps=501 q=19.0 size= 3063412kB time=00:08:19.44 bitrate=50246.4kbits/s speed= 1x 04:59:58 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=249980 fps=501 q=19.0 size= 3066228kB time=00:08:19.95 bitrate=50241.3kbits/s speed= 1x 04:59:58 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=249980 fps=501 q=25.0 size= 3066986kB time=00:08:19.95 bitrate=50253.7kbits/s speed= 1x 04:59:59 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=250236 fps=501 q=19.0 size= 3069044kB time=00:08:20.47 bitrate=50235.8kbits/s speed= 1x 04:59:59 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=250236 fps=501 q=25.0 size= 3070058kB time=00:08:20.47 bitrate=50252.4kbits/s speed= 1x 04:59:59 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=250493 fps=501 q=19.0 size= 3071860kB time=00:08:20.98 bitrate=50230.3kbits/s speed= 1x 04:59:59 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=250493 fps=501 q=25.0 size= 3072874kB time=00:08:20.98 bitrate=50246.9kbits/s speed= 1x 05:00:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814766.888928, '127.0.0.1', 4003] 05:00:00 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=250757 fps=501 q=26.0 size= 3076458kB time=00:08:21.51 bitrate=50252.5kbits/s speed= 1x 05:00:00 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=250757 fps=501 q=21.0 size= 3075956kB time=00:08:21.51 bitrate=50244.3kbits/s speed= 1x 05:00:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814767.03216, '127.0.0.1', 4003] 05:00:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814767.225568, '127.0.0.1', 4003] 05:00:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814767.388896, '127.0.0.1', 4003] 05:00:00 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251012 fps=501 q=22.0 size= 3080564kB time=00:08:22.02 bitrate=50268.5kbits/s speed= 1x 05:00:00 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251012 fps=501 q=26.0 size= 3081066kB time=00:08:22.02 bitrate=50276.7kbits/s speed= 1x 05:00:01 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251269 fps=501 q=25.0 size= 3084906kB time=00:08:22.53 bitrate=50287.8kbits/s speed= 1x 05:00:01 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251269 fps=501 q=20.0 size= 3084148kB time=00:08:22.53 bitrate=50275.5kbits/s speed= 1x 05:00:01 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251524 fps=501 q=27.0 size= 3088490kB time=00:08:23.04 bitrate=50295.2kbits/s speed= 1x 05:00:01 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251524 fps=501 q=21.0 size= 3087476kB time=00:08:23.04 bitrate=50278.7kbits/s speed= 1x 05:00:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814768.656832, '127.0.0.1', 4003] 05:00:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814768.799712, '127.0.0.1', 4003] 05:00:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814769.031616, '127.0.0.1', 4003] 05:00:02 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251784 fps=501 q=26.0 size= 3092330kB time=00:08:23.56 bitrate=50305.8kbits/s speed= 1x 05:00:02 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=251784 fps=501 q=21.0 size= 3091572kB time=00:08:23.56 bitrate=50293.4kbits/s speed= 1x 05:00:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814769.197088, '127.0.0.1', 4003] 05:00:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814769.556096, '127.0.0.1', 4003] 05:00:03 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=252044 fps=501 q=27.0 size= 3096170kB time=00:08:24.08 bitrate=50316.3kbits/s speed= 1x 05:00:03 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4759:BONSAI: frame=252044 fps=501 q=21.0 size= 3095412kB time=00:08:24.08 bitrate=50303.9kbits/s speed= 1x 05:00:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 1814769.711616, '127.0.0.1', 4003] 05:00:03 PM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4282:trial stalled 5 minutes, user continued trials

11:07:57 AM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:172: RuntimeWarning: Mean of empty slice RewardedHistoryF[i+1-kernel_size]=np.nanmean(RewardedHistoryT[i+1-kernel_size:i+1]) 11:07:57 AM:INFO:Foraging:Foraging.py:_Save:line 2451:Saving current session, ForceSave=1 11:07:57 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1008:Loaded Water Calibration 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\446-7-A\739199\behavior_739199_2024-10-23_09-52-59 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 11:07:57 AM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 11:07:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 14417862.242976, '127.0.0.1', 4002] 11:07:59 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 14417862.245504, '127.0.0.1', 4002] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 14417863.226976, '127.0.0.1', 4002] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 14417863.22848, '127.0.0.1', 4002] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 14417863.229184, 4, '127.0.0.1'] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 14417863.4096, '127.0.0.1', 4003] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 14417863.408992, '127.0.0.1', 4002] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorLeft', '127.0.0.1', 4002] 11:08:00 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 14417863.81568, '127.0.0.1', 4003] 11:08:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 14417866.409984, '127.0.0.1', 4002] 11:08:03 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 14417866.411488, '127.0.0.1', 4002] 11:08:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 14417877.383648, '127.0.0.1', 4003] 11:08:14 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 14417877.577856, '127.0.0.1', 4003] 11:08:15 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 14417877.870464, '127.0.0.1', 4003] 11:13:11 AM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4295:trial stalled 5 minutes, user continued trials

03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364674.218976, '127.0.0.1', 4012] 03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364674.22048, '127.0.0.1', 4012] 03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364674.268992, '127.0.0.1', 4012] 03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364674.270496, '127.0.0.1', 4012] 03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364674.271104, 4, '127.0.0.1'] 03:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364675.268992, '127.0.0.1', 4012] 03:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:37:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364678.284992, '127.0.0.1', 4012] 03:37:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364678.287488, '127.0.0.1', 4012] 03:46:19 PM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4344:trial stalled 5 minutes, user continued trials

03:35:00 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile! 03:35:00 PM: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)] 03:35:00 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61 03:35:00 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8 03:35:00 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean 03:35:00 PM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes 03:35:00 PM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window 03:35:00 PM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window 03:35:00 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file 03:35:00 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_workflow_path), using default: 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings 03:35:00 PM: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 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (open_ephys_machine_ip_address), using default: 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\ 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\ 03:35:00 PM: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 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (AutomaticUpload), using default: True 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True 03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True 03:35:00 PM:ERROR:Foraging:Foraging.py:_LoadSchedule:line 1084:Could not find schedule at Z:\dynamic_foraging\DynamicForagingSchedule.csv 03:35:00 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:35:00 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_447-1-B_2024-11-05_09_08_01.json 03:35:00 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json 03:35:00 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json 03:35:00 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json 03:35:00 PM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface 03:35:00 PM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 447-1-B 03:35:00 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai 03:35:00 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC 03:35:01 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out 03:35:01 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai 03:35:01 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting 03:35:02 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC 03:35:03 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out 03:35:03 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC 03:35:04 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out 03:35:05 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC 03:35:05 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 1.5 seconds 03:35:05 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully 03:35:05 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims 03:35:06 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims 03:35:06 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_2.json 03:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes 03:35:06 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages 03:35:06 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 871:found 2 newscale stages 03:35:06 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 895:Found the newscale stage from the settings file 03:35:06 PM:INFO:Foraging:Foraging.py:_connect_stage:line 922:Successfully connected to newscale stage: 46112 03:35:06 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 743:Checking stage connection 03:35:06 PM:INFO:Foraging:Foraging.py:_GetPositions:line 755:Grabbing current stage position 03:35:07 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_447-1-B_2024-11-05_09_08_01.json 03:35:07 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 953:attempting to close bonsai connection 03:35:08 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 961:bonsai connection closed 03:35:08 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to restart bonsai 03:35:08 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai 03:35:08 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC 03:35:08 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1360:Connected to already running Bonsai 03:35:08 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1361:Bonsai started successfully 03:35:08 PM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete 03:35:09 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5290 03:35:10 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3860 03:35:10 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/ 03:35:10 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/ 03:35:11 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/ 03:35:11 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/ 03:35:11 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0 03:35:11 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2 03:35:11 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum 03:35:28 PM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.03 -> 0.047 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.03 -> 0.053 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.03 -> 0.047 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.03 -> 0.053 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: GiveWaterL, 0.03 -> 0.053 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: GiveWaterR, 0.03 -> 0.047 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: PositionZ, -> 4375.0 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: PositionY, -> 8326.5 03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: PositionX, -> 8054.0 03:35:30 PM:INFO:Foraging:Foraging.py:_Start:line 3846:Starting session, with experimenter: the ghost in the shell 03:35:30 PM:INFO:Foraging:Foraging.py:_set_default_project:line 3715:Setting Project name: Behavior Platform 03:35:30 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes 03:35:30 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes 03:35:30 PM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging 03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\metadata-dir 03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior 03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior\raw.harp 03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior-videos 03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\fib 03:35:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\behavior_data\\447-1-B\\0\\behavior_0_2024-11-08_15-35-30\\behavior\\raw.harp', '127.0.0.1', 4012] 03:35:30 PM:INFO:Foraging:Foraging.py:log_session:line 4159:Starting log file at C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior 03:35:30 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4176:starting trial loop 03:35:30 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 1 03:35:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364530.984, '127.0.0.1', 4012] 03:35:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364530.987488, '127.0.0.1', 4012] 03:35:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364532.818976, '127.0.0.1', 4012] 03:35:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364532.821504, '127.0.0.1', 4012] 03:35:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364533.634976, '127.0.0.1', 4012] 03:35:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364533.638496, '127.0.0.1', 4012] 03:35:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364533.638304, 4, '127.0.0.1'] 03:35:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364534.640992, '127.0.0.1', 4012] 03:35:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:35:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364535.734752, '127.0.0.1', 4013] 03:35:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364535.734784, '127.0.0.1', 4013] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364537.652, '127.0.0.1', 4012] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364537.654496, '127.0.0.1', 4012] 03:35:37 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 2 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364537.742976, '127.0.0.1', 4012] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364537.747488, '127.0.0.1', 4012] 03:35:37 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:35:37 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 415:No laser calibration file for session metadata 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.900256, '127.0.0.1', 4013] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.911136, '127.0.0.1', 4013] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.964096, '127.0.0.1', 4013] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.97088, '127.0.0.1', 4013] 03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.976992, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.130272, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.1376, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.148, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.15264, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.164224, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.193984, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.199168, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.200992, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.315968, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.323168, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.329024, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.333984, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.348544, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.353504, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.564288, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.5744, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.582496, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.584, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.586336, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.590976, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.775488, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.783424, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.785216, '127.0.0.1', 4013] 03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.832, '127.0.0.1', 4013] 03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.500096, '127.0.0.1', 4013] 03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.510368, '127.0.0.1', 4013] 03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364539.734976, '127.0.0.1', 4012] 03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364539.73648, '127.0.0.1', 4012] 03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.771264, '127.0.0.1', 4013] 03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.781728, '127.0.0.1', 4013] 03:35:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364541.768, '127.0.0.1', 4012] 03:35:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364541.770496, '127.0.0.1', 4012] 03:35:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364542.117984, '127.0.0.1', 4012] 03:35:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364542.12048, '127.0.0.1', 4012] 03:35:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364542.121216, 4, '127.0.0.1'] 03:35:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364543.117984, '127.0.0.1', 4012] 03:35:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364546.134976, '127.0.0.1', 4012] 03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364546.13648, '127.0.0.1', 4012] 03:35:46 PM:INFO:Foraging:Foraging.py:_generate_upload_manifest:line 4609:Skipping upload manifest, because this is the test mouse 03:35:46 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 3 03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364546.206976, '127.0.0.1', 4012] 03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364546.210496, '127.0.0.1', 4012] 03:35:46 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:35:46 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:35:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364548.852, '127.0.0.1', 4012] 03:35:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364548.853504, '127.0.0.1', 4012] 03:35:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364549.152, '127.0.0.1', 4012] 03:35:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364549.153504, '127.0.0.1', 4012] 03:35:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364549.154112, 4, '127.0.0.1'] 03:35:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364550.152, '127.0.0.1', 4012] 03:35:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364552.883648, '127.0.0.1', 4013] 03:35:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364553.168, '127.0.0.1', 4012] 03:35:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364553.170496, '127.0.0.1', 4012] 03:35:53 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 4 03:35:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364553.258976, '127.0.0.1', 4012] 03:35:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364553.262496, '127.0.0.1', 4012] 03:35:53 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:35:53 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:35:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:35:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364553.595904, '127.0.0.1', 4013] 03:35:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364553.676992, '127.0.0.1', 4013] 03:35:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364554.184, '127.0.0.1', 4013] 03:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364556.968, '127.0.0.1', 4012] 03:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364556.970496, '127.0.0.1', 4012] 03:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364557.017984, '127.0.0.1', 4012] 03:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364557.02048, '127.0.0.1', 4012] 03:35:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364557.021408, 4, '127.0.0.1'] 03:35:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364558.017984, '127.0.0.1', 4012] 03:35:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364561.034976, '127.0.0.1', 4012] 03:36:00 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364561.03648, '127.0.0.1', 4012] 03:36:01 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 5 03:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364561.108, '127.0.0.1', 4012] 03:36:01 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364561.111488, '127.0.0.1', 4012] 03:36:01 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:36:01 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:36:01 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364564.901984, '127.0.0.1', 4012] 03:36:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364564.903488, '127.0.0.1', 4012] 03:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364565.401984, '127.0.0.1', 4012] 03:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364565.403488, '127.0.0.1', 4012] 03:36:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364565.404352, 4, '127.0.0.1'] 03:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364566.401984, '127.0.0.1', 4012] 03:36:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:36:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364568.511968, '127.0.0.1', 4013] 03:36:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364568.512, '127.0.0.1', 4013] 03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364569.417984, '127.0.0.1', 4012] 03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364569.42048, '127.0.0.1', 4012] 03:36:09 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 6 03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364569.468, '127.0.0.1', 4012] 03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364569.471488, '127.0.0.1', 4012] 03:36:09 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:36:09 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:36:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364569.921856, '127.0.0.1', 4013] 03:36:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364569.929984, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364570.46832, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364570.973952, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364570.983392, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364570.988992, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364570.993472, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364570.997088, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364571.000512, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364571.01056, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364571.022816, '127.0.0.1', 4013] 03:36:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364571.032128, '127.0.0.1', 4013] 03:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364572.217984, '127.0.0.1', 4012] 03:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364572.22048, '127.0.0.1', 4012] 03:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364572.434976, '127.0.0.1', 4012] 03:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364572.43648, '127.0.0.1', 4012] 03:36:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364572.437248, 4, '127.0.0.1'] 03:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364573.434976, '127.0.0.1', 4012] 03:36:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.842528, '127.0.0.1', 4013] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.849984, '127.0.0.1', 4013] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.856864, '127.0.0.1', 4013] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.92096, '127.0.0.1', 4013] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.922112, '127.0.0.1', 4013] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.924, '127.0.0.1', 4013] 03:36:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364574.928, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.351872, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.441152, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.754848, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.756352, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.776992, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.778976, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.814976, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.816992, '127.0.0.1', 4013] 03:36:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364575.822848, '127.0.0.1', 4013] 03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364576.452, '127.0.0.1', 4012] 03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364576.453504, '127.0.0.1', 4012] 03:36:16 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 7 03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364576.521984, '127.0.0.1', 4012] 03:36:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364576.525504, '127.0.0.1', 4012] 03:36:16 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:36:16 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:36:16 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.324832, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.334976, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.354976, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.35968, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.362976, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.430976, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.436, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.573792, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.583904, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364579.612896, '127.0.0.1', 4013] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364579.617984, '127.0.0.1', 4012] 03:36:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364579.62048, '127.0.0.1', 4012] 03:36:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364580.534976, '127.0.0.1', 4012] 03:36:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364580.537216, 4, '127.0.0.1'] 03:36:20 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364580.53648, '127.0.0.1', 4012] 03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364581.534976, '127.0.0.1', 4012] 03:36:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364584.552, '127.0.0.1', 4012] 03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364584.553504, '127.0.0.1', 4012] 03:36:24 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 8 03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364584.632992, '127.0.0.1', 4012] 03:36:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364584.63648, '127.0.0.1', 4012] 03:36:24 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:36:24 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:36:24 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:36:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364585.701984, '127.0.0.1', 4012] 03:36:25 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364585.703488, '127.0.0.1', 4012] 03:36:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364586.217984, '127.0.0.1', 4012] 03:36:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364586.22048, '127.0.0.1', 4012] 03:36:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364586.221152, 4, '127.0.0.1'] 03:36:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364587.217984, '127.0.0.1', 4012] 03:36:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364590.234976, '127.0.0.1', 4012] 03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364590.23648, '127.0.0.1', 4012] 03:36:30 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 9 03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364590.274976, '127.0.0.1', 4012] 03:36:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364590.278496, '127.0.0.1', 4012] 03:36:30 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:36:30 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected! 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected! 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True 03:36:30 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True 03:36:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364595.152, '127.0.0.1', 4012] 03:36:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364595.153504, '127.0.0.1', 4012] 03:36:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364596.134976, '127.0.0.1', 4012] 03:36:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364596.137408, 4, '127.0.0.1'] 03:36:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364596.137504, '127.0.0.1', 4012] 03:36:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364597.134976, '127.0.0.1', 4012] 03:36:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012] 03:36:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364600.152, '127.0.0.1', 4012] 03:36:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364600.153504, '127.0.0.1', 4012] 03:36:40 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 10 03:36:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364600.221984, '127.0.0.1', 4012] 03:36:40 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364600.225504, '127.0.0.1', 4012] 03:36:40 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1 03:36:40 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration 03:36:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30 03:36:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields 03:36:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found! 03:36:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected! 03:36:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected! 03:36:40 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!

This issue reoccurred:

file: Foraging.py
function: _StartTrialLoop
line 4344
logfile: W10DT714033/W10DT714033-B_gui_log_2024-11-08_15-35-00.txt
boxes: 1B
count: 1
text: trial stalled 5 minutes, user continued trials

GUI Log snippet (click for full log)

03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364674.218976, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364674.22048, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364674.268992, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364674.270496, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364674.271104, 4, '127.0.0.1']
03:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364675.268992, '127.0.0.1', 4012]
03:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364678.284992, '127.0.0.1', 4012]
03:37:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364678.287488, '127.0.0.1', 4012]
03:46:19 PM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4344:trial stalled 5 minutes, user continued trials

Full GUI log (first 200 and last 200 lines)

03:35:00 PM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4707:Starting logfile!
03:35:00 PM: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)]
03:35:00 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4735:Current git commit branch, hash: main, 4f4f59556389b4696a28bcbed810dec00816cf61
03:35:00 PM:INFO:Foraging:Foraging.py:log_git_hash:line 4739:Current foraging_gui version: 1.6.8
03:35:00 PM:WARNING:Foraging:Foraging.py:log_git_hash:line 4749:local repository is clean
03:35:00 PM:INFO:Foraging:Foraging.py:<module>:line 4850:Setting QApplication attributes
03:35:00 PM:INFO:Foraging:Foraging.py:<module>:line 4858:Starting QApplication and Window
03:35:00 PM:INFO:Foraging:Foraging.py:__init__:line 66:Creating Window
03:35:00 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1156:Loaded settings_box file
03:35:00 PM:INFO:Foraging:Foraging.py:_GetSettings:line 1184:Loaded settings file
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_workflow_path), using default: 
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings
03:35:00 PM: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
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (open_ephys_machine_ip_address), using default: 
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\
03:35:00 PM: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
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box1), using default: 5000
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box2), using default: 5000
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box3), using default: 5000
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (lick_spout_distance_box4), using default: 5000
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (save_each_trial), using default: True
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (AutomaticUpload), using default: True
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (auto_engage), using default: True
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (clear_figure_after_save), using default: True
03:35:00 PM:WARNING:Foraging:Foraging.py:_GetSettings:line 1194:Missing setting (add_default_project_name), using default: True
03:35:00 PM:ERROR:Foraging:Foraging.py:_LoadSchedule:line 1084:Could not find schedule at Z:\dynamic_foraging\DynamicForagingSchedule.csv
03:35:00 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:35:00 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_447-1-B_2024-11-05_09_08_01.json
03:35:00 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json
03:35:00 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json
03:35:00 PM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json
03:35:00 PM:INFO:Foraging:Foraging.py:_LoadUI:line 259:Using ForagingGUI.ui interface
03:35:00 PM:INFO:Foraging:Foraging.py:__init__:line 107:Setting Window title: 447-1-B
03:35:00 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
03:35:00 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
03:35:01 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1357:Could not connect: timed out
03:35:01 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1368:Starting Bonsai
03:35:01 PM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4822:BONSAI logging starting
03:35:02 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
03:35:03 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 0.5 seconds: timed out
03:35:03 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
03:35:04 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1382:Could not connect, total waiting time 1.0 seconds: timed out
03:35:05 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
03:35:05 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1385:Connected to Bonsai after 1.5 seconds
03:35:05 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1386:Bonsai started successfully
03:35:05 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1263:Attempting to connect to Slims
03:35:06 PM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1280:Successfully connected to Slims
03:35:06 PM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 509:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_2.json
03:35:06 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
03:35:06 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 857:Scanning for newscale stages
03:35:06 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 871:found 2 newscale stages
03:35:06 PM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 895:Found the newscale stage from the settings file
03:35:06 PM:INFO:Foraging:Foraging.py:_connect_stage:line 922:Successfully connected to newscale stage: 46112
03:35:06 PM:INFO:Foraging:Foraging.py:_CheckStageConnection:line 743:Checking stage connection
03:35:06 PM:INFO:Foraging:Foraging.py:_GetPositions:line 755:Grabbing current stage position
03:35:07 PM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1525:Found existing rig.json: rig_447-1-B_2024-11-05_09_08_01.json
03:35:07 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 953:attempting to close bonsai connection
03:35:08 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 961:bonsai connection closed
03:35:08 PM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to restart bonsai
03:35:08 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1353:Trying to connect to already running Bonsai
03:35:08 PM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1406:connecting to GUI and Bonsai through OSC
03:35:08 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1360:Connected to already running Bonsai
03:35:08 PM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1361:Bonsai started successfully
03:35:08 PM:INFO:Foraging:Foraging.py:__init__:line 203:Start up complete
03:35:09 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_nwb_bonsai_processed/df_sessions.pkl, len(df) = 5290
03:35:10 PM:INFO:aws_util:aws_util.py:import_df_from_s3:line 115:Dataframe imported from s3://aind-behavior-data/foraging_auto_training/df_manager_447_demo.pkl, len(df) = 3860
03:35:10 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
03:35:10 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/
03:35:11 PM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
03:35:11 PM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 29 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/
03:35:11 PM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2397:No entry found in df_training_manager for subject_id: 0
03:35:11 PM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2745:Override stage clicked: state=2
03:35:11 PM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2771:Current stage to apply: unknown training stage @unknown curriculum
03:35:28 PM:INFO:Foraging:Foraging.py:_Start:line 3780:Start button pressed: starting trial loop
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.03 -> 0.047
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.03 -> 0.053
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: RightValue, 0.03 -> 0.047
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: LeftValue, 0.03 -> 0.053
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: GiveWaterL, 0.03 -> 0.053
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: GiveWaterR, 0.03 -> 0.047
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: PositionZ,  -> 4375.0
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: PositionY,  -> 8326.5
03:35:29 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1939:Changing parameter: PositionX,  -> 8054.0
03:35:30 PM:INFO:Foraging:Foraging.py:_Start:line 3846:Starting session, with experimenter: the ghost in the shell
03:35:30 PM:INFO:Foraging:Foraging.py:_set_default_project:line 3715:Setting Project name: Behavior Platform
03:35:30 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
03:35:30 PM:INFO:Foraging:Foraging.py:keyPressEvent:line 1880:processing parameter changes
03:35:30 PM:INFO:Foraging:Foraging.py:_restartlogging:line 979:Restarting logging
03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2760:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2763:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\metadata-dir
03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2766:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior
03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2769:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior\raw.harp
03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2772:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior-videos
03:35:30 PM:INFO:Foraging:Foraging.py:_GetSaveFolder:line 2775:Created new folder: C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\fib
03:35:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/loggerstarted', 'C:\\behavior_data\\447-1-B\\0\\behavior_0_2024-11-08_15-35-30\\behavior\\raw.harp', '127.0.0.1', 4012]
03:35:30 PM:INFO:Foraging:Foraging.py:log_session:line 4159:Starting log file at C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30\behavior
03:35:30 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4176:starting trial loop
03:35:30 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 1
03:35:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364530.984, '127.0.0.1', 4012]
03:35:30 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364530.987488, '127.0.0.1', 4012]
03:35:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364532.818976, '127.0.0.1', 4012]
03:35:32 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364532.821504, '127.0.0.1', 4012]
03:35:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364533.634976, '127.0.0.1', 4012]
03:35:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364533.638496, '127.0.0.1', 4012]
03:35:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364533.638304, 4, '127.0.0.1']
03:35:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364534.640992, '127.0.0.1', 4012]
03:35:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:35:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364535.734752, '127.0.0.1', 4013]
03:35:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364535.734784, '127.0.0.1', 4013]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364537.652, '127.0.0.1', 4012]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364537.654496, '127.0.0.1', 4012]
03:35:37 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 2
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364537.742976, '127.0.0.1', 4012]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364537.747488, '127.0.0.1', 4012]
03:35:37 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:35:37 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 415:No laser calibration file for session metadata
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:35:37 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.900256, '127.0.0.1', 4013]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.911136, '127.0.0.1', 4013]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.964096, '127.0.0.1', 4013]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.97088, '127.0.0.1', 4013]
03:35:37 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364537.976992, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.130272, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.1376, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.148, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.15264, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.164224, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.193984, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.199168, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.200992, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.315968, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.323168, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.329024, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.333984, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.348544, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.353504, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.564288, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.5744, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.582496, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.584, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.586336, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.590976, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.775488, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.783424, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.785216, '127.0.0.1', 4013]
03:35:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364538.832, '127.0.0.1', 4013]
03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.500096, '127.0.0.1', 4013]
03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.510368, '127.0.0.1', 4013]
03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364539.734976, '127.0.0.1', 4012]
03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364539.73648, '127.0.0.1', 4012]
03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.771264, '127.0.0.1', 4013]
03:35:39 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 26364539.781728, '127.0.0.1', 4013]
03:35:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364541.768, '127.0.0.1', 4012]
03:35:41 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364541.770496, '127.0.0.1', 4012]
03:35:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364542.117984, '127.0.0.1', 4012]
03:35:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364542.12048, '127.0.0.1', 4012]
03:35:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364542.121216, 4, '127.0.0.1']
03:35:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364543.117984, '127.0.0.1', 4012]
03:35:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364546.134976, '127.0.0.1', 4012]
03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364546.13648, '127.0.0.1', 4012]
03:35:46 PM:INFO:Foraging:Foraging.py:_generate_upload_manifest:line 4609:Skipping upload manifest, because this is the test mouse
03:35:46 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 3
03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364546.206976, '127.0.0.1', 4012]
03:35:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364546.210496, '127.0.0.1', 4012]
03:35:46 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:35:46 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:35:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:35:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364548.852, '127.0.0.1', 4012]
03:35:48 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364548.853504, '127.0.0.1', 4012]
03:35:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364549.152, '127.0.0.1', 4012]
03:35:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364549.153504, '127.0.0.1', 4012]
03:35:49 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364549.154112, 4, '127.0.0.1']
03:35:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364550.152, '127.0.0.1', 4012]
03:35:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:35:52 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 26364552.883648, '127.0.0.1', 4013]
_____SKIPPING_____
03:36:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364610.152, '127.0.0.1', 4012]
03:36:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364610.153504, '127.0.0.1', 4012]
03:36:50 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364610.154304, 4, '127.0.0.1']
03:36:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364611.152, '127.0.0.1', 4012]
03:36:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:36:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364614.168, '127.0.0.1', 4012]
03:36:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364614.170496, '127.0.0.1', 4012]
03:36:54 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 12
03:36:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364614.241984, '127.0.0.1', 4012]
03:36:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364614.245504, '127.0.0.1', 4012]
03:36:54 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:36:54 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:36:54 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:36:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364618.284992, '127.0.0.1', 4012]
03:36:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364618.286496, '127.0.0.1', 4012]
03:36:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364618.834976, '127.0.0.1', 4012]
03:36:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364618.837504, '127.0.0.1', 4012]
03:36:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364618.838208, 4, '127.0.0.1']
03:36:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364619.834976, '127.0.0.1', 4012]
03:36:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364622.852, '127.0.0.1', 4012]
03:37:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364622.853504, '127.0.0.1', 4012]
03:37:02 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 13
03:37:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364622.922976, '127.0.0.1', 4012]
03:37:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364622.926496, '127.0.0.1', 4012]
03:37:02 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:02 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:02 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364624.452, '127.0.0.1', 4012]
03:37:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364624.453504, '127.0.0.1', 4012]
03:37:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364625.434976, '127.0.0.1', 4012]
03:37:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364625.437504, '127.0.0.1', 4012]
03:37:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364625.438176, 4, '127.0.0.1']
03:37:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364626.434976, '127.0.0.1', 4012]
03:37:06 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364629.452, '127.0.0.1', 4012]
03:37:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364629.453504, '127.0.0.1', 4012]
03:37:09 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 14
03:37:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364629.521984, '127.0.0.1', 4012]
03:37:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364629.525504, '127.0.0.1', 4012]
03:37:09 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:09 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364634.834976, '127.0.0.1', 4012]
03:37:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364634.837504, '127.0.0.1', 4012]
03:37:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364635.818976, '127.0.0.1', 4012]
03:37:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364635.82048, '127.0.0.1', 4012]
03:37:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364635.821408, 4, '127.0.0.1']
03:37:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364636.818976, '127.0.0.1', 4012]
03:37:16 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364639.834976, '127.0.0.1', 4012]
03:37:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364639.837504, '127.0.0.1', 4012]
03:37:19 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 15
03:37:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364639.921984, '127.0.0.1', 4012]
03:37:19 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364639.925504, '127.0.0.1', 4012]
03:37:19 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:19 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:19 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364641.218976, '127.0.0.1', 4012]
03:37:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364641.22048, '127.0.0.1', 4012]
03:37:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364642.201984, '127.0.0.1', 4012]
03:37:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364642.203488, '127.0.0.1', 4012]
03:37:22 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364642.204384, 4, '127.0.0.1']
03:37:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364643.201984, '127.0.0.1', 4012]
03:37:23 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364646.218976, '127.0.0.1', 4012]
03:37:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364646.22048, '127.0.0.1', 4012]
03:37:26 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 16
03:37:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364646.304, '127.0.0.1', 4012]
03:37:26 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364646.30848, '127.0.0.1', 4012]
03:37:26 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:26 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:26 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364647.368992, '127.0.0.1', 4012]
03:37:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364647.370496, '127.0.0.1', 4012]
03:37:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364647.434976, '127.0.0.1', 4012]
03:37:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364647.437504, '127.0.0.1', 4012]
03:37:27 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364647.438304, 4, '127.0.0.1']
03:37:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364648.434976, '127.0.0.1', 4012]
03:37:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364651.452, '127.0.0.1', 4012]
03:37:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364651.453504, '127.0.0.1', 4012]
03:37:31 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 17
03:37:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364651.521984, '127.0.0.1', 4012]
03:37:31 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364651.525504, '127.0.0.1', 4012]
03:37:31 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:31 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:31 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364653.584992, '127.0.0.1', 4012]
03:37:33 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364653.587488, '127.0.0.1', 4012]
03:37:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364654.568992, '127.0.0.1', 4012]
03:37:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364654.570496, '127.0.0.1', 4012]
03:37:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364654.571264, 4, '127.0.0.1']
03:37:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364655.568992, '127.0.0.1', 4012]
03:37:35 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364658.584992, '127.0.0.1', 4012]
03:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364658.587488, '127.0.0.1', 4012]
03:37:38 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 18
03:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364658.668992, '127.0.0.1', 4012]
03:37:38 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364658.67248, '127.0.0.1', 4012]
03:37:38 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:38 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:38 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364662.084992, '127.0.0.1', 4012]
03:37:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364662.087488, '127.0.0.1', 4012]
03:37:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364662.118976, '127.0.0.1', 4012]
03:37:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364662.12048, '127.0.0.1', 4012]
03:37:42 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364662.121216, 4, '127.0.0.1']
03:37:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364663.118976, '127.0.0.1', 4012]
03:37:43 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364666.134976, '127.0.0.1', 4012]
03:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364666.137504, '127.0.0.1', 4012]
03:37:46 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4204:Current trial: 19
03:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 26364666.205984, '127.0.0.1', 4012]
03:37:46 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 26364666.210496, '127.0.0.1', 4012]
03:37:46 PM:INFO:Foraging:Foraging.py:_Save:line 2452:Saving current session, ForceSave=1
03:37:46 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1046:Loaded Water Calibration
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 90:processing:C:\behavior_data\447-1-B\0\behavior_0_2024-11-08_15-35-30
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 398:Cannot log reward delivery in session metadata - missing fields
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1235:No reward delivery metadata found!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1070:No opto calibration results detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 908:No ephys data stream detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 627:No photometry data stream detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 605:No camera data stream detected!
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 117:Session metadata generated successfully: True
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 118:Rig metadata generated successfully: True
03:37:46 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 119:Data description generated successfully: True
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 26364674.218976, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364674.22048, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 26364674.268992, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364674.270496, '127.0.0.1', 4012]
03:37:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 26364674.271104, 4, '127.0.0.1']
03:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 26364675.268992, '127.0.0.1', 4012]
03:37:55 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'NoResponse', '127.0.0.1', 4012]
03:37:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 26364678.284992, '127.0.0.1', 4012]
03:37:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 26364678.287488, '127.0.0.1', 4012]
03:46:19 PM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4344:trial stalled 5 minutes, user continued trials

12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.351744, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.476448, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.548224, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.553824, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.691424, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731129.742112, '127.0.0.1', 4023] 12:31:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731133.249888, '127.0.0.1', 4023] 12:31:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731133.734496, '127.0.0.1', 4023] 12:31:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731133.875456, '127.0.0.1', 4023] 12:31:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731140.024736, '127.0.0.1', 4023] 12:31:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731140.1976, '127.0.0.1', 4023] 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 6.00%. 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 9.73%. 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 7.73%. 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 1.72%. 12:32:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731203.06336, '127.0.0.1', 4023] 12:32:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731203.063424, '127.0.0.1', 4023] 12:32:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731207.529856, '127.0.0.1', 4023] 12:32:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731207.529856, '127.0.0.1', 4023] 12:32:51 PM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4302:trial stalled 5 minutes, user continued trials

10:55:54 AM:INFO:Foraging:Foraging.py:start_gui_log_file:line 4679:Starting logfile! 10:55:54 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4690:Python version: 3.11.9 | packaged by Anaconda, Inc. | (main, Apr 19 2024, 16:40:41) [MSC v.1916 64 bit (AMD64)] 10:55:54 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4707:Current git commit branch, hash: main, 60f8beb5cf259b096e71331217b2a631d1eaeb43 10:55:54 AM:INFO:Foraging:Foraging.py:log_git_hash:line 4711:Current foraging_gui version: 1.6.9 10:55:54 AM:WARNING:Foraging:Foraging.py:log_git_hash:line 4721:local repository is clean 10:55:54 AM:INFO:Foraging:Foraging.py:<module>:line 4822:Setting QApplication attributes 10:55:54 AM:INFO:Foraging:Foraging.py:<module>:line 4830:Starting QApplication and Window 10:55:54 AM:INFO:Foraging:Foraging.py:__init__:line 69:Creating Window 10:55:54 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1166:Loaded settings_box file 10:55:54 AM:INFO:Foraging:Foraging.py:_GetSettings:line 1194:Loaded settings file 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_workflow_path), using default: 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (FIP_settings), using default: C:\Users\svc_aind_behavior\Documents\FIPSettings 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (bonsai_config_path), using default: C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\bonsai\Bonsai.config 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (metadata_dialog_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\metadata_dialog\ 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (rig_metadata_folder), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\rig_metadata\ 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (project_info_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\Project Name and Funding Source v2.csv 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (schedule_path), using default: Z:\dynamic_foraging\DynamicForagingSchedule.csv 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box1), using default: 60 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box2), using default: 60 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (go_cue_decibel_box4), using default: 60 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box1), using default: 5000 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box2), using default: 5000 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box3), using default: 5000 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (lick_spout_distance_box4), using default: 5000 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (name_mapper_file), using default: C:\Users\svc_aind_behavior\Documents\ForagingSettings\name_mapper.json 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (create_rig_metadata), using default: True 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (save_each_trial), using default: True 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (AutomaticUpload), using default: True 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (manifest_flag_dir), using default: C:\Users\svc_aind_behavior\Documents\aind_watchdog_service\manifest 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (auto_engage), using default: True 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (clear_figure_after_save), using default: True 10:55:54 AM:WARNING:Foraging:Foraging.py:_GetSettings:line 1204:Missing setting (add_default_project_name), using default: True 10:55:54 AM:INFO:Foraging:Foraging.py:_LoadSchedule:line 1092:Loaded behavior schedule 10:55:54 AM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration 10:55:54 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-C_2024-11-12_13_28_18.json 10:55:54 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 60:building rig json 10:55:54 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json_core:line 624:finished building rig json 10:55:54 AM:INFO:RigJsonBuilder:RigJsonBuilder.py:build_rig_json:line 53:Using existing rig json 10:55:54 AM:INFO:Foraging:Foraging.py:_LoadUI:line 275:Using ForagingGUI.ui interface 10:55:54 AM:INFO:Foraging:Foraging.py:__init__:line 119:Setting Window title: 446-7-C 10:55:54 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai 10:55:54 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC 10:55:55 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1367:Could not connect: timed out 10:55:55 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1376:Starting Bonsai 10:55:55 AM:INFO:Foraging:Foraging.py:log_subprocess_output:line 4794:BONSAI logging starting 10:55:55 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC 10:55:56 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 0.5 seconds: timed out 10:55:57 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC 10:55:58 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1390:Could not connect, total waiting time 1.0 seconds: timed out 10:55:59 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC 10:55:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1393:Connected to Bonsai after 1.5 seconds 10:55:59 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1394:Bonsai started successfully 10:55:59 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1273:Attempting to connect to Slims 10:56:00 AM:INFO:Foraging:Foraging.py:_ConnectSlims:line 1290:Successfully connected to Slims 10:56:00 AM:WARNING:Dialogs:Dialogs.py:_LoadCalibrationParameters:line 507:could not find water calibration parameters: C:\Users\svc_aind_behavior\Documents\ForagingSettings\WaterCalibrationPar_3.json 10:56:00 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes 10:56:00 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 867:Scanning for newscale stages 10:56:00 AM:INFO:Foraging:Foraging.py:_InitializeMotorStage:line 877:Could not find any instances of NewScale Stage 10:56:00 AM:INFO:Foraging:Foraging.py:_insert_stage_widget:line 255:Inserting Stage Widget 10:56:00 AM:INFO:connection:connection.py:_connect:line 688:Connecting to aibspi(10.128.108.106):2181, use_ssl: False 10:56:00 AM:INFO:client:client.py:_session_callback:line 561:Zookeeper connection established, state: CONNECTED 10:56:00 AM:INFO:connection:connection.py:_connect_attempt:line 655:Closing connection to aibspi:2181 10:56:00 AM:INFO:client:client.py:_session_callback:line 567:Zookeeper session closed, state: CLOSED 10:56:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:__init__:line 68:Connected to COM6, device id: 1130 10:56:01 AM:INFO:stepper_motor_device:stepper_motor_device.py:load_registers:line 149:Getting available registers on device 10:56:01 AM:INFO:stage_model:stage_model.py:configure_device:line 81:Configuring registers with default values (can be modified in config file) 10:56:01 AM:INFO:move_worker:move_worker.py:goto_origin:line 194:(move to origin): Moving stage to origin 10:56:01 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, -27200, -27200, 0] 10:56:03 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [-27200, 0, 0, 0] 10:56:10 AM:INFO:move_worker:move_worker.py:move_relative:line 336:(move relative): Moved motors by steps specified in [0, 0, 0, -27200] 10:56:13 AM:INFO:stage_model:stage_model.py:configure_device:line 87:Zeroed all motor positions 10:56:13 AM:INFO:stage_model:stage_model.py:configure_device:line 88:Finished configuring stepper motor device ############################################################# 10:56:13 AM:INFO:Foraging:Foraging.py:_load_most_recent_rig_json:line 1526:Found existing rig.json: rig_446-7-C_2024-11-12_13_28_18.json 10:56:13 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 963:attempting to close bonsai connection 10:56:15 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 971:bonsai connection closed 10:56:15 AM:INFO:Foraging:Foraging.py:_ReconnectBonsai:line 973:attempting to restart bonsai 10:56:15 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1363:Trying to connect to already running Bonsai 10:56:15 AM:INFO:Foraging:Foraging.py:_ConnectOSC:line 1410:connecting to GUI and Bonsai through OSC 10:56:15 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1370:Connected to already running Bonsai 10:56:15 AM:INFO:Foraging:Foraging.py:_InitializeBonsai:line 1371:Bonsai started successfully 10:56:15 AM:INFO:Foraging:Foraging.py:__init__:line 219:Start up complete 10:56:16 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) = 5403 10:56:17 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) = 3963 10:56:18 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/ 10:56:18 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/capsule/scratch/saved_curriculums/ 10:56:18 AM:INFO:aws_util:aws_util.py:download_dir_from_s3:line 140:134 objects downloaded from s3://aind-behavior-data/foraging_auto_training/saved_curriculums/ to C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/ 10:56:18 AM:INFO:curriculum_manager:curriculum_manager.py:download_curriculums:line 162:Found 26 curriculums in C:\Users\svc_aind_behavior/.aind_auto_train/curriculum_manager/ 10:56:18 AM:INFO:Dialogs:Dialogs.py:update_auto_train_fields:line 2386:No entry found in df_training_manager for subject_id: 0 10:56:18 AM:INFO:Dialogs:Dialogs.py:_override_curriculum_clicked:line 2734:Override stage clicked: state=2 10:56:18 AM:INFO:Dialogs:Dialogs.py:_update_stage_to_apply:line 2760:Current stage to apply: unknown training stage @unknown curriculum 10:57:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725480.568, '127.0.0.1', 4023] 10:57:01 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725480.57248, '127.0.0.1', 4023] 10:57:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725480.902976, '127.0.0.1', 4023] 10:57:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725480.907488, '127.0.0.1', 4023] 10:57:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725490.558976, '127.0.0.1', 4023] 10:57:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725490.558976, '127.0.0.1', 4023] 10:57:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725490.562496, '127.0.0.1', 4023] 10:57:11 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725490.563488, '127.0.0.1', 4023] 10:57:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725490.888992, '127.0.0.1', 4023] 10:57:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725490.889984, '127.0.0.1', 4023] 10:57:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725490.89248, '127.0.0.1', 4023] 10:57:12 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725490.893504, '127.0.0.1', 4023] 10:57:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725500.556, '127.0.0.1', 4023] 10:57:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725500.556, '127.0.0.1', 4023] 10:57:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725500.558496, '127.0.0.1', 4023] 10:57:21 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725500.559488, '127.0.0.1', 4023] 10:57:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725500.885984, '127.0.0.1', 4023] 10:57:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725500.885984, '127.0.0.1', 4023] 10:57:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725500.88848, '127.0.0.1', 4023] 10:57:22 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725500.889504, '127.0.0.1', 4023] 10:57:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725510.556992, '127.0.0.1', 4023] 10:57:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725510.557984, '127.0.0.1', 4023] 10:57:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725510.56048, '127.0.0.1', 4023] 10:57:31 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725510.561504, '127.0.0.1', 4023] 10:57:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725510.886976, '127.0.0.1', 4023] 10:57:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725510.888992, '127.0.0.1', 4023] 10:57:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725510.890496, '127.0.0.1', 4023] 10:57:32 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725510.891488, '127.0.0.1', 4023] 10:57:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725520.556, '127.0.0.1', 4023] 10:57:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725520.556, '127.0.0.1', 4023] 10:57:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725520.559488, '127.0.0.1', 4023] 10:57:41 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725520.56048, '127.0.0.1', 4023] 10:57:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725520.884992, '127.0.0.1', 4023] 10:57:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725520.886976, '127.0.0.1', 4023] 10:57:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725520.88848, '127.0.0.1', 4023] 10:57:42 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725520.889504, '127.0.0.1', 4023] 10:57:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725530.556, '127.0.0.1', 4023] 10:57:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725530.556992, '127.0.0.1', 4023] 10:57:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725530.558496, '127.0.0.1', 4023] 10:57:51 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725530.559488, '127.0.0.1', 4023] 10:57:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725530.884992, '127.0.0.1', 4023] 10:57:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725530.886976, '127.0.0.1', 4023] 10:57:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725530.88848, '127.0.0.1', 4023] 10:57:52 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725530.889504, '127.0.0.1', 4023] 10:57:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualLeftWaterStartTime', 11725535.556992, '127.0.0.1', 4023] 10:57:56 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftRewardDeliveryTimeHarp', 11725535.559488, '127.0.0.1', 4023] 10:58:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725540.888992, '127.0.0.1', 4023] 10:58:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ManualRightWaterStartTime', 11725540.889984, '127.0.0.1', 4023] 10:58:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725540.89248, '127.0.0.1', 4023] 10:58:02 AM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11725540.893504, '127.0.0.1', 4023] 10:58:03 AM:INFO:Foraging:Foraging.py:_StopCurrentSession:line 3599:Stopping current trials 10:58:08 AM:INFO:Foraging:Foraging.py:_Open:line 2966:Quick load success: C:\behavior_data\446-7-C\749622\behavior_749622_2024-11-13_11-16-40\behavior\749622_2024-11-13_11-16-40.json 10:58:08 AM:INFO:Foraging:Foraging.py:_NewSession:line 3509:New Session pressed 10:58:08 AM:INFO:Foraging:Foraging.py:_NewSession:line 3541:Resetting session run flag 10:58:08 AM:INFO:Foraging:Foraging.py:_NewSession:line 3579:New Session complete 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 30.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 7.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 5.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ID, 0.0 -> 749622.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayBeta, 1.0 -> 0.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: DelayMax, 1.0 -> 0.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMax, 60.0 -> 30.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardDelay, 0.0 -> 0.1 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIMax, 8.0 -> 7.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ITIBeta, 2.0 -> 3.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: ResponseTime, 1.0 -> 5.0 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.03 -> 0.041 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.03 -> 0.035 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterL, 0.03 -> 0.035 10:58:08 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: GiveWaterR, 0.03 -> 0.041 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes 10:58:09 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:58:09 AM:INFO:Foraging:Foraging.py:_check_drop_frames:line 674: 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1881:processing parameter changes 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 5.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMin, 20.0 -> 10.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 20000.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardFamily, 1.0 -> 3.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.027 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Unrewarded, 200.0 -> 5.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue_volume, 3.0 -> 2.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: warm_min_trial, 60.0 -> 50.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Ignored, 100.0 -> 5.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockBeta, 20.0 -> 10.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: BlockMin, 20.0 -> 10.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: StopIgnores, 20.0 -> 20000.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: MaxTime, 120.0 -> 75.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardConsumeTime, 3.0 -> 1.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: Multiplier, 0.8 -> 0.5 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RewardFamily, 1.0 -> 3.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue_volume, 3.0 -> 2.0 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: RightValue, 0.041 -> 0.027 10:58:09 AM:INFO:Foraging:Foraging.py:keyPressEvent:line 1940:Changing parameter: LeftValue, 0.035 -> 0.023 _____SKIPPING_____ 12:26:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True 12:26:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:26:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:26:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:26:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:26:53 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:26:53 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730872.717216, '127.0.0.1', 4023] 12:26:54 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730872.885696, '127.0.0.1', 4023] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11730876.34, '127.0.0.1', 4022] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730876.34448, '127.0.0.1', 4022] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11730876.590976, '127.0.0.1', 4022] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11730876.594112, 4, '127.0.0.1'] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730876.594496, '127.0.0.1', 4022] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730876.725984, '127.0.0.1', 4023] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11730876.724992, '127.0.0.1', 4022] 12:26:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'ErrorRight', '127.0.0.1', 4022] 12:26:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730876.87696, '127.0.0.1', 4023] 12:26:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730877.05424, '127.0.0.1', 4023] 12:26:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730877.202688, '127.0.0.1', 4023] 12:26:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11730877.724992, '127.0.0.1', 4022] 12:26:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730877.727488, '127.0.0.1', 4022] 12:26:58 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191: 12:26:58 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 743 12:26:58 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11730877.752, '127.0.0.1', 4022] 12:26:59 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11730877.754496, '127.0.0.1', 4022] 12:26:59 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1]) 12:26:59 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1 12:26:59 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\749622\behavior_749622_2024-11-14_11-12-10 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:26:59 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:27:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730881.183072, '127.0.0.1', 4023] 12:27:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730881.516128, '127.0.0.1', 4023] 12:27:02 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730881.667008, '127.0.0.1', 4023] 12:27:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11730882.540992, '127.0.0.1', 4022] 12:27:03 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730882.54448, '127.0.0.1', 4022] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11730882.790976, '127.0.0.1', 4022] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730882.794496, '127.0.0.1', 4022] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11730882.795168, 4, '127.0.0.1'] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730882.961088, '127.0.0.1', 4023] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11730882.960992, '127.0.0.1', 4022] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 11730882.960992, '127.0.0.1', 4023] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 11730883.074976, '127.0.0.1', 4023] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11730883.077504, '127.0.0.1', 4023] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730883.193504, '127.0.0.1', 4023] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730883.350528, '127.0.0.1', 4023] 12:27:04 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730883.466528, '127.0.0.1', 4023] 12:27:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11730883.957984, '127.0.0.1', 4022] 12:27:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730883.96048, '127.0.0.1', 4022] 12:27:05 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191: 12:27:05 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 744 12:27:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11730883.988992, '127.0.0.1', 4022] 12:27:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11730883.991488, '127.0.0.1', 4022] 12:27:05 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1]) 12:27:05 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1 12:27:05 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\749622\behavior_749622_2024-11-14_11-12-10 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:27:05 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:27:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11730886.674976, '127.0.0.1', 4022] 12:27:07 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730886.677504, '127.0.0.1', 4022] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11730886.924992, '127.0.0.1', 4022] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11730886.928192, 4, '127.0.0.1'] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730886.92848, '127.0.0.1', 4022] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730887.103072, '127.0.0.1', 4023] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11730887.102976, '127.0.0.1', 4022] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 11730887.102976, '127.0.0.1', 4023] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 11730887.208, '127.0.0.1', 4023] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11730887.210496, '127.0.0.1', 4023] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730887.384192, '127.0.0.1', 4023] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730887.488128, '127.0.0.1', 4023] 12:27:08 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730887.604608, '127.0.0.1', 4023] 12:27:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11730888.090976, '127.0.0.1', 4022] 12:27:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730888.094496, '127.0.0.1', 4022] 12:27:09 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191: 12:27:09 PM:INFO:Foraging:Foraging.py:_StartTrialLoop:line 4159:Current trial: 745 12:27:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialStartTime', 11730888.124, '127.0.0.1', 4022] 12:27:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/ITIStartTimeHarp', 11730888.126496, '127.0.0.1', 4022] 12:27:09 PM:WARNING:warnings:warnings.py:_showwarnmsg:line 110:C:\Users\svc_aind_behavior\Documents\GitHub\dynamic-foraging-task\src\foraging_gui\Visualization.py:160: RuntimeWarning: Mean of empty slice RewardedHistoryF[i+1-self.kernel_size]=np.nanmean(RewardedHistoryT[i+1-self.kernel_size:i+1]) 12:27:09 PM:INFO:Foraging:Foraging.py:_Save:line 2459:Saving current session, ForceSave=1 12:27:09 PM:INFO:Foraging:Foraging.py:_GetWaterCalibration:line 1056:Loaded Water Calibration 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 88:processing:C:\behavior_data\446-7-C\749622\behavior_749622_2024-11-14_11-12-10 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_handle_edge_cases:line 361:Cannot log reward delivery in session metadata - missing fields 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 114:Session metadata generated successfully: True 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:__init__:line 115:Rig metadata generated successfully: True 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_reward_delivery:line 1192:No reward delivery metadata found! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_opto_calibration:line 1027:No opto calibration results detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ephys_stream:line 865:No ephys data stream detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_ophys_stream:line 584:No photometry data stream detected! 12:27:09 PM:INFO:GenerateMetadata:GenerateMetadata.py:_get_high_speed_camera_stream:line 562:No camera data stream detected! 12:27:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/DelayStartTime', 11730890.406976, '127.0.0.1', 4022] 12:27:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730890.410496, '127.0.0.1', 4022] 12:27:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTime', 11730890.656992, '127.0.0.1', 4022] 12:27:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730890.661504, '127.0.0.1', 4022] 12:27:11 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/GoCueTimeSoundCard', 11730890.661216, 4, '127.0.0.1'] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730890.910592, '127.0.0.1', 4023] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcomeTime', 11730890.909984, '127.0.0.1', 4022] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTime', 11730890.909984, '127.0.0.1', 4023] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RewardOutcome', 'RewardRight', '127.0.0.1', 4022] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/EarnedRightWaterStartTime', 11730891.024, '127.0.0.1', 4023] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightRewardDeliveryTimeHarp', 11730891.027488, '127.0.0.1', 4023] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730891.136224, '127.0.0.1', 4023] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730891.271392, '127.0.0.1', 4023] 12:27:12 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730891.383616, '127.0.0.1', 4023] 12:27:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/TrialEndTime', 11730891.908, '127.0.0.1', 4022] 12:27:13 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/BehaviorEvent', 11730891.910496, '127.0.0.1', 4022] 12:27:13 PM:WARNING:MyFunctions:MyFunctions.py:_CheckStop:line 1191:Stop because running time exceeds or equals: 75m 12:27:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730929.94832, '127.0.0.1', 4023] 12:27:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730930.173344, '127.0.0.1', 4023] 12:27:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730930.364672, '127.0.0.1', 4023] 12:27:51 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730930.54544, '127.0.0.1', 4023] 12:27:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730935.361376, '127.0.0.1', 4023] 12:27:56 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730935.521856, '127.0.0.1', 4023] 12:27:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730935.824672, '127.0.0.1', 4023] 12:27:57 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730936.03472, '127.0.0.1', 4023] 12:28:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730943.934016, '127.0.0.1', 4023] 12:28:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730944.094752, '127.0.0.1', 4023] 12:28:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730944.26848, '127.0.0.1', 4023] 12:28:05 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730944.431712, '127.0.0.1', 4023] 12:28:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730967.309312, '127.0.0.1', 4023] 12:28:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730967.513248, '127.0.0.1', 4023] 12:28:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730967.591872, '127.0.0.1', 4023] 12:28:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730967.671296, '127.0.0.1', 4023] 12:28:29 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730967.872192, '127.0.0.1', 4023] 12:28:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730974.88336, '127.0.0.1', 4023] 12:28:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11730975.062688, '127.0.0.1', 4023] 12:28:36 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11730975.266912, '127.0.0.1', 4023] 12:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731092.76752, '127.0.0.1', 4023] 12:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731092.767584, '127.0.0.1', 4023] 12:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731092.920096, '127.0.0.1', 4023] 12:30:34 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731093.068672, '127.0.0.1', 4023] 12:30:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731103.304384, '127.0.0.1', 4023] 12:30:44 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731103.491776, '127.0.0.1', 4023] 12:31:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731128.514784, '127.0.0.1', 4023] 12:31:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731128.555776, '127.0.0.1', 4023] 12:31:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731128.6096, '127.0.0.1', 4023] 12:31:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731128.615648, '127.0.0.1', 4023] 12:31:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731128.61632, '127.0.0.1', 4023] 12:31:09 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731128.628224, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731128.7736, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731128.849856, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.158848, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731129.161248, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.219264, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.320576, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.351744, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.476448, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.548224, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.553824, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731129.691424, '127.0.0.1', 4023] 12:31:10 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731129.742112, '127.0.0.1', 4023] 12:31:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731133.249888, '127.0.0.1', 4023] 12:31:14 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731133.734496, '127.0.0.1', 4023] 12:31:15 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731133.875456, '127.0.0.1', 4023] 12:31:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731140.024736, '127.0.0.1', 4023] 12:31:21 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731140.1976, '127.0.0.1', 4023] 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 913:Percentage of left lick intervals under 100 ms is 6.00%. 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 919:Percentage of right lick intervals under 100 ms is 9.73%. 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 926:Percentage of right and left lick intervals under 100 ms is 7.73%. 12:32:10 PM:INFO:MyFunctions:MyFunctions.py:calculate_inter_lick_intervals:line 951:Percentage of cross side lick intervals under 100 ms is 1.72%. 12:32:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731203.06336, '127.0.0.1', 4023] 12:32:24 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731203.063424, '127.0.0.1', 4023] 12:32:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/RightLickTime', 11731207.529856, '127.0.0.1', 4023] 12:32:28 PM:INFO:rigcontrol:rigcontrol.py:msg_handler:line 56:['/LeftLickTime', 11731207.529856, '127.0.0.1', 4023] 12:32:51 PM:ERROR:Foraging:Foraging.py:_StartTrialLoop:line 4302:trial stalled 5 minutes, user continued trials

AllenNeuralDynamics / dynamic-foraging-task

trial stalled 5 minutes, user continued trials #761