What happens in Weewx around 3AM

[sbar...@gmail.com]

Hi, 

My Weewx dies on a daily basis a little before 3AM. The cause for the dying is some not properly handled exception that I need to fix on my own.

However, the faulty code is in a constructor class call by the constructor of my user extension (so I would expect it to only be called once). So the question is : Is there recycling of the user extensions happening daily?

If yes, is there a clean-up method I can implement in my extension to prevent the next constructor call from failing.

Regards,

[gjr80]

Hi,

Probably easiest if you post a log extract showing the lead up to a failure and the actual error trace. Also what version of WeeWX are you running and is WeeWX running under python 2 or python 3?

Gary

[sbar...@gmail.com]

Hi,

Ok I can try that.

I am running weewx 4.3.0 installed with setup.py.

I have a SDR with weewx SDR driver and a custom extension derived from a BME280 extension that will inject some extra measures in the measure loop.

Regarding logs, even though I set debug=1, i find only minimal info in message and no stacktrace whatsoever.

So I run ./bin/weewxd > logfile 2>&1.

Below is the crash log from last night:

LOOP:   2021-02-13 02:57:20 CET (1613181440) altimeter: 30.226434601579474, dateTime: 1613181440, extraTemp2: 66.18199999999999, inDewpoint: 39.600169912207505, inHumidity: 39.51263427734375, inTemp: 64.80874633789062, maxSolarRad: 0.0, pressure: 29.54738971773132, radiation: 0.0, rainRate: 0.0, usUnits: 1, windBatteryStatus: 1, windDir: None, windGust: 0.0, windSpeed: 0.0Traceback (most recent call last):

  File "/home/weewx/bin/weedb/mysql.py", line 52, in guarded_fn

    return fn(*args, **kwargs)

  File "/home/weewx/bin/weedb/mysql.py", line 133, in __init__

    db=database_name, **kwargs)

  File "/usr/lib/python3/dist-packages/MySQLdb/__init__.py", line 86, in Connect

    return Connection(*args, **kwargs)

  File "/usr/lib/python3/dist-packages/MySQLdb/connections.py", line 204, in __init__

    super(Connection, self).__init__(*args, **kwargs2)

_mysql_exceptions.OperationalError: (2002, "Can't connect to MySQL server on 'diskstation' (115)")

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/home/weewx/bin/weewx/reportengine.py", line 196, in run

    obj.start()

  File "/home/weewx/bin/weewx/reportengine.py", line 281, in start

    self.run()

  File "/home/weewx/bin/weewx/cheetahgenerator.py", line 146, in run

    self.initExtensions(gen_dict[section_name])

  File "/home/weewx/bin/weewx/cheetahgenerator.py", line 190, in initExtensions

    self.search_list_objs.append(class_(self))

  File "/home/weewx/bin/weewx/cheetahgenerator.py", line 499, in __init__

    archive = self.generator.db_binder.get_manager(binding)

  File "/home/weewx/bin/weewx/manager.py", line 534, in get_manager

    self.manager_cache[data_binding] = open_manager(manager_dict, initialize)

  File "/home/weewx/bin/weewx/manager.py", line 687, in open_manager

    manager_dict['table_name'])

  File "/home/weewx/bin/weewx/manager.py", line 129, in open

    connection = weedb.connect(database_dict)

  File "/home/weewx/bin/weedb/__init__.py", line 92, in connect

    return driver_mod.connect(**db_dict)

  File "/home/weewx/bin/weedb/mysql.py", line 70, in connect

    database_name=database_name, engine=engine, autocommit=autocommit, **kwargs)

  File "/home/weewx/bin/weedb/mysql.py", line 61, in guarded_fn

    raise klass(e)

weedb.CannotConnectError: (2002, "Can't connect to MySQL server on 'diskstation' (115)")

Traceback (most recent call last):

  File "/home/weewx/bin/weedb/mysql.py", line 52, in guarded_fn

    return fn(*args, **kwargs)

  File "/home/weewx/bin/weedb/mysql.py", line 133, in __init__

    db=database_name, **kwargs)

  File "/usr/lib/python3/dist-packages/MySQLdb/__init__.py", line 86, in Connect

    return Connection(*args, **kwargs)

  File "/usr/lib/python3/dist-packages/MySQLdb/connections.py", line 204, in __init__

    super(Connection, self).__init__(*args, **kwargs2)

_mysql_exceptions.OperationalError: (2002, "Can't connect to MySQL server on 'diskstation' (115)")

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/home/weewx/bin/weewx/reportengine.py", line 196, in run

    obj.start()

  File "/home/weewx/bin/weewx/reportengine.py", line 281, in start

    self.run()

  File "/home/weewx/bin/weewx/imagegenerator.py", line 41, in run

    self.genImages(self.gen_ts)

  File "/home/weewx/bin/weewx/imagegenerator.py", line 88, in genImages

    db_manager = self.db_binder.get_manager(binding)

  File "/home/weewx/bin/weewx/manager.py", line 534, in get_manager

    self.manager_cache[data_binding] = open_manager(manager_dict, initialize)

  File "/home/weewx/bin/weewx/manager.py", line 687, in open_manager

    manager_dict['table_name'])

  File "/home/weewx/bin/weewx/manager.py", line 129, in open

    connection = weedb.connect(database_dict)

  File "/home/weewx/bin/weedb/__init__.py", line 92, in connect

    return driver_mod.connect(**db_dict)

  File "/home/weewx/bin/weedb/mysql.py", line 70, in connect

    database_name=database_name, engine=engine, autocommit=autocommit, **kwargs)

  File "/home/weewx/bin/weedb/mysql.py", line 61, in guarded_fn

    raise klass(e)

weedb.CannotConnectError: (2002, "Can't connect to MySQL server on 'diskstation' (115)")

Traceback (most recent call last):

  File "/home/weewx/bin/weedb/mysql.py", line 52, in guarded_fn

    return fn(*args, **kwargs)

  File "/home/weewx/bin/weedb/mysql.py", line 133, in __init__

    db=database_name, **kwargs)

  File "/usr/lib/python3/dist-packages/MySQLdb/__init__.py", line 86, in Connect

    return Connection(*args, **kwargs)

  File "/usr/lib/python3/dist-packages/MySQLdb/connections.py", line 204, in __init__

    super(Connection, self).__init__(*args, **kwargs2)

_mysql_exceptions.OperationalError: (2002, "Can't connect to MySQL server on 'diskstation' (115)")

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/home/weewx/bin/weewx/reportengine.py", line 196, in run

    obj.start()

  File "/home/weewx/bin/weewx/reportengine.py", line 281, in start

    self.run()

  File "/home/weewx/bin/weewx/cheetahgenerator.py", line 146, in run

    self.initExtensions(gen_dict[section_name])

  File "/home/weewx/bin/weewx/cheetahgenerator.py", line 190, in initExtensions

    self.search_list_objs.append(class_(self))

  File "/home/weewx/bin/weewx/cheetahgenerator.py", line 499, in __init__

    archive = self.generator.db_binder.get_manager(binding)

  File "/home/weewx/bin/weewx/manager.py", line 534, in get_manager

    self.manager_cache[data_binding] = open_manager(manager_dict, initialize)

  File "/home/weewx/bin/weewx/manager.py", line 687, in open_manager

    manager_dict['table_name'])

  File "/home/weewx/bin/weewx/manager.py", line 129, in open

    connection = weedb.connect(database_dict)

  File "/home/weewx/bin/weedb/__init__.py", line 92, in connect

    return driver_mod.connect(**db_dict)

  File "/home/weewx/bin/weedb/mysql.py", line 70, in connect

    database_name=database_name, engine=engine, autocommit=autocommit, **kwargs)

  File "/home/weewx/bin/weedb/mysql.py", line 61, in guarded_fn

    raise klass(e)

weedb.CannotConnectError: (2002, "Can't connect to MySQL server on 'diskstation' (115)")

0:00:08.384725

1000.589306640625

[1000.06640625, 999.97119140625, 1001.36669921875, 1000.1455078125, 1000.163330078125, 999.9951171875, 1000.04296875, 1000.19921875, 1001.275146484375, 1001.266845703125]

LOOP:   2021-02-13 02:57:28 CET (1613181448) altimeter: 30.222221545855962, barometer: 30.262156773782465, cloudbase: 1454.6444807035157, dateTime: 1613181448, dewpoint: 24.9344792686867, extraTemp2: 66.2, heatindex: 28.58, humidex: 28.58, inDewpoint: 39.49696677266399, inHumidity: 39.373779296875, inTemp: 64.79432678222656, maxSolarRad: 0.0, outHumidity: 86.0, outTemp: 28.58, outTempBatteryStatus: 1, outTempDay: None, outTempNight: 28.58, pressure: 29.543253645019227, radiation: 0.0, rainRate: 0.0, usUnits: 1

0:00:27.803524

1000.4492431640625

[1000.06640625, 999.97119140625, 1001.279296875, 1000.1455078125, 1000.163330078125, 999.9951171875, 1000.04296875, 1000.19921875, 1001.275146484375, 1001.266845703125]

LOOP:   2021-02-13 02:57:56 CET (1613181476) altimeter: 30.221958642886392, dateTime: 1613181476, extraTemp2: 66.2, inDewpoint: 39.50952906952261, inHumidity: 39.3798828125, inTemp: 64.80393981933594, maxSolarRad: 0.0, pressure: 29.542995546007383, radiation: 0.016213107638888887, rain: 0.0, rainBatteryStatus: 1, rainRate: 0.0, rain_total: 86.704, usUnits: 1

0:00:10.993303

1000.4405029296875

[1000.06640625, 999.97119140625, 1001.279296875, 1001.29345703125, 1000.163330078125, 999.9951171875, 1000.04296875, 1000.19921875, 1001.275146484375, 1001.266845703125]

LOOP:   2021-02-13 02:58:06 CET (1613181486) altimeter: 30.22541163041881, dateTime: 1613181486, extraHumid1: 43.0, extraTemp2: 66.18199999999999, extraTemp3: 63.5, inDewpoint: 39.55189165879104, inHumidity: 39.4317626953125, inTemp: 64.81355285644531, inTempBatteryStatus: 1, maxSolarRad: 0.0, pressure: 29.546385438615417, radiation: 0.0, rainRate: 0.0, usUnits: 1

0:00:00.313137

LOOP:   2021-02-13 02:58:07 CET (1613181487) dateTime: 1613181487, extraHumid1: 43.0, extraTemp3: 63.5, inTempBatteryStatus: 1, maxSolarRad: 0.0, rainRate: 0.0, usUnits: 1

0:00:14.156020

1000.5552978515625

[1000.06640625, 999.97119140625, 1001.279296875, 1001.29345703125, 1001.2890625, 999.9951171875, 1000.04296875, 1000.19921875, 1001.275146484375, 1001.266845703125]

LOOP:   2021-02-13 02:58:19 CET (1613181499) altimeter: 30.228797789343705, dateTime: 1613181499, extraTemp2: 66.18199999999999, inDewpoint: 39.459679025970544, inHumidity: 39.3890380859375, inTemp: 64.741455078125, maxSolarRad: 0.0, pressure: 29.54970972505005, radiation: 0.0, rainRate: 0.0, usUnits: 1, UV: 0.0

Traceback (most recent call last):

  File "/home/weewx/bin/user/TCS34725.py", line 115, in __init__

    self.pwm = GPIO.PWM(18, 1000)

RuntimeError: A PWM object already exists for this GPIO channel

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "./bin/weewxd", line 261, in <module>

    main()

  File "./bin/weewxd", line 148, in main

    engine = weewx.engine.StdEngine(config_dict)

  File "/home/weewx/bin/weewx/engine.py", line 93, in __init__

    self.loadServices(config_dict)

  File "/home/weewx/bin/weewx/engine.py", line 161, in loadServices

    obj = weeutil.weeutil.get_object(svc)(self, config_dict)

  File "/home/weewx/bin/user/PiSensewx.py", line 121, in __init__

    self.Light=TCS34725(0X29, debug=False)

  File "/home/weewx/bin/user/TCS34725.py", line 122, in __init__

    loginf(" Exception during GPIO Init "+ str(Exception))

NameError: name 'loginf' is not defined

the mysql exception may be linked to the mysql instance nightly backup. I don't remembet having these on the previous nights.

the loginf is not defined (I botched my traces in exception handling), should have been a print.

;

PISenseWX.py is the fancy name I gave to my extension.

TCS32725.py is the sample python module provided with the pisense for lightsensor use.

[sbar...@gmail.com]

To be complete , the log from messages : 

Feb 13 02:58:10 weatherpi /weewxd: PiSense: Pressure :1000.5552978515625

Feb 13 02:58:11 weatherpi /weewxd: PiSense: Lux:0.0

Feb 13 02:58:24 weatherpi /weewxd: PiSense: Pressure :1000.66787109375

Feb 13 02:58:25 weatherpi /weewxd: PiSense: Lux:0.0

Feb 13 02:58:25 weatherpi weewx[4256] INFO weewx.engine: Main loop exiting. Shutting engine down.

Feb 13 02:58:25 weatherpi weewx[4256] INFO weewx.engine: Shutting down StdReport thread

Feb 13 02:58:25 weatherpi weewx[4256] INFO user.sdr: shutdown process rtl_433 -M utc -F json

Feb 13 02:58:35 weatherpi weewx[4256] INFO user.sdr: timed out waiting for stdout-thread

Feb 13 02:58:45 weatherpi weewx[4256] INFO user.sdr: timed out waiting for stderr-thread

Feb 13 02:59:46 weatherpi weewx[4256] INFO __main__: retrying...

Feb 13 02:59:46 weatherpi weewx[4256] INFO __main__: Using configuration file /home/weewx/weewx.conf

Feb 13 02:59:46 weatherpi weewx[4256] INFO __main__: Debug is 1

Feb 13 02:59:46 weatherpi weewx[4256] INFO weewx.engine: Loading station type SDR (user.sdr)

Feb 13 02:59:46 weatherpi weewx[4256] INFO user.sdr: driver version is 0.78

Feb 13 02:59:46 weatherpi weewx[4256] INFO user.sdr: sensor map is {'windGust': 'wind_gust.0:*.OSWGR800Packet', 'windSpeed': 'wind_speed.0:*.OSWGR800Packet', 'windBatteryStatus': 'battery.0:*.OSWGR800Packet', 'windDir': 'wind_dir.0:*.OSWGR800Packet', 'outHumidity': 'humidity.1:*.OSTHGR810Packet', 'outTemp': 'temperature.1:*.OSTHGR810Packet', 'outTempBatteryStatus': 'battery.1:*.OSTHGR810Packet', 'rain_total': 'rain_total.0:*.OSPCR800Packet', 'rainBatteryStatus': 'battery.0:*.OSPCR800Packet', 'UV': 'uv_index.1:*.OSUV800Packet', 'extraTemp3': 'temperature.1:*.OSBTHGN129Packet', 'extraHumid1': 'humidity.1:*.OSBTHGN129Packet', 'inTempBatteryStatus': 'battery.1:*.OSBTHGN129Packet'}

Feb 13 02:59:46 weatherpi weewx[4256] INFO user.sdr: deltas is {'rain': 'rain_total', 'strikes': 'strikes_total'}

Feb 13 02:59:46 weatherpi weewx[4256] INFO user.sdr: startup process 'rtl_433 -M utc -F json'

Feb 13 02:59:46 weatherpi /weewxd: PiSense: PiSensewx configuration {}

Feb 13 02:59:46 weatherpi /weewxd: PiSense: I2C port: 1

Feb 13 02:59:46 weatherpi /weewxd: PiSense: I2C address: 0x5c

Feb 13 02:59:46 weatherpi /weewxd: PiSense: fallback default units: US

Feb 13 02:59:46 weatherpi weewx[4256] INFO user.sdr: shutdown process rtl_433 -M utc -F json

Feb 13 03:00:03 weatherpi weewx[4256] INFO user.sdr: timed out waiting for stderr-thread

Feb 13 17:29:51 weatherpi weewx[10237] INFO __main__: Initializing weewx version 4.3.0

[gjr80]

Looks pretty clear that the issue is WeeWX losing its connection to the MySQL server. WeeWX will be wanting database access each time it saves records to database (every archive interval seconds) and every report cycle but I don't see WeeWX doing anything to cause the error.

I guess only you know exactly what is going on with backups on your network but I could certainly understand a database backup causing a problem each day at 3am. Also, if the MySQL database is on another server that adds additional fragility. Does the problem go away if you turn off the backup one morning (if you can) or temporarily have WeeWX use a local (to the RPi) SQLite or MySQL database? If so perhaps you need to re-jig your backup strategy. There have been a number of threads re db backup in weew-user over the years, they may provide some insights.

Gary

[Ryan Stasel]

If the database is myisam format that could cause it to fail to write during backups. 

I personally shut down weewx nightly to do my backups just so I get a clean backup. So you may want to have weewx shutdown just before your backup job kicks off then start back up again. 

On Feb 13, 2021, at 17:37, gjr80 <gjrod...@gmail.com> wrote:



--
You received this message because you are subscribed to the Google Groups "weewx-development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-developm...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/weewx-development/d8d5ce00-7442-445b-bc6c-d4183b89fcb9n%40googlegroups.com.

[sbar...@gmail.com]

Hi,

Thank you for the information. I looked into tonight's log and sure enough the issue happened, but my weewx did not fully crash because the exception was properly trapped this time.

So there were 2 crashes  : 1 at 2:57 and 1 à 3:00. These are the start time for the backup tasks that apply to mysql database server.

FWIW : my message log shows no database issue what so ever at that time.

And my own log does not because I do not know how to print a full traceback in python.

Now comes the naïve question : Why would weewx die on mysql exception and not just trap & log them? At least database related operation problems would not kill the app, and it give the opportunity to assume the outage is temporary, keep the records in memory and flush them when the database comes back.

[gjr80]

I don’t know about anyone else but I’m confused. Why run WeeWX directly with redirected stderr and WeeWX logging to syslog when you can run WeeWX as a daemon and have the whole lot go to syslog. That way you have the whole story chronologically timestamped in one place, the syslog. If it is imperative that you run WeeWX directly then skip the stderr redirection, WeeWX will log all errors it encounters to syslog.

As for traceback, when WeeWX encounters an error if it’s serious enough it will case an error trace to be written to syslog. If it’s not serious enough it will still be logged.

Gary

[sbar...@gmail.com]

Well, I used to run as daemon since the beginning as it is suggested in the docs.

But I found that errors and exception do not go in messages in my setup. I ran weewx from the command line at one point in time, and saw that way more info was coming on the output, as well as stack traces.

That's why I run with stderr redirection and not just -d.

[Cameron D]

The MySQL server may be the trigger but not the actual problem.

Some time ago it used to be the case on my system that Weewx would exit whenever the MySQL server was restarted, such as during an upgrade.

My recollection was that weewx was changed to try harder to restart under these conditions, some time during the late 3.x versions.

On the other hand, sometime around those months I moved weewx to the same server that was running MariaDB and then

I could have systemd unit file that tells it of the dependency.

I just tried disabling the "BindsTo=mysql.service" and I see in the logs: 

  .. CRITICAL __main__: Database connection exception: (2006, 'MySQL server has gone away')

  .. CRITICAL __main__:     ****  Waiting 60 seconds then retrying...

And then weewx reinitialises with the same PID  rather than as a new process.

Is it possible that there is something  in your code that cannot cope with the initialisation code being run again?

When I do my mysqldump backups, there is no evidence of any interruption to weewx  in the log files. However my tables are all innodb.