Refactor FileWatchSensor to remove logshipper

[blag]

This PR refactors the FileWatchSensor from the linux pack, to remove it's dependency on logshipper, and use watchdog instead.

Upstream logshipper hasn't been touched in years, so we switched to our own fork. That hasn't been well maintained either, and the Tail implementation, which is all we use from it, is a bit of a mess on top of depending on pyinotify has been itself unmaintained for even longer.

This PR borrows some code from the previous sensor, but also breaks up the code into well structured classes that all have a single focus, possibly allowing this code to be reused elsewhere. Additionally, you can run the sensor Python script itself, which should help serve as an example of how to write a "good" sensor.

The watchdog project is now being actively maintained, has wide support for Linux, macOS, BSD, Windows, and a polling fallback implementation. The pyinotify package refuses to even install on macOS (not being able to run is understandable, but preventing installation is too limiting IMO).

I realize that it's a bit odd to make the linux depend less on Linux-specific features, but since pyinotify refused to even install on macOS, I couldn't do simple things like run make requirements without Linux running in a full Docker or VM environment.

This PR also fixes a bug in logshipper (has to do with lines that do not end in newlines - previous code only took the last character, new code takes the whole line), and also presents a workaround for another possible bug in the comments.

Currently being held up by #5095.

[Kami]

Overall, I'm fine with the change, but some tests would be good :)

[blag]

Just running these tests gives us excellent coverage:

................................................
Name                   Stmts   Miss Branch BrPart  Cover
--------------------------------------------------------
file_watch_sensor.py     221      8     68     11    93%
----------------------------------------------------------------------
Ran 48 tests in 14.800s

OK

Almost all of the untested code was in the sensor itself.

[blag]

I tested this manually, both on macOS bare metal and in a Docker container (running on macOS).

contrib/linux/Dockerfile:

FROM ubuntu:18.04

RUN apt update && apt install --yes git make python3-dev python3-pip

RUN python3 -m pip install coverage eventlet mock nose watchdog

VOLUME /code

WORKDIR /code
ENV PYTHONPATH=actions:sensors
ENV NOSE_COVER_CONFIG_FILE=.coveragerc
CMD nosetests --with-coverage --cover-branches --cover-html tests/test_file_watch_sensor.py

And the coverage configuration contrib/linux/.coveragerc:

[run]
include = sensors/file_watch_sensor.py

[report]
include = sensors/file_watch_sensor.py

Commands (on bare metal):

cd contrib/linux
docker build --tag contrib-linux-pack-test .
docker run --rm --volume $(pwd):/code --workdir /code contrib-linux-pack-test

If you want to debug anything, run:

docker run -it --rm --volume $(pwd):/code --workdir /code contrib-linux-pack-test /bin/bash

Commands (within running Docker container):

# run a single test (specified at the bottom of test_file_watch_sensor.py)
python3 tests/test_file_watch_sensor.py

# run all tests and report coverage results in HTML
nosetests --with-coverage --cover-branches --cover-html tests/test_file_watch_sensor.py

then you can view results in your web browser.

I'm having an issue with the Travis tests where inotify events don't seem to be delivered. I'll have to debug that. But these testing instructions should suffice for anybody else who is interested in testing this out.

[cognifloyd]

The requirements compile issues have been resolved.
The pylint error about importing pika in a tools/ script has been resolved.

Now there's one consistent error left in the unit tests, though I don't know why this PR would cause that:

======================================================================
1) FAIL: test_process_error_handling (tests.unit.test_workflow_engine.WorkflowExecutionHandlerTest)
----------------------------------------------------------------------
   Traceback (most recent call last):
    virtualenv/lib/python3.6/site-packages/mock/mock.py line 1346 in patched
      return func(*newargs, **newkeywargs)
    st2actions/tests/unit/test_workflow_engine.py line 203 in test_process_error_handling
      self.assertEqual(t1_ex_db.status, wf_statuses.FAILED)
   AssertionError: 'succeeded' != 'failed'
   - succeeded
   + failed

[cognifloyd]

Well. I can't reproduce that test failure in CI. It might be related to #5358 which was just merged and touched the test that was failing. But, it's not failing anymore. If it shows up again, we can look into it.

Anyway, all tests are green now.

[cognifloyd]

I'm currently testing this.

• ✅ The first issue is that the Readme is not correct (and wasn't correct for the previous sensor either). You do NOT add a list of files to watch in the pack config. Instead, you must create a rule that uses the linux.file_watch.line trigger. You define the file_path trigger parameter in that rule.

• Next issue: Using the original sensor, I've tried several variations on the rule, but I don't see any trigger instances or rule enforcements. So, the status quo does not work for me. Interestingly, the sensorcontainer logs do show that it adds and watches the correct file.

[cognifloyd]

• ✅ Next issue: If a rule is updated (eg change file path being watched) then the sensor needs to handle the update and change the watched path. (testing the sensor in this PR)

[cognifloyd]

OK. With debug logging (using the sensor from this PR), I can see that:

• TailManager.run() logs its Running TailManager line
• FileWatchSensor.add_trigger() gets called as expected due to a rule that uses the appropriate parametrized trigger
  • tail_manager.tail_file() gets called
    • SingleFileTail inits correctly
      • opens the file
      • runs observer.schedule() to start the file and parent dir watches
  • tail_manager.start() gets called logging its Starting TailManager line
    • the observer.start() method does not seem to be returning. I do not see the Started Observer, emitters log line.
      • observer.start() loops through its emitters, calling emitter.start(), but that is already called in observer.schedule() so that's probably not it
      • observer.start() also calls BaseThread.start() (via super(): approx mro BaseObserver(EventDispatcher(watchdog.utils.BaseThread)))
      • BaseThread(threading.Thread).start() calls self.on_thread_start()
        • This inits an InotifyBuffer which is itself a BaseThread.
          • inotify_buffer is geting the file change notifications correctly because its log lines are showing up
      • BaseThread(threading.Thread).start() should finally call threading.Thread.start(self) but I can't tell if this gets called or if it completes
  • so, add_trigger never returns - this is probably one reason updates don't happen.

observer is a watchdog.observers.Observer instance.

We might also need to modify:

• TailManager.run() as it uses time.sleep ... not sure if we need to use eventlet's version

[cognifloyd]

Since this doesn't work with eventlet yet, I marked it as draft.

[cognifloyd]

Using eventlet.debug.spew() it looks like watchdog's observer is blocking on trying to read events with os.read(self._inotify_fd, event_buffer_size). If the thread patching had worked it would have switched contexts back to something else (another greenlet / thread).

• https://github.com/gorakhargosh/watchdog/blob/v2.1.6/src/watchdog/observers/inotify_buffer.py#L88
• https://github.com/gorakhargosh/watchdog/blob/v2.1.6/src/watchdog/observers/inotify_c.py#L285

When I modify the file, this forces it to continue on to the next line (because it was able to read the fd). Then it seems to get lost in the logger:

• https://github.com/gorakhargosh/watchdog/blob/v2.1.6/src/watchdog/observers/inotify_buffer.py#L57

Subsequent file edits never spew anything else from watchdog. Instead there are some lines from eventlet.green.threading and a loop in eventlet.patcher and a couple lines from threading about a limbo lock... Something is not respecting eventlet. Not sure what.

[cognifloyd]

History of PRs touching the sensor in this pack (my git spelunking notes):

• Promote linux pack to st2 #1134
• Add example to file_watch_sensor #1966
• Set same env variables as sensor process and s/_sensor_service/sensor_service #2695
• Disable filewatch sensor by default #3293
• File watch sensor to utilize trigger with parameters #3361
• Just declare one trigger type for file watch sensor #3398
• Remove 'linux' pack config #3475
• Fix a bug with trigger payload validation in linux.FileWatchSensor sensor #4491
• copyright/license PR(s)
• this one :)

[cognifloyd]

...

• tail_manager.start() gets called logging its Starting TailManager line

  • the observer.start() method does not seem to be returning. I do not see the Started Observer, emitters log line.

    • observer.start() loops through its emitters, calling emitter.start(), but that is already called in observer.schedule() so that's probably not it

    • observer.start() also calls BaseThread.start() (via super(): approx mro BaseObserver(EventDispatcher(watchdog.utils.BaseThread)))

    • BaseThread(threading.Thread).start() calls self.on_thread_start()

      • This inits an InotifyBuffer which is itself a BaseThread.

        • inotify_buffer is geting the file change notifications correctly because its log lines are showing up

    • BaseThread(threading.Thread).start() should finally call threading.Thread.start(self) but I can't tell if this gets called or if it completes

• so, add_trigger never returns - this is probably one reason updates don't happen.

observer is a watchdog.observers.Observer instance.

Watchdog uses threading. But the threading module is not getting monkey patched. I tried adjusting the monkey patching, monkey_patch(patch_thread=True), but that made no difference.

Actually, it looks like threading is partially getting monkey patched, but adjusting that monkey patch call didn't change anything.

For reference, I used this to determine the state of monkey patching, just before the observer "thread" is supposed to start. In every scenario I tried, I got eventlet.green.threading and False, so it is monkey patched, but eventlet doesn't think it is. 🤷 So, this is going to have to wait until we can get rid of eventlet. 😭

    def start(self):
        if self.tails and not self.started:
            self.logger.debug("Starting TailManager")
            import threading
            self.logger.debug(f"threading monkey_patch: {threading.current_thread.__module__}")
            import eventlet
            self.logger.debug(f"threading monkey_patch: {eventlet.patcher.is_monkey_patched(threading)}")

            self.observer.start()

We might also need to modify:

• TailManager.run() as it uses time.sleep ... not sure if we need to use eventlet's version

I tested using eventlet.sleep, but that didn't make a difference because the context never goes back to that loop.