Yes, everything has been working fine since the changes. No, there isn't anything else talking to the WLL, except that the WLL posts to the Davis WLL website - but those are all outbound. Since I changed the check on the counter from 1 to 2 I have seen none of those warning messages.
I wait to install your new code once it arrives until week after next, as I will be out of town, and I know what I have now is stable - so, no rush. THANKS! JRJ On Friday, June 18, 2021 at 9:38:16 AM UTC-5 [email protected] wrote: > OK, I've just taken a look into the 5 minutes thing. Forget my point from > above, the 5 minutes correspond to the 300 second archive interval. > I was able to confirm this by changing the interval. > > Michael Schantl schrieb am Freitag, 18. Juni 2021 um 15:41:57 UTC+2: > >> OK, will push a new release shortly with the change you suggested. >> Did everything work in the last few days? >> >> On the topic of the regular messages, is there any other device or >> process talking to the WLL. I've noticed that the WLL's HTTP server can act >> weird when there are too many connections in too quick succession. >> >> - Michael >> >> >> [email protected] schrieb am Dienstag, 15. Juni 2021 um 23:42:40 UTC+2: >> >>> FYI, now that I am monitoring for the WARNING messages, I am seeing them >>> like clockwork every 5 minutes - in the SAME SECOND for which I see weewx >>> "Added record" messages. Doubt it is a coincidence - correlation is nearly >>> 99% (once in a while there is no WARNING. Suggest only issuing the warning >>> if >= 2 misses. >>> >>> JRJ >>> >>> On Saturday, June 12, 2021 at 1:50:39 PM UTC-5 [email protected] >>> 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 >>>> >>>> [email protected] 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 >>>>>>>>>> [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/529d7af2-3b4f-4608-abce-b58c1c1793cdn%40googlegroups.com.
