search

allangood / rtlamr2mqtt

Docker container to send rtlamr readings to a mqtt broker
MIT License
320 stars 50 forks source link

rtlamr not killed, running constantly #41

Closed lymanbuttler closed 2 years ago

lymanbuttler commented 2 years ago

This is with Docker Desktop on Mac OS. Logs output:

` Sending message to MQTT:

hostname => 192.168.0.6 port => 1883 username => homeassistant password => REDACTED topic => rtlamr/56341459/state payload => 00501905 retain => True Sleep_for defined, time to sleep! Terminating all subprocess... Sleeping for 300 seconds, see you later... `

In fact, the rtlamr process stays alive, constantly using 30% CPU. The script does in fact run every 300 seconds and send the new meter reading to the MQTT server, though. Would try to find a fix myself but unfortunately I know nothing about Docker. Thanks!

allangood commented 2 years ago

Hi, could you send some more detailed information about this? I cannot reproduce what are you describing. The container itself should be running all the time, but both process rtl_tcp and rtlamr should be terminated after a successful reading.

If you execute docker stats, you should see something like this:

CONTAINER ID   NAME               CPU %     MEM USAGE / LIMIT     MEM %     NET I/O          BLOCK I/O         PIDS
2e807114e0aa   rtlamr2mqtt        0.00%     6.637MiB / 1.967GiB   0.33%     1.06MB / 270kB   369kB / 0B        1

The CPU usage should drop to 0% when it is sleeping.

lymanbuttler commented 2 years ago

Yes, this is the behavior I would expect. Here's my docker stats output: Screen Shot 2021-11-24 at 5 31 31 PM There's also out-of-control network I/O which is pretty baffling. I'm running Docker Desktop 4.1.1 on Mac OS 11.6 Big Sur.

allangood commented 2 years ago

Could you provide more info about it? Also, the project had a lot of changes in the past days, could you pull the latest version and try again?

Please, provide your configuration file, docker command or compose section

lymanbuttler commented 2 years ago

docker-compose.yaml:

version: "3"
services:
  rtlamr:
    container_name: rtlamr2mqtt
    image: allangood/rtlamr2mqtt
    restart: unless-stopped
    volumes:
      - /Users/lb/Sites/rtlamr/:/etc/

configuration file:

# (Optional section)
general:
  # Sleep for this amount of seconds after one successful of every meter
  # Set this to 0 (default) to disable it
  sleep_for: 300
  # Set the verbosity level. It can be debug or info
  verbosity: debug

# (Required section)
# MQTT configuration
mqtt:
  # MQTT host name or IP address
  host: 192.168.0.6
  # MQTT user name if you have, remove if you don't use authentication
  user: homeassistant
  # MQTT user password if you use one, remove if you don't use authentication
  password: ****************
  # Whether to use Home Assistant auto-discovery feature or not
  ha_autodiscovery: true
  # Home Assistant auto-discovery topic
  ha_autodiscovery_topic: homeassistant
# (Optional)
# This entire section is optional.
# If you don't need any custom parameter, don't use it.
# ***DO NOT ADD -msgtype, -filterid nor -protocol parameters here***
custom_parameters:
  # Documentation for rtl_tcp: https://osmocom.org/projects/rtl-sdr/wiki/Rtl-sdr
  # rtltcp: "-s 2048000"
  # Documentation for rtlamr: https://github.com/bemasher/rtlamr/wiki/Configuration
  rtlamr: "-server=host.docker.internal:1234"

# (Required section)
# Here is the place to define your meters
meters:
    # The ID of your meter
  - id: 56341459
    # The protocol
    protocol: scm
    # A nice name to show on your Home Assistant/Node Red
    name: meter_gas
    # A number format to be used for your meter
    format: "########"
    # A measurement unit to be used by Home Assistant
    unit_of_measurement: "ft³"
    # An icon to be used by Home Assistant
    icon: mdi:gauge
lymanbuttler commented 2 years ago

Removed the image and pulled latest, issue persists. Here's a few minutes of log with the new container. I'm stumped. Aside from Docker Desktop for Mac, the only other unusual thing about my setup that I can think of is that I configured rtlamr to connect to an external rtltcp server (necessary because Docker containers on Mac apparently can't connect to USB devices).

2021-11-25T13:51:50.817728576Z  > retain => True
2021-11-25T13:51:50.822529822Z Sleep_for defined, time to sleep!
2021-11-25T13:51:50.822647961Z Terminating all subprocess...
2021-11-25T13:51:50.822661379Z Sleeping for 300 seconds, see you later...
2021-11-25T13:56:50.685519725Z Sending message to MQTT:
2021-11-25T13:56:50.685622639Z  > topic => rtlamr/status
2021-11-25T13:56:50.685631703Z  > payload => online
2021-11-25T13:56:50.685640871Z  > retain => True
2021-11-25T13:56:50.698525849Z {"Time":"2021-11-25T13:52:51.297585189Z","Offset":0,"Length":0,"Type":"SCM","Message":{"ID":56341459,"Type":12,"TamperPhy":1,"TamperEnc":0,"Consumption":503543,"ChecksumVal":60006}}
2021-11-25T13:56:50.698907106Z Meter "56341459" - Consumption 00503543. Sending value to MQTT.
2021-11-25T13:56:50.699107346Z Sending message to MQTT:
2021-11-25T13:56:50.699359750Z  > topic => rtlamr/56341459/state
2021-11-25T13:56:50.699506168Z  > payload => {"Time": "2021-11-25T13:52:51.297585189Z", "Offset": 0, "Length": 0, "Type": "SCM", "Message": {"ID": 56341459, "Type": 12, "TamperPhy": 1, "TamperEnc": 0, "Consumption": 503543, "ChecksumVal": 60006}}
2021-11-25T13:56:50.699692118Z  > retain => Tru
2021-11-25T13:56:50.707263136Z Sleep_for defined, time to sleep!
2021-11-25T13:56:50.707514927Z Terminating all subprocess..
2021-11-25T13:56:50.707578733Z Sleeping for 300 seconds, see you later...
2021-11-25T14:01:50.557052685Z Sending message to MQTT
2021-11-25T14:01:50.557166651Z  > topic => rtlamr/status
2021-11-25T14:01:50.557237074Z  > payload => online
2021-11-25T14:01:50.557265958Z  > retain => True
2021-11-25T14:01:50.563982283Z {"Time":"2021-11-25T13:53:21.802547973Z","Offset":0,"Length":0,"Type":"SCM","Message":{"ID":56341459,"Type":12,"TamperPhy":1,"TamperEnc":0,"Consumption":503543,"ChecksumVal":60006}}
2021-11-25T14:01:50.564687050Z Meter "56341459" - Consumption 00503543. Sending value to MQTT.
2021-11-25T14:01:50.564964527Z Sending message to MQTT:
2021-11-25T14:01:50.564984761Z  > topic => rtlamr/56341459/state
2021-11-25T14:01:50.564992188Z  > payload => {"Time": "2021-11-25T13:53:21.802547973Z", "Offset": 0, "Length": 0, "Type": "SCM", "Message": {"ID": 56341459, "Type": 12, "TamperPhy": 1, "TamperEnc": 0, "Consumption": 503543, "ChecksumVal": 60006}}
2021-11-25T14:01:50.565096194Z  > retain => True
2021-11-25T14:01:50.570175186Z Sleep_for defined, time to sleep!
2021-11-25T14:01:50.570210895Z Terminating all subprocess...
2021-11-25T14:01:50.570215497Z Sleeping for 300 seconds, see you later...
2021-11-25T14:02:04.006116137Z Shutdown detected, killing process.
2021-11-25T14:02:04.006189275Z Killing RTLAMR...
2021-11-25T14:02:04.041579849Z Killed in the first attempt.
2021-11-25T14:02:04.041800621Z Graceful shutdown.
2021-11-25T14:02:04.041821043Z Sending message to MQTT:
2021-11-25T14:02:04.041827297Z  > topic => rtlamr/status
2021-11-25T14:02:04.041831610Z  > payload => offline
2021-11-25T14:02:04.041835933Z  > retain => True
2021-11-25T14:02:06.010687922Z Configured MQTT sender:
2021-11-25T14:02:06.010741160Z  > hostname => 192.168.0.6
2021-11-25T14:02:06.010752052Z  > port => 1883
2021-11-25T14:02:06.010758505Z  > username => homeassistant
2021-11-25T14:02:06.010764670Z  > client_id => rtlamr2mqtt
2021-11-25T14:02:06.011246026Z Sending message to MQTT:
2021-11-25T14:02:06.011267474Z  > topic => rtlamr/status
2021-11-25T14:02:06.011271564Z  > payload => online
2021-11-25T14:02:06.011275281Z  > retain => True
2021-11-25T14:02:06.020117672Z server: host.docker.internal:1234, host: host.docker.internal, port: 1234
2021-11-25T14:02:06.020164317Z Attempting to tune rtl_tcp to a different freq to shake things up
2021-11-25T14:02:06.257167647Z Successfully tickled rtl_tcp
2021-11-25T14:02:06.257201021Z Trying to start RTLAMR: /usr/bin/rtlamr -msgtype=scm -format=json -filterid=56341459 -server=host.docker.internal:1234
2021-11-25T14:02:06.257536893Z RTLAMR started with PID 9
2021-11-25T14:02:09.864871544Z 14:02:09.863545 main.go:90: Error connecting to spectrum server: dial tcp 192.168.65.2:1234: connect: connection refused
2021-11-25T14:02:09.864905301Z rcvr.Connect
2021-11-25T14:02:09.864910020Z main.(*Receiver).NewReceiver
2021-11-25T14:02:09.864913655Z  /go/pkg/mod/github.com/bemasher/rtlamr@v0.9.3/main.go:90
2021-11-25T14:02:09.864917579Z main.main
2021-11-25T14:02:09.864920930Z  /go/pkg/mod/github.com/bemasher/rtlamr@v0.9.3/main.go:313
2021-11-25T14:02:09.864924492Z runtime.main
2021-11-25T14:02:09.864927841Z  /usr/local/go/src/runtime/proc.go:255
2021-11-25T14:02:09.864931372Z runtime.goexit
2021-11-25T14:02:09.864934744Z  /usr/local/go/src/runtime/asm_amd64.s:158
2021-11-25T14:02:09.865619356Z Sleep_for defined, time to sleep!
2021-11-25T14:02:09.865641519Z Terminating all subprocess...
2021-11-25T14:02:09.865646151Z Sleeping for 300 seconds, see you later..
2021-11-25T14:07:09.750781749Z Sending message to MQTT:
2021-11-25T14:07:09.750833586Z  > topic => rtlamr/status
2021-11-25T14:07:09.750839995Z  > payload => online
2021-11-25T14:07:09.750844682Z  > retain => True
2021-11-25T14:07:09.765938442Z server: host.docker.internal:1234, host: host.docker.internal, port: 1234
2021-11-25T14:07:09.765983581Z Attempting to tune rtl_tcp to a different freq to shake things up
2021-11-25T14:07:10.040845287Z Successfully tickled rtl_tcp
2021-11-25T14:07:10.043161606Z Trying to start RTLAMR: /usr/bin/rtlamr -msgtype=scm -format=json -filterid=56341459 -server=host.docker.internal:1234
2021-11-25T14:07:10.044635325Z RTLAMR started with PID 15
2021-11-25T14:07:10.174962442Z 14:07:10.173765 decode.go:45: CenterFreq: 912600155
2021-11-25T14:07:10.174995739Z 14:07:10.174764 decode.go:46: SampleRate: 2359296
2021-11-25T14:07:10.175000585Z 14:07:10.174809 decode.go:47: DataRate: 3276
2021-11-25T14:07:10.175004672Z 14:07:10.174845 decode.go:48: ChipLength: 72
2021-11-25T14:07:10.175081063Z 14:07:10.174878 decode.go:49: PreambleSymbols: 21
2021-11-25T14:07:10.175410475Z 14:07:10.175043 decode.go:50: PreambleLength: 3024
2021-11-25T14:07:10.175429493Z 14:07:10.175211 decode.go:51: PacketSymbols: 96
2021-11-25T14:07:10.175434474Z 14:07:10.175332 decode.go:52: PacketLength: 13824
2021-11-25T14:07:10.175792563Z 14:07:10.175445 decode.go:59: Protocols: scm
2021-11-25T14:07:10.175809881Z 14:07:10.175652 decode.go:60: Preambles: 111110010101001100000
2021-11-25T14:07:10.175814989Z 14:07:10.175701 main.go:124: GainCount: 29
2021-11-25T14:07:19.919426113Z {"Time":"2021-11-25T14:07:19.918752821Z","Offset":0,"Length":0,"Type":"SCM","Message":{"ID":56341459,"Type":12,"TamperPhy":1,"TamperEnc":0,"Consumption":503556,"ChecksumVal":36055}}
2021-11-25T14:07:19.920016239Z Meter "56341459" - Consumption 00503556. Sending value to MQTT.
2021-11-25T14:07:19.920033496Z Sending MQTT autodiscovery payload to Home Assistant...
2021-11-25T14:07:19.920249376Z Sending message to MQTT:
2021-11-25T14:07:19.920594239Z  > topic => homeassistant/sensor/rtlamr/meter_gas/config
2021-11-25T14:07:19.920609941Z  > payload => {"name": "meter_gas", "unique_id": "56341459", "unit_of_measurement": "ft\u00b3", "icon": "mdi:gauge", "availability_topic": "rtlamr/status", "state_class": "total_increasing", "state_topic": "rtlamr/56341459/state", "value_template": "{{ value_json.Message.Consumption | float / 1 }}", "json_attributes_topic": "rtlamr/56341459/state", "json_attributes_template": "{{ value_json.Message | tojson }}"}
2021-11-25T14:07:19.920621110Z  > qos => 1
2021-11-25T14:07:19.920642712Z  > retain => True
2021-11-25T14:07:19.934787653Z Sending message to MQTT:
2021-11-25T14:07:19.934871468Z  > topic => rtlamr/56341459/state
2021-11-25T14:07:19.934885530Z  > payload => {"Time": "2021-11-25T14:07:19.918752821Z", "Offset": 0, "Length": 0, "Type": "SCM", "Message": {"ID": 56341459, "Type": 12, "TamperPhy": 1, "TamperEnc": 0, "Consumption": 503556, "ChecksumVal": 36055}}
2021-11-25T14:07:19.934895673Z  > retain => True
2021-11-25T14:07:19.940156127Z Sleep_for defined, time to sleep!
2021-11-25T14:07:19.940193090Z Terminating all subprocess...
2021-11-25T14:07:19.940197950Z Sleeping for 300 seconds, see you later...
allangood commented 2 years ago

I can't see the "termination" message after the "terminating all subprocess..." message.

This is my output for reference:

Sleep_for defined, time to sleep!
Terminating all subprocess...
Kill process called.
Killing RTL_TCP...
Killed in the first attempt.
Killing RTLAMR...
Killed in the first attempt.
Sleeping for 300 seconds, see you later...

I am trying to replicate the problem.

lymanbuttler commented 2 years ago

Yes that's correct, my log doesn't show any of the lines between "Terminating..." and "Sleeping...". On the other hand, sometimes these messages DO show up, even though the process hasn't been killed! It's like the container doesn't understand the kill command. Totally baffling.

allangood commented 2 years ago

I have found the problem! Is a bug introduced by me in a recent change! This error only happens when an external rtl_tcp is used.

allangood commented 2 years ago

It should be fixed with #43

Could you test again and see if it is working properly now?

lymanbuttler commented 2 years ago

Success! Thank you so much.

cgoudie commented 1 month ago

Is this bug still present in the 6713e36e_rtlamr2mqtt! 2.3.4 release? I'm getting this same behavior years later running HAOS and the add in.