Sudden exit without notice after first failed attempt to get LOOP data; what causes this?

[Zeph Smith]

Running weewx with acurite 02032C on RPi

This morning weewx appears to have just stopped.  I just discovered it this afternoon.

Last syslog message (from weewx) was:

weewx[2809]: acurite: Failed attempt 1 of 10 to get LOOP data: error sending control signal: Connection timed out

So I checked 

sudo /etc/init.d/weewx status

was not running.  So I started it:

sudo /etc/init.d/weewx start

and now it seems to be running fine for the last half hour or so.  I have not changed or rebooted the system - just looked at the logfile and restarted per the above.

My question is: what might have caused it to just quit?  Was this just a USB error?  How can I make it more reliable?

Thanks!

[Thomas Keffer]

Please post more of the log than a single line. In particular, what came after this line?

-tk

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

[Zeph Smith]

That was the last message from weewx in the log.  There are hourly cron messages about wifi key updates (which are also interspersed every hour while weewx is running).

I'm posting from a laptop.

The messages before the error are just the normal ones that repeat every 5 minutes from weewx.  I can quote them later.

[Thomas Keffer]

1. Humor me. Please post more of the log, including what comes later.

2. What log file are you posting from? /var/log/syslog? 

3. Is this error repeatable?

-tk

[Zeph Smith]

On Friday, April 22, 2016 at 6:29:28 PM UTC-7, Tom Keffer wrote:

1. Humor me. Please post more of the log, including what comes later.

2. What log file are you posting from? /var/log/syslog? 

3. Is this error repeatable?

s.google.com/d/optout.

Yes, from syslog.  Not repeatable as in "can cause it deliberately", but it has now happened twice in a couple of days.  Here is the second time it quit.  It's going along normally and generating web pages and WU updates, and then it gets an error.  The hourly rekeying and cron jobs continue indefintely after this.  I was filtering on weewx originally, but now I see the USB kernal error that happens.  The station console is continually connected and untouched when the error occurs; it's set to streaming only mode.  Anyway:

 

Apr 23 14:35:21 d-section weewx[7776]: restx: Wunderground-PWS: Published record 2016-04-23 14:35:00 PDT (1461447300)

Apr 23 14:35:27 d-section weewx[7776]: cheetahgenerator: Generated 14 files for report StandardReport in 6.79 seconds

Apr 23 14:35:32 d-section weewx[7776]: genimages: Generated 12 images for StandardReport in 4.77 seconds

Apr 23 14:35:32 d-section weewx[7776]: reportengine: copied 0 files to /home/weewx/public_html

Apr 23 14:40:20 d-section weewx[7776]: manager: added record 2016-04-23 14:40:00 PDT (1461447600) to database 'weewx.sdb'

Apr 23 14:40:20 d-section weewx[7776]: manager: added record 2016-04-23 14:40:00 PDT (1461447600) to daily summary in 'weewx.sdb'

Apr 23 14:40:23 d-section weewx[7776]: restx: Wunderground-PWS: Published record 2016-04-23 14:40:00 PDT (1461447600)

Apr 23 14:40:28 d-section weewx[7776]: cheetahgenerator: Generated 14 files for report StandardReport in 6.90 seconds

Apr 23 14:40:32 d-section weewx[7776]: genimages: Generated 12 images for StandardReport in 4.72 seconds

Apr 23 14:40:32 d-section weewx[7776]: reportengine: copied 0 files to /home/weewx/public_html

Apr 23 14:45:15 d-section weewx[7776]: manager: added record 2016-04-23 14:45:00 PDT (1461447900) to database 'weewx.sdb'

Apr 23 14:45:16 d-section weewx[7776]: manager: added record 2016-04-23 14:45:00 PDT (1461447900) to daily summary in 'weewx.sdb'

Apr 23 14:45:18 d-section weewx[7776]: restx: Wunderground-PWS: Published record 2016-04-23 14:45:00 PDT (1461447900)

Apr 23 14:45:23 d-section weewx[7776]: cheetahgenerator: Generated 14 files for report StandardReport in 6.89 seconds

Apr 23 14:45:28 d-section weewx[7776]: genimages: Generated 12 images for StandardReport in 4.77 seconds

Apr 23 14:45:28 d-section weewx[7776]: reportengine: copied 0 files to /home/weewx/public_html

Apr 23 14:50:23 d-section weewx[7776]: manager: added record 2016-04-23 14:50:00 PDT (1461448200) to database 'weewx.sdb'

Apr 23 14:50:23 d-section weewx[7776]: manager: added record 2016-04-23 14:50:00 PDT (1461448200) to daily summary in 'weewx.sdb'

Apr 23 14:50:26 d-section weewx[7776]: restx: Wunderground-PWS: Published record 2016-04-23 14:50:00 PDT (1461448200)

Apr 23 14:50:30 d-section weewx[7776]: cheetahgenerator: Generated 14 files for report StandardReport in 6.83 seconds

Apr 23 14:50:35 d-section weewx[7776]: genimages: Generated 12 images for StandardReport in 4.80 seconds

Apr 23 14:50:35 d-section weewx[7776]: reportengine: copied 0 files to /home/weewx/public_html

Apr 23 14:55:24 d-section weewx[7776]: manager: added record 2016-04-23 14:55:00 PDT (1461448500) to database 'weewx.sdb'

Apr 23 14:55:25 d-section weewx[7776]: manager: added record 2016-04-23 14:55:00 PDT (1461448500) to daily summary in 'weewx.sdb'

Apr 23 14:55:27 d-section weewx[7776]: restx: Wunderground-PWS: Published record 2016-04-23 14:55:00 PDT (1461448500)

Apr 23 14:55:32 d-section weewx[7776]: cheetahgenerator: Generated 14 files for report StandardReport in 6.82 seconds

Apr 23 14:55:37 d-section weewx[7776]: genimages: Generated 12 images for StandardReport in 4.78 seconds

Apr 23 14:55:37 d-section weewx[7776]: reportengine: copied 0 files to /home/weewx/public_html

Apr 23 14:56:25 d-section weewx[7776]: acurite: Failed attempt 1 of 10 to get LOOP data: error sending control message: Connection timed out

Apr 23 14:56:25 d-section kernel: [227508.403364] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 25 ret -110

Apr 23 14:56:44 d-section wpa_supplicant[1840]: wlan0: WPA: Group rekeying completed with c0:c1:c0:7a:64:86 [GTK=TKIP]

Apr 23 14:56:44 d-section wpa_supplicant[1840]: wlan0: WPA: Group rekeying completed with c0:c1:c0:7a:64:86 [GTK=TKIP]

Apr 23 15:17:01 d-section /USR/SBIN/CRON[11839]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)

Apr 23 15:56:39 d-section wpa_supplicant[1840]: wlan0: WPA: Group rekeying completed with c0:c1:c0:7a:64:86 [GTK=TKIP]

Apr 23 15:56:39 d-section wpa_supplicant[1840]: wlan0: WPA: Group rekeying completed with c0:c1:c0:7a:64:86 [GTK=TKIP]

Apr 23 16:17:01 d-section /USR/SBIN/CRON[11857]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)

[Zeph Smith]

More info: I'm now running the last version of wheezy (per advice on this list) so that I can run ramlog.  I made the html directory a ram disk.  Have not yet done anything about the database file (to reduce SD card writes)

pi@d-section ~ $ df

Filesystem     1K-blocks    Used Available Use% Mounted on

/dev/root        3668812 2868504    601072  83% /

devtmpfs          218244       0    218244   0% /dev

tmpfs              44504     304     44200   1% /run

tmpfs               5120       0      5120   0% /run/lock

tmpfs              89000       0     89000   0% /run/shm

/dev/mmcblk0p1     57288   20296     36992  36% /boot

tmpfs               2048     556      1492  28% /home/weewx/public_html

/dev/root        3668812 2868504    601072  83% /var/log.hdd

ramlog-tmpfs      222516    3520    218996   2% /var/log

[mwall]

On Sunday, April 24, 2016 at 1:55:03 PM UTC-4, Zeph Smith wrote:

Apr 23 14:56:25 d-section weewx[7776]: acurite: Failed attempt 1 of 10 to get LOOP data: error sending control message: Connection timed out

Apr 23 14:56:25 d-section kernel: [227508.403364] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 25 ret -110

the 'USBDEVFS_CONTROL failed' is the killer.

looks like the usb gets borked, probably by something the 02032 said or did.

i've seen this on arm-based 'plug' computers, but never on anything x86 or x64, so it might be power/bus related.

it seems to happen more with a 2032C than any other acurite model, although i have seen it with a 01036.

however, it should *not* cause the weewx process to die.

could you run weewx directly instead of as a daemon?  there is a chance that weewx is dumping a stack trace, but that stack trace is getting swallowed somewhere.  most likely you'll see a 'segmentation fault', which would indicate a problem in the rpi usb libraries.

to diagnose these, i run screen, then run weewx from within screen as 'weewxd weewx.conf'.  that way you don't need to stay logged in to see what happens.  reattach to the screen later when you want to check in on weewx.

we cannot prevent the 02032 from being stupid, but we can make the os and weewx impervious to its stupidity.

m

[Zeph Smith]

I am attempting to comply.

I started an LXTerminal from the Pi's GUI

first I stopped the daemon: 

   sudo /etc/init.d/weewx stop

Then:

   cd /home/weewx

   sudo weewxd weewx.conf

Then from another terminal, I did:

   tail -n 50 /var/log/syslog

It has started.  Some messages are still on syslog, but the LOOP: and REC: messages are showing up on the terminal

If it dies in the next day or two, I will hope for something I can show you.

(And I agree: we can't keep the 02032C from doing something stupid but we can hope to not die from it)

Thanks!

[Zeph Smith]

I am attempting to comply.

I started an LXTerminal from the Pi's GUI

first I stopped the daemon: 

   sudo /etc/init.d/weewx stop

Then:

   cd /home/weewx

   sudo bin/weewxd weewx.conf

I had to use bin/weewxd 

[Glenn McKechnie]

A suggestion, or perhaps two. And they are only suggestions as what you're doing is satisfying Mathew and Tom just fine....

In that 2nd terminal, you can use  tail -f  /var/log/syslog for a continual output, at least until the file gets rotated where  tail -F /var/log/syslog is apparently the better choice.  I haven't tried that particular incantation as I use multitail (a colourized alternative) that can, optionally,  follow multiple files and I know it handles the log rotation seamlessly. It's in constant use here and has never failed.

Sounds like you're running with a monitor and keyboard attached, so this next comment is not so important;  but...
Mathew's comment regarding screen. It's a fantastic program to log into remote terminals with, or any terminal where you have long running jobs / sessions and don't want to lose them to flaky connections, or from a local Desktop where you can just drop them all into the background and de-clutter without losing them, they'll still be running.
If you're logged in remotely, you can lose your network link and when you reconnect to the machine, just reattach to the screen session you had before, it's as though you never left. It has way more features than this (shared sessions etc) but that's enough to make it a good candidate to add to your tool chest - for later.
It's a little daunting to learn and remember the commands for it, but a search will turn up a cheat sheet or 20.
If you install byobu as well as screen, then you can run screen, or it's default tmux, with a preconfigured status bar that reminds you where you are and the ability to track any nested terminals started from within the session. Plus you get a menu to set it up with - it's a little more (way more) user friendly than just the default screen install.

cheers
Glenn

[Zeph Smith]

In that 2nd terminal, you can use  tail -f  /var/log/syslog for a continual output, at least until the file gets rotated where  tail -F /var/log/syslog is apparently the better choice.  I haven't tried that particular incantation as I use multitail (a colourized alternative) that can, optionally,  follow multiple files and I know it handles the log rotation seamlessly. It's in constant use here and has never failed.

Good tip.  I only knew about tail -f

 

Sounds like you're running with a monitor and keyboard attached,

Only while I try to get this stable... so far it only runs a day or two before dying.

 

Mathew's comment regarding screen. It's a fantastic program to log into remote terminals with, or any terminal where you have long running jobs / sessions and don't want to lose them to flaky connections, or from a local Desktop where you can just drop them all into the background and de-clutter without losing them,

Ah, thanks.  I didn't know what screen was.  It turns out to help to search for gnu screen.  (I thought it was more of a client terminal program like putty, didn't realize it was a server). Sounds useful.  And then there's tmux, and byobu which works with both.  The learning curve is somewhat steep, but these tips help.

Meanwhile - all working.  Waiting for a glitch to see if I get a dump that would help.  (What we used to call a core dump; wonder if anybody remembers magnetic core memories?)

[Thomas Keffer]

My first computer experience was with an IBM 1130, with 8,192 words of true core memory.

-tk

[J.L. Blom]

On 25/04/16 21:38, Zeph Smith wrote:
>
> In that 2nd terminal, you can use tail -f /var/log/syslogfor a

> continual output, at least until the file gets rotated where tail

> -F /var/log/syslogis apparently the better choice. I haven't

> tried that particular incantation as I use multitail (a colourized
> alternative) that can, optionally, follow multiple files and I
> know it handles the log rotation seamlessly. It's in constant use
> here and has never failed.
>
>
> Good tip. I only knew about tail -f
>
> Sounds like you're running with a monitor and keyboard attached,
>
>
> Only while I try to get this stable... so far it only runs a day or
> two before dying.
>
> Mathew's comment regarding screen. It's a fantastic program to log
> into remote terminals with, or any terminal where you have long
> running jobs / sessions and don't want to lose them to flaky
> connections, or from a local Desktop where you can just drop them
> all into the background and de-clutter without losing them,
>
>
> Ah, thanks. I didn't know what screen was. It turns out to help to
> search for gnu screen. (I thought it was more of a client terminal
> program like putty, didn't realize it was a server). Sounds useful.
> And then there's tmux, and byobu which works with both. The learning
> curve is somewhat steep, but these tips help.
>
> Meanwhile - all working. Waiting for a glitch to see if I get a dump
> that would help. (What we used to call a core dump; wonder if anybody
> remembers magnetic core memories?)
>
>

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

> <mailto:weewx-user+...@googlegroups.com>.

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

Same time. I worked with a PDP-8 and had to manually install the
bootstrap loader no ROM.
Joep

[Andrew Milner]

Aha - the good old RIM loader

@7756

6032  KCC

6031  KSF

5357  JMP .-1

6036  KRB

7106  CLL RTL

7006  RTL

7510  SPA

5357  JMP 7757

7006  RTL

6031  KSF

5367  JMP .-1

6034  KRS

7420  SNL

3776  DCA I TEMP

3376  DCA TEMP

5356  JMP 7756

0000  TEMP, 0

Wow - that brought back memories as I cheated and hunted around on the net to find it!!

> <mailto:weewx-user+unsub...@googlegroups.com>.

[Zeph Smith]

Recap from beginning and Update:

Started thread after I ran weewx for 3 days as an init.d service, and got two errors which killed the service:

Apr 22 09:51:19 d-section kernel: [122798.484009] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 25 ret -110

I have been running it directly (not as a service) for several days, in order to try to capture more info when it dies.   So far no abort.  But for the record, I thought I'd post an example of the USB errors which have NOT caused it to abort (from syslog):

Apr 27 06:33:36 d-section kernel: [542952.065286] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 10 ret -110
Apr 27 06:44:40 d-section kernel: [543616.091478] Transfer to device 8 endpoint 0x1 frame 748 failed - FIQ reported NYET. Data may have been lost.
Apr 27 06:48:53 d-section kernel: [543869.261874] Transfer to device 8 endpoint 0x1 frame 1980 failed - FIQ reported NYET. Data may have been lost.
Apr 27 06:57:02 d-section kernel: [544357.680229] Transfer to device 8 endpoint 0x1 frame 860 failed - FIQ reported NYET. Data may have been lost.
Apr 27 07:53:33 d-section kernel: [547749.052976] Transfer to device 8 endpoint 0x1 frame 284 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:01:19 d-section kernel: [551815.109383] Transfer to device 8 endpoint 0x1 frame 508 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:30:57 d-section kernel: [553593.230232] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 10 ret -110
Apr 27 09:35:22 d-section kernel: [553858.555010] Transfer to device 8 endpoint 0x1 frame 1820 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:43:14 d-section kernel: [554330.203078] Transfer to device 8 endpoint 0x1 frame 316 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:52:53 d-section kernel: [554909.177738] Transfer to device 8 endpoint 0x1 frame 1676 failed - FIQ reported NYET. Data may have been lost.
Apr 27 10:10:00 d-section kernel: [555936.694820] usb 1-1.3-port2: disabled by hub (EMI?), re-enabling...
Apr 27 10:10:00 d-section kernel: [555936.695261] usb 1-1.3.2: USB disconnect, device number 15
Apr 27 10:10:01 d-section kernel: [555936.938390] usb 1-1.3.2: new low-speed USB device number 16 using dwc_otg
Apr 27 10:10:01 d-section kernel: [555937.048224] usb 1-1.3.2: New USB device found, idVendor=24c0, idProduct=0003
Apr 27 10:10:01 d-section kernel: [555937.048327] usb 1-1.3.2: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Apr 27 10:10:01 d-section kernel: [555937.048355] usb 1-1.3.2: Product: Chaney Instrument
Apr 27 10:10:11 d-section kernel: [555947.078763] hid-generic 0003:24C0:0003.000C: timeout initializing reports
Apr 27 10:10:11 d-section kernel: [555947.079410] input: Chaney Instrument as /devices/platform/soc/20980000.usb/usb1/1-1/1-1.3/1-1.3.2/1-1.3.2:1.0/0003:24C0:0003.000C/input/input11
Apr 27 10:10:11 d-section kernel: [555947.087922] hid-generic 0003:24C0:0003.000C: input,hidraw0: USB HID v1.11 Device [Chaney Instrument] on usb-20980000.usb-1.3.2/input0
Apr 27 11:00:21 d-section kernel: [558957.967800] Transfer to device 8 endpoint 0x1 frame 1020 failed - FIQ reported NYET. Data may have been lost.
Apr 27 11:20:39 d-section kernel: [560175.061154] Transfer to device 8 endpoint 0x1 frame 1436 failed - FIQ reported NYET. Data may have been lost.
Apr 27 11:54:42 d-section kernel: [562218.282742] Transfer to device 8 endpoint 0x1 frame 476 failed - FIQ reported NYET. Data may have been lost.

These are from grep kernel /var/log/syslog

As we can see, along with routine endpoint failures,  there are errors just like the ones which killed the service, but which are not killing the non-service job.  Does that bring anything to mind?  Is there something which might be fatal only when running as a service?

On Friday, April 22, 2016 at 4:47:21 PM UTC-7, Zeph Smith wrote:

[Steve]

I think the fix for me when my RPi 2 (Wheezy) spat out a bunch of those was to add dwc_otg.fiq_fsm_mask=0xF to /boot/cmdline.txt  I only did it to stop syslog from filling up with the messages. 

On Thursday, 28 April 2016 05:44:03 UTC+10, Zeph Smith wrote:

Recap from beginning and Update:

Started thread after I ran weewx for 3 days as an init.d service, and got two errors which killed the service:

Apr 22 09:51:19 d-section kernel: [122798.484009] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 25 ret -110

I have been running it directly (not as a service) for several days, in order to try to capture more info when it dies.   So far no abort.  But for the record, I thought I'd post an example of the USB errors which have NOT caused it to abort (from syslog):

Apr 27 06:33:36 d-section kernel: [542952.065286] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 10 ret -110
Apr 27 06:44:40 d-section kernel: [543616.091478] Transfer to device 8 endpoint 0x1 frame 748 failed - FIQ reported NYET. Data may have been lost.
Apr 27 06:48:53 d-section kernel: [543869.261874] Transfer to device 8 endpoint 0x1 frame 1980 failed - FIQ reported NYET. Data may have been lost.
Apr 27 06:57:02 d-section kernel: [544357.680229] Transfer to device 8 endpoint 0x1 frame 860 failed - FIQ reported NYET. Data may have been lost.
Apr 27 07:53:33 d-section kernel: [547749.052976] Transfer to device 8 endpoint 0x1 frame 284 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:01:19 d-section kernel: [551815.109383] Transfer to device 8 endpoint 0x1 frame 508 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:30:57 d-section kernel: [553593.230232] usb 1-1.3.2: usbfs: USBDEVFS_CONTROL failed cmd weewxd rqt 161 rq 1 len 10 ret -110
Apr 27 09:35:22 d-section kernel: [553858.555010] Transfer to device 8 endpoint 0x1 frame 1820 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:43:14 d-section kernel: [554330.203078] Transfer to device 8 endpoint 0x1 frame 316 failed - FIQ reported NYET. Data may have been lost.
Apr 27 09:52:53 d-section kernel: [554909.177738] Transfer to device 8 endpoint 0x1 frame 1676 failed - FIQ reported NYET. Data may have been lost.
Apr 27 10:10:00 d-section kernel: [555936.694820] usb 1-1.3-port2: disabled by hub (EMI?), re-enabling...
Apr 27 10:10:00 d-section kernel: [555936.695261] usb 1-1.3.2: USB disconnect, device number 15
Apr 27 10:10:01 d-section kernel: [555936.938390] usb 1-1.3.2: new low-speed USB device number 16 using dwc_otg
Apr 27 10:10:01 d-section kernel: [555937.048224] usb 1-1.3.2: New USB device found, idVendor=24c0, idProduct=0003
Apr 27 10:10:01 d-section kernel: [555937.048327] usb 1-1.3.2: New USB device strings: Mfr=0, Product=2, SerialNumber=0
Apr 27 10:10:01 d-section kernel: [555937.048355] usb 1-1.3.2: Product: Chaney Instrument
Apr 27 10:10:11 d-section kernel:

...

[Zeph Smith]

Thanks for the tip.  It's mumbo jumbo to me - where is this documented?

RIght now I'm trying to get more error messages when the RPi stops.  But in the longer run, it could be good to turn off useless error messages.  Is it the case that this command just suppresses some error messages on syslog, rather than "fixing" anything?

[Steve]

Here's one link https://github.com/raspberrypi/linux/issues/624 There's a lot of hits out there depending on exactly what you search for.

Regards,

Steve.