As asked earlier in this thread I changed debug=0 to debug=1 in weewx..conf. From then it started to log to /var/log/weewx.log. I thought this was the normal behaviour? Before, when debug=0, it all was logged to /var/log/syslog. I am a bit confused now on what to show you here from what logfile.
Op donderdag 26 december 2019 23:34:19 UTC+1 schreef Thomas Keffer: > > It looks to me that neither of these last two log excerpts correspond with > the earlier ones you posted. The first is the wrong date (the crash > happened on the 24th, not the 25th), and the second is too early in the day. > > I'm surprised you are not seeing weewx entries in /var/log/syslog. Did you > change the logging in any way? > > I should add that I am traveling, so I do not have an RPi available to > remind me of what gets logged where. > > -tk > > On Thu, Dec 26, 2019 at 8:37 AM Franklin Bockstael <[email protected] > <javascript:>> wrote: > >> Hi Thomas. >> >> We are looking at /var/log/weewx.log >> This is the output of /var/log/syslog around the time of the first error >> >> Dec 25 17:11:51 Grandix rngd[526]: stats: entropy added to kernel pool: >> 724608 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2 successes: 39 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2 failures: 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2(2001-10-10) Monobit: >> 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2(2001-10-10) Poker: 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2(2001-10-10) Runs: 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2(2001-10-10) Long >> run: 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS 140-2(2001-10-10) >> Continuous run: 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: HRNG source speed: (min=86.238; >> avg=499.925; max=835.776)Kibits/s >> Dec 25 17:11:51 Grandix rngd[526]: stats: FIPS tests speed: (min=1.401; >> avg=4.988; max=6.191)Mibits/s >> Dec 25 17:11:51 Grandix rngd[526]: stats: Lowest ready-buffers level: 2 >> Dec 25 17:11:51 Grandix rngd[526]: stats: Entropy starvations: 0 >> Dec 25 17:11:51 Grandix rngd[526]: stats: Time spent starving for >> entropy: (min=0; avg=0.000; max=0)us >> Dec 25 17:15:01 Grandix CRON[13002]: (pi) CMD (/home/pi/upload > >> /dev/null) >> Dec 25 17:15:01 Grandix CRON[13003]: (pi) CMD (/home/pi/launch.sh) >> Dec 25 17:15:01 Grandix CRON[12994]: (CRON) info (No MTA installed, >> discarding output) >> Dec 25 17:17:01 Grandix CRON[13028]: (root) CMD ( cd / && run-parts >> --report /etc/cron.hourly) >> Dec 25 17:20:01 Grandix CRON[13046]: (pi) CMD (/home/pi/launch.sh) >> Dec 25 17:20:01 Grandix CRON[13047]: (pi) CMD (/home/pi/upload > >> /dev/null) >> Dec 25 17:20:01 Grandix CRON[13038]: (CRON) info (No MTA installed, >> discarding output) >> >> >> And on the time of the second error >> >> Dec 25 22:15:02 Grandix CRON[14832]: (pi) CMD (/home/pi/launch.sh) >> Dec 25 22:15:02 Grandix CRON[14833]: (pi) CMD (/home/pi/upload > >> /dev/null) >> Dec 25 22:15:02 Grandix CRON[14823]: (CRON) info (No MTA installed, >> discarding output) >> Dec 25 22:17:01 Grandix CRON[14855]: (root) CMD ( cd / && run-parts >> --report /etc/cron.hourly) >> Dec 25 22:20:01 Grandix CRON[14874]: (pi) CMD (/home/pi/upload > >> /dev/null) >> Dec 25 22:20:01 Grandix CRON[14877]: (pi) CMD (/home/pi/launch.sh) >> Dec 25 22:20:01 Grandix CRON[14866]: (CRON) info (No MTA installed, >> discarding output) >> Dec 25 22:22:30 Grandix kernel: [ 0.000000] Booting Linux on physical >> CPU 0x0 >> Dec 25 22:22:30 Grandix fake-hwclock[82]: Wed 25 Dec 21:17:01 UTC 2019 >> >> >> The fake-hwclock is giving a time of 21:17:01 wich should be 21:22:30. >> This is more than 300 seconds difference (the time between 2 messages from >> the Vantage console?). Am I very wrong if Isuspect this is the thing that >> is giving me those errors and freezes? >> >> Several pid on startup is caused by me rebooting manually the RPi but in >> the log I sometimes find multiple instances of weewx or a new instance with >> aother pid. >> The question is why the RPi is thinking it should start a new weewx >> process. >> I looked at top and there is nothing abnormal there. Just one process of >> weewx and no abnormal load. Weewx is the only process that is running on >> that RPi. >> What I see with that strange thing is the dates of occuring and the >> timestamp that is mentioned in the log. >> >> Op donderdag 26 december 2019 13:22:38 UTC+1 schreef Thomas Keffer: >>> >>> Could be a systemd issue. Perhaps your RPi was low on memory, and >>> systemd had to kill weewxd? >>> >>> Things to try: >>> 1. Which log are we looking at here? If it's a systemd issue, it should >>> have told us that it is killing a process. But, not all logs show all >>> messages, so it's possible that the systemd messages are ending up >>> someplace else. >>> 2. There are several process IDs appearing on start up. Double check >>> that only one instance of weewxd is running. >>> 3. Using a tool such as "top", check the amount of memory that's >>> available. Do you have other things besides weewxd running? >>> 4. The "strange things happening with strange timestamps" looks normal >>> to me. What is catching your eye here? >>> >>> -tk >>> >>> On Thu, Dec 26, 2019 at 2:35 AM Franklin Bockstael <[email protected]> >>> wrote: >>> >>>> >>>> 1. I obeserved this until now and had some time without errors. But >>>> suddenly on Christmas Eve there they were again. The system is >>>> installed on >>>> a fresh SANDISK sd-card with latest weewx on a RPi B. In my log file I >>>> find >>>> this: >>>> >>>> Dec 24 17:15:22 Grandix weewx[629]: cheetahgenerator: Generated 2 files >>>> for report StandardReport in 2.10 seconds >>>> Dec 24 17:15:22 Grandix weewx[629]: reportengine: Running report 'FTP' >>>> Dec 24 17:15:22 Grandix weewx[629]: reportengine: Found configuration >>>> file /home/weewx/skins/Ftp/skin.conf for report 'FTP' >>>> Dec 24 17:15:22 Grandix weewx[629]: ftpupload: Attempting connection to >>>> grandix.nl >>>> Dec 24 17:15:22 Grandix weewx[629]: ftpupload: Connected to grandix.nl >>>> Dec 24 17:15:22 Grandix weewx[629]: ftpupload: Uploaded file >>>> /grandixweerdata.htm >>>> Dec 24 17:15:22 Grandix weewx[629]: ftpupload: Uploaded file >>>> /openweerdata.htm >>>> Dec 24 17:15:22 Grandix weewx[629]: ftpgenerator: ftp'd 2 files in 0.33 >>>> seconds >>>> Dec 24 17:15:22 Grandix weewx[629]: reportengine: Report 'RSYNC' not >>>> enabled. Skipping. >>>> Dec 24 17:18:08 Grandix weewx[629]: engine: Received signal TERM (15). >>>> Dec 24 17:18:08 Grandix weewx[629]: engine: Main loop exiting. Shutting >>>> engine down. >>>> Dec 24 17:18:08 Grandix weewx[629]: engine: Shutting down StdReport >>>> thread >>>> Dec 24 17:18:08 Grandix weewx[629]: engine: StdReport thread has been >>>> terminated >>>> Dec 24 17:18:08 Grandix weewx[629]: restx: Shut down AWEKAS thread. >>>> Dec 24 17:18:08 Grandix weewx[629]: restx: Shut down WOW thread. >>>> Dec 24 17:18:08 Grandix weewx[629]: restx: Shut down CWOP thread. >>>> Dec 24 17:18:08 Grandix weewx[629]: restx: Shut down PWSWeather thread. >>>> Dec 24 17:18:08 Grandix weewx[629]: restx: Shut down Wunderground-PWS >>>> thread. >>>> Dec 24 17:18:08 Grandix weewx[629]: engine: Terminating weewx version >>>> 3.9.2 >>>> Dec 24 17:18:08 Grandix weewx[629]: **** Traceback (most recent >>>> call last): >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 894, in main >>>> Dec 24 17:18:08 Grandix weewx[629]: **** engine.run() >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 188, in run >>>> Dec 24 17:18:08 Grandix weewx[629]: **** for packet in >>>> self.console.genLoopPackets(): >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/home/weewx/bin/weewx/drivers/vantage.py", line 508, in genLoopPackets >>>> Dec 24 17:18:08 Grandix weewx[629]: **** for _loop_packet in >>>> self.genDavisLoopPackets(200): >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/home/weewx/bin/weewx/drivers/vantage.py", line 535, in >>>> genDavisLoopPackets >>>> Dec 24 17:18:08 Grandix weewx[629]: **** _buffer = >>>> self.port.read(99) >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/home/weewx/bin/weewx/drivers/vantage.py", line 256, in read >>>> Dec 24 17:18:08 Grandix weewx[629]: **** _buffer = >>>> self.serial_port.read(chars) >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/usr/lib/python2.7/dist-packages/serial/serialposix.py", line 472, in read >>>> Dec 24 17:18:08 Grandix weewx[629]: **** ready, _, _ = >>>> select.select([self.fd, self.pipe_abort_read_r], [], [], >>>> timeout.time_left()) >>>> Dec 24 17:18:08 Grandix weewx[629]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 812, in sigTERMhandler >>>> Dec 24 17:18:08 Grandix weewx[629]: **** raise Terminate >>>> Dec 24 17:18:08 Grandix weewx[629]: **** Terminate >>>> Dec 24 17:18:14 Grandix weewx[750]: Stopping weewx weather system: >>>> weewx.. >>>> Dec 24 17:18:15 Grandix weewx[792]: engine: Initializing weewx version >>>> 3.9.2 >>>> Dec 24 17:18:15 Grandix weewx[792]: engine: Using Python 2.7.13 >>>> (default, Sep 26 2018, 18:42:22) #012[GCC 6.3.0 20170516] >>>> Dec 24 17:18:15 Grandix weewx[792]: engine: Platform >>>> Linux-4.19.66+-armv6l-with-debian-9.9 >>>> Dec 24 17:18:15 Grandix weewx[792]: engine: Locale is 'en_GB.UTF-8' >>>> Dec 24 17:18:15 Grandix weewx[792]: engine: pid file is >>>> /var/run/weewx.pid >>>> Dec 24 17:18:16 Grandix weewx[781]: Starting weewx weather system: >>>> weewx. >>>> >>>> >>>> And on Christmas Dayon 22:20again, this time out of the blue: >>>> >>>> Dec 25 22:20:28 Grandix weewx[796]: ftpupload: Uploaded file >>>> /openweerdata.htm >>>> Dec 25 22:20:28 Grandix weewx[796]: ftpgenerator: ftp'd 2 files in 0.34 >>>> seconds >>>> Dec 25 22:20:28 Grandix weewx[796]: reportengine: Report 'RSYNC' not >>>> enabled. Skipping. >>>> Dec 25 22:20:35 Grandix weewx[796]: restx: WOW: Failed upload attempt >>>> 1: timed out >>>> Dec 25 22:20:40 Grandix weewx[796]: restx: WOW: Failed upload attempt >>>> 2: HTTP Error 429: Too frequent observations. >>>> Dec 25 22:20:45 Grandix weewx[796]: restx: WOW: Failed upload attempt >>>> 3: HTTP Error 429: Too frequent observations. >>>> Dec 25 22:20:50 Grandix weewx[796]: restx: WOW: Failed to publish >>>> record 2019-12-25 22:20:00 CET (1577308800): Failed upload after 3 tries >>>> Dec 25 22:23:01 Grandix weewx[574]: engine: Initializing weewx version >>>> 3.9.2 >>>> Dec 25 22:23:01 Grandix weewx[574]: engine: Using Python 2.7.13 >>>> (default, Sep 26 2018, 18:42:22) #012[GCC 6.3.0 20170516] >>>> Dec 25 22:23:01 Grandix weewx[574]: engine: Platform >>>> Linux-4.19.66+-armv6l-with-debian-9.11 >>>> >>>> >>>> Later that evening: >>>> >>>> Dec 25 23:18:01 Grandix weewx[594]: restx: Unable to shut down WOW >>>> thread >>>> Dec 25 23:18:01 Grandix weewx[594]: restx: Shut down CWOP thread. >>>> Dec 25 23:18:01 Grandix weewx[594]: restx: Shut down PWSWeather thread. >>>> Dec 25 23:18:01 Grandix weewx[594]: restx: Shut down Wunderground-PWS >>>> thread. >>>> Dec 25 23:18:01 Grandix weewx[594]: engine: Terminating weewx version >>>> 3.9.2 >>>> Dec 25 23:18:01 Grandix weewx[594]: **** Traceback (most recent >>>> call last): >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 894, in main >>>> Dec 25 23:18:01 Grandix weewx[594]: **** engine.run() >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 191, in run >>>> Dec 25 23:18:01 Grandix weewx[594]: **** >>>> self.dispatchEvent(weewx.Event(weewx.NEW_LOOP_PACKET, packet=packet)) >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 224, in dispatchEvent >>>> Dec 25 23:18:01 Grandix weewx[594]: **** callback(event) >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 546, in new_loop_packet >>>> Dec 25 23:18:01 Grandix weewx[594]: **** >>>> self.accumulator.addRecord(event.packet, add_hilo=self.loop_hilo) >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/accum.py", line 260, in addRecord >>>> Dec 25 23:18:01 Grandix weewx[594]: **** func(self, record, >>>> obs_type, add_hilo, weight) >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/accum.py", line 319, in add_value >>>> Dec 25 23:18:01 Grandix weewx[594]: **** >>>> self[obs_type].addSum(val, weight=weight) >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/accum.py", line 96, in addSum >>>> Dec 25 23:18:01 Grandix weewx[594]: **** self.sum += val >>>> Dec 25 23:18:01 Grandix weewx[594]: **** File >>>> "/home/weewx/bin/weewx/engine.py", line 812, in sigTERMhandler >>>> Dec 25 23:18:01 Grandix weewx[594]: **** raise Terminate >>>> Dec 25 23:18:01 Grandix weewx[594]: **** Terminate >>>> Dec 25 23:18:02 Grandix weewx[653]: Stopping weewx weather system: >>>> weewx..... >>>> Dec 25 23:18:04 Grandix weewx[730]: engine: Initializing weewx version >>>> 3.9.2 >>>> Dec 25 23:18:04 Grandix weewx[730]: engine: Using Python 2.7.13 >>>> (default, Sep 26 2018, 18:42:22) #012[GCC 6.3.0 20170516] >>>> Dec 25 23:18:04 Grandix weewx[730]: engine: Platform >>>> Linux-4.19.66+-armv6l-with-debian-9.11 >>>> Dec 25 23:18:04 Grandix weewx[730]: engine: Locale is 'en_GB.UTF-8' >>>> Dec 25 23:18:04 Grandix weewx[730]: engine: pid file is >>>> /var/run/weewx.pid >>>> Dec 25 23:18:04 Grandix weewx[719]: Starting weewx weather system: >>>> weewx. >>>> Dec 25 23:18:05 Grandix weewx[734]: engine: Using configuration file >>>> /home/weewx/weewx.conf >>>> Dec 25 23:18:05 Grandix weewx[734]: engine: Debug is 1 >>>> Dec 25 23:18:05 Grandix weewx[734]: engine: Initializing engine >>>> >>>> >>>> >>>> When the second process weewx starts the RPi cuts off all posibility to >>>> connect to it via ssh and cannot ping the RPi. So I have to reboot the >>>> RPi, >>>> restart the weewx process again and then everything is running ok for some >>>> time (longer or shorter). I ordered a hardware RTC but did not receive it >>>> yet. >>>> What I can't understand is that it worked flawless for years and >>>> suddenly it is giving me all these trouble I don't understand. >>>> What can I do more? >>>> >>>> Another issue in the log files I can't explain is this: >>>> Dec 24 23:30:20 Grandix weewx[796]: vantage: DMPAFT complete: page >>>> timestamp 2019-12-16 02:15:00 CET (1576458900) less than final timestamp >>>> 2019-12-24 23:30:00 CET (1577226600) >>>> Dec 24 23:30:20 Grandix weewx[796]: vantage: Catch up complete. >>>> Dec 24 23:30:20 Grandix weewx[796]: vantage: Requesting 200 LOOP >>>> packets. >>>> Dec 24 23:30:20 Grandix weewx[796]: vantage: Gentle wake up of console >>>> successful >>>> >>>> >>>> Why is this strange thing happening with strange timestamps? >>>> >>>> >>>> >>>> >>>> Op maandag 4 november 2019 16:10:43 UTC+1 schreef vince: >>>>> >>>>> On Monday, November 4, 2019 at 1:35:30 AM UTC-8, Franklin Bockstael >>>>> wrote: >>>>> >>>>>> The uptime is not so important I guess. Everytime this error occurs >>>>>> the pi becomes unresponsive and I have to reboot. Iti s not a real long >>>>>> time that it is on because this happens sometimes twice a day and then >>>>>> not >>>>>> for a few weeks. >>>>>> >>>>> >>>>> You're not telling us what 'unresponsive' means. Can you ping it ? >>>>> >>>>> A pi that is unresponsive over wifi, especially a model-B, is >>>>> typically it losing its wifi connection if you have an after-market wifi >>>>> dongle plugged into USB. I used to see that frequently years ago on my >>>>> model-B cards before I got a much more powerful wifi access point. >>>>> >>>>> I turned on debug now and restarted weewx. I have to wait till this >>>>>> happens again. >>>>>> >>>>>> >>>>> That is always the next step. >>>>> >>>>> You're not giving us enough information to help much here. You could >>>>> be out of ram. You could have a SD card that is throwing errors. You >>>>> could have poor power on the pi. Far too many possibilities with no >>>>> real >>>>> data from you that we can go on. >>>>> >>>> -- >>>> 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/cfb9d670-22ae-4e34-9e61-b2173cf6cc35%40googlegroups.com >>>> >>>> <https://groups.google.com/d/msgid/weewx-user/cfb9d670-22ae-4e34-9e61-b2173cf6cc35%40googlegroups.com?utm_medium=email&utm_source=footer> >>>> . >>>> >>> -- >> 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] <javascript:>. >> To view this discussion on the web visit >> https://groups.google.com/d/msgid/weewx-user/ea648256-3906-4bc0-8ee2-5580ae9509b7%40googlegroups.com >> >> <https://groups.google.com/d/msgid/weewx-user/ea648256-3906-4bc0-8ee2-5580ae9509b7%40googlegroups.com?utm_medium=email&utm_source=footer> >> . >> > -- 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/64fa6bcf-4542-4e9b-ab6d-546090904d02%40googlegroups.com.
