Weewx, R.Pi and Vantage Pro 2

[Matthew VK3EVL]

Hi All,
ok so heres another of those dreaded web page not updating but i refuse to believe it is a corrupted memory error on the console.
i have done a lot of debugging as i can replicate the issue but unfortunately my knowledge comes to screaming halt when i reach python.

My setup
Raspberry Pi running weewx
Synology NAS which runs a MySQL database that weewx uses plus it also runs Apache where weewx uploads to.
I have a vantage pro 2 plus with a serial logger in it.
Everything is in to a UPS giving me 40 min of run time at which point "NUT" triggers the raspberry pi to shut down cleanly and then the NAS.

I have something (or a multitude of things combined) that trips out my RCD. unfortunately this setup is on the same circuit.

sequence of events
power goes out
UPS kicks in.
When UPS battery is exhausted everything is shutdown gracefully.
When power is restored, everything fires up and all the archive records are retrieved from the console up to the point the power is restored.
The web page is updated based on the time of restoration.
But then the web page stops updating.

i'm seeing this in the log

Oct 11 22:06:15 weatherpi weewx[2642]: VantagePro: Getting archive packets since 2013-10-11 17:25:00 EST (1381472700)
Oct 11 22:06:15 weatherpi weewx[2642]: VantagePro: successfully woke up console
Oct 11 22:06:15 weatherpi weewx[2642]: VantagePro: Retrieving 57 page(s); starting index= 1
Oct 11 22:06:15 weatherpi weewx[2642]: VantagePro: DMPAFT complete: page timestamp 2013-10-11 10:48:00 EST (1381448880) less than final timestamp 2013-10-11 17:25:00 EST (1381472700)
Oct 11 22:06:15 weatherpi weewx[2642]: VantagePro: Catch up complete.

10:48 is when the UPS exhausted 17:25 is when power was restored (give or take a few minutes)

I went to the stats db and checked the metadata table where the last update was showing the current time and still updating

I went in to the weewx database and run
DELETE FROM `weather_weewx`.`archive` WHERE `archive`.`dateTime` > 1381448880;
It now sees the 1381448880 entry as the last entry. When it receives that from the console it does not fail. Strangely It successfully downloads everything from 17:27 onwards in this case but not from 10:48

Oct 11 23:09:15 weatherpi weewx[2827]: VantagePro: Getting archive packets since 2013-10-11 10:48:00 EST (1381448880)
Oct 11 23:09:15 weatherpi weewx[2827]: VantagePro: successfully woke up console
Oct 11 23:09:15 weatherpi weewx[2827]: VantagePro: Retrieving 69 page(s); starting index= 2
Oct 11 23:09:16 weatherpi weewx[2827]: Archive: added archive record 2013-10-11 17:27:00 EST (1381472820)
Oct 11 23:09:16 weatherpi weewx[2827]: Archive: added archive record 2013-10-11 17:28:00 EST (1381472880)

but i have now lost the data between the power outage and restoration because i deleted it. Now of course i took a backup and can re-insert it.

reading through the davis serial protocol it says the following

"In order to use the "DMPAFT" command you need to determine the time and date-stamp of the last record that you already have, AND this record should match one of the records already archived in the WeatherLink data logger. (if the data is not found, then the entire contents of the data archive will be downloaded.)"

now i suspect that the 17:26 record hasn't been archived on the console because it was to busy playing catchup for weewx.
when weewx says, ok give me everything after XXX i think it may be asking for 17:26.
as the 17:26 record doesn't exist, it starts from earlier, weewx recognises this as the data having looped therefore doesn't download any more.

i am at a loss as to why i don't get the 10:48 to 17:25 records though.



another separate but somewhat related issue as i tried using it whilst troubleshooting the above problem.
I run the console and DB in metric. It stores the data in the DB as type 16. When i run a dump it seems to think the dump data is type 1 so the dump fails as there is a mismatch between the data and DB.


I hope this is descriptive enough Tom and maybe it might trigger an idea as to why this is happening :)

Please yell out if you want more info.

Cheers
Matthew

[Thomas Keffer]

That's about the most thorough analysis I've seen of this recurring problem. It sure would be nice to solve it!

Just to confirm, it looks like you're using a one minute archive interval. Is that correct?

It is possible to get a summary of what records the console has in its logger memory. Do this:

  1. Stop weewx

  2. Run wee_config_vantage /home/weewx/weewx.conf --logger-summary=/tmp/summary.log

This will take a couple minutes. Look through the file /tmp/summary.log. It contains record number, page number, index number. Are the records betwen 10:48 and 17:25 in there? How about the 17:26 record? What is the latest record?

Your experience suggests that we need a utility that "resynchronizes" the VP and the database, by going through all the data in the logger, looking for the last timestamp, and using that as the last valid time, rather than what's in the database. Because it would take a couple minutes to run, it would only be used on an "as needed" basis.

The Davis console logger always stores things in US Customary. When you change to metric units on the console, all you're doing is changing what is displayed, not what is stored.

-tk

Tom Keffer

kef...@threefools.org
+1 541-386-8891 (h)
+1 541-490-9507 (c)

Skype: tkeffer

--
You received this message because you are subscribed to the Google Groups "Weewx user's group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Matthew VK3EVL]

Hi Tom,
1 minute archive interval is correct.
the log is a little interesting and explains why your script is doing what it is doing.

1324  264    4 | 2013-10-11 17:24 | 2013-10-11 17:24:00 EST (1381472640)
1325  265    0 | 2013-10-11 17:25 | 2013-10-11 17:25:00 EST (1381472700)
1326  265    1 | 2013-10-11 10:48 | 2013-10-11 10:48:00 EST (1381448880)
1327  265    2 | 2013-10-11 17:27 | 2013-10-11 17:27:00 EST (1381472820)
1328  265    3 | 2013-10-11 17:28 | 2013-10-11 17:28:00 EST (1381472880)

You ask for everything after record 1325. it sends 1326 and with the timestamp it has, plus the expected loop behaviour, the script rightly terminates the dump. There is a correctly stamped record for 10:48

given enough time for the logger to loop (1.7 days in my case i believe), this would actually fix itself losing 1 minute of data. not so fortunate for those running longer archive intervals.
What is curious though is where it gets the time to log this in the first place.

So this got me thinking. The Raspberry Pi hardware itself does not have a hardware clock. It sets its time on bootup using NTP. Looking back through the logs, it shutdown at 10:42 then booted up at 10:42. even though it booted some 7 hours later.
Once my NAS is up and running (which contains my mysql db) weewx will start working. However, my internet is still not working as yet.
so lets look at this syslog.

Oct 11 10:47:09 weatherpi weewx[2085]: wxengine: Using configuration file /etc/weewx/weewx.conf
Oct 11 10:47:09 weatherpi weewx[2085]: wxengine: Loading station type Vantage (weewx.drivers.vantage)
Oct 11 10:47:10 weatherpi weewx[2085]: wxengine: StdConvert target unit is 0x10
Oct 11 10:47:10 weatherpi weewx[2085]: wxengine: Using station hardware archive interval of 60
Oct 11 10:47:10 weatherpi weewx[2085]: wxengine: Record generation will be attempted in 'hardware'
Oct 11 10:47:10 weatherpi weewx[2085]: wxengine: Using archive database: archive_mysql
Oct 11 10:47:11 weatherpi weewx[2085]: stats: stats database up to date.
Oct 11 10:47:11 weatherpi weewx[2085]: wxengine: Using stats database: stats_mysql
Oct 11 10:47:11 weatherpi weewx[2085]: wxengine: Starting up weewx version 2.4.0
Oct 11 10:47:11 weatherpi weewx[2085]: wxengine: Clock error is 23902.69 seconds (positive is fast)
Oct 11 10:47:12 weatherpi weewx[2085]: VantagePro: Clock set to 2013-10-11 10:47:11 EST (1381448831)
Oct 11 10:47:13 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:43:00 EST (1381448580)
Oct 11 10:47:14 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:44:00 EST (1381448640)
Oct 11 10:47:14 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:45:00 EST (1381448700)
Oct 11 10:47:14 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:46:00 EST (1381448760)
Oct 11 10:47:14 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:47:00 EST (1381448820)
Oct 11 10:47:14 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:48:00 EST (1381448880)
Oct 11 10:47:15 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:49:00 EST (1381448940)
Oct 11 10:47:15 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:50:00 EST (1381449000)
Oct 11 10:47:15 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 10:51:00 EST (1381449060)

then the internet link comes up and the time is updated (noting timestamps)

Oct 11 10:47:33 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 12:26:00 EST (1381454760)
Oct 11 10:47:33 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 12:27:00 EST (1381454820)
Oct 11 17:25:58 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 12:28:00 EST (1381454880)
Oct 11 17:25:58 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 12:29:00 EST (1381454940)

scroll a bit further (note i'm dropping the wunderground entries out for clarity)

Oct 11 17:26:54 weatherpi weewx[2085]: Archive: added archive record 2013-10-11 17:25:00 EST (1381472700)
Oct 11 17:26:54 weatherpi weewx[2085]: wxengine: Starting main packet loop.
Oct 11 17:26:54 weatherpi weewx[2085]: wxengine: Clock error is -23906.23 seconds (positive is fast)
Oct 11 17:26:55 weatherpi weewx[2085]: VantagePro: Clock set to 2013-10-11 17:26:54 EST (1381472814)
Oct 11 17:27:02 weatherpi weewx[2085]: VantagePro: LOOP #1; read error. Try #1
Oct 11 17:27:02 weatherpi weewx[2085]:       ****  Expected to read 99 chars; got 0 instead

It has 3 tries then seems to work as designed from then on.



soooooo

in essence, with your guidance, i think we have the following conclusions.
your script runs exactly as it was designed to.
this problem will eventually rectify itself once the logger loops data, this may be a very long time dependant on your archive interval.
It is a specific issue with raspberry pi resulting from a race condition when recovering from a power outage whilst not having internet connectivity to update its time it incorrectly updates the console time resulting in an incorrect timestamp.
I imagine this is going to be an issue when daylight savings stops as well when the time goes backwards an hour.

I see a couple of solutions
install a hardware clock on the pi. This will fix all but the daylight savings issue but requires removal of the package fake-hwclock which is a standard part of the debian ras-pi distribution and it will require modifying the kernel as well.
Whilst this is achievable, i imagine there are many out there who use this type of setup that do not have the skills/ability/desire to do surface mount soldering combined with re-compiling kernels making their systems relatively non-standard which in turns makes them harder to support.

remove fake-hwclock from the pi, this means on reboot it will not remember the shutdown time and instead set itself to unix epoch time. A test could then be inserted in to weewx, not to update the console time if the detected system time is before some arbitrary date. Again this does not help with coming out of daylight savings.

do not update console time if there is a difference of more than 2 minutes. Instead maybe issue some alert and provide a method of manually forcing an update of more than 2 minutes. It is extremely unlikely to see a drift of 2 minutes over one archive interval. Instead you would see it during initial setup or if something has gone wrong. Not sure on behaviour during daylight savings.

find a way to detect if the NTP has connectivity and has updated the time since last boot.
possibly the following testing for system peer != 0.0.0.0 before updating console. This had have to be a config option as whilst Pi's have NTP client installed by default, many systems don't.

root@weatherpi:/var/log/ntpstats# ntpdc -c sysinfo
system peer:          0.0.0.0
system peer mode:     unspec
leap indicator:       11
stratum:              16
precision:            -20
root distance:        0.00000 s
root dispersion:      0.00381 s
reference ID:         [73.78.73.84]
reference time:       00000000.00000000  Thu, Feb  7 2036 17:28:16.000
system flags:         auth monitor ntp kernel stats
jitter:               0.000000 s
stability:            0.000 ppm
broadcastdelay:       0.000000 s
authdelay:            0.000000 s
root@weatherpi:/var/log/ntpstats#



ok.... i've been detailed enough for this morning :) again let me know if you need/want more info.

we'll get over this one, then i'll come back to the dump not working (presuming the dump doesn't do the conversion to metric that the normal daemon does)

[Andrew Milner]

Couldnt you just do something like prevent weewx startup if current system time < weewx shutdown time + 3 minutes (or less if the pi really sets clock at startup to system shutdown time whilst waiting for internet and NTP to update the time).  This would work for all Pis with or without clocks, and just mean that there would be an enforced 3 minute delay between weewx shutdown and startup in the worst case scenario ie no loss of time occurred).  Of course, as part of weewx shutdown it would have to put the time somewhere!!

Andrew

[Matthew VK3EVL]

The time taken for Internet to come up can vary dependent on each individual's setup so I personally would shy away from boot plus x mins. Even a check of Internet connectivity isn't fool proof as there will be a delay between Internet being restored and the time being corrected.
The reliance of weewx to make a record of shutdown during a clean shutdown is well and good but I imagine most people don't have their pi plugged in to a ups and have that ups control the clean shutdown when batteries are coming close to exhaustion.

My workaround is I have installed an ntp server on my NAS. Given weewx won't work until the NAS is fully booted, there's now only a small risk that the db on the NAS has started but ntp server hasn't. This is on top of weewx not updating the time on the console until after it has done its initial dump which in my case will be at least 40 mins worth of data by which time I hope the ntp server is running, and the pi has updated. This however is very specific to my setup which I don't think is typical.

We will still have a daylight savings ending problem I think though. I'm not sure how this is handled now (for those of us that have to set the console to manual)

[Thomas Keffer]

Very nice and thorough analysis.

The lack of a clock on the RPi has been fingered before in other threads. Here's an unusually long one. 

We have discovered time and time again that there is simply no good way to write a robust algorithm without the correct time on the console and the server.

I think the right way to solve this is in the daemon script. It already has a requirement that NTP be running before starting weewx, but it should really mean it! I'm not enough of an NTP whiz to know how to do this, but it should not allow weewx to proceed until there has been a successful NTP update. 

As for DST, that's another headache, unique to the Davis series. They are wonderful instruments, very reliable, very flexible, but Davis made an unfortunate decision to store local time in the logger without any clue whether DST is in effect or not. As data comes off the logger, it will simply jump backwards an hour with no other explanation.

Unless weewx were to become locale aware, it can't know why the time went backwards. For it to become locale aware would require installing pytz and a whole new set of headaches that come with that.

It only happens once a year, so by the time the next year rolls around I don't remember the details, but as I recall, what will happen is we get one hours worth of "PRIMARY KEY MUST BE UNIQUE" errors.  Not so bad.

We've learned to simply live with it.

-tk

Tom Keffer

kef...@threefools.org
+1 541-386-8891 (h)
+1 541-490-9507 (c)

Skype: tkeffer

--

[Steve M]

In case it hasn't been discussed here yet, it is easy to add a hardware Real Time Clock (RTC) with battery backup to the raspberry pi, which should solve this issue. There are a number of different solutions, just search around for ds1307 to find the one you like and for a few dollars and a few minutes you can add it to the i2c bus.

For a few dollars more you can get a bit nicer package like this one http://nicegear.co.nz/blog/using-an-i2c-real-time-clock-rtc-with-a-raspberry-pi/

Other instructions here http://learn.adafruit.com/adding-a-real-time-clock-to-raspberry-pi/overview

[Matthew VK3EVL]

Thanks Steve.
That is in fact exactly what I did and it's served me well so far.

Cheers
Matthew

[Phil Homewood]

On Saturday, October 12, 2013 10:56:12 PM UTC+10, Tom Keffer wrote:

I think the right way to solve this is in the daemon script. It already has a requirement that NTP be running before starting weewx, but it should really mean it! I'm not enough of an NTP whiz to know how to do this, but it should not allow weewx to proceed until there has been a successful NTP update. 

A quick hack to both the weewx startup script and (sadly) a script that ships with ntp, which seems to work for me:-

--- /etc/init.d/weewx.orig      2013-11-30 20:10:49.903077214 +1000

+++ /etc/init.d/weewx   2013-11-30 21:28:28.606480454 +1000

@@ -61,6 +61,13 @@

     if [ $NPROC != 0 ]; then

        return 1

     fi

+

+    # Ensure NTP is up

+    if ! ntp-wait -n 20 -s 3; then

+        log_daemon_msg "Not starting $DESC: NTP not synchronised" "$NAME"

+        return 2

+    fi

+    

     start-stop-daemon --start --chuid $WEEWX_USER --pidfile $PIDFILE --exec $DAEMON -- $DAEMON_ARGS || return 2

     return 0

 }

--- /usr/sbin/ntp-wait.orig     2013-11-30 21:27:55.016819640 +1000

+++ /usr/sbin/ntp-wait  2013-12-02 14:03:20.280256199 +1000

@@ -39,7 +39,7 @@

 

       if (/Connection refused/) {

        print "\bntpd is not running!\n" if ($opt_v);

-       exit 1;

+       last;

       }

 

       # Otherwise, we have a bigger problem.

[Thomas Keffer]

I'm not a "Pi head," but this looks like a great solution.

If it works, we can include it in the wiki.

-tk

[Andrew Milner]

I must have my thick potato head on as I could not unravel what actually had to be edited!!  I could not find what the $NPROC bit referred to as it had neither + nor - at the front of it

--
You received this message because you are subscribed to a topic in the Google Groups "Weewx user's group" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/weewx-user/tmbrOC6-UiM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to weewx-user+...@googlegroups.com.

[Phil Homewood]

One more thing that I did, that I think was necessary: "apt-get install ntpdate". Seems that if NTP fires up and has to make a huge adjustment, it goes into a less happy state that ntp-wait doesn't like. If ntpdate is run (by the network interface up scripts) before ntpd starts, everything seems happy.

[Phil Homewood]

Andrew, these are in "diff" format, generally applied using the "patch" command. But they're also easy enough to hack in manually, just add the block that has the "+" signs in front of it (without the "+" signs themselves) before the "start-stop-daemon" line at line 64 of /etc/init.d/weewx, and change the "exit 1" to "last" at line 42 of /usr/sbin/ntp-wait.

(that ntp-wait thing is silly. It should probably go upstream to the NTP maintainers.... exiting there makes no sense given what the script is designed for..)

-P.

[Andrew Milner]

I can only presume that I had been lazy and not read a README or something when I installed 2.5 - as it appears that the init.d script had changed from the version I was running .... hence why I could not get my head around the edit!!

Got the correct version now, and trying it out.

Thanks for coming back with the info I needed!!

Andrew

[Phil Homewood]

The wiki doesn't like me.

"Error 403 Edit access required"

[Thomas Keffer]

Try it now. 

I changed permissions so any authenticated SourceForge user can edit.

-tk

[Phil Homewood]

But not create a new page ,it seems :-)

Error 403 Create access required

[Thomas Keffer]

That's right. I'm a little reluctant to throw it wide open. Send me your sourceforge id and I'll add you. My email is tkeffer at gmail dot com.

-tk

[Jeremy Whiting]

Hey Phil or any of the other "Pi Heads" :)

I was wondering if anyone has this hack working in weewx 2.6.1?

I know this is an ongoing issue with the raspberry pi due to the lack of a RTC but the discussion here seemed to be very encouraging.

Using my admittedly-rudimentary Linux skills, I went ahead and made a backup copy of both /etc/init.d/weewx and /usr/sbin/ntp-wait then used 'sudo nano' to edit and save both files as shown in the quote.

When I rebooted the pi, weewx did not open as expected. There weren't any error messages in syslog to indicate why. The NTP seemed to do it's thing (the process was at least running). I waited about 30 minutes to see if weewx would eventually open and it never did. I then tried to manually start weewx using the typical "sudo /etc/init.d/weewx start" and it opened without problems.

Anyway, I moved the original /etc/init.d/weewx back into place to get everything back to normal

Cheers
Jeremy

[Andrew Milner]

works fine for me!!  Just make sure that you did the edits correctly.  Post your edited files here if possible ... 

[Jeremy Whiting]

That's encouraging! Hopefully I'm on the right track then. Just can't quite seem to get it to work yet

I just tried it again and there were no error messages in syslog from weewx. So I tried to manually start weewx, it outputs the following:
[FAIL] Starting weewx weather system: weewx[....] Not starting weewx weather system: NTP not synchronised: weewx failed!

I must have been delusional when I thought it started up last time I tried (?).

Here it the section of my edited /etc/init.d/weewx:

do_start()
{
    NPROC=`ps ax | grep $WEEWX_BIN | grep $NAME.pid | wc -l`

    if [ $NPROC != 0 ]; then
        return 1
    fi

    #Ensure NTP is up

    if ! ntp-wait -n 20 -s 3; then

       log_daemon_msg "Not starting $DESC: NTP not synchronised" "$NAME"

       return 2
    fi

    start-stop-daemon --start --chuid $WEEWX_USER --pidfile $PIDFILE --exec $DAEMON -- $DAEMON_ARGS || return 2
    return 0
}

Here's the edited section of /usr/sbin/ntp-wait

      if (/Connection refused/) {
        print "\bntpd is not running!\n" if ($opt_v);

        last;
      }

I did install ntpdate as well

Are those the only three steps? Edit /etc/init.d/weewx, edit /usr/sbin/ntp-wait, install ntpdate, and then shut down/restart and see if it works?

Thanks for the help :)

[Andrew Milner]

my script has the second grep as weewx.pid rather than $NAME.pid - don't know if that makes a difference!!

When you reboot tail and follow the log  with tail -f to see what it is doing when starting.  Use ctrl/c to exit the tail

--
You received this message because you are subscribed to a topic in the Google Groups "Weewx user's group" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/weewx-user/tmbrOC6-UiM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to weewx-user+...@googlegroups.com.

[Jeremy Whiting]

Unfortunately, I couldn't get it to work. I'm not very good at debugging this stuff but it seemed to me that the ntp-wait command was running into trouble if it didn't "see" the NTP synchronization happen (i.e. ntp-wait had to be "watching" when the time was updated or it would say that the time wasn't synchronized, even if the time had already synchronized before it was watching)

After messing around with it for a little while in various ways, I added the command "sudo /etc/init.d/ntp restart" to the beginning of the NTP check part and it now works for me. This makes the time synchronize while ntp-wait is actively watching for it to sync

The full start section of the script I'm using is below with the ntp restart command in bold:

do_start()
{
    NPROC=`ps ax | grep $WEEWX_BIN | grep $NAME.pid | wc -l`
    if [ $NPROC != 0 ]; then
        return 1
    fi

    # Ensure NTP is up

    sudo /etc/init.d/ntp restart
    if ! ntp-wait -v -n 20 -s 3; then

       log_daemon_msg "Not starting $DESC: NTP not synchronised" "$NAME"
       return 2
    fi

    start-stop-daemon --start --chuid $WEEWX_USER --pidfile $PIDFILE --exec $DAEMON -- $DAEMON_ARGS || return 2
    return 0
}

I turned the pi off for a while, then turned it back on and the pi did update the time to the correct time before (successfully) starting weewx

It seems to work for me but I'd appreciate comments from the rest of y'all if there's a better way to accomplish this change! (For example, it does slow down the starting of weewx when you're not rebooting the system because it still restarts ntp and waits for an update before it will start weewx. Not a big deal in the end because it is left up most of the time!)

Thanks a bunch :)

Syslog up to weewx start is below in case it is helpful

Feb 19 00:09:50 raspberrypi kernel: [    0.948124] NET: Registered protocol family 2
Feb 19 00:09:50 raspberrypi kernel: [    0.953548] TCP established hash table entries: 4096 (order: 3, 32768 bytes)
Feb 19 00:09:50 raspberrypi kernel: [    0.960816] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
Feb 19 00:09:50 raspberrypi kernel: [    0.967341] TCP: Hash tables configured (established 4096 bind 4096)
Feb 19 00:09:50 raspberrypi kernel: [    0.973817] TCP: reno registered
Feb 19 00:09:50 raspberrypi kernel: [    0.977077] UDP hash table entries: 256 (order: 0, 4096 bytes)
Feb 19 00:09:50 raspberrypi kernel: [    0.982989] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Feb 19 00:09:50 raspberrypi kernel: [    0.989730] NET: Registered protocol family 1
Feb 19 00:09:50 raspberrypi kernel: [    0.994661] RPC: Registered named UNIX socket transport module.
Feb 19 00:09:50 raspberrypi kernel: [    1.000727] RPC: Registered udp transport module.
Feb 19 00:09:50 raspberrypi kernel: [    1.005456] RPC: Registered tcp transport module.
Feb 19 00:09:50 raspberrypi kernel: [    1.010206] RPC: Registered tcp NFSv4.1 backchannel transport module.
Feb 19 00:09:50 raspberrypi kernel: [    1.017559] bcm2708_dma: DMA manager at f2007000
Feb 19 00:09:50 raspberrypi kernel: [    1.022380] bcm2708_gpio: bcm2708_gpio_probe c05a5e50
Feb 19 00:09:50 raspberrypi kernel: [    1.027833] vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
Feb 19 00:09:50 raspberrypi kernel: [    1.037222] audit: initializing netlink socket (disabled)
Feb 19 00:09:50 raspberrypi kernel: [    1.042900] type=2000 audit(0.890:1): initialized
Feb 19 00:09:50 raspberrypi kernel: [    1.204713] VFS: Disk quotas dquot_6.5.2
Feb 19 00:09:50 raspberrypi kernel: [    1.209108] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Feb 19 00:09:50 raspberrypi kernel: [    1.217964] FS-Cache: Netfs 'nfs' registered for caching
Feb 19 00:09:50 raspberrypi kernel: [    1.224701] NFS: Registering the id_resolver key type
Feb 19 00:09:50 raspberrypi kernel: [    1.230023] Key type id_resolver registered
Feb 19 00:09:50 raspberrypi kernel: [    1.234235] Key type id_legacy registered
Feb 19 00:09:50 raspberrypi kernel: [    1.239059] msgmni has been set to 875
Feb 19 00:09:50 raspberrypi kernel: [    1.244933] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Feb 19 00:09:50 raspberrypi kernel: [    1.252784] io scheduler noop registered
Feb 19 00:09:50 raspberrypi kernel: [    1.256745] io scheduler deadline registered (default)
Feb 19 00:09:50 raspberrypi kernel: [    1.262337] io scheduler cfq registered
Feb 19 00:09:50 raspberrypi kernel: [    1.266481] bcm2708_fb_debugfs_init: could not create debugfs entry
Feb 19 00:09:50 raspberrypi kernel: [    1.274066] BCM2708FB: allocated DMA memory 5b400000
Feb 19 00:09:50 raspberrypi kernel: [    1.279221] BCM2708FB: allocated DMA channel 0 @ f2007000
Feb 19 00:09:50 raspberrypi kernel: [    1.302108] Console: switching to colour frame buffer device 82x26
Feb 19 00:09:50 raspberrypi kernel: [    1.312280] uart-pl011 dev:f1: no DMA platform data
Feb 19 00:09:50 raspberrypi kernel: [    1.318617] kgdb: Registered I/O driver kgdboc.
Feb 19 00:09:50 raspberrypi kernel: [    1.325224] vc-cma: Videocore CMA driver
Feb 19 00:09:50 raspberrypi kernel: [    1.330584] vc-cma: vc_cma_base      = 0x00000000
Feb 19 00:09:50 raspberrypi kernel: [    1.336593] vc-cma: vc_cma_size      = 0x00000000 (0 MiB)
Feb 19 00:09:50 raspberrypi kernel: [    1.343355] vc-cma: vc_cma_initial   = 0x00000000 (0 MiB)
Feb 19 00:09:50 raspberrypi kernel: [    1.359415] brd: module loaded
Feb 19 00:09:50 raspberrypi kernel: [    1.369031] loop: module loaded
Feb 19 00:09:50 raspberrypi kernel: [    1.373730] vchiq: vchiq_init_state: slot_zero = 0xdb000000, is_master = 0
Feb 19 00:09:50 raspberrypi kernel: [    1.382860] Loading iSCSI transport class v2.0-870.
Feb 19 00:09:50 raspberrypi kernel: [    1.390296] usbcore: registered new interface driver smsc95xx
Feb 19 00:09:50 raspberrypi kernel: [    1.397784] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Feb 19 00:09:50 raspberrypi kernel: [    1.605088] Core Release: 2.80a
Feb 19 00:09:50 raspberrypi kernel: [    1.609591] Setting default values for core params
Feb 19 00:09:50 raspberrypi kernel: [    1.615639] Finished setting default values for core params
Feb 19 00:09:50 raspberrypi kernel: [    1.822535] Using Buffer DMA mode
Feb 19 00:09:50 raspberrypi kernel: [    1.827124] Periodic Transfer Interrupt Enhancement - disabled
Feb 19 00:09:50 raspberrypi kernel: [    1.834247] Multiprocessor Interrupt Enhancement - disabled
Feb 19 00:09:50 raspberrypi kernel: [    1.841106] OTG VER PARAM: 0, OTG VER FLAG: 0
Feb 19 00:09:50 raspberrypi kernel: [    1.846734] Dedicated Tx FIFOs mode
Feb 19 00:09:50 raspberrypi kernel: [    1.852053] dwc_otg: Microframe scheduler enabled
Feb 19 00:09:50 raspberrypi kernel: [    1.852293] dwc_otg bcm2708_usb: DWC OTG Controller
Feb 19 00:09:50 raspberrypi kernel: [    1.858508] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Feb 19 00:09:50 raspberrypi kernel: [    1.867127] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Feb 19 00:09:50 raspberrypi kernel: [    1.873949] Init: Port Power? op_state=1
Feb 19 00:09:50 raspberrypi kernel: [    1.879244] Init: Power Port (0)
Feb 19 00:09:50 raspberrypi kernel: [    1.883884] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Feb 19 00:09:50 raspberrypi kernel: [    1.892095] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Feb 19 00:09:50 raspberrypi kernel: [    1.900734] usb usb1: Product: DWC OTG Controller
Feb 19 00:09:50 raspberrypi kernel: [    1.906809] usb usb1: Manufacturer: Linux 3.10.25+ dwc_otg_hcd
Feb 19 00:09:50 raspberrypi kernel: [    1.914031] usb usb1: SerialNumber: bcm2708_usb
Feb 19 00:09:50 raspberrypi kernel: [    1.920712] hub 1-0:1.0: USB hub found
Feb 19 00:09:50 raspberrypi kernel: [    1.925845] hub 1-0:1.0: 1 port detected
Feb 19 00:09:50 raspberrypi kernel: [    1.931481] dwc_otg: FIQ enabled
Feb 19 00:09:50 raspberrypi kernel: [    1.931499] dwc_otg: NAK holdoff enabled
Feb 19 00:09:50 raspberrypi kernel: [    1.931510] dwc_otg: FIQ split fix enabled
Feb 19 00:09:50 raspberrypi kernel: [    1.931529] Module dwc_common_port init
Feb 19 00:09:50 raspberrypi kernel: [    1.931964] usbcore: registered new interface driver usb-storage
Feb 19 00:09:50 raspberrypi kernel: [    1.939784] mousedev: PS/2 mouse device common for all mice
Feb 19 00:09:50 raspberrypi kernel: [    1.947318] bcm2835-cpufreq: min=700000 max=700000 cur=700000
Feb 19 00:09:50 raspberrypi kernel: [    1.954632] bcm2835-cpufreq: switching to governor powersave
Feb 19 00:09:50 raspberrypi kernel: [    1.961694] bcm2835-cpufreq: switching to governor powersave
Feb 19 00:09:50 raspberrypi kernel: [    1.968608] cpuidle: using governor ladder
Feb 19 00:09:50 raspberrypi kernel: [    1.973952] cpuidle: using governor menu
Feb 19 00:09:50 raspberrypi kernel: [    1.979161] sdhci: Secure Digital Host Controller Interface driver
Feb 19 00:09:50 raspberrypi kernel: [    1.986588] sdhci: Copyright(c) Pierre Ossman
Feb 19 00:09:50 raspberrypi kernel: [    1.992257] sdhci: Enable low-latency mode
Feb 19 00:09:50 raspberrypi kernel: [    2.038820] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
Feb 19 00:09:50 raspberrypi kernel: [    2.049306] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
Feb 19 00:09:50 raspberrypi kernel: [    2.056539] sdhci-pltfm: SDHCI platform and OF driver helper
Feb 19 00:09:50 raspberrypi kernel: [    2.063693] ledtrig-cpu: registered to indicate activity on CPUs
Feb 19 00:09:50 raspberrypi kernel: [    2.073290] hidraw: raw HID events driver (C) Jiri Kosina
Feb 19 00:09:50 raspberrypi kernel: [    2.087648] usbcore: registered new interface driver usbhid
Feb 19 00:09:50 raspberrypi kernel: [    2.094702] usbhid: USB HID core driver
Feb 19 00:09:50 raspberrypi kernel: [    2.104547] TCP: cubic registered
Feb 19 00:09:50 raspberrypi kernel: [    2.111309] Initializing XFRM netlink socket
Feb 19 00:09:50 raspberrypi kernel: [    2.119031] NET: Registered protocol family 17
Feb 19 00:09:50 raspberrypi kernel: [    2.125027] Key type dns_resolver registered
Feb 19 00:09:50 raspberrypi kernel: [    2.133992] Indeed it is in host mode hprt0 = 00021501
Feb 19 00:09:50 raspberrypi kernel: [    2.140973] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Feb 19 00:09:50 raspberrypi kernel: [    2.169594] registered taskstats version 1
Feb 19 00:09:50 raspberrypi kernel: [    2.179149] drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
Feb 19 00:09:50 raspberrypi kernel: [    2.193195] Waiting for root device /dev/sda2...
Feb 19 00:09:50 raspberrypi kernel: [    2.202631] mmc0: new high speed SDHC card at address 1234
Feb 19 00:09:50 raspberrypi kernel: [    2.219515] mmcblk0: mmc0:1234 SA16G 14.6 GiB
Feb 19 00:09:50 raspberrypi kernel: [    2.240476]  mmcblk0: p1 p2
Feb 19 00:09:50 raspberrypi kernel: [    2.368843] usb 1-1: new high-speed USB device number 2 using dwc_otg
Feb 19 00:09:50 raspberrypi kernel: [    2.376938] Indeed it is in host mode hprt0 = 00001101
Feb 19 00:09:50 raspberrypi kernel: [    2.579516] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Feb 19 00:09:50 raspberrypi kernel: [    2.587742] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Feb 19 00:09:50 raspberrypi kernel: [    2.597407] hub 1-1:1.0: USB hub found
Feb 19 00:09:50 raspberrypi kernel: [    2.602828] hub 1-1:1.0: 3 ports detected
Feb 19 00:09:50 raspberrypi kernel: [    2.889024] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Feb 19 00:09:50 raspberrypi kernel: [    3.009564] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Feb 19 00:09:50 raspberrypi kernel: [    3.017948] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Feb 19 00:09:50 raspberrypi kernel: [    3.029679] smsc95xx v1.0.4
Feb 19 00:09:50 raspberrypi kernel: [    3.095007] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:f2:04:71
Feb 19 00:09:50 raspberrypi kernel: [    3.189060] usb 1-1.2: new full-speed USB device number 4 using dwc_otg
Feb 19 00:09:50 raspberrypi kernel: [    3.314773] usb 1-1.2: New USB device found, idVendor=067b, idProduct=2303
Feb 19 00:09:50 raspberrypi kernel: [    3.323347] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
Feb 19 00:09:50 raspberrypi kernel: [    3.332330] usb 1-1.2: Product: USB-Serial Controller
Feb 19 00:09:50 raspberrypi kernel: [    3.338949] usb 1-1.2: Manufacturer: Prolific Technology Inc.
Feb 19 00:09:50 raspberrypi kernel: [    3.439101] usb 1-1.3: new high-speed USB device number 5 using dwc_otg
Feb 19 00:09:50 raspberrypi kernel: [    3.561445] usb 1-1.3: New USB device found, idVendor=03f0, idProduct=f807
Feb 19 00:09:50 raspberrypi kernel: [    3.569946] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Feb 19 00:09:50 raspberrypi kernel: [    3.578823] usb 1-1.3: Product: v221w
Feb 19 00:09:50 raspberrypi kernel: [    3.584014] usb 1-1.3: Manufacturer: HP
Feb 19 00:09:50 raspberrypi kernel: [    3.589353] usb 1-1.3: SerialNumber: AA41170090000239
Feb 19 00:09:50 raspberrypi kernel: [    3.596931] usb-storage 1-1.3:1.0: USB Mass Storage device detected
Feb 19 00:09:50 raspberrypi kernel: [    3.605401] scsi0 : usb-storage 1-1.3:1.0
Feb 19 00:09:50 raspberrypi kernel: [    5.171628] scsi 0:0:0:0: Direct-Access     hp       v221w            1638 PQ: 0 ANSI: 4
Feb 19 00:09:50 raspberrypi kernel: [    5.184126] sd 0:0:0:0: [sda] 31950720 512-byte logical blocks: (16.3 GB/15.2 GiB)
Feb 19 00:09:50 raspberrypi kernel: [    5.196251] sd 0:0:0:0: [sda] Write Protect is off
Feb 19 00:09:50 raspberrypi kernel: [    5.202804] sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00
Feb 19 00:09:50 raspberrypi kernel: [    5.203491] sd 0:0:0:0: [sda] No Caching mode page found
Feb 19 00:09:50 raspberrypi kernel: [    5.210442] sd 0:0:0:0: [sda] Assuming drive cache: write through
Feb 19 00:09:50 raspberrypi kernel: [    5.221982] sd 0:0:0:0: [sda] No Caching mode page found
Feb 19 00:09:50 raspberrypi kernel: [    5.228861] sd 0:0:0:0: [sda] Assuming drive cache: write through
Feb 19 00:09:50 raspberrypi kernel: [    5.237687]  sda: sda1 sda2
Feb 19 00:09:50 raspberrypi kernel: [    5.245613] sd 0:0:0:0: [sda] No Caching mode page found
Feb 19 00:09:50 raspberrypi kernel: [    5.252606] sd 0:0:0:0: [sda] Assuming drive cache: write through
Feb 19 00:09:50 raspberrypi kernel: [    5.260225] sd 0:0:0:0: [sda] Attached SCSI removable disk
Feb 19 00:09:50 raspberrypi kernel: [    5.355662] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
Feb 19 00:09:50 raspberrypi kernel: [    5.366289] VFS: Mounted root (ext4 filesystem) on device 8:2.
Feb 19 00:09:50 raspberrypi kernel: [    5.377771] devtmpfs: mounted
Feb 19 00:09:50 raspberrypi kernel: [    5.382800] Freeing unused kernel memory: 144K (c0573000 - c0597000)
Feb 19 00:09:50 raspberrypi kernel: [    8.254465] usbcore: registered new interface driver usbserial
Feb 19 00:09:50 raspberrypi kernel: [    8.361984] usbcore: registered new interface driver usbserial_generic
Feb 19 00:09:50 raspberrypi kernel: [    8.452647] usbserial: USB Serial support registered for generic
Feb 19 00:09:50 raspberrypi kernel: [    8.665806] usbcore: registered new interface driver pl2303
Feb 19 00:09:50 raspberrypi kernel: [    8.895834] bcm2708-i2s bcm2708-i2s.0: Failed to create debugfs directory
Feb 19 00:09:50 raspberrypi kernel: [    8.919103] usbserial: USB Serial support registered for pl2303
Feb 19 00:09:50 raspberrypi kernel: [    8.926855] pl2303 1-1.2:1.0: pl2303 converter detected
Feb 19 00:09:50 raspberrypi kernel: [    9.359761] usb 1-1.2: pl2303 converter now attached to ttyUSB0
Feb 19 00:09:50 raspberrypi kernel: [   13.780393] EXT4-fs (sda2): re-mounted. Opts: (null)
Feb 19 00:09:50 raspberrypi kernel: [   14.191093] EXT4-fs (sda2): re-mounted. Opts: (null)
Feb 19 00:09:50 raspberrypi kernel: [   20.209959] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
Feb 19 00:09:50 raspberrypi kernel: [   22.853994] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
Feb 19 00:09:50 raspberrypi kernel: [   24.467073] smsc95xx 1-1.1:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0x41E1
Feb 19 00:09:51 raspberrypi /usr/sbin/cron[1905]: (CRON) INFO (pidfile fd = 3)
Feb 19 00:09:51 raspberrypi /usr/sbin/cron[1906]: (CRON) STARTUP (fork ok)
Feb 19 00:09:51 raspberrypi /usr/sbin/cron[1906]: (CRON) INFO (Running @reboot jobs)
Feb 19 00:09:51 raspberrypi dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Feb 19 00:09:51 raspberrypi ifplugd(eth0)[1575]: client: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Feb 19 00:09:51 raspberrypi dhclient: DHCPOFFER from 192.168.1.1
Feb 19 00:09:51 raspberrypi ifplugd(eth0)[1575]: client: DHCPOFFER from 192.168.1.1
Feb 19 00:09:51 raspberrypi kernel: [   27.572969] Adding 102396k swap on /var/swap.  Priority:-1 extents:1 across:102396k FS
Feb 19 00:09:52 raspberrypi ntpd[1979]: ntpd 4.2...@1.2349-o Fri May 18 20:30:57 UTC 2012 (1)
Feb 19 00:09:52 raspberrypi ntpd[1982]: proto: precision = 1.000 usec
Feb 19 00:09:52 raspberrypi ntpd[1982]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Feb 19 00:09:52 raspberrypi ntpd[1982]: Listen normally on 1 lo 127.0.0.1 UDP 123
Feb 19 00:09:52 raspberrypi ntpd[1982]: peers refreshed
Feb 19 00:09:52 raspberrypi ntpd[1982]: Listening on routing socket on fd #18 for interface updates
Feb 19 00:09:52 raspberrypi ntpd[1982]: restrict: error in address '::' on line 38. Ignoring...
Feb 19 00:09:52 raspberrypi ntpd[1982]: restrict: error in address '::1' on line 42. Ignoring...
Feb 19 00:09:52 raspberrypi ntpd[1982]: Deferring DNS for 0.debian.pool.ntp.org 1
Feb 19 00:09:52 raspberrypi ntpd[1982]: Deferring DNS for 1.debian.pool.ntp.org 1
Feb 19 00:09:52 raspberrypi ntpd[1982]: Deferring DNS for 2.debian.pool.ntp.org 1
Feb 19 00:09:52 raspberrypi ntpd[1982]: Deferring DNS for 3.debian.pool.ntp.org 1
Feb 19 00:09:52 raspberrypi ntpd[1991]: signal_no_reset: signal 17 had flags 4000000
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Found user 'avahi' (UID 107) and group 'avahi' (GID 110).
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Successfully dropped root privileges.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: avahi-daemon 0.6.31 starting up.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Successfully called chroot().
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Successfully dropped remaining capabilities.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Loading service file /services/udisks.service.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: socket() failed: Address family not supported by protocol
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Failed to create IPv6 socket, proceeding in IPv4 only mode
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: socket() failed: Address family not supported by protocol
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Network interface enumeration completed.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Registering HINFO record with values 'ARMV6L'/'LINUX'.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Server startup complete. Host name is raspberrypi.local. Local service cookie is 1318528320.
Feb 19 00:09:52 raspberrypi avahi-daemon[2008]: Service "raspberrypi" (/services/udisks.service) successfully established.
Feb 19 00:09:53 raspberrypi dhclient: DHCPACK from 192.168.1.1
Feb 19 00:09:53 raspberrypi ifplugd(eth0)[1575]: client: DHCPACK from 192.168.1.1
Feb 19 00:09:53 raspberrypi avahi-daemon[2008]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.6.
Feb 19 00:09:53 raspberrypi avahi-daemon[2008]: New relevant interface eth0.IPv4 for mDNS.
Feb 19 00:09:53 raspberrypi avahi-daemon[2008]: Registering new address record for 192.168.1.6 on eth0.IPv4.
Feb 19 00:09:53 raspberrypi dhclient: bound to 192.168.1.6 -- renewal in 41366 seconds.
Feb 19 00:09:53 raspberrypi ifplugd(eth0)[1575]: client: bound to 192.168.1.6 -- renewal in 41366 seconds.
Feb 19 00:09:54 raspberrypi ntpd[1982]: ntpd exiting on signal 15
Feb 19 00:09:54 raspberrypi ntpd_intres[1991]: DNS 0.debian.pool.ntp.org -> 204.2.134.163
Feb 19 00:09:54 raspberrypi ntpd_intres[1991]: parent died before we finished, exiting
Feb 19 00:17:06 raspberrypi ntpdate[2183]: step time server 208.68.36.196 offset 422.055244 sec
Feb 19 00:17:06 raspberrypi ifplugd(eth0)[1575]: Program executed successfully.
Feb 19 00:17:13 raspberrypi ntpd[2240]: ntpd 4.2...@1.2349-o Fri May 18 20:30:57 UTC 2012 (1)
Feb 19 00:17:13 raspberrypi ntpd[2241]: proto: precision = 1.000 usec
Feb 19 00:17:13 raspberrypi ntpd[2241]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Feb 19 00:17:13 raspberrypi ntpd[2241]: Listen normally on 1 lo 127.0.0.1 UDP 123
Feb 19 00:17:13 raspberrypi ntpd[2241]: Listen normally on 2 eth0 192.168.1.6 UDP 123
Feb 19 00:17:13 raspberrypi ntpd[2241]: peers refreshed
Feb 19 00:17:13 raspberrypi ntpd[2241]: Listening on routing socket on fd #19 for interface updates
Feb 19 00:17:13 raspberrypi ntpd[2241]: restrict: error in address '::' on line 38. Ignoring...
Feb 19 00:17:13 raspberrypi ntpd[2241]: restrict: error in address '::1' on line 42. Ignoring...
Feb 19 00:17:33 raspberrypi weewx[2275]: wxengine: Initializing weewx version 2.6.1

[Jeremy Whiting]

At the risk of looking like a fool for quoting myself...

I wanted to report a problem with my script edit that I have noticed. It is quite reliable at starting weewx when the system is up and has been running, but for some reason, when the Pi is starting up, the script does not always trigger a successful start of weewx. It only works about half the time after a reboot or boot.

I don't know for sure why this is happening, but I think it may have to do with so much going on at startup that the timing needed to verify the NTP synchronization is thrown off.

For mine, I decided to add a 30 second delay to the script to delay weewx from the other startup processes

    # Ensure NTP is up

    sleep 30s

    sudo /etc/init.d/ntp restart
    if ! ntp-wait -v -n 20 -s 3; then
       log_daemon_msg "Not starting $DESC: NTP not synchronised" "$NAME"
       return 2
    fi

So why not just a "sleep" command and forget about the NTP sync check? Because if the internet is down or if there are other problems preventing the Pi from syncing with NTP, I'd rather not have weewx start because the time being off screws things up

Of course, a downside for this approach is that the normal restart procedure 'sudo /etc/init.d/weewx stop' 'sudo /etc/init.d/weewx start' takes a lot longer. So I have been using the original script (which I stored at /etc/init.d/weewx.orig) when I need to restart

I'd love to hear from y'all if this is an ill-advised approach to the problem :)

[Andrew Milner]

My weewx init.d script does not appear to have have the ntprestart in it which yours has.... but I would have thought you would have been better off with your 30 second delay after the ntprestart if you're going to restart rather than before if you put a delay anywhere.

[Thomas Keffer]

Jeremy,

When you say that "the script does not always trigger a successful start of weewx," what are the symptoms? Does anything show in the log?

-tk

--

You received this message because you are subscribed to the Google Groups "Weewx user's group" group.

To unsubscribe from this group and stop receiving emails from it, send an email to weewx-user+...@googlegroups.com.

[Jeremy Whiting]

Yeah the ntprestart was added by me. When I used the original script edits from Phil Homewood above, it wouldn't start on boot and would rarely start manually.

I added the '-v' tag to my ntpwait command so I could see what was happening. When trying to start manually, I got the following (this is with the original Phil Homewood script):

pi@raspberrypi ~ $ sudo /etc/init.d/weewx start
[....] Starting weewx weather system: weewxWaiting for ntpd to synchronize... No!
ntpd did not synchronize.
[FAIL] Not starting weewx weather system: NTP not synchronised: weewx failed!

To add to the mystery, I have gotten this script to work a handful of times, but only after the Pi has run for a while (as in hours) beforehand and I start it manually. It is strange. It has never worked on boot for me (I can't find any error messages in syslog to tell me why)

If I add the ntprestart command and run the script manually, I get the following:

pi@raspberrypi ~ $ sudo /etc/init.d/weewx start
[ ok ] Starting weewx weather system: weewx[....] Stopping NTP server: ntpd.
[ ok ] Starting NTP server: ntpd.
Waiting for ntpd to synchronize... OK!
. ok

And weewx starts up according to syslog. However, the script doesn't always start weewx on boot. It's about 50/50. The syslog shows NTP starting due to the boot process, then closing due to the ntp restart command in the script, then reopening. However there are no further messages in syslog relating to the script nor is there any weewx error message. I expect that there would be an output similar to above ("Not starting weewx weather system: NTP not synchronised: weewx failed!") but I can't find the log file where this would be. Do you know where I can look to see the error output of the init.d script?

Here's the relevant NTP entries from syslog when it doesn't work:

Feb 27 11:59:32 raspberrypi ntpd[2079]: ntpd 4.2...@1.2349-o Fri May 18 20:30:57 UTC 2012 (1)
Feb 27 11:59:32 raspberrypi ntpd[2086]: proto: precision = 1.000 usec
Feb 27 11:59:32 raspberrypi ntpd[2086]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Feb 27 11:59:32 raspberrypi ntpd[2086]: Listen normally on 1 lo 127.0.0.1 UDP 123
Feb 27 11:59:32 raspberrypi ntpd[2086]: Listen normally on 2 eth0 192.168.1.9 UDP 123
Feb 27 11:59:32 raspberrypi ntpd[2086]: peers refreshed
Feb 27 11:59:32 raspberrypi ntpd[2086]: Listening on routing socket on fd #19 for interface updates
Feb 27 11:59:32 raspberrypi ntpd[2086]: restrict: error in address '::' on line 38. Ignoring...
Feb 27 11:59:32 raspberrypi ntpd[2086]: restrict: error in address '::1' on line 42. Ignoring...
Feb 27 11:59:33 raspberrypi ntpdate[2133]: the NTP socket is in use, exiting
Feb 27 11:59:33 raspberrypi ifplugd(eth0)[1649]: Program executed successfully.
Feb 27 11:59:34 raspberrypi ntpd[2086]: ntpd exiting on signal 15
...
Feb 27 11:59:37 raspberrypi ntpd[2286]: ntpd 4.2...@1.2349-o Fri May 18 20:30:57 UTC 2012 (1)
Feb 27 11:59:37 raspberrypi ntpd[2290]: proto: precision = 0.999 usec
Feb 27 11:59:37 raspberrypi ntpd[2290]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Feb 27 11:59:37 raspberrypi ntpd[2290]: Listen normally on 1 lo 127.0.0.1 UDP 123
Feb 27 11:59:37 raspberrypi ntpd[2290]: Listen normally on 2 eth0 192.168.1.9 UDP 123
Feb 27 11:59:37 raspberrypi ntpd[2290]: peers refreshed
Feb 27 11:59:37 raspberrypi ntpd[2290]: Listening on routing socket on fd #19 for interface updates
Feb 27 11:59:37 raspberrypi ntpd[2290]: restrict: error in address '::' on line 38. Ignoring...
Feb 27 11:59:37 raspberrypi ntpd[2290]: restrict: error in address '::1' on line 42. Ignoring...

I have added the delay and it has worked every time I tried it. This doesn't mean that it is the best solution

Ideally, what I'd like to do is stop ntpd>start ntpwait>start ntpd while ntpwait is "waiting" but I don't know how to accomplish that since the script causes ntpwait to wait until it has finished it's output before going on to do the next step

[Jeremy Whiting]

Tom,

I apologize for not being more clear. I have provided a more detailed description above in my reply to Andrew.

The symptoms on boot are:
-ntpd starts on boot according to syslog
-ntpd then exits with "ntpd[2086]: ntpd exiting on signal 15" according to syslog. I believe that this is the NTP restart from the script
-ntpd reopens
-nothing else in syslog

Do you know where log messages for the init.d script would be kept? If there is such a thing, it may help debug the problem. I tried looking in daemon.log and it wasn't there

[Thomas Keffer]

It's usually in /var/log/syslog or /var/log/messages.

-tk

[Oz Greg]

A few things I have noticed on my PI is it is slow to start up the name resolver so during boot I have NTP point to a ip address..  Also as a tip for everyone you can also get ntp time from a samba share (if you have one on your network) which I do so my pi time is already set prior to weewx starting up (which is also at boot)..

I think this is your issue as you have a number of deferring DNS messages in your boot log..

Hope this helps

[Jeremy Whiting]

OK I think I may have fixed my issue and (hopefully) made a more robust script edit, at least for my own pi. YMMV if it works for you!

Here are some instructions.

A few notes to start off with: Since the pi doesn't have a battery powered clock, it relies on NTP servers to get the time. However, the default ntp program ntpd doesn't like to make big jumps in the time. It slowly moves the time forward or backward to hit the real time. This is done for the stability of programs and stuff that could otherwise have problems if the time jumps a lot.

However, in my application (and probably for most other pi users on this user group), we just want to be able to use weewx and we want the time to jump straight to the correct time on boot before weewx starts without messing around with incremental changes.

Therefore, I'd rather use the ntpdate command to make the big jump to the correct time at boot, then start ntpd and use that for the ongoing maintenance of the correct time. (ntpdate and ntpd don't play well together, so if ntpdate is run after ntpd, ntpdate gives an error message and exits)

First step: install ntpdate (ntpdate is technically a deprecated program but it still works in our application here)
# apt-get install ntpdate

Second step: stop ntpd from running at boot
#  sudo update-rc.d -f ntp remove
(If you end up wanting to start ntpd again at boot, just run "sudo update-rc.d ntp defaults")

Third step: edit the /etc/init.d/weewx startup script

First save the original one for a backup copy in case things go south
# sudo cp /etc/init.d/weewx /etc/init.d/weewx.orig

Now edit the startup script to insert the following, starting at line 64
# sudo nano /etc/init.d/weewx
Scroll down until you see:


    NPROC=`ps ax | grep $WEEWX_BIN | grep $NAME.pid | wc -l`
    if [ $NPROC != 0 ]; then
        return 1
    fi

Right after that, insert the following:


    # Ensure NTP is up


    # On boot, get time with ntpdate then start ntpd
    if echo "" && sudo ntpdate-debian; then
       sudo /etc/init.d/ntp start
       logger -s "Starting $DESC: ntpdate synchronised time"
    # If ntpdate-debian fails, restart ntpd and check for ntp synchronization
    elif sudo /etc/init.d/ntp restart && ntp-wait -v -n 20 -s 3; then
       logger -s "Starting $DESC: ntpd synchronised time"
    # If both fail, then provide error message and make sure ntpd is running regardless
    else
       logger -s "Not starting $DESC: NTP not synchronised, check internet connection"
       sudo /etc/init.d/ntp start
       return 2
    fi


Now save the edit.

Fourth step: make an edit to the ntp-wait command

First make a backup copy of it
# sudo cp /usr/sbin/ntp-wait /usr/sbin/ntp-wait.orig

Now open for editing
# sudo nano /usr/sbin/ntp-wait

We're going to make a change from "exit 1;" to "last;" at line 42

       if (/Connection refused/) {

        print "\bntpd is not running!\n" if ($opt_v);

       last;

       }

 

       # Otherwise, we have a bigger problem.

Now save the edit

You're done!

Notes: If you want to manually start weewx, you can use the modified script to do it (aka "sudo /etc/init.d/weewx start"). The script is designed to work by confirming that ntp is updated even when started manually this way. The drawback is that it will take longer to startup than the normal script does. If you're confident that the time is close enough for government work (which is probably true if ntpd has been running), then do "sudo /etc/init.d/weewx.orig start" and you'll use the original script to start up quickly. It doesn't matter which script you use to stop as they'll both have the same effect

There may be a way to get ntpd to work on boot if you can use the "ntpd -g" command on startup. I tried messing around with it for a few minutes but couldn't get it to work the right way.

[Bill]

I am pretty sure (since I am using this way), that ntpd will set the clock to
the correct time right away if is *way off*, for example set to 1970. The
slow adjustments only happen if the clock is close to being correct.

Check you are using '-g'; on Debian it is will be in /etc/default/ntp.

On the PI it uses something called 'fakeclock' which syncs the time while
running, then on boot sets the clock to the last known time. So if you have
this running and shutdown for an hour, the clock will be off by an hour.

I think the best thing to do is to remove 'fakeclock', let the PI boot into
1970, let 'ntpd -g' run and set it correctly from the network.

This has the advantage of it being very easy to tell when the clock has been
correctly set. If the clock thinks it is in the last century, it ain't been
set, and if it is in this century it has been. So a simple check of the year
for >2000 is all you need to know if things have started up.

/bill

On Friday 28 February 2014 02:26, Jeremy Whiting wrote:
> OK I think I may have fixed my issue and (hopefully) made a more robust
> script edit, at least for my own pi. YMMV if it works for you!
>
> Here are some instructions.
>
> A few notes to start off with: Since the pi doesn't have a battery powered
> clock, it relies on NTP servers to get the time. However, the default ntp
> program ntpd doesn't like to make big jumps in the time. It slowly moves
> the time forward or backward to hit the real time. This is done for the
> stability of programs and stuff that could otherwise have problems if the
> time jumps a lot.
>
> However, in my application (and probably for most other pi users on this
> user group), we just want to be able to use weewx and we want the time to
> jump straight to the correct time on boot before weewx starts without
> messing around with incremental changes.
>
> Therefore, I'd rather use the ntpdate command to make the big jump to the
> correct time at boot, then start ntpd and use that for the ongoing
> maintenance of the correct time. (ntpdate and ntpd don't play well
> together, so if ntpdate is run after ntpd, ntpdate gives an error message
> and exits)
>

> *First step:* install ntpdate (ntpdate is technically a deprecated program

> but it still works in our application here)
> # apt-get install ntpdate
>

> *Second step:* stop ntpd from running at boot

> # sudo update-rc.d -f ntp remove
> (If you end up wanting to start ntpd again at boot, just run "sudo
> update-rc.d ntp defaults")
>

> *Third step:* edit the /etc/init.d/weewx startup script

> *Fourth step:* make an edit to the ntp-wait command

>
> First make a backup copy of it
> # sudo cp /usr/sbin/ntp-wait /usr/sbin/ntp-wait.orig
>
> Now open for editing
> # sudo nano /usr/sbin/ntp-wait
>
> We're going to make a change from "exit 1;" to "last;" at line 42
>
> if (/Connection refused/) {
>
> > print "\bntpd is not running!\n" if ($opt_v);
> >

> > *last;*

> > }
> >
> > # Otherwise, we have a bigger problem.
>
> Now save the edit
>
> You're done!
>

> *Notes:* If you want to manually start weewx, you can use the modified

[Jeremy Whiting]

Nice! I like it. So far my edits have been rock solid for me and I'm tired of messing with it, but if I encounter problems, I'll switch to this method

[JD Mueller]

Do you think you could elaborate on this method you have described? This sounds like the more correct route to go instead of installing depreciated software. If you could write a more detailed or step-by-step solution to incorporate this, others might be interested. The guide posted above is fairly easy for anyone to follow for those of us that don't have much experience with the RPi or Linux systems.

[Ron Knapp]

I know this is old thread but has any solution been found to this issue? From what I have observed the problem is when the pi comes up its time is last shutdown. My issue is that when

it comes up with the wrong time weewx then sets the vantage console to the wrong time. A few seconds later the pi's NTP corrects the computer time but the records being retrieved

from the vantage now are time stamped with the wrong time. This is solved by restarting weewx and it then sets the console time to the correct time.if I understand this correctly the timestamp

of the entry in the database is the time of the vantage console, not that of the pi, so the the console is still logging records with the correct timestamp till weewx sets it wrong with bad time

from the Pi. If I understand this correctly then it seems the fix would be to install a max delta limit on the setting the vantage console time, NTP has something similar. I would set mine for 1 min. So when

weewx goes to set the time on the console, if the difference is more then 1 minute it aborts and does not  change the time. Later when the pi has the correct time set it tries to set the time and finds

it is 2 seconds off, so it completes the time change on the console. If this has been resolved please correct me as I happen today when I shut the pi down for an image backup.

Rpm

[Ron Knapp]

A very poor solution I used was to put a sleep 30 in the start function of Weewx init script. While this prevents Weewx from starting till the Pi has had a chance to correct the time, it causes

the init system to report that weewx failed to start when in fact it started fine. I also changed the init start symlinks to S99weewx from S02weewx, this makes it the last thing to start giving

the pi even more time to get its time fixed.

[Thomas Keffer]

Weewx now comes with a delay that prevents it from proceeding until the date is after 1 January 2000.

All you have to do is remove fake clock:

$ sudo apt-get remove fake-hwclock

Then remove the old, recorded time:

$ sudo rm /etc/fake-hwclock.data

--
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 weewx-user+...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Robert Mantel]

I know this is an old thread but I want to ask you about another possible solution.  I have a Particle Photon based weather station that I have dumping sensor readings to a phant server I have running on my network.  The phant server timestamps everything in UTC.  I can then do a jsonp query with a cron job python script I have running then parse that into a format that fileparse.py likes.  I also parse out and convert the EST corrected timestamp from the server into unix epoch format.  Can weewx be set up to ignore it's own timestamps and just use the imported ones, which technically are more accurate because they represent the very moment the reading was taken?  I tried using fileparse to import the timestamp into the dateTime label in weewx, but I think it didn't like that.

Another possible solution to the NTP problem is to use a server you have on your local network and configure it as an NTP relay.  I have a freenas box running my phant server in a jail on it so would be easy to just set it up to act as an NTP relay and have the Pi sync from that rather than the internet, therefore I can operate completely in a net down situation and keep collecting data with proper timestamps.  

[Thomas Keffer]

On Tue, Jan 17, 2017 at 6:03 AM, Robert Mantel <rae...@gmail.com> wrote:

I know this is an old thread but I want to ask you about another possible solution.  I have a Particle Photon based weather station that I have dumping sensor readings to a phant server I have running on my network.  The phant server timestamps everything in UTC.  I can then do a jsonp query with a cron job python script I have running then parse that into a format that fileparse.py likes.  I also parse out and convert the EST corrected timestamp from the server into unix epoch format.  Can weewx be set up to ignore it's own timestamps and just use the imported ones, which technically are more accurate because they represent the very moment the reading was taken?  I tried using fileparse to import the timestamp into the dateTime label in weewx, but I think it didn't like that.

If you just add a 'dateTime' line to the file, the time you use there should replace the one provided by fileparse.py.​

 

Another possible solution to the NTP problem is to use a server you have on your local network and configure it as an NTP relay.  I have a freenas box running my phant server in a jail on it so would be easy to just set it up to act as an NTP relay and have the Pi sync from that rather than the internet, therefore I can operate completely in a net down situation and keep collecting data with proper timestamps.  

​Yes, but would it after a "power down" situation? Also, setting up a dedicated NTP relay is beyond the ken of most users.

-tk​

[Robert Mantel]

You mean the if I add to the label_map in weewx.conf the line: 

timestamp (from my phant server)=dateTime 

it will use this timestamp in the weewx database instead of the generated one?