Directly connecting to Optical Pulse Counter with RPi?

pulses.py changed to

f = ' '.join((str(t), str(nodeid), str(pulse_id[1]), str(7))) # Changed

Output

2016-11-13 20:04:05,124 INFO     MQTT       Connecting to MQTT Server
2016-11-13 20:04:05,130 INFO     MQTT       connection status: Connection successful
2016-11-13 20:04:05,131 DEBUG    MQTT       CONACK => Return code: 0
2016-11-13 20:04:05,239 INFO     MQTT       on_subscribe
2016-11-13 20:04:23,173 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1479067463
2016-11-13 20:04:24,811 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2016-11-13 20:04:24,812 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-13 20:04:53,201 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1479067493
2016-11-13 20:04:54,472 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2016-11-13 20:04:54,473 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-13 20:04:57,398 DEBUG    Pulse      1 NEW FRAME : 1479067497.17 18 1 7
2016-11-13 20:04:57,399 DEBUG    Pulse      1 Timestamp : 1479067497.17
2016-11-13 20:04:57,400 DEBUG    Pulse      1 From Node : 18
2016-11-13 20:04:57,401 DEBUG    Pulse      1    Values : [1, 7]
2016-11-13 20:04:57,402 DEBUG    Pulse      1 Sent to channel(start)' : ch1
2016-11-13 20:04:57,403 DEBUG    Pulse      1 Sent to channel(end)' : ch1
2016-11-13 20:04:57,404 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-13 20:04:57,536 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:57,778 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:58,005 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:58,242 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:58,468 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:58,694 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:58,918 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:59,144 WARNING  MainThread Pulse thread is dead
2016-11-13 20:04:59,370 WARNING  MainThread Pulse thread is dead

So much for that idea then!

I’ll look at the emoncmshttp interfacer and suggest some extra log entries as it definitely seems to stumble after “Sent to channel(start)’ : ToEmonCMS” despite previously returning from the “1 Sent to channel(start)’ : ch1” ok. However what happened to the MQTT publishing? From that last log

2016-11-13 20:04:57,401 DEBUG    Pulse      1    Values : [1, 7]
2016-11-13 20:04:57,402 DEBUG    Pulse      1 Sent to channel(start)' : ch1

SHOULDN'T THERE BE 4 MQTT PUBLISHED LINES IN HERE !!!

2016-11-13 20:04:57,403 DEBUG    Pulse      1 Sent to channel(end)' : ch1
2016-11-13 20:04:57,404 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-13 20:04:57,536 WARNING  MainThread Pulse thread is dead

EDIT - Just noticed the MQTT is missing from the previous but one log too! is it producing inputs in emoncms still?

EDIT2 - The comma is missing from the MQTT "subchannels = ch1, " line of your emonhub.conf, the comma is required to force a list of one item. Can you retry with the comma just to confirm the MQTT publishes ok before we move on? I do not think it will impact the thread dying after data is sent to emoncmsorg interfacer though.

It’s a bit crude, but it’ll do the job (I hope), if you can add the 5 lines ending with a “#TEMP LOG” comment to the receiver function in EmonHubEmoncmsHTTPInterfacer.py like so…

  def receiver(self, cargo):
    
        # Create a frame of data in "emonCMS format"
        self._log.debug(str(cargo.uri) + " TP1" + str(f))        #TEMP LOG
        f = []
        f.append(int(cargo.timestamp))
        self._log.debug(str(cargo.uri) + " TP2" + str(f))        #TEMP LOG
        f.append(cargo.nodeid)
        self._log.debug(str(cargo.uri) + " TP3" + str(f))        #TEMP LOG
        for i in cargo.realdata:
            f.append(i)
        self._log.debug(str(cargo.uri) + " TP4" + str(f))        #TEMP LOG
        if cargo.rssi:
            f.append(cargo.rssi)

        self._log.debug(str(cargo.uri) + " adding frame to buffer => "+ str(f))
        
        # Append to bulk post buffer
        self.buffer.append(f)
        self._log.debug(str(cargo.uri) + " TP5" + str(f))        #TEMP LOG

We should get a step by step log of the emoncms frame being constructed right up to when it fails. If you could retry it a couple of times just to be sure it fails consistently at the same point each time we should be able to pinpoint exactly where it trips up.

All 6 log entries (5x temp and the pre-exisiting one) should print between "Sent to channel(start)’ : ToEmonCMS " and " Sent to channel(end)’ : ToEmonCMS ", but we’ll see how many actually print before the “Pulse thread is dead” message strikes.

My bad, added back in comma, I think this is what you were expecting

2016-11-14 06:42:00,138 INFO     emoncmsorg sending: https://emoncms.org/input/b
ulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1479105720
2016-11-14 06:42:01,479 DEBUG    emoncmsorg acknowledged receipt with 'ok' from 
https://emoncms.org
2016-11-14 06:42:01,480 INFO     emoncmsorg sending: https://emoncms.org/myip/se
t.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-14 06:42:30,148 INFO     emoncmsorg sending: https://emoncms.org/input/b
ulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1479105750
2016-11-14 06:42:31,452 DEBUG    emoncmsorg acknowledged receipt with 'ok' from 
https://emoncms.org
2016-11-14 06:42:31,453 INFO     emoncmsorg sending: https://emoncms.org/myip/se
t.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-14 06:42:36,841 DEBUG    Pulse      1 NEW FRAME : 1479105756.79 18 1 7
2016-11-14 06:42:36,842 DEBUG    Pulse      1 Timestamp : 1479105756.79
2016-11-14 06:42:36,843 DEBUG    Pulse      1 From Node : 18
2016-11-14 06:42:36,843 DEBUG    Pulse      1    Values : [1, 7]
2016-11-14 06:42:36,844 DEBUG    Pulse      1 Sent to channel(start)' : ch1
2016-11-14 06:42:36,845 INFO     Pulse      Publishing: emon/18/1 1
2016-11-14 06:42:36,850 INFO     Pulse      Publishing: emon/18/2 7
2016-11-14 06:42:36,853 INFO     Pulse      Publishing: emon/18/rssi 0
2016-11-14 06:42:36,860 INFO     Pulse      Publishing: emonhub/rx/18/values 1,7
2016-11-14 06:42:36,862 INFO     Pulse      Publishing: emonhub/rx/18/rssi 0
2016-11-14 06:42:36,864 DEBUG    Pulse      1 Sent to channel(end)' : ch1
2016-11-14 06:42:36,865 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCM
S
2016-11-14 06:42:37,045 WARNING  MainThread Pulse thread is dead
2016-11-14 06:42:37,271 WARNING  MainThread Pulse thread is dead
2016-11-14 06:42:37,513 WARNING  MainThread Pulse thread is dead
2016-11-14 06:42:37,738 WARNING  MainThread Pulse thread is dead
2016-11-14 06:42:37,964 WARNING  MainThread Pulse thread is dead
2016-11-14 06:42:38,190 WARNING  MainThread Pulse thread is dead

One entry gets input INPUTS

trying next suggestion next…

Done that, editing the file in /home/pi/emonhub/src/interfacers.
So I think this is basically Test 3, but with two data items from your/my pulse.py, and correcting the comma in MQTT.

Repeated this several times with consistent results.
Your extra debug lines do not seem to appear

Output is :
One data item appears in INPUT for each key, ie the two values sent from pulse.py

2016-11-14 07:16:25,405 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=
[]&sentat=1479107785
2016-11-14 07:16:26,795 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2016-11-14 07:16:26,796 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-14 07:16:34,932 DEBUG    Pulse      1 NEW FRAME : 1479107794.79 18 1 7
2016-11-14 07:16:34,933 DEBUG    Pulse      1 Timestamp : 1479107794.79
2016-11-14 07:16:34,934 DEBUG    Pulse      1 From Node : 18
2016-11-14 07:16:34,934 DEBUG    Pulse      1    Values : [1, 7]
2016-11-14 07:16:34,941 DEBUG    Pulse      1 Sent to channel(start)' : ch1
2016-11-14 07:16:34,943 INFO     Pulse      Publishing: emon/18/1 1
2016-11-14 07:16:34,946 INFO     Pulse      Publishing: emon/18/2 7
2016-11-14 07:16:34,948 INFO     Pulse      Publishing: emon/18/rssi 0
2016-11-14 07:16:34,950 INFO     Pulse      Publishing: emonhub/rx/18/values 1,7
2016-11-14 07:16:34,954 INFO     Pulse      Publishing: emonhub/rx/18/rssi 0
2016-11-14 07:16:34,956 DEBUG    Pulse      1 Sent to channel(end)' : ch1
2016-11-14 07:16:34,957 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-14 07:16:35,156 WARNING  MainThread Pulse thread is dead
2016-11-14 07:16:35,382 WARNING  MainThread Pulse thread is dead
2016-11-14 07:16:35,608 WARNING  MainThread Pulse thread is dead
2016-11-14 07:16:35,832 WARNING  MainThread Pulse thread is dead

Just for clarity my config is. Please double check @pb66 , Affraid i’ve lost track of what you want in here now

#######################################################################
#######################      emonhub.conf     #########################
#######################################################################
### emonHub configuration file, for info see documentation:
### http://github.com/openenergymonitor/emonhub/blob/emon-pi/configuration.md
#######################################################################
#######################    emonHub  settings    #######################
#######################################################################

[hub]
### loglevel must be one of DEBUG, INFO, WARNING, ERROR, and CRITICAL
loglevel = DEBUG
### Uncomment this to also send to syslog
# use_syslog = yes
#######################################################################
#######################       Interfacers       #######################
#######################################################################

[interfacers]
### This interfacer manages the RFM12Pi/RFM69Pi/emonPi module
[[RFM2Pi]]
    #Type = EmonHubJeeInterfacer
    [[[init_settings]]]
        com_port = /dev/ttyAMA0
        com_baud = 38400                        # 9600 for old RFM12Pi
    [[[runtimesettings]]]
        pubchannels = ToEmonCMS,
        subchannels = ToRFM12,

        group = 210
        frequency = 433
        baseid = 5                              # emonPi / emonBase nodeID
        quiet = true                            # Report incomplete RF packets (no implemented on emonPi)
        calibration = 230V                      # (UK/EU: 230V, US: 110V)
        # interval =  0                         # Interval to transmit time to emonGLCD (seconds)

[[MQTT]]

    Type = EmonHubMqttInterfacer
    [[[init_settings]]]
        mqtt_host = 127.0.0.1
        mqtt_port = 1883
        mqtt_user = emonpi
        mqtt_passwd = emonpimqtt2016

    [[[runtimesettings]]]
        pubchannels = ToRFM12,
        subchannels = ch1,

        # emonhub/rx/10/values format
        # Use with emoncms Nodes module
        node_format_enable = 1
        node_format_basetopic = emonhub/

        # emon/emontx/power1 format - use with Emoncms MQTT input
        # http://github.com/emoncms/emoncms/blob/master/docs/RaspberryPi/MQTT.md
        nodevar_format_enable = 1
        nodevar_format_basetopic = emon/

[[emoncmsorg]]
    Type = EmonHubEmoncmsHTTPInterfacer
    [[[init_settings]]]
    [[[runtimesettings]]]
        pubchannels = ToRFM12,
        subchannels = ToEmonCMS, 
        url = https://emoncms.org
        apikey = xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx 
        senddata = 1                    # Enable sending data to Emoncms.org
        sendstatus = 1                  # Enable sending WAN IP to Emoncms.org MyIP > https://emoncms.org/myip/list
        sendinterval= 30                # Bulk send interval to Emoncms.org in seconds

[[Pulse]]
        Type = EmonHubSocketInterfacer
        [[[init_settings]]]
                port_nb = 50012
        [[[runtimesettings]]]
                pubchannels = ch1, ToEmonCMS
                timestamped = True

#######################################################################
#######################          Nodes          #######################
#######################################################################

[nodes]

## See config user guide: http://github.com/openenergymonitor/emonhub/blob/master/configuration.md

[[5]]
    nodename = emonpi
    [[[rx]]]
        names = power1,power2,power1pluspower2,vrms,t1,t2,t3,t4,t5,t6,pulsecount
        datacodes = h, h, h, h, h, h, h, h, h, h, L
        scales = 1,1,1,0.01,0.1,0.1,0.1,0.1,0.1,0.1,1
        units = W,W,W,V,C,C,C,C,C,C,p

[[6]]
    nodename = emontxshield
    [[[rx]]]
       names = power1, power2, power3, power4, vrms
       datacode = h
       scales = 1,1,1,1,0.01
       units =W,W,W,W,V

[[7]]
   nodename = emontx4
   [[[rx]]]
      names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
      datacodes = h,h,h,h,h,h,h,h,h,h,h,L
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[8]]
    nodename = emontx3
    [[[rx]]]
       names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       datacodes = h,h,h,h,h,h,h,h,h,h,h,L
       scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
       units =W,W,W,W,V,C,C,C,C,C,C,p

[[9]]
   nodename = emontx2
   [[[rx]]]
      names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
      datacode = h
      scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
      units =W,W,W,W,V,C,C,C,C,C,C,p

[[10]]
    nodename = emontx1
    [[[rx]]]
       names = power1, power2, power3, power4, vrms, temp1, temp2, temp3, temp4, temp5, temp6, pulse
       datacode = h
       scales = 1,1,1,1,0.01,0.1,0.1, 0.1,0.1,0.1,0.1,1
       units =W,W,W,W,V,C,C,C,C,C,C,p

#[[18]]
#    nodename = pulsecounter
#    [[[rx]]]
#    names = pulsecnt1
#    scales = 1
#    units = W

[[19]]
   nodename = emonth1
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[20]]
   nodename = emonth2
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[21]]
   nodename = emonth3
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V

[[22]]
   nodename = emonth4
   [[[rx]]]
      names = temperature, external temperature, humidity, battery
      datacode = h
      scales = 0.1,0.1,0.1,0.1
      units = C,C,%,V
[[23]]
    nodename = emonth5
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[24]]
    nodename = emonth6
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[25]]
    nodename = emonth7
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[26]]
    nodename = emonth8
    [[[rx]]]
       names = temperature, external temperature, humidity, battery, pulsecount
       datacodes = h,h,h,h,L
       scales = 0.1,0.1,0.1,0.1,1
       units = C,C,%,V,p

[[11]]
    nodename = 3phase
    [[[rx]]]
       names = powerL1, powerL2, powerL3, power4, Vrms, temp1, temp2, temp3, temp4, temp5, temp6
       datacode = h
       scales = 1,1,1,1,0.01,0.1,0.1,0.1,0.1,0.1,0.1
       units =W,W,W,W,V,C,C,C,C,C,C


Yep, that makes more sense!

I was surprised none of them show at all, “TP1” was intended to just confirm entry to the function, there are no prior steps to cause a fail before that log entry. “Sent to channel(start)’ : ToEmonCMS” marks the beginning of a second loop of the for loop
https://github.com/openenergymonitor/emonhub/blob/emon-pi/src/interfacers/emonhub_interfacer.py#L81-L84

Can you try editing the “TP1” line so it is a very basic text log without reliance on variables like so

self._log.debug(" TP1")        #TEMP LOG

DOH! Sorry! I just realized the log message is prior to “f” being declared, my mistake I thought I had put “TP1” after “f = ”, it will have failed at that first log message independent of the issue we are debugging.

It looks fine, I think we are “on the same page” so to speak,

So if you can retry with the amended “TP1” log message, the results should (fingers crossed) be different.

And If they are not, you could try

  1. changing the Pulse interfacer’s pubchannels = setting from “pubchannels = ch1, ToEmonCMS” to “pubchannels = ToEmonCMS, ch1” to switch the order they are actioned just to confirm it’s still the “emoncmsorg” that fails, rather than which ever happens to be second (another long shot, but worth eliminating).

  2. remove “ch1” from the Pulse pubchannels and edit MQTT subchannels to “ToEmonCMS” to see if the results differ when both MQTT and emoncmsorg interfacers are listening to the same channel, this is the stock configuration and ironically, should be the most prone to fail as it is actually doing what should be done on 2 separate threads at one time rather than one after the other as we currently have it.

Simplifying log message (and with ‘pubchannels = ch1, ToEmonCMS’ gives (and data appears in INPUTS):

2016-11-14 18:29:35,658 DEBUG    Pulse      1 Timestamp : 1479148175.54
2016-11-14 18:29:35,659 DEBUG    Pulse      1 From Node : 18
2016-11-14 18:29:35,659 DEBUG    Pulse      1    Values : [1, 7]
2016-11-14 18:29:35,660 DEBUG    Pulse      1 Sent to channel(start)' : ch1
2016-11-14 18:29:35,661 INFO     Pulse      Publishing: emon/18/1 1
2016-11-14 18:29:35,663 INFO     Pulse      Publishing: emon/18/2 7
2016-11-14 18:29:35,664 INFO     Pulse      Publishing: emon/18/rssi 0
2016-11-14 18:29:35,666 INFO     Pulse      Publishing: emonhub/rx/18/values 1,7
2016-11-14 18:29:35,667 INFO     Pulse      Publishing: emonhub/rx/18/rssi 0
2016-11-14 18:29:35,669 DEBUG    Pulse      1 Sent to channel(end)' : ch1
2016-11-14 18:29:35,669 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-14 18:29:35,670 DEBUG    Pulse       TP1
2016-11-14 18:29:35,800 WARNING  MainThread Pulse thread is dead
2016-11-14 18:29:36,043 WARNING  MainThread Pulse thread is dead
2016-11-14 18:29:36,268 WARNING  MainThread Pulse thread is dead
2016-11-14 18:29:36,493 WARNING  MainThread Pulse thread is dead
2016-11-14 18:29:36,718 WARNING  MainThread Pulse thread is dead

swapping to pubchannels = ToEmonCMS, ch1
gives (and nothing appears in INPUTS)

2016-11-14 18:34:11,512 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-14 18:34:40,286 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[]&sentat=1479148480
2016-11-14 18:34:41,594 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2016-11-14 18:34:41,595 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y
2016-11-14 18:34:44,753 DEBUG    Pulse      1 NEW FRAME : 1479148484.65 18 1 7
2016-11-14 18:34:44,754 DEBUG    Pulse      1 Timestamp : 1479148484.65
2016-11-14 18:34:44,755 DEBUG    Pulse      1 From Node : 18
2016-11-14 18:34:44,756 DEBUG    Pulse      1    Values : [1, 7]
2016-11-14 18:34:44,756 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-14 18:34:44,757 DEBUG    Pulse       TP1
2016-11-14 18:34:44,800 WARNING  MainThread Pulse thread is dead
2016-11-14 18:34:45,029 WARNING  MainThread Pulse thread is dead
2016-11-14 18:34:45,258 WARNING  MainThread Pulse thread is dead
2016-11-14 18:34:45,484 WARNING  MainThread Pulse thread is dead
2016-11-14 18:34:45,709 WARNING  MainThread Pulse thread is dead
2016-11-14 18:34:45,936 WARNING  MainThread Pulse thread is dead
2016-11-14 18:34:46,161 WARNING  MainThread Pulse thread is dead

This looks better as the “TP1” is printed, narrowing the location of the issue sigificantly. The second test/log further confirms those findings as the fail has moved with the “emoncmsorg” code to the first loop and retaining the “TP1” log message.

So those results point to the issue being triggered within these 3 lines

        f = []
        f.append(int(cargo.timestamp))
        self._log.debug(str(cargo.uri) + " TP2" + str(f))        #TEMP LOG

the odd thing is the RFM2Pi data is also passed through this code too, without issue (most of the time). I had noticed that there is no " import Cargo" at the beginning of the EmonHubEmoncmsHTTPInterfacer.py file but thought no more about it as the RFM2PI data was able to pass. Perhaps we should try adding the import statement.

If you also want to switch back the Pulse pubchannels to “pubchannels = ch1, ToEmonCMS” the logs will show the successful MQTT before a failed emoncmsorg loop again which is better for debugging. In between debugging attempts you should be able to just add a hash to the emoncmsorg Type = for it to run without the thread dying albeit without posting to emoncms.org for now.

It’s been a long day today and my heads a bit fried, I will try and figure this out but there might not be any progress untill tomorrow if adding the import statement doesn’t help.

import Cargo

didn’t help !

Here are some additional log entries to add and further narrow the search (2 blocks of 3 log entries), I’ve shown that whole function including the previous log entries for clarity.

def receiver(self, cargo):
    
        # Create a frame of data in "emonCMS format"
        self._log.debug(" TP1")        #TEMP LOG
        f = []

        self._log.debug(" TP1.1.1")                                #TEMP LOG
        self._log.debug(" TP1.1.2" + str(cargo.timestamp))         #TEMP LOG
        self._log.debug(" TP1.1.3" + str(int(cargo.timestamp)))    #TEMP LOG

        f.append(int(cargo.timestamp))

        self._log.debug(" TP1.2.1")                                #TEMP LOG
        self._log.debug(" TP1.2.2" + str(cargo.uri))               #TEMP LOG
        self._log.debug(" TP1.2.3" + str(f))                       #TEMP LOG

        self._log.debug(str(cargo.uri) + " TP2" + str(f))        #TEMP LOG
        f.append(cargo.nodeid)
        self._log.debug(str(cargo.uri) + " TP3" + str(f))        #TEMP LOG
        for i in cargo.realdata:
            f.append(i)
        self._log.debug(str(cargo.uri) + " TP4" + str(f))        #TEMP LOG
        if cargo.rssi:
            f.append(cargo.rssi)

        self._log.debug(str(cargo.uri) + " adding frame to buffer => "+ str(f))
        
        # Append to bulk post buffer
        self.buffer.append(f)
        self._log.debug(str(cargo.uri) + " TP5" + str(f))        #TEMP LOG

The piece of code we are looking at has very little going on, the only real action performed is casting the timestamp to an int, Unless it’s a typo, I assume this is to remove the fractional part and force the timestamp to only report whole seconds (which IMO isn’t a good thing even if it’s not the issue here).

if TP1 to TP1.1.2 prints but TP1.1.3 doesn’t, eg

2016-11-14 18:34:44,756 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-14 18:34:44,757 DEBUG    Pulse       TP1
2016-11-14 18:34:44,758 DEBUG    Pulse       TP1.1.1
2016-11-14 18:34:44,759 DEBUG    Pulse       TP1.1.2 1479148484.65
2016-11-14 18:34:44,800 WARNING  MainThread Pulse thread is dead

Edit the “f.append(int(cargo.timestamp))” line to "f.append(str(cargo.timestamp)) and retry.

That line is not tolerant of string representations of decimal numbers, a marginally less wrong way of doing it could have been “f.append(str(int(float(cargo.timestamp))))” but I see no good reason to truncate the timestamps to whole seconds, round if anything, but truncating must play havoc on fixed interval feed engines. but that’s a debate for another day/thread.

:grinning:

Nearly there !

Your code snippet above resulted as you predicted in

2016-11-16 04:42:53,618 INFO     Pulse      Publishing: emonhub/rx/18/values 1,7
2016-11-16 04:42:53,620 INFO     Pulse      Publishing: emonhub/rx/18/rssi 0
2016-11-16 04:42:53,639 DEBUG    Pulse      1 Sent to channel(end)' : ch1
2016-11-16 04:42:53,641 DEBUG    Pulse      1 Sent to channel(start)' : ToEmonCMS
2016-11-16 04:42:53,643 DEBUG    Pulse       TP1
2016-11-16 04:42:53,644 DEBUG    Pulse       TP1.1.1
2016-11-16 04:42:53,645 DEBUG    Pulse       TP1.1.21479271373.47
2016-11-16 04:42:53,786 WARNING  MainThread Pulse thread is dead
2016-11-16 04:42:54,016 WARNING  MainThread Pulse thread is dead

Then doing as you suggested

PLUS
Change

self._log.debug(" TP1.1.3" + str(int(cargo.timestamp)))    #TEMP LOG

to

self._log.debug(" TP1.1.3" + str((cargo.timestamp)))    #TEMP LOG

and we get some success with data seemingly going to both EMONCMS

2016-11-16 08:09:54,282 DEBUG    Pulse      1481 NEW FRAME : 1479283794.13 18 5 7
2016-11-16 08:09:54,283 DEBUG    Pulse      1481 Timestamp : 1479283794.13
2016-11-16 08:09:54,284 DEBUG    Pulse      1481 From Node : 18
2016-11-16 08:09:54,284 DEBUG    Pulse      1481    Values : [0.01, 14]
2016-11-16 08:09:54,286 DEBUG    Pulse      1481 Sent to channel(start)' : ch1
2016-11-16 08:09:54,287 INFO     Pulse      Publishing: emon/pulsecounter/pulsecnt1 0.01
2016-11-16 08:09:54,288 INFO     Pulse      Publishing: emon/pulsecounter/ano 14
2016-11-16 08:09:54,290 INFO     Pulse      Publishing: emon/pulsecounter/rssi 0
2016-11-16 08:09:54,291 INFO     Pulse      Publishing: emonhub/rx/18/values 0.01,14
2016-11-16 08:09:54,292 INFO     Pulse      Publishing: emonhub/rx/18/rssi 0
2016-11-16 08:09:54,293 DEBUG    Pulse      1481 Sent to channel(end)' : ch1
2016-11-16 08:09:54,294 DEBUG    Pulse      1481 Sent to channel(start)' : ToEmonCMS
2016-11-16 08:09:54,295 DEBUG    Pulse       TP1
2016-11-16 08:09:54,295 DEBUG    Pulse       TP1.1.1
2016-11-16 08:09:54,296 DEBUG    Pulse       TP1.1.21479283794.13
2016-11-16 08:09:54,296 DEBUG    Pulse       TP1.1.31479283794.13
2016-11-16 08:09:54,297 DEBUG    Pulse       TP1.2.1
2016-11-16 08:09:54,297 DEBUG    Pulse       TP1.2.21481
2016-11-16 08:09:54,298 DEBUG    Pulse       TP1.2.3['1479283794.13']
2016-11-16 08:09:54,298 DEBUG    Pulse      1481 TP2['1479283794.13']
2016-11-16 08:09:54,299 DEBUG    Pulse      1481 TP3['1479283794.13', 18]
2016-11-16 08:09:54,299 DEBUG    Pulse      1481 TP4['1479283794.13', 18, 0.01, 14]
2016-11-16 08:09:54,300 DEBUG    Pulse      1481 adding frame to buffer => ['1479283794.13', 18, 0.01, 14]
2016-11-16 08:09:54,300 DEBUG    Pulse      1481 TP5['1479283794.13', 18, 0.01, 14]
2016-11-16 08:09:54,301 DEBUG    Pulse      1481 Sent to channel(end)' : ToEmonCMS
2016-11-16 08:10:07,418 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[["1479283785.9",18,0.008,14],["1479283794.13",18,0.01,14]]&sentat=1479283807
2016-11-16 08:10:08,718 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2016-11-16 08:10:08,719 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y

**BTW ** Those numbers being logged to ECMONS are different to the pulse count as I now have

[[18]]
   nodename = pulsecounter
   [[[rx]]]
      names = pulsecnt1,  ano
      scales = 0.002, 2
      units = W,W

because my meter gives 500 impulses/kWh

Ahh yes, I should of thought of that! But glad you spotted it…

All those log messages can be removed once we’re done of course.

Although the code is now working ok, the timestamp is actually now a string (hence the quotes around it in the emoncms url), I think it should only be cast to a string for our test logs now we have located the bug. As far as I can tell there should be no reason the value isn’t numerical rather than a string within the array as str(f) will cast the whole array for the purpose of the log messages.

So could you test this code

def receiver(self, cargo):
    
        # Create a frame of data in "emonCMS format"
        self._log.debug(" TP1 ")        #TEMP LOG
        f = []

        self._log.debug(" TP1.1.1 ")                                #TEMP LOG
        self._log.debug(" TP1.1.2 " + str(cargo.timestamp))         #TEMP LOG
        self._log.debug(" TP1.1.3 " + str(float(cargo.timestamp)))    #TEMP LOG

        f.append(float(cargo.timestamp))

        self._log.debug(" TP1.2.1 ")                                #TEMP LOG
        self._log.debug(" TP1.2.2 " + str(cargo.uri))               #TEMP LOG
        self._log.debug(" TP1.2.3 " + str(f))                       #TEMP LOG

        self._log.debug(str(cargo.uri) + " TP2 " + str(f))        #TEMP LOG
        f.append(cargo.nodeid)
        self._log.debug(str(cargo.uri) + " TP3 " + str(f))        #TEMP LOG
        for i in cargo.realdata:
            f.append(i)
        self._log.debug(str(cargo.uri) + " TP4 " + str(f))        #TEMP LOG
        if cargo.rssi:
            f.append(cargo.rssi)

        self._log.debug(str(cargo.uri) + " adding frame to buffer => "+ str(f))
        
        # Append to bulk post buffer
        self.buffer.append(f)
        self._log.debug(str(cargo.uri) + " TP5 " + str(f))        #TEMP LOG

That should give us something like

2016-11-16 08:09:54,294 DEBUG    Pulse      1481 Sent to channel(start)' : ToEmonCMS
2016-11-16 08:09:54,295 DEBUG    Pulse       TP1
2016-11-16 08:09:54,295 DEBUG    Pulse       TP1.1.1
2016-11-16 08:09:54,296 DEBUG    Pulse       TP1.1.2 1479283794.13
2016-11-16 08:09:54,296 DEBUG    Pulse       TP1.1.3 1479283794.13
2016-11-16 08:09:54,297 DEBUG    Pulse       TP1.2.1
2016-11-16 08:09:54,297 DEBUG    Pulse       TP1.2.2 1481
2016-11-16 08:09:54,298 DEBUG    Pulse       TP1.2.3 [1479283794.13]
2016-11-16 08:09:54,298 DEBUG    Pulse      1481 TP2 [1479283794.13]
2016-11-16 08:09:54,299 DEBUG    Pulse      1481 TP3 [1479283794.13, 18]
2016-11-16 08:09:54,299 DEBUG    Pulse      1481 TP4 [1479283794.13, 18, 0.01, 14]
2016-11-16 08:09:54,300 DEBUG    Pulse      1481 adding frame to buffer => [1479283794.13, 18, 0.01, 14]
2016-11-16 08:09:54,300 DEBUG    Pulse      1481 TP5 [1479283794.13, 18, 0.01, 14]
2016-11-16 08:09:54,301 DEBUG    Pulse      1481 Sent to channel(end)' : ToEmonCMS

if that works I will wrap it up in a proper “try catch” statement with an appropriate “WARNING” level log message for a PR and we can get rid of all those ugly “TEMP” log messages.

Looks OK

2016-11-16 11:40:05,340 DEBUG    Pulse      27 Sent to channel(end)' : ToEmonCMS
2016-11-16 11:40:13,422 DEBUG    Pulse      28 NEW FRAME : 1479296413.34 18 41 7
2016-11-16 11:40:13,423 DEBUG    Pulse      28 Timestamp : 1479296413.34
2016-11-16 11:40:13,424 DEBUG    Pulse      28 From Node : 18
2016-11-16 11:40:13,425 DEBUG    Pulse      28    Values : [0.082, 14]
2016-11-16 11:40:13,425 DEBUG    Pulse      28 Sent to channel(start)' : ch1
2016-11-16 11:40:13,426 INFO     Pulse      Publishing: emon/pulsecounter/pulsecnt1 0.082
2016-11-16 11:40:13,428 INFO     Pulse      Publishing: emon/pulsecounter/ano 14
2016-11-16 11:40:13,429 INFO     Pulse      Publishing: emon/pulsecounter/rssi 0
2016-11-16 11:40:13,431 INFO     Pulse      Publishing: emonhub/rx/18/values 0.082,14
2016-11-16 11:40:13,439 INFO     Pulse      Publishing: emonhub/rx/18/rssi 0
2016-11-16 11:40:13,441 DEBUG    Pulse      28 Sent to channel(end)' : ch1
2016-11-16 11:40:13,441 DEBUG    Pulse      28 Sent to channel(start)' : ToEmonCMS
2016-11-16 11:40:13,442 DEBUG    Pulse       TP1
2016-11-16 11:40:13,443 DEBUG    Pulse       TP1.1.1
2016-11-16 11:40:13,443 DEBUG    Pulse       TP1.1.21479296413.34
2016-11-16 11:40:13,444 DEBUG    Pulse       TP1.1.31479296413.34
2016-11-16 11:40:13,444 DEBUG    Pulse       TP1.2.1
2016-11-16 11:40:13,445 DEBUG    Pulse       TP1.2.228
2016-11-16 11:40:13,445 DEBUG    Pulse       TP1.2.3[1479296413.34]
2016-11-16 11:40:13,446 DEBUG    Pulse      28 TP2[1479296413.34]
2016-11-16 11:40:13,446 DEBUG    Pulse      28 TP3[1479296413.34, 18]
2016-11-16 11:40:13,447 DEBUG    Pulse      28 TP4[1479296413.34, 18, 0.082, 14]
2016-11-16 11:40:13,447 DEBUG    Pulse      28 adding frame to buffer => [1479296413.34, 18, 0.082, 14]
2016-11-16 11:40:13,448 DEBUG    Pulse      28 TP5[1479296413.34, 18, 0.082, 14]
2016-11-16 11:40:13,448 DEBUG    Pulse      28 Sent to channel(end)' : ToEmonCMS
2016-11-16 11:40:15,582 INFO     emoncmsorg sending: https://emoncms.org/input/bulk.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y&data=[[1479296389.09,18,0.074,14],[1479296397.17,18,0.076,14],[1479296405.24,18,0.08,14],[1479296413.34,18,0.082,14]]&sentat=1479296415
2016-11-16 11:40:17,088 DEBUG    emoncmsorg acknowledged receipt with 'ok' from https://emoncms.org
2016-11-16 11:40:17,089 INFO     emoncmsorg sending: https://emoncms.org/myip/set.json?apikey=E-M-O-N-C-M-S-A-P-I-K-E-Y

and values tuning up in remote emoncms

Excellent!

I’m just heading out now, but if I’m back at a reasonable time I’ll try and make the changes later.

This should be ok.

def receiver(self, cargo):

        # Create a frame of data in "emonCMS format"
        f=[]
        try:
            f.append(float(cargo.timestamp))
            f.append(cargo.nodeid)
            for i in cargo.realdata:
                f.append(i)
            f.append(cargo.rssi)
		self._log.debug(str(cargo.uri) + " adding frame to buffer => "+ str(f))
        except:
            self._log.warning("Failed to create emonCMS frame " + str(f))

        # Append to bulk post buffer
        self.buffer.append(f)
        

it’s not a perfect solution, but it gets the job done. once you have tested it (if you don’t mind) I will do a PR.

Nearly …!
Fixing the indent on the first log message and all is OK. :wink:

Data arrives in local and remote EMONCMS

My function is


    def receiver(self, cargo):
    
        # Create a frame of data in "emonCMS format"
        f=[]
        try:
            f.append(float(cargo.timestamp))
            f.append(cargo.nodeid)
            for i in cargo.realdata:
                f.append(i)
            f.append(cargo.rssi)
            self._log.debug(str(cargo.uri) + " adding frame to buffer => "+ str(f))
        except:
            self._log.warning("Failed to create emonCMS frame " + str(f))

        # Append to bulk post buffer
        self.buffer.append(f)

Thanks for your help @pb66
I’ll try to tidy up this thread and summarise once complete.
Looks like I’ve still got some issues in correctly generating my feeds and calculating instant power from the accumulating pulses but I should do some more reading/browsing of forums before mentioning.

Thanks for your help on reaching a solution. I’ve submitted a PR

If/when this gets accepted it will be automatically included in future emonPi updates, but the edits made to your local copy will prevent those changes being pulled in via git without first undoing those changes precisely or reseting to a “clean” copy of the file using git checkout -- src/interfacers/EmonHubEmoncmsHTTPInterfacer.py from the emonhub directory, which will permanently remove the edits.

You may be better off using git stash from within the emonhub directory before updating, to temporarily undo the edits, stashing them away and then if the changes are not pulled in during an update you can use git stash apply to reapply the edits.

Merged, thanks.

An update from me, unrelated to the last dozen or so emails fixing a bug with Paul/pb66
I have just returned to this after a down time to try to address some unreliable pulse detections.
I have a standard optical sensor connected to my GPIO pins and using Paul’s script above.
I am running on a pi 2 Model B.
My sensor was on an extended cable about 4-5 m long.
I was receiving strange output from the script with multiple OFFs with no intervening ONs
My meter produces 500 impulses/kWh.
The ON pulse seems very short…

I suspected issues with pullups/pulldowns or cable length or noise on the edge transitions, but rejected those as the cause after some experiments.
I then came across this https://raspberrypi.stackexchange.com/questions/14105/how-does-python-gpio-bouncetime-parameter-work see the last few answers.

I believe I was detecting the RISING edge (to LED on) but by the time the handler polled the data it was back low again. This seems to explain why I was getting two OFF’s for every pulse and no ON.

I believe I have solved my problem by -

  1. Changing my event detect from GPIO.BOTH to GPIO.FALLING
  2. Adding time.sleep(0.1) at the start of the eventHandler
  3. Changing if status to if not status in processpulse

I now have a nice clean power curve with no sporadic spikes or drop outs to zero. ie it is now working fine. :slight_smile:

This is just FYI.
No assistance required, thanks

Neil & @pb66 ,

Could you please summarize the following?

  • How you connected the optical sensors to the GPIO pins?
  • How you start pulses.py (have you automated this for a restart, etc?)
  • How pulses.py interfaces with your configuration?

My intention is to have one pi with 1 sensor in my basement where my solar meter is, and 1 pi with 1 sensor in my garage where I can monitor my net meter which is outside.

I’m assuming if I start with the 1st pi in the basement, that the second pi can send data over mqtt or some other interface to that one?

Thanks

1 Like