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 [email protected] >>>> 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. >>>>> >>>>> [email protected] 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 [email protected] >>>>>> 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 [email protected] >>>>>>> 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 >>>>>>>> [email protected] 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 [email protected] >>>>>>>>>> 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 [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-user/fe1410cb-01c4-492f-aef9-539bd9a5c8e7n%40googlegroups.com.
