Shell command gurus, really need some help

mattlward · March 19, 2018, 2:27pm

I have a series of shell commands that are called to populate a remote device with an http command. The command works great from the command line. When called from an automation it tends to work but breaks things, like knocking the recorder offline. And caused an odd error when executed. The odd thing is that it does not always fail and it does always get to the point that the database becomes corrupted. It could be that they work great from the command line because they are not repeatedly called.

It almost seems like a memory leak or something else that builds up. With all of them disable (6), the system is stable. If I turn on a couple, the errors creep in over the next half hour or so. If all are enable it is minutes before it becomes unstable.

Am I making the calls properly, or have I missed a recent change that is causing this failure.

Is there a problem with the current version of curl?

I am running fully a updated Hass.io install at 65.5. System is a RPi2, ethernet connected. I have tried 2 pi’s, 4 memory cards and 2 different power supplies. This started either late in the 64 train or at the beginning of 65. I really need this to work, the unit that gets the data is a Wemos D1 with a display that in turn sends the data to other Wemos D1 units with displays. They are small info panels for current local weather and weather alerts now that we are in spring and tornadoes and strong storms will be the concern.

Here is one example of the automation and the shell command:

- id: "Broadcast Real Temp HTTP"
  alias: 'Broadcast Real Temp HTTP'
  initial_state: 'off'
  hide_entity: false
  trigger:
    - platform: time
      minutes: '/2'
      seconds: '30'
  action:
    - service: shell_command.wu_temp_http
      data_template:
        state: '{{ states.sensor.pws_temp_f.state }}'

shell_command:
  wu_temp_http: /usr/bin/curl "http://192.168.1.121/control?cmd=event,RealTemp={{state}}"

018-03-18 19:08:45 ERROR (Recorder) [homeassistant.components.recorder.util] Error executing query: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8)
2018-03-18 19:08:45 ERROR (Recorder) [homeassistant.components.recorder] Error in database connectivity: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8). (retrying in 3 seconds)
2018-03-18 19:12:45 ERROR (Recorder) [homeassistant.components.recorder.util] Error executing query: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8)
2018-03-18 19:12:45 ERROR (Recorder) [homeassistant.components.recorder] Error in database connectivity: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8). (retrying in 3 seconds)
2018-03-18 19:15:45 ERROR (Recorder) [homeassistant.components.recorder.util] Error executing query: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8)
2018-03-18 19:15:45 ERROR (Recorder) [homeassistant.components.recorder] Error in database connectivity: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8). (retrying in 3 seconds)
2018-03-18 19:22:45 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `/usr/bin/curl "http://192.168.1.121/control?cmd=event,FeelsLike={{state}}"`, return code: -11
NoneType: None
2018-03-18 19:24:30 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `/usr/bin/curl "http://192.168.1.121/control?cmd=event,RealTemp={{state}}"`, return code: -11
NoneType: None
2018-03-18 19:24:45 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `/usr/bin/curl "http://192.168.1.121/control?cmd=event,FeelsLike={{state}}"`, return code: -11
NoneType: None

Without the shell commands running, I am seeing this from time to time as well: I am not sure, but suspect this may be weather underground related.

2018-03-19 07:24:54 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 231, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp\_http_parser.pyx", line 295, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: invalid HTTP method

I know, the logs are a few days old but I have turned off all of the automations in order to keep my install running. Tested last night and saw the same behavior.

Bit-River · March 19, 2018, 2:32pm

Off the top of my head, change to above to

shell_command:
wu_temp_http: "/usr/bin/curl http://192.168.1.121/control?cmd=event,RealTemp={{state}}”

Alternatively, make a bash script with what you need and call that instead.

walt · March 19, 2018, 2:54pm

Here is what I would do, run it manually for a while in a shell and see what happens:

while true; do /usr/bin/curl "http://192.168.1.121/control?cmd=event,RealTemp=$(/usr/bin/curl -X GET -H "x-ha-access: your-api-password" -H "Content-Type: application/json" http://127.0.0.1:8123/api/states/sensor.pws_temp_f 2>/dev/null | sed -e 's/.*state.*\"$.*$\".*/\1/')"; sleep 30; done

Your shell_command wu_temp_http quoting shouldn’t matter. Best practice would be to have it formatted like this:

shell_command:
  wu_temp_http: '/usr/bin/curl "http://192.168.1.121/control?cmd=event,RealTemp={{state}}"'

Curl is not memory resident so it is probably not the source of your problems. It loads into memory on each run, then exits completely.

I would guess that maybe your device at 192.168.1.121 starts to slow down and possibly takes down HASS.IO as you have a large number of concurrent curl sessions running.

mattlward · March 19, 2018, 2:54pm

So, I made the suggested change to the shell command syntax and within 3 minutes of saving, rebooting and enabling 1 of the automations to call 1 shell command… I have the following in the log file:

2018-03-19 09:48:30 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `/usr/bin/curl http://192.168.1.121/control?cmd=event,RealTemp={{state}}`, return code: -11
NoneType: None

So, would a bash script here just call the shell and process thru a list of commands? I have not added a called shell script to my install before.

#!/bin/bash
/usr/bin/curl http://192.168.1.121/control?cmd=event,RealTemp={{state}}
/usr/bin/curl http://192.168.1.121/control?cmd=event,FeelsLike={{state}}
/usr/bin/curl http://192.168.1.121/control?cmd=event,Wind={{state}}
/usr/bin/curl http://192.168.1.121/control?cmd=event,Gust={{state}}
/usr/bin/curl http://192.168.1.121/control?cmd=event,WindDeg={{state}}
/usr/bin/curl http://192.168.1.121/control?cmd=event,Humidity={{state}}

And then just call it every now and then with 1 automation?

mattlward · March 19, 2018, 2:57pm

I am not sure… I have the automations all staggered to eliminate slamming the units. Their system load does not seem to increase while being loaded with these variables. I am sending them from once every 2.5 minutes to once every 4 minutes.

I will have to study your code and figure it out, not a real coder!

Bit-River · March 19, 2018, 2:58pm

Yeah, that should work.

It’s the route I went when the double-quotes & single-quotes started driving me around the bend.

walt · March 19, 2018, 3:00pm

That command runs curl every thirty seconds, and pulls the data out of Home Assistant to make it accurate. You can also just put some dummy data in there:

while true; do /usr/bin/curl "http://192.168.1.121/control?cmd=event,RealTemp=70"; sleep 30; done

If you have a way to monitor proccess on hass.io, you could turn on all the automations and do a “ps auxw | grep curl” from maybe the SSH add on to see if curl sessions are persisting.

mattlward · March 19, 2018, 3:24pm

Walt, would that go into a shell script, or where would that go? Would that be a possible long term solution? I definitely do not need that frequency as WU does not update that often.

If I am reading that correctly, it would not get called by an automation, it would just start at boot?

walt · March 19, 2018, 3:38pm

That’s all just a test to eliminate Home Assistant as a variable. It’s a command line equivalent of polling/updating your device with curl. If the error occurs here it means the issue is with the device (192.168.1.121), if not we would have to look at Home Assistant in more detail.

My gut feel is that you are essentially fork bombing your self as your device gets slow to respond and more and more curl binaries get loaded until you run out of memory.

mattlward · March 19, 2018, 3:49pm

I will definitely try this. Right now the process is crapping out with just 1 of the commands running every 2.5 minutes.

mattlward · March 19, 2018, 3:51pm

In fact 1 process has already killed the recorder… Latest home-assistant.log:

2018-03-19 09:48:30 ERROR (MainThread) [homeassistant.components.shell_command] Error running command: `/usr/bin/curl http://192.168.1.121/control?cmd=event,RealTemp={{state}}`, return code: -11
NoneType: None
2018-03-19 10:07:20 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 231, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp\_http_parser.pyx", line 295, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: invalid HTTP method
2018-03-19 10:34:30 ERROR (Recorder) [homeassistant.components.recorder.util] Error executing query: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8)
2018-03-19 10:34:31 ERROR (Recorder) [homeassistant.components.recorder] Error in database connectivity: (sqlite3.OperationalError) disk I/O error (Background on this error at: http://sqlalche.me/e/e3q8). (retrying in 3 seconds)

mattlward · March 19, 2018, 4:23pm

Walt, I have built this into a bash script and it is running fine. I have had a bunch of interations and the load on the remote arduino is Load: 4% (LC=14024), and it is running fine. I am going to let the script run for a good while, just to be sure.

The device is seeing the data stream, confirmed by log entries.

The script is slowly using memory on the Pi. Down from 695k to 680k with it running, and still slowly falling.

mattlward · March 19, 2018, 4:30pm

Ok, so 33 iterations and 0 bad log entries!

I have added a counter and will just let it run!

My test script:

#! /bin/bash
x=0
while true; do /usr/bin/curl "http://192.168.1.121/control?cmd=event,RealTemp=70"; sleep 30; x=$[$x +1]; echo "$x"; done

mattlward · March 19, 2018, 6:02pm

Ok, 125 runs and no new log entries and Pi is still running well.

Output from script:
OK125

Pi memory holding at around 681k.

mattlward · March 19, 2018, 9:47pm

So, got to 570 runs, did not appear to have any issues on the remote Wemos.

Did get the following in my logs:

2018-03-19 15:47:08 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <bound method SendfileStreamWriter._sendfile_cb of <aiohttp.web_fileresponse.SendfileStreamWriter object at 0x6f6d94d0>>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 49, in uvloop.loop.Handle._run
  File "/usr/lib/python3.6/site-packages/aiohttp/web_fileresponse.py", line 36, in _sendfile_cb
    loop.remove_writer(out_fd)
  File "uvloop/loop.pyx", line 2098, in uvloop.loop.Loop.remove_writer
  File "uvloop/loop.pyx", line 730, in uvloop.loop.Loop._remove_writer
  File "uvloop/loop.pyx", line 649, in uvloop.loop.Loop._ensure_fd_no_transport
RuntimeError: File descriptor 42 is used by transport <TCPTransport closed=False reading=True 0x6f8a11e8>
2018-03-19 15:49:38 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 231, in data_received
    messages, upgraded, tail = self._request_parser.feed_data(data)
  File "aiohttp\_http_parser.pyx", line 295, in aiohttp._http_parser.HttpParser.feed_data
aiohttp.http_exceptions.BadStatusLine: invalid HTTP method
2018-03-19 16:02:50 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.read callback)
TimeoutError: [Errno 110] Operation timed out

Not sure what it means, but I suspect WU as it throws errors every now and then.

mattlward · March 20, 2018, 2:49am

So, I tried to take it one step further and convert the api query into a shell_command in my configuration.yaml and it really complains about the -H.

Here is what I tried:

  wu_temp_http: "/usr/bin/curl -X GET -H "x-ha-access: xxxxxxxx" -H "Content-Type: application/json" http://192.168.1.6:8123/api/states/sensor.pws_temp_f 2>/dev/null | sed -e 's/.*state.*\"\(.*\)\".*/\1/')"

incomplete explicit mapping pair; a key node is missed; or followed by a non-tabulated empty line at line 852, column 82:
     ... cess: xxxxxxxxx" -H "Content-Type: application/json" http://192.1 ...

Yevgeniy · March 20, 2018, 9:17am

Try it like this:

  action:
    service: shell_command.wu_temp_http

shell_command:
  wu_temp_http: 'curl GET http://192.168.1.121/control?cmd=event,RealTemp={{ states.sensor.pws_temp_f.state }}'

I’m using the curl command with a similar syntax.

mattlward · March 20, 2018, 12:56pm

Testing this now…

Yevgeniy · March 20, 2018, 1:11pm

Also please try with double quotes

mattlward · March 20, 2018, 1:36pm

@Yevgeniy, you are the man! Your suggestion is running error free, at least for a couple of minutes. I will report back.

So, what is the difference between the 2 and why was the first killing the running database?

wu_temp_http: "/usr/bin/curl http://192.168.1.121/control?cmd=event,RealTemp={{state}}"
wu_temp_http: 'curl GET http://192.168.1.121/control?cmd=event,RealTemp={{ states.sensor.pws_temp_f.state }}'

Thanks again!!!