Home » Forums » Archived: Software

emonhub hanging on boot

Submitted by derek_j on Sun, 10/01/2016 - 16:25

I am running the 22-12-15 Beta of 9.3 (and very nice it is too) , and find that emonhub hangs on boot with the exception

Jan 10 16:03:51 cloudserver emonhub[422]: SerialException: device reports readiness to read but returned no data (device disconnected?)
Jan 10 16:03:51 cloudserver emonhub[422]: raise SerialException('device reports readiness to read but returned no data (device disconnected?)')
Jan 10 16:03:51 cloudserver emonhub[422]: File "/usr/lib/python2.7/dist-packages/serial/serialposix.py", line 460, in read
Jan 10 16:03:51 cloudserver emonhub[422]: self._rx_buf = self._rx_buf + self._ser.readline()
Jan 10 16:03:51 cloudserver emonhub[422]: File "/home/pi/emonhub/src/interfacers/EmonHubJeeInterfacer.py", line 78, in read
Jan 10 16:03:51 cloudserver emonhub[422]: rxc = self.read()
Jan 10 16:03:51 cloudserver emonhub[422]: File "/home/pi/emonhub/src/interfacers/emonhub_interfacer.py", line 73, in run
Jan 10 16:03:51 cloudserver emonhub[422]: self.run()
Jan 10 16:03:51 cloudserver emonhub[422]: File "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
Jan 10 16:03:51 cloudserver emonhub[422]: Traceback (most recent call last):
Jan 10 16:03:51 cloudserver emonhub[422]: Exception in thread RFM2Pi:

If I restart emonhub it works fine.  I have tried starting emonhub later in the boot by renaming /etc/rc5.d/S03emonhub but it makes no difference.

emonhub.conf includes

[[RFM2Pi]]
    Type = EmonHubJeeInterfacer
    [[[init_settings]]]
        com_port = /dev/ttyAMA0
        com_baud = 38400

 

I notice there have been other reports of emonhub hanging at boot, but not with the same exception.

‹ New Visualization - Timecompare Monitor energy usage of a generator in a Vehicle // Bad internet connection ›
»
pb66's picture

Re: emonhub hanging on boot

Submitted by pb66 on Sun, 10/01/2016 - 19:47.

Hi, where are you seeing this log? I don't recognize the format.

What do you see in emonhub.log (DEBUG level) when it occurs?

What hardware are you using? eg an emonPi or a Pi and rfm69pi?

The only "hanging" I'm aware of is due to the auto-baud detection not being as good as it should be, but that can be avoided by defining the baud in emonhub.conf, which I see you have done. 

Does it do it using " sudo shutdown -r now " or just when you power cycle ?

Paul

»
derek_j's picture

Re: emonhub hanging on boot

Submitted by derek_j on Sun, 10/01/2016 - 20:56.

Hi Paul.  Thanks for the response.

The log is from

journalctl -r _SYSTEMD_UNIT=emonhub.service

 

I normally use distros which have had systemd longer than debian so have got used to using the systemd tools.  The same exception appears in the rsyslogd log as well.

 

I am using a Pi with rfm69pi 868MHz.

I get that exception consistently when doing a warm boot with "shutdown -r now".

I just tried a cold boot and I did not get the exception, but emonhub still hung and had to be restarted.

 

Derek

 

»
pb66's picture

Re: emonhub hanging on boot

Submitted by pb66 on Sun, 10/01/2016 - 21:58.

Most of us here are only just transitioning from Raspbian Wheezy to Jessie so systemd is still pretty new.

emonhub was built and tested with init so I cannot rule out a compatibility issue but i'm led to believe systemd is backwards compatible with system V init. I have both a Pi 2 with an rfm69pi running Jessie and a emonPi  running the latest emonSD image built on Minibian (minimal jessie) and cannot reproduce the issue.

Can you tell me what is logged in emonhub.log (using loglevel DEBUG) this may give us clues that are more familiar.

Have you made any other changes to the stock image?

Paul

 

»
derek_j's picture

Re: emonhub hanging on boot

Submitted by derek_j on Sun, 10/01/2016 - 22:35.

I have not made any changes to the stock image.  Jessie runs systemd and journalctl 'out of the box'.

Both the journalctl and rsyslogd logs are enabled by default in Jessie. I did not have to do anything to enable it. 

Here is the exception as seen in emonhub.log

2016-01-10 22:25:11,191 INFO     MainThread EmonHub emonHub 'emon-pi' variant v1.1
2016-01-10 22:25:11,198 INFO     MainThread Opening hub...
2016-01-10 22:25:11,199 INFO     MainThread Logging level set to DEBUG
2016-01-10 22:25:11,202 INFO     MainThread Creating EmonHubJeeInterfacer 'RFM2Pi'
2016-01-10 22:25:11,217 DEBUG    MainThread Opening serial port: /dev/ttyAMA0 @ 38400 bits/s
2016-01-10 22:25:13,236 INFO     MainThread RFM2Pi device firmware version: [RF12demo.12]
2016-01-10 22:25:13,237 INFO     MainThread RFM2Pi device current settings:  @ i0 g210 @ 868 MHz
2016-01-10 22:25:13,239 INFO     MainThread Setting RFM2Pi quiet: 0 (0q)
2016-01-10 22:25:14,242 INFO     MainThread Setting RFM2Pi baseid: 5 (5i)
2016-01-10 22:25:20,286 INFO     MainThread Setting RFM2Pi calibration: 230V (1p)
2016-01-10 22:25:21,289 DEBUG    MainThread Setting RFM2Pi subchannels: ['ToRFM12']
2016-01-10 22:25:21,291 DEBUG    MainThread Interfacer: Subscribed to channel' : ToRFM12
2016-01-10 22:25:21,293 DEBUG    MainThread Setting RFM2Pi pubchannels: ['ToEmonCMS']
2016-01-10 22:25:21,295 DEBUG    MainThread Interfacer: Subscribed to channel' : ToRFM12
2016-01-10 22:25:21,298 INFO     MainThread Creating EmonHubMqttInterfacer 'MQTT'
2016-01-10 22:25:21,301 INFO     MainThread MQTT Init mqtt_host=127.0.0.1 mqtt_port=1883 mqtt_user=emonpi
2016-01-10 22:25:21,303 DEBUG    RFM2Pi     acknowledged command: > 0q
2016-01-10 22:25:21,312 DEBUG    MainThread MQTT Subscribed to channel' : ToEmonCMS
2016-01-10 22:25:21,315 INFO     MainThread Creating EmonHubEmoncmsHTTPInterfacer 'emoncmsorg'
2016-01-10 22:25:21,318 DEBUG    MainThread emoncmsorg Subscribed to channel' : ToEmonCMS
2016-01-10 22:25:21,415 INFO     MQTT       Connecting to MQTT Server
2016-01-10 22:25:21,429 INFO     MQTT       connection status: Connection successful
2016-01-10 22:25:21,432 DEBUG    MQTT       CONACK => Return code: 0
2016-01-10 22:25:21,515 DEBUG    RFM2Pi     acknowledged command: > 5i
2016-01-10 22:25:21,535 INFO     MQTT       on_subscribe
2016-01-10 22:25:21,619 DEBUG    RFM2Pi     device settings updated: E i5 g210 @ 868 MHz
2016-01-10 22:25:21,739 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 54 180 31 255 184 119 13 144 6 7 230 0 218 28 75 161 200 213 2
23 159 183 (-87)
2016-01-10 22:25:21,843 DEBUG    RFM2Pi     acknowledged command: > 1p
2016-01-10 22:25:22,206 DEBUG    RFM2Pi     acknowledged command: <nn> i     - set node ID (standard node ids are 1..30)
2016-01-10 22:25:22,334 DEBUG    RFM2Pi     acknowledged command: <n> b      - set MHz band (4 = 433, 8 = 868, 9 = 915)
2016-01-10 22:25:22,441 DEBUG    RFM2Pi     acknowledged command: <nnnn> o   - change frequency offset within the band (default 1600)
2016-01-10 22:25:22,708 DEBUG    RFM2Pi     acknowledged command: <nnn> g    - set network group (RFM12 only allows 212, 0 = any)
2016-01-10 22:25:22,873 DEBUG    RFM2Pi     acknowledged command: <n> c      - set collect mode (advanced, normally 0)
2016-01-10 22:25:23,143 DEBUG    RFM2Pi     acknowledged command: ...,<nn> a - send data packet to node <nn>, request ack
2016-01-10 22:25:23,249 DEBUG    RFM2Pi     acknowledged command: ...,<nn> s - send data packet to node <nn>, no ack
2016-01-10 22:25:23,366 DEBUG    RFM2Pi     acknowledged command: <n> q      - set quiet mode (1 = don't report bad packets)
2016-01-10 22:25:23,475 DEBUG    RFM2Pi     acknowledged command: <n> x      - set reporting format (0: decimal, 1: hex, 2: hex+ascii)
2016-01-10 22:25:23,850 DEBUG    RFM2Pi     acknowledged command: <hchi>,<hclo>,<addr>,<cmd> f     - FS20 command (868 MHz)
2016-01-10 22:25:23,956 DEBUG    RFM2Pi     acknowledged command: <addr>,<dev>,<on> k              - KAKU command (433 MHz)
2016-01-10 22:25:24,212 DEBUG    RFM2Pi     device settings updated: E i5 g210 @ 868 MHz
2016-01-10 22:25:24,358 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 57 70 202 218 225 226 58 24 248 121 147 78 (-104)
2016-01-10 22:25:24,468 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 51 43 169 144 149 177 27 249 80 236 113 165 245 171 137 242 49
 159 207 224 19 (-97)
2016-01-10 22:25:24,574 DEBUG    RFM2Pi     8 NEW FRAME : OK 6 0 0 188 1 0 0 0 0 75 95 195 0 (-75)
2016-01-10 22:25:24,578 DEBUG    RFM2Pi     8 Timestamp : 1452464724.57
2016-01-10 22:25:24,579 DEBUG    RFM2Pi     8 From Node : 6
2016-01-10 22:25:24,581 DEBUG    RFM2Pi     8    Values : [0, 444, 0, 0, 243.95000000000002, 19.5]
2016-01-10 22:25:24,583 DEBUG    RFM2Pi     8      RSSI : -75
2016-01-10 22:25:24,603 INFO     RFM2Pi     Publishing: emonhub/rx/6/values 0,444,0,0,243.95,19.5
2016-01-10 22:25:24,606 INFO     RFM2Pi     Publishing: emonhub/rx/6/rssi -75
2016-01-10 22:25:24,609 DEBUG    RFM2Pi     8 adding frame to buffer => [1452464724, 6, 0, 444, 0, 0, 243.95000000000002, 19.5, -75]
2016-01-10 22:25:24,611 DEBUG    RFM2Pi     8 Sent to channel' : ToEmonCMS
2016-01-10 22:25:24,940 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 63 35 184 150 4 77 23 173 157 111 205 98 156 189 6 1 136 143 2
35 202 131 (-97)
2016-01-10 22:25:26,701 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 159 102 229 36 59 115 195 143 90 152 31 91 242 110 30 0 219 25
3 63 10 161 (-95)
2016-01-10 22:25:28,438 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 191 19 38 198 63 166 187 78 23 220 91 31 179 137 18 200 86 250
 92 245 252 (-96)
2016-01-10 22:25:30,309 DEBUG    RFM2Pi     Discarding RX frame 'unreliable content'? 59 26 252 21 58 129 64 188 161 125 226 53 47 24 176 245 43 123
 139 255 24 (-98)
2016-01-10 22:25:30,681 DEBUG    RFM2Pi     9 NEW FRAME : OK 6 0 0 189 1 0 0 0 0 74 95 195 0 (-75)
2016-01-10 22:25:30,685 DEBUG    RFM2Pi     9 Timestamp : 1452464730.68
2016-01-10 22:25:30,687 DEBUG    RFM2Pi     9 From Node : 6
2016-01-10 22:25:30,689 DEBUG    RFM2Pi     9    Values : [0, 445, 0, 0, 243.94, 19.5]
2016-01-10 22:25:30,690 DEBUG    RFM2Pi     9      RSSI : -75
2016-01-10 22:25:30,693 INFO     RFM2Pi     Publishing: emonhub/rx/6/values 0,445,0,0,243.94,19.5
2016-01-10 22:25:30,696 INFO     RFM2Pi     Publishing: emonhub/rx/6/rssi -75
2016-01-10 22:25:30,700 DEBUG    RFM2Pi     9 adding frame to buffer => [1452464730, 6, 0, 445, 0, 0, 243.94, 19.5, -75]
2016-01-10 22:25:30,702 DEBUG    RFM2Pi     9 Sent to channel' : ToEmonCMS
2016-01-10 22:25:42,204 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:42,467 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:42,730 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:43,014 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:43,282 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:43,534 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:43,816 WARNING  MainThread RFM2Pi thread is dead
2016-01-10 22:25:44,073 WARNING  MainThread RFM2Pi thread is dead

(Plus lots more "thread is dead" messages)

Interesting that it actually receives a good frame before dying.

If I restart emonhub, then it happily keeps running forever.

Hope that helps

Derek

 

»
derek_j's picture

Re: emonhub hanging on boot

Submitted by derek_j on Mon, 11/01/2016 - 08:25.

OK I found the problem.  I should have mentioned that one thing I had done was install fhem in order to control some smart radiator valves via a USB serial radio. When fhem starts it probes the serial ports and causes emonhub to fail.  It does this even when configured not to probe the ports, and even when not a member of the dialout group (and not running as root).

I shall have to see if I can get Openhab to manage the valves instead.

Thanks for the help.

Derek

»

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.