weewx stopped for no apparent reason

[Jay Jaeger]

Over the weekend moved from weewx 3.9.2 to weewx 4.5.1.   It was essentially a reinstall, as I also moved from a Davis wmII (community driver) to a VantageVue with WeatherLinkLive (also a community driver), editing the config file from scratch.

 System is Ubuntu Linux LTS 20.04, python 3.8, mySQL 5.7  The last start of weewx was on 5-Jun-2021.  It stopped reporting after 3:15 CDT on 7-Jun-2021, for no apparent reason that I can see.  

(The exact time seems to have been around 3:18 AM on 7-Jun-2021 - that is when I no longer saw broadcasts from WeatherLinkLive.)

Now, it is certainly possible that this is an issue in the WeatherLinkLive driver - and I will raise it as an issue with them, but also decided to check here just in case.

The last things in /var/log/syslog were:

Jun  7 03:15:17 mythtv2 weewx[119044] INFO weewx.manager: Added record 2021-06-07 03:15:00 CDT (1623053700) to database 'weewx'

Jun  7 03:15:17 mythtv2 weewx[119044] INFO weewx.manager: Added record 2021-06-07 03:15:00 CDT (1623053700) to daily summary in 'weewx'

Jun  7 03:15:18 mythtv2 weewx[119044] INFO weewx.restx: Wunderground-PWS: Published record 2021-06-07 03:15:00 CDT (1623053700)

Jun  7 03:15:18 mythtv2 weewx[119044] INFO weewx.cheetahgenerator: Generated 8 files for report SeasonsReport in 0.62 seconds

Jun  7 03:15:18 mythtv2 weewx[119044] INFO weewx.imagegenerator: Generated 14 images for report SeasonsReport in 0.29 seconds

Jun  7 03:15:18 mythtv2 weewx[119044] INFO weewx.reportengine: Copied 0 files to /opt/weewx/public_html

Jun  7 03:30:01 mythtv2 CRON[154439]: (root) CMD (/usr/bin/sshpass -p 'CM12RVdx' /usr/bin/scp -r /opt/weewx/public_html/* we...@45.33.104.133:/var/www/html/computercollection.net/public_html/weewx)

The last things in my firewall log which is currently logging the broadcasts:

Jun  7 03:18:45 cirith kernel: [23782696.289934] IN=eth1 OUT= MAC=ff:ff:ff:ff:ff:ff:ec:fa:bc:ce:49:b7:08:00 SRC=192.168.42.75 DST=192.168.42.255 LEN=426 TOS=0x00 PREC=0x00 TTL=128 ID=64354 PROTO=UDP SPT=25447 DPT=22222 LEN=406

Jun  7 03:18:47 cirith kernel: [23782698.792825] IN=eth1 OUT= MAC=ff:ff:ff:ff:ff:ff:ec:fa:bc:ce:49:b7:08:00 SRC=192.168.42.75 DST=192.168.42.255 LEN=426 TOS=0x00 PREC=0x00 TTL=128 ID=64355 PROTO=UDP SPT=25447 DPT=22222 LEN=406

Jun  7 03:18:50 cirith kernel: [23782701.291975] IN=eth1 OUT= MAC=ff:ff:ff:ff:ff:ff:ec:fa:bc:ce:49:b7:08:00 SRC=192.168.42.75 DST=192.168.42.255 LEN=426 TOS=0x00 PREC=0x00 TTL=128 ID=64356 PROTO=UDP SPT=25447 DPT=22222 LEN=406

All times CDT.

JRJ

[tomn...@frontier.com]

First thing, it's unwise to post your password for the world to see, so go change that now.  :^)

Next, if weewx is stopped, try that scp command from the command line.  It's way easier to debug that way.

As for your firewall entries, it looks like something is talking directly to your gateway or LAN broadcast via UDP

port 22222.  Can't say what, but that isn't weewx trying to get to your web hosting service.

Searching "udp port 22222" did mention Davis Weatherlink among other things.  Have you messed with anthing

related to that?

Chris

[Jay Jaeger]

Oh it is worse than unwise.  I know better (I worked in network security for years) - incredibly STUPID is more like it.  Fortunately, a sandboxed, unpriviledged user - and fixed now.  ;)  [I tried to edit the post post facto to take it out, but it wouldn't let me edit the post.  8(]

That "something" which is indeed my LAN is my Davis WeatherLinkLive interface box (WLL) - which broadcasts on port 22222 when appropriately "tickled" by an http request.  (It also makes TCP connections to the Davis server for their app.)  The first logs are from the machine at home (named mythtv2 for historical reasons), which is where weewx actually runs.  The scp is just copying the html and graphics up to my cloud-hosted website - not relevant to the problem - that kept on going fine (it is triggered by a cron job).  The scp isn't the issue at all.

The bottom logs are from my firewall ("cirithi") as a convenient place to spot such broadcasts and log them.

weewx was not stopped in that the service was still running on Linux.  Whether it was in a blocked or deadlocked process state (waiting for something that would never happen) I cannot say for sure.   It might just be that the data from the WSS wasn't waking it up any more.  That UDP broadcast should be every 3 seconds or so, but weren't  showing up after 3:18:50 AM.  My *suspicion* is that the weewx WLL driver missed (or didn't get) one of the UDP packets, and so didn't wake up to tickle the WLL with another HTTP request, and so went off to sleep forever.  

I only posted it here on the off chance that 1) someone else saw weewx go to sleep who may or may not be running WLL or 2) someone else running the WLL driver noticed the same thing.

[Michael Schantl]

Hi, I'm the author of that WLL driver.

Yes, the UDP broadcasts come from the WeatherLink Live. The driver should continue to 'tickle' the WLL even if any packets should have been missed, so that shouldn't be an issue.

Were there no errors in the log? Your log dump looks absolutely normal.

- Michael

[Jay Jaeger]

I knew the log looked "normal" aside from messages from weewx stopping - had there been some error or other, I would have tracked it down on my own.  The log extract was done using "grep weewx /var/log/syslog" [my logs rotate at midnight].   (Note: I  ded "tweaked" the WLL driver code to suppress the "Emitting poll/(broadcast) messages by changing those two log calls to "log.debug").  

weewx simply went night-night.  The "reportengine" message shown in my post was the last message from weewx until I restarted it.  Note the 15 minute gap between that and the CRON message - there ought to have been a couple more report generation sequences in between, which there were not.

weewx did catch the TERM signal and ended normally when I ran "service weewx stop".

JRJ

[Jay Jaeger]

FYI, it has happened again, at about 18:00 today.  Any suggestions on instrumentation?

JRJ

[vince]

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.

[Michael Schantl]

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?

[Jay Jaeger]

@vince:  I worked in IT for over 36 years, and with UNIX and "C" since 1976.  I know what I am doing.  There can be lots of reasons why an issue appears on one machine vs. another, often related to the timing relationship between events.  Yes, it occurred to me that logging at the DEBUG level is in order, but haven't gotten around to it yet (the last post was just before I went to bed last night).  I also wrote a little program to monitor the UDP messages coming from the WLL (has to run from another machine), but haven't deployed it yet.

[Jay Jaeger]

@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

[Christopher Shaker]

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

[Christopher Shaker]

I have set debug to 1, and disabled the crontab reboot, to see if I can collect some debug data.
Chris Shaker

[Jay Jaeger]

@Chris:  Version 3 weewx with my wmII was rock solid.  I didn't run the wmII more than a day under version 4, so I can't speak to that.  I had no issues restarting weewx - didn't need a reboot.

NOTE:  systemd behavior, being what it is, if a service crashes, it still is not STOPPED, and it won't start a service that it thinks is still running.  Instead, you have to stop it (service weewx stop) before you can start it (or, you could do a "service weewx restart" which does a stop first.)

JRJ

[Jay Jaeger]

@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:

[Christopher J. Shaker]

Jay:

I tried 'sudo service weewx restart', and it did NOT fix the problem. I rebooted the machine, and it worked
great. Hopefully, now that I've got debug enabled, if it happens again, I can debug it.

Thank you for sharing your WMII driver for Python 3!

Chris Shaker

--
You received this message because you are subscribed to a topic in the Google Groups "weewx-user" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/weewx-user/GYnuZbTdhuM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to weewx-user+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-user/868ff588-eed6-4cee-b94b-61143e0cfa85n%40googlegroups.com.

[Michael Schantl]

@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.

[Jay Jaeger]

@michael:  No, that is not what I am saying.  In fact, the converse is likely true: that it ALSO stopped recording data in the database, as there are no more messages of the sort "Added record ... to database" INFO level messages in my logs once this occurred, as can be seen in my original post - *all* messages out of weewx stopped at 03:15:18 in that example.  (Of course it did also stop generating reports.)

JRJ

[Eric K]

@JRJ, it appears this (or something similar) has just happened on my weewx 4.5.1 installation.

I suppose I should start a new thread on it.  

I'll be watching yours to see if you find out whats going wrong!

[Jay Jaeger]

@eric thread population is up to you, if you want to post on this one, that is fine with me.  FYI, I have now been running a little over 1 full day with debug with the newer WeatherLinkLive driver with no untoward events - but note that the first one took over two days to occur.

[Jay Jaeger]

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:

[Jay Jaeger]

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

[Jay Jaeger]

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.)

[Jay Jaeger]

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.

[Jay Jaeger]

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.

[Jay Jaeger]

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

[Michael Schantl]

Hi JRJ,

thank you for the extensive debugging.

I've just pushed a new dev release.

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

[Jay Jaeger]

FYI, since I made the change (using my own code, and only on the WllPollHost related call, it has stayed up.  HOWEVER, it also has not issued any error message, and it has not yet been, say, 3 days, so that might be a coincidence.  After, say, Tuesday, I'll give your new dev release a whirl (or sooner if the one that is running now locks up.)

(I have no idea if the request class honors any global timeout default, or not - no clue there.)

You are more than welcome - I actually enjoy debugging.  ;)

JRJ

[Jay Jaeger]

FYI, I did have an instance of the issue late yesterday, and the patch I put did allow it to recover.   I just installed the dev release snapshot and will keep you posted if/when I see the recoveries.  THANKS!

JRJ

On Saturday, June 12, 2021 at 1:50:39 PM UTC-5 michael.s...@gmail.com wrote:

[Jay Jaeger]

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:

[Jay Jaeger]

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 michael.s...@gmail.com wrote:

[Michael Schantl]

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

[Michael Schantl]

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.

[Jay Jaeger]

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