FYI, just had my first case under the new code - worked fine. Suggestion: The message logged is the same for both start_broadcast and request_current - spotted that when I saw the message and I couldn't tell which had failed without looking at the debug log to see the DEBUG entry - and even at that I am not 100% certain - if they overlapped?
Here is what got logged (sans the "mapper" entries) *Jun 15 08:44:10 mythtv2 weewx[297697] DEBUG user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-15 13:44:20 Z* *Jun 15 13:44:20 mythtv2 weewx[297697] DEBUG user.weatherlink_live.scheduler: Scheduler tick* *Jun 15 13:44:20 mythtv2 weewx[297697] DEBUG user.weatherlink_live.scheduler: Notifying poll callback* *Jun 15 13:44:20 mythtv2 weewx[297697] DEBUG urllib3.connectionpool: Starting new HTTP connection (1): vantagevieww.lan:80* *Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG urllib3.connectionpool: http://vantagevieww.lan:80 "GET /v1/current_conditions HTTP/1.1" 200 None* Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:24 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:24 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:24 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:24 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:24 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:24 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet *Jun 15 13:44:29 mythtv2 weewx[297697] WARNING user.weatherlink_live: No data since 1 iterations* Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:29 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 08:44:21 mythtv2 weewx[297697] DEBUG user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-15 13:44:31 Z Jun 15 13:44:31 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:31 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:31 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:31 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:31 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:31 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:34 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:34 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:34 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:34 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:34 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:34 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:36 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:36 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:36 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:36 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:36 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:36 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:39 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:39 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:39 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:39 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:39 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:39 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:41 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:41 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:41 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:41 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:41 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:41 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:44 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:44 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:44 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:44 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:44 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:44 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet *Jun 15 13:44:46 mythtv2 weewx[297697] ERROR user.weatherlink_live.davis_http: HTTPConnectionPool(host='vantagevieww.lan', port=80): Read timed out.* *Jun 15 13:44:46 mythtv2 weewx[297697] ERROR user.weatherlink_live.davis_http: HTTP Request failed. Retry #0 follows shortly* Jun 15 13:44:46 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:46 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet Jun 15 13:44:46 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet Jun 15 13:44:46 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:46 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:46 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet *Jun 15 13:44:48 mythtv2 weewx[297697] DEBUG urllib3.connectionpool: Starting new HTTP connection (1): vantagevieww.lan:80* *Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG urllib3.connectionpool: http://vantagevieww.lan:80 "GET /v1/current_conditions HTTP/1.1" 200 None* Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create HTTP conditions packet Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Polled current conditions *Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.scheduler: 3 scheduler ticks until next push refresh* Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-15 18:44:59 Z Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting poll packet Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Wind observations windSpeed:windDir not in record Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.davis_broadcast: Received 395 bytes from ('192.168.42.75', 25447) Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.packets: Trying to create UDP conditions packet *Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.data_host: Received new broadcast packet* Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Emitting push (broadcast) packet Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live.service: WllWindGustService: Updating record with dict: {'windGust': 8.0, 'windGustDir': 77} Jun 15 13:44:49 mythtv2 weewx[297697] DEBUG user.weatherlink_live: Waiting for new packet (And then it was fine.) On Saturday, June 12, 2021 at 1:50:39 PM UTC-5 michael.s...@gmail.com wrote: > Hi JRJ, > thank you for the extensive debugging. > I've just pushed a new dev release > <https://github.com/michael-slx/weewx-weatherlink-live/releases/tag/SNAPSHOT-2021-06-12> > . > > Yeah, you're right with the missing timeout. I had assumed the requests > library honors the socket timeout configured globally, but apparently not. > The standard WeeWX timeout option is now also used for the HTTP requests. > Additionally, for good measures, I've also added a watchdog for when no > packets are received. It has an option to configure the iterations allowed > without data. See the changelog for details. > > - Michael > > cub...@gmail.com schrieb am Freitag, 11. Juni 2021 um 18:13:15 UTC+2: > >> I noticed that there is no timeout keyword on the request call >> davis_http.request_current. I will add one to see if it helps. (I also >> note that there is no timeout on the call in start_broadcast either. >> >> JRJ >> >> On Friday, June 11, 2021 at 10:58:48 AM UTC-5 Jay Jaeger wrote: >> >>> I just noticed that the call to _poll_callback() [to WllPollHost.poll] >>> is indeed apparently not returning - noticed in the above logs that there >>> is NO message "Polled current conditions". Working theory: if it receives >>> a UDP (broadcast) packet while it is doing the HTTP poll request, the >>> driver gets confused. >>> >>> On Friday, June 11, 2021 at 10:35:39 AM UTC-5 Jay Jaeger wrote: >>> >>>> >>>> Happened again while I was looking at logs. Just for grins, I fired >>>> off an HTTP request from my PC, and it woke back up. >>>> >>>> So: for some reason the WLL driver scheduler _do_tick method call to >>>> _poll_callback() never returns, so that _do_tick never returns to >>>> _scheduler_tick and thus it goes off to sleepy-land. QUERY: Is there >>>> some reason it is calling _do_tick() before scheduling the next tick by >>>> calling enterabs? (And no, there is no exception being caught, as far as >>>> I >>>> can tell.) >>>> >>>> Adding a log.debug call after the _poll_callback() call - but I have no >>>> doubt that under these conditions it will not be triggered. >>>> >>>> On Friday, June 11, 2021 at 10:06:10 AM UTC-5 Jay Jaeger wrote: >>>> >>>>> Here are some more datapoints from the log that confirm that the >>>>> needed HTTP request to the WLL box is not occurring: >>>>> >>>>> Jun 10 22:37:01 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: 13scheduler ticks until next push refresh >>>>> Jun 10 22:37:01 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-11 >>>>> 03:37:11 >>>>> Z >>>>> Jun 10 22:37:11 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Scheduler tick >>>>> Jun 10 22:37:11 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Notifying poll callback >>>>> Jun 10 22:37:12 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: 12scheduler ticks until next push refresh >>>>> Jun 10 22:37:12 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-11 >>>>> 03:37:22 >>>>> Z >>>>> Jun 10 22:37:22 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Scheduler tick >>>>> Jun 10 22:37:22 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Notifying poll callback >>>>> Jun 10 22:37:23 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: 11scheduler ticks until next push refresh >>>>> Jun 10 22:37:23 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-11 >>>>> 03:37:33 >>>>> Z >>>>> Jun 10 22:37:33 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Scheduler tick >>>>> Jun 10 22:37:33 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Notifying poll callback >>>>> Jun 10 22:37:34 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: 10scheduler ticks until next push refresh >>>>> Jun 10 22:37:34 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Next scheduler tick at 2021-06-11 >>>>> 03:37:44 >>>>> Z >>>>> Jun 10 22:37:44 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Scheduler tick >>>>> Jun 10 22:37:44 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.scheduler: Notifying poll callback >>>>> >>>>> *** That was the last log message including scheduler >>>>> >>>>> After that we see (excluding most of the .mappers log entries) >>>>> >>>>> Jun 10 22:37:44 mythtv2 weewx[239040] DEBUG urllib3.connectionpool: >>>>> Starting new HTTP connection (1): vantagevieww.lan:80 >>>>> Jun 10 22:37:45 mythtv2 weewx[239040] DEBUG urllib3.connectionpool: >>>>> http://vantagevieww.lan:80 "GET /v1/current_conditions HTTP/1.1" 200 >>>>> None >>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.davis_broadcast: Received 394 bytes from >>>>> ('192.168.42.75', 25447) >>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.packets: Trying to create UDP conditions packet >>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.data_host: Received new broadcast packet >>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Emitting push (broadcast) packet >>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: Updating record with >>>>> dict: {'windGust': 0.75, 'windGustDir': 114} >>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Waiting for new packet >>>>> << SNIP >> >>>>> Jun 10 22:38:00 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.davis_broadcast: Received 394 bytes from >>>>> ('192.168.42.75', 25447) >>>>> Jun 10 22:38:00 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.packets: Trying to create UDP conditions packet >>>>> Jun 10 22:38:00 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.data_host: Received new broadcast packet >>>>> << snip >> >>>>> Jun 10 22:42:25 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Emitting push (broadcast) packet >>>>> Jun 10 22:42:25 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: New wind vector 0.00:0 >>>>> larger than 0.00:0 >>>>> Jun 10 22:42:25 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: Updating record with >>>>> dict: {'windGust': 0.0, 'windGustDir': 0} >>>>> Jun 10 22:42:25 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Waiting for new packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.davis_broadcast: Received 394 bytes from >>>>> ('192.168.42.75', 25447) >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.packets: Trying to create UDP conditions packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.data_host: Received new broadcast packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: THMapping[['1']]: Observation not found in >>>>> packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: THIndoorMapping[[]]: Observation not found >>>>> in packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: BaroMapping[[]]: Observation not found in >>>>> packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainSize=0.01 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainCountRate=0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainRate=0.0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainCount=0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rain=0.0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: WindMapping[['1']]: Mapped: windDir=0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: WindMapping[['1']]: Mapped: windSpeed=0.0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: ThwMapping[['1']]: Observation not found >>>>> in >>>>> packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: WindChillMapping[['1']]: Observation not >>>>> found in packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Emitting push (broadcast) packet >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: New wind vector 0.00:0 >>>>> larger than 0.00:0 >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: Updating record with >>>>> dict: {'windGust': 0.0, 'windGustDir': 0} >>>>> Jun 10 22:42:28 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Waiting for new packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.davis_broadcast: Received 394 bytes from >>>>> ('192.168.42.75', 25447) >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.packets: Trying to create UDP conditions packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.data_host: Received new broadcast packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: THMapping[['1']]: Observation not found in >>>>> packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: THIndoorMapping[[]]: Observation not found >>>>> in packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainSize=0.01 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainCountRate=0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainRate=0.0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainCount=0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rain=0.0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: WindMapping[['1']]: Mapped: windDir=0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: WindMapping[['1']]: Mapped: windSpeed=0.0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: ThwMapping[['1']]: Observation not found >>>>> in >>>>> packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.mappers: WindChillMapping[['1']]: Observation not >>>>> found in packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Emitting push (broadcast) packet >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: New wind vector 0.00:0 >>>>> larger than 0.00:0 >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>> user.weatherlink_live.service: WllWindGustService: Updating record with >>>>> dict: {'windGust': 0.0, 'windGustDir': 0} >>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Waiting for new packet >>>>> Jun 10 22:42:50 mythtv2 weewx[239040] message repeated 4 times: [ >>>>> DEBUG user.weatherlink_live: Waiting for new packet] >>>>> Jun 10 22:42:55 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>> Waiting for new packet >>>>> Jun 10 22:43:50 mythtv2 weewx[239040] message repeated 11 times: [ >>>>> DEBUG user.weatherlink_live: Waiting for new packet] >>>>> (it has gone to sleep, and with nothing to cause the WLL box to send >>>>> more UDP packets, it will stay that way.) >>>>> >>>>> >>>>> >>>>> >>>>> >>>>> >>>>> On Friday, June 11, 2021 at 7:46:13 AM UTC-5 Jay Jaeger wrote: >>>>> >>>>>> This time it lasted only a couple of hours before >>>>>> >>>>>> Jun 10 22:37:44 mythtv2 weewx[239040] DEBUG urllib3.connectionpool: >>>>>> Starting new HTTP connection (1): vantagevieww.lan:80 [Last HTTP request] >>>>>> Jun 10 22:37:45 mythtv2 weewx[239040] DEBUG urllib3.connectionpool: >>>>>> http://vantagevieww.lan:80 "GET /v1/current_conditions HTTP/1.1" 200 >>>>>> None >>>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>>> user.weatherlink_live.davis_broadcast: Received 394 bytes from >>>>>> ('192.168.42.75', 25447) >>>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>>> user.weatherlink_live.packets: Trying to create UDP conditions packet >>>>>> Jun 10 22:37:46 mythtv2 weewx[239040] DEBUG >>>>>> user.weatherlink_live.data_host: Received new broadcast packet >>>>>> ... >>>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG >>>>>> user.weatherlink_live.service: WllWindGustService: Updating record with >>>>>> dict: {'windGust': 0.0, 'windGustDir': 0} >>>>>> Jun 10 22:42:30 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>>> Waiting for new packet >>>>>> Jun 10 22:42:50 mythtv2 weewx[239040] message repeated 4 times: [ >>>>>> DEBUG user.weatherlink_live: Waiting for new packet] >>>>>> Jun 10 22:42:55 mythtv2 weewx[239040] DEBUG user.weatherlink_live: >>>>>> Waiting for new packet >>>>>> Jun 10 22:43:50 mythtv2 weewx[239040] message repeated 11 times: [ >>>>>> DEBUG user.weatherlink_live: Waiting for new packet] >>>>>> >>>>>> JRJ >>>>>> >>>>>> On Thursday, June 10, 2021 at 8:26:15 PM UTC-5 Jay Jaeger wrote: >>>>>> >>>>>>> So, it happened again. Here is how the events seem to have >>>>>>> unfolded, based on the logs: >>>>>>> >>>>>>> *** The last HTTP request seems to have gone out at 16:26 (so, >>>>>>> before data stopped flowing) - there were no more HTTP requests after >>>>>>> that >>>>>>> - it was the last appearnce of http or HTTP from the weewx process in >>>>>>> the >>>>>>> logs: >>>>>>> >>>>>>> Jun 10 16:26:12 mythtv2 weewx[206240] DEBUG urllib3.connectionpool: >>>>>>> http://vanta >>>>>>> gevieww.lan:80 "GET /v1/current_conditions HTTP/1.1" 200 None >>>>>>> >>>>>>> *** The last every-5-minute record update was at 16:40 CDT Today: >>>>>>> Jun 10 16:40:16 mythtv2 weewx[206240] INFO weewx.manager: Added >>>>>>> record 2021-06-10 16:40:00 CDT (1623361200) to daily summary in 'weewx' >>>>>>> >>>>>>> *** UDP packets continued until 16:43, after which they stopped >>>>>>> (presumably because the WLL box was in need of an HTTP "tickle"_ >>>>>>> >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.davis_broadcast: Received 394 bytes from >>>>>>> ('192.168.42.75', 25447) >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.packets: Trying to create UDP conditions packet >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.data_host: Received new broadcast packet >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.mappers: THMapping[['1']]: Observation not found >>>>>>> in >>>>>>> packet >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.mappers: THIndoorMapping[[]]: Observation not >>>>>>> found >>>>>>> in packet >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.mappers: BaroMapping[[]]: Observation not found >>>>>>> in >>>>>>> packet >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.mappers: RainMapping[['1']]: Mapped: rainSize=0.01 >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.mappers: RainM >>>>>>> << SNIP more of the above >> >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG user.weatherlink_live: >>>>>>> Emitting push (broadcast) packet >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG >>>>>>> user.weatherlink_live.service: WllWindGustService: Updating record with >>>>>>> dict: {'windGust': 2.62, 'windGustDir': 106} >>>>>>> Jun 10 16:43:14 mythtv2 weewx[206240] DEBUG user.weatherlink_live: >>>>>>> Waiting for new packet >>>>>>> Jun 10 16:43:49 mythtv2 weewx[206240] message repeated 7 times: [ >>>>>>> DEBUG user.weatherlink_live: Waiting for new packet] >>>>>>> >>>>>>> After that, no more UDP packets were flowing, and the WLL driver >>>>>>> repeated the waiting for packet message from then on (this time is as I >>>>>>> am >>>>>>> posting) >>>>>>> Jun 10 20:09:25 mythtv2 weewx[206240] message repeated 4 times: [ >>>>>>> DEBUG user.weatherlink_live: Waiting for new packet] >>>>>>> >>>>>>> My diagnosis is that the most likely cause was that WLL didn't >>>>>>> receive a needed HTTP request to keep data flowing, because either the >>>>>>> WLL >>>>>>> driver didn't send it for some reason, or the connection attempt failed >>>>>>> or >>>>>>> some such. >>>>>>> >>>>>>> Perhaps a cure/workaround would be this: one expects to see those >>>>>>> UDP packets about every two seconds. If 15 (or maybe 30) have gone >>>>>>> by, >>>>>>> generate an error log entry and send an HTTP request - all one would >>>>>>> have >>>>>>> to do is put a counter in the place where it is issuing the Waiting >>>>>>> message >>>>>>> (regardless of whether debugging was enabled or not) . Also, if the >>>>>>> code >>>>>>> is relying on an HTTP TCP connection staying open between requests, it >>>>>>> would be better to open a new TCP connection for each request (I >>>>>>> haven't >>>>>>> looked at the code.) >>>>>>> >>>>>>> JRJ >>>>>>> >>>>>>> On Wednesday, June 9, 2021 at 1:30:17 PM UTC-5 >>>>>>> michael.s...@gmail.com wrote: >>>>>>> >>>>>>>> @JRJ: So, you're saying that WeeWX stopped generating reports but >>>>>>>> data still was recorded in the database, correct? >>>>>>>> If yes, it seems unlikely that it's a driver issue and more on the >>>>>>>> weewx engine's side. >>>>>>>> >>>>>>>> cub...@gmail.com schrieb am Mittwoch, 9. Juni 2021 um 20:22:01 >>>>>>>> UTC+2: >>>>>>>> >>>>>>>>> @chris: yes, indeed, the issue on my system was that weewx >>>>>>>>> stopped producing reports (and also there were no reporting-related >>>>>>>>> messages in the log. I do am now running with debug set to 1 in the >>>>>>>>> config. >>>>>>>>> >>>>>>>>> JRJ >>>>>>>>> >>>>>>>>> On Wednesday, June 9, 2021 at 12:09:08 PM UTC-5 cjsh...@gmail.com >>>>>>>>> wrote: >>>>>>>>> >>>>>>>>>> JRJ: >>>>>>>>>> >>>>>>>>>> Are you saying that weewx stopped generating reports? My weewx >>>>>>>>>> stopped generating reports, with no error messages, at 4:00 AM. >>>>>>>>>> Restarting >>>>>>>>>> service weewx did not fix it. Rebooting my raspberry pi DID fix it. >>>>>>>>>> So, I >>>>>>>>>> added a crontab entry to reboot my raspberry pi each morning: >>>>>>>>>> 5 4 * * * /sbin/shutdown -r now >>>>>>>>>> >>>>>>>>>> So far, it has not happened again. I'm using a WMII, with serial >>>>>>>>>> port connection, using Python3 and the latest version of the driver >>>>>>>>>> from >>>>>>>>>> JayJaeger >>>>>>>>>> >>>>>>>>>> Chris Shaker >>>>>>>>>> >>>>>>>>>> On Wednesday, June 9, 2021 at 5:46:52 AM UTC-7 cub...@gmail.com >>>>>>>>>> wrote: >>>>>>>>>> >>>>>>>>>>> @michael: It should not be related to the SCP upload, which >>>>>>>>>>> continues even after weewx has gone "night night". It is running >>>>>>>>>>> from a >>>>>>>>>>> cron, not under weewx. It merely copies the generated >>>>>>>>>>> HTML/graphics up to >>>>>>>>>>> another machine. It runs every 17 minutes. If it were, say, >>>>>>>>>>> locking up >>>>>>>>>>> a file and causing a report to fail there ought to be a message >>>>>>>>>>> from Python >>>>>>>>>>> about that, and there are no such messages. This same SCP was >>>>>>>>>>> running with >>>>>>>>>>> weewx version 3 for many months without issues - originally every >>>>>>>>>>> 15 >>>>>>>>>>> minutes, I changed it from 15 to 17 yesterday to put it out of sync >>>>>>>>>>> from >>>>>>>>>>> the report generation a bit it after the second failure, just in >>>>>>>>>>> case. >>>>>>>>>>> >>>>>>>>>>> [It did occur to me to add a little mod akin to the RSYNC >>>>>>>>>>> present in weewx itself, or to cut over to using then RSYNC under >>>>>>>>>>> weewx >>>>>>>>>>> after the rest of this gets straightened out.] >>>>>>>>>>> >>>>>>>>>>> I also verified that all of the files and directories are owned >>>>>>>>>>> by and have the same group as the weewx process, and they are, so >>>>>>>>>>> it should >>>>>>>>>>> not be an issue of file permissions during report generation, >>>>>>>>>>> either. >>>>>>>>>>> >>>>>>>>>>> Regarding the dev release driver, sure, I'll give that a try, >>>>>>>>>>> and turn on more logging later today. >>>>>>>>>>> >>>>>>>>>>> JRJ >>>>>>>>>>> >>>>>>>>>>> On Wednesday, June 9, 2021 at 1:40:52 AM UTC-5 >>>>>>>>>>> michael.s...@gmail.com wrote: >>>>>>>>>>> >>>>>>>>>>>> Nah, the logging level change doesn't matter, I've published a >>>>>>>>>>>> dev release a few days ago making exactly that change. >>>>>>>>>>>> >>>>>>>>>>>> I'd suggest you to try the new driver version anyway since I >>>>>>>>>>>> also made some changes regarding the HTTP interaction with the >>>>>>>>>>>> WLL. You >>>>>>>>>>>> should also enable debug logging so we get a more exhaustive look >>>>>>>>>>>> into >>>>>>>>>>>> what's going on. >>>>>>>>>>>> >>>>>>>>>>>> My suspicion is that something's wrong with the report >>>>>>>>>>>> generation or the SCP upload. Was the last iteration of the report >>>>>>>>>>>> actually >>>>>>>>>>>> uploaded correctly? >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> vince schrieb am Mittwoch, 9. Juni 2021 um 06:10:01 UTC+2: >>>>>>>>>>>> >>>>>>>>>>>>> On Tuesday, June 8, 2021 at 12:43:44 PM UTC-7 cub...@gmail.com >>>>>>>>>>>>> wrote: >>>>>>>>>>>>> >>>>>>>>>>>>>> (Note: I did "tweaked" the WLL driver code to suppress the >>>>>>>>>>>>>> "Emitting poll/(broadcast) messages by changing those two log >>>>>>>>>>>>>> calls to >>>>>>>>>>>>>> "log.debug"). >>>>>>>>>>>>> >>>>>>>>>>>>> >>>>>>>>>>>>> I'd suggest running the unaltered driver and especially in >>>>>>>>>>>>> this case so you get the maximum logging so the author can help >>>>>>>>>>>>> you. >>>>>>>>>>>>> >>>>>>>>>>>>> If you start changing his code, eventually it'll be "you >>>>>>>>>>>>> changed it, you own the results good or bad" when he can't >>>>>>>>>>>>> recreate the >>>>>>>>>>>>> issue because your code has diverged from the authoritative >>>>>>>>>>>>> version. >>>>>>>>>>>>> >>>>>>>>>>>>> -- You received this message because you are subscribed to the Google Groups "weewx-user" group. To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+unsubscr...@googlegroups.com. To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-user/cbd1d8d5-f448-4a0f-8f0a-785e39417a14n%40googlegroups.com.
