search

merbanan / rtl_433

Program to decode radio transmissions from devices on the ISM bands (and other frequencies)
GNU General Public License v2.0
6.04k stars 1.31k forks source link

>24000 LIBUSB_ERROR_INVALID_PARAM log messages per second #2218

Closed midiwidi closed 1 year ago

midiwidi commented 1 year ago

I'm running rtl_433 as a systemd service on a Raspberry Pi 4 (64bit PiOS - version bullseye). I don't know which rtl_433 version it is. rtl_433 reports "rtl_433 version unknown inputs file rtl_tcp RTL-SDR SoapySDR". I installed it using apt. I noticed that my root partition (11 GB) was full and found out that the syslog file is a couple of GB big. Analysing the syslog showed that from a certain point in time rtl_433 repeatedly outputs 2 log messages

...
Oct 27 23:22:59 FunPi rtl_433[12161]: LIBUSB_ERROR_INVALID_PARAM: Invalid parameter!
Oct 27 23:22:59 FunPi rtl_433[12161]: Check your RTL-SDR dongle, USB cables, and power supply.
Oct 27 23:22:59 FunPi rtl_433[12161]: LIBUSB_ERROR_INVALID_PARAM: Invalid parameter!
Oct 27 23:22:59 FunPi rtl_433[12161]: Check your RTL-SDR dongle, USB cables, and power supply.
Oct 27 23:22:59 FunPi rtl_433[12161]: LIBUSB_ERROR_INVALID_PARAM: Invalid parameter!
Oct 27 23:22:59 FunPi rtl_433[12161]: Check your RTL-SDR dongle, USB cables, and power supply.
...

and this with a very high frequency -> more than 24000 !!! log lines per second. This fills up the log files very quickly.

knarrff commented 1 year ago

(Disclaimer: I am merely another user, not one of the maintainers.)

Concerning the version, if you did install it using apt on bullseye, it likely is version 20.11-1. You can confirm this using dpkg -s rtl-433.

The list of files this installed can be seen here: https://packages.debian.org/bullseye/armhf/rtl-433/filelist

From there and the Debian installation files I cannot see any service that might have been created. I bring this up because it looks like rtl_433 should quit in case of such problems, but either does not do so or is restarted by something external. Because of this, I have to ask: how did you start rtl_433 (give the full command)? Can you reproduce the problem?

midiwidi commented 1 year ago

I checked the version and your guess was right, it is 20.11-1.

What I meant is that I run it as a service. I created a service file

[Unit]
Description=RTL_433 service script
StartLimitIntervalSec=5
Documentation=https://github.com/merbanan/rtl_433/README.md
After=syslog.target network.target

[Service]
Type=exec
ExecStart=rtl_433
User=midiwidi
Group=midiwidi
Restart=always
RestartSec=30s
SyslogIdentifier=rtl_433
StandardOutput=syslog
StandardError=syslog

[Install]
WantedBy=multi-user.target

I know that it instructs systemd to restart rtl_433 if it exits, but there is a quite big restart delay in there and also I would expect to see startup messages in the log in between the LIBUSB_ERROR_INVALID_PARAM log messages. So I don't think systemd is restarting rtl_433 24000 times a minute.

This is the content of my rtl_433.conf

output json
output mqtt://192.168.2.6:1883,user=mqtt-user,pass=mypassword,retain=0,events=rtl_433[/model]/id[id]/ch[channel]
report_meta time:utc
convert si
protocol 3   # Prologue, FreeTec NC-7104, NC-7159-675 temperature sensor
protocol 52  # Bresser Thermo-/Hygro-Sensor 3CH

After the last service restart rtl_433 was running for a while without any errors (have to check the log to find out for how long). But now I'm seeing a different error in the logs (but only 1 message per second)

Oct 28 08:44:03 FunPi rtl_433[14645]: LIBUSB_ERROR_NOT_FOUND: Entity not found!
Oct 28 08:44:03 FunPi rtl_433[14645]: Check your RTL-SDR dongle, USB cables, and power supply.
Oct 28 08:44:03 FunPi rtl_433[14645]: Allocating 15 zero-copy buffers
Oct 28 08:44:03 FunPi rtl_433[14645]: Failed to allocate zero-copy buffer for transfer 0
Oct 28 08:44:03 FunPi rtl_433[14645]: Falling back to buffers in userspace
Oct 28 08:44:03 FunPi rtl_433[14645]: Failed to submit transfer 0
Oct 28 08:44:03 FunPi rtl_433[14645]: Please increase your allowed usbfs buffer size with the following command:
Oct 28 08:44:03 FunPi rtl_433[14645]: echo 0 > /sys/module/usbcore/parameters/usbfs_memory_mb
Oct 28 08:44:04 FunPi rtl_433[14645]: LIBUSB_ERROR_NOT_FOUND: Entity not found!
Oct 28 08:44:04 FunPi rtl_433[14645]: Check your RTL-SDR dongle, USB cables, and power supply.
Oct 28 08:44:04 FunPi rtl_433[14645]: Allocating 15 zero-copy buffers
Oct 28 08:44:04 FunPi rtl_433[14645]: Failed to allocate zero-copy buffer for transfer 0
Oct 28 08:44:04 FunPi rtl_433[14645]: Falling back to buffers in userspace
Oct 28 08:44:04 FunPi rtl_433[14645]: Failed to submit transfer 0
Oct 28 08:44:04 FunPi rtl_433[14645]: Please increase your allowed usbfs buffer size with the following command:
Oct 28 08:44:04 FunPi rtl_433[14645]: echo 0 > /sys/module/usbcore/parameters/usbfs_memory_mb
zuckschwerdt commented 1 year ago

thanks @knarrff -- you are exactly right, the message is a termination message from rtl_433 https://github.com/merbanan/rtl_433/blob/eee869e78a9ddb70a2284cecdb4e5c139f1658d4/src/sdr.c#L552-L561 There must be some external restart.

The error itself "LIBUSB_ERROR_INVALID_PARAM" is not something we have seen before, but if it worked before then it's likely a hardware problem. If it works again after unplugging the dongle or a cold start then maybe a power glitch caused this.

midiwidi commented 1 year ago

I had a look into the code you pointed me to @zuckschwerdt and saw that rtl_433 version 20.11 (the version which is in the bullseye repository) doesn't exit the read loop by setting dev->running to 0. It just prints the error and tries again. This explains why I get more than 24000 of those messages per second. I had rtl_433 running in the same hardware configuration before but under 32bit buster and didn't see these errors. But there I compiled rtl_433 myself and therefore I was using the latest version. I probably ran into the same USB problem but it produced only 1 error message which I didn't notice and then rtl_433 quit and was restarted by systemd.

After a rtl_433 restart everything is working again (I have confirmed that just now). There is no hardware cold start required. So it must be just a temporary glitch which I haven't noticed in my old software setup.

I will compile and use the latest version. That should solve the problem.

zuckschwerdt commented 1 year ago

Oh, you are right. That's the bug from #1581 then.

midiwidi commented 1 year ago

I've replaced version 20.11 from PiOS bullseye with the latest version which I compiled myself. It is running for 2 days now without any error messages. It looks like the latest version did not only fix the problem with the repeated error message but also might prevent the error from occurring.

midiwidi commented 1 year ago

I checked again after a week and now I could see occasional errors. But only one at a time as RTL_433 exits now and gets restarted by systemd. Afterwards everything is back to normal.

Nov 01 10:34:59 FunPi systemd[1]: Starting RTL_433 service script...
Nov 01 10:34:59 FunPi systemd[1]: Started RTL_433 service script.
Nov 01 10:34:59 FunPi rtl_433[132949]: rtl_433 version 21.12-160-geee869e7 branch master at 202210252023 inputs file rtl_tcp RTL-SDR with TLS
Nov 01 10:34:59 FunPi rtl_433[132949]: Use -h for usage help and see https://triq.org/ for documentation.
Nov 01 10:34:59 FunPi rtl_433[132949]: Trying conf file at "rtl_433.conf"...
Nov 01 10:34:59 FunPi rtl_433[132949]: Trying conf file at "/home/midiwidi/.config/rtl_433/rtl_433.conf"...
Nov 01 10:34:59 FunPi rtl_433[132949]: Trying conf file at "/usr/local/etc/rtl_433/rtl_433.conf"...
Nov 01 10:34:59 FunPi rtl_433[132949]: Trying conf file at "/etc/rtl_433/rtl_433.conf"...
Nov 01 10:34:59 FunPi rtl_433[132949]: Reading conf from "/etc/rtl_433/rtl_433.conf".
Nov 01 10:34:59 FunPi rtl_433[132949]: Publishing MQTT data to 192.168.2.6 port 1883
Nov 01 10:34:59 FunPi rtl_433[132949]: Publishing events info to MQTT topic "rtl_433[/model]/id[id]/ch[channel]".
Nov 01 10:34:59 FunPi rtl_433[132949]: Registered 2 out of 223 device decoding protocols [ 3 52 ]
Nov 01 10:34:59 FunPi rtl_433[132949]: Detached kernel driver
Nov 01 10:34:59 FunPi rtl_433[132949]: Found Rafael Micro R820T tuner
Nov 01 10:34:59 FunPi rtl_433[132949]: Exact sample rate is: 250000.000414 Hz
Nov 01 10:35:00 FunPi rtl_433[132949]: [R82XX] PLL not locked!
Nov 01 10:35:00 FunPi rtl_433[132949]: Sample rate set to 250000 S/s.
Nov 01 10:35:00 FunPi rtl_433[132949]: Tuner gain set to Auto.
Nov 01 10:35:00 FunPi rtl_433[132949]: Tuned to 433.920MHz.
Nov 01 10:35:00 FunPi rtl_433[132949]: Allocating 15 zero-copy buffers
Nov 01 10:35:00 FunPi rtl_433[132949]: MQTT Connected...
Nov 01 10:35:01 FunPi rtl_433[132949]: MQTT Connection established.
Nov 04 17:41:11 FunPi rtl_433[132949]: cb transfer status: 1, canceling...
Nov 04 17:41:11 FunPi rtl_433[132949]: LIBUSB_ERROR_NOT_FOUND: Entity not found!
Nov 04 17:41:11 FunPi rtl_433[132949]: Check your RTL-SDR dongle, USB cables, and power supply.
Nov 04 17:41:11 FunPi rtl_433[132949]: WARNING: async read failed (-5).
Nov 04 17:41:11 FunPi rtl_433[132949]: Library error -5, exiting...
Nov 04 17:41:11 FunPi rtl_433[132949]: Reattaching kernel driver failed!
Nov 04 17:41:11 FunPi systemd[1]: rtl_433.service: Main process exited, code=exited, status=5/NOTINSTALLED
Nov 04 17:41:11 FunPi systemd[1]: rtl_433.service: Failed with result 'exit-code'.
Nov 04 17:41:11 FunPi systemd[1]: rtl_433.service: Consumed 37min 49.136s CPU time.
Nov 04 17:41:41 FunPi systemd[1]: rtl_433.service: Scheduled restart job, restart counter is at 5.
Nov 04 17:41:41 FunPi systemd[1]: Stopped RTL_433 service script.
Nov 04 17:41:41 FunPi systemd[1]: rtl_433.service: Consumed 37min 49.136s CPU time.
Nov 04 17:41:41 FunPi systemd[1]: Starting RTL_433 service script...
Nov 04 17:41:41 FunPi systemd[1]: Started RTL_433 service script.
Nov 04 17:41:41 FunPi rtl_433[367501]: rtl_433 version 21.12-160-geee869e7 branch master at 202210252023 inputs file rtl_tcp RTL-SDR with TLS
Nov 04 17:41:41 FunPi rtl_433[367501]: Use -h for usage help and see https://triq.org/ for documentation.
Nov 04 17:41:41 FunPi rtl_433[367501]: Trying conf file at "rtl_433.conf"...
Nov 04 17:41:41 FunPi rtl_433[367501]: Trying conf file at "/home/midiwidi/.config/rtl_433/rtl_433.conf"...
Nov 04 17:41:41 FunPi rtl_433[367501]: Trying conf file at "/usr/local/etc/rtl_433/rtl_433.conf"...
Nov 04 17:41:41 FunPi rtl_433[367501]: Trying conf file at "/etc/rtl_433/rtl_433.conf"...
Nov 04 17:41:41 FunPi rtl_433[367501]: Reading conf from "/etc/rtl_433/rtl_433.conf".
Nov 04 17:41:41 FunPi rtl_433[367501]: Publishing MQTT data to 192.168.2.6 port 1883
Nov 04 17:41:41 FunPi rtl_433[367501]: Publishing events info to MQTT topic "rtl_433[/model]/id[id]/ch[channel]".
Nov 04 17:41:41 FunPi rtl_433[367501]: Registered 2 out of 223 device decoding protocols [ 3 52 ]
Nov 04 17:41:42 FunPi rtl_433[367501]: Detached kernel driver
Nov 04 17:41:42 FunPi rtl_433[367501]: Found Rafael Micro R820T tuner
Nov 04 17:41:42 FunPi rtl_433[367501]: Exact sample rate is: 250000.000414 Hz
Nov 04 17:41:42 FunPi rtl_433[367501]: [R82XX] PLL not locked!
Nov 04 17:41:42 FunPi rtl_433[367501]: Sample rate set to 250000 S/s.
Nov 04 17:41:42 FunPi rtl_433[367501]: Tuner gain set to Auto.
Nov 04 17:41:42 FunPi rtl_433[367501]: Tuned to 433.920MHz.
Nov 04 17:41:42 FunPi rtl_433[367501]: Allocating 15 zero-copy buffers
Nov 04 17:41:43 FunPi rtl_433[367501]: MQTT Connected...
Nov 04 17:41:44 FunPi rtl_433[367501]: MQTT Connection established.
zuckschwerdt commented 1 year ago

Great to hear, thanks for the feedback! Some of my RTL-SDRs also drop out every other week or so.