0

I have a source observable which I subscribe to with a logger observer for logging purposes.

I also subscribe to source so I can perform computations. When my computations are completed, I'm done with source and I want to dispose of the logger:

             +-------------------+
             |                   |
   +---------+ source observable +--------+
   |         |                   |        |
   |         +-------------------+        |
   |                                      |
   |                                      |
+--v---------------+         +------------v--------+
|                  |         |                     |
|     logger       |         |    computations     |
|    (observer)    |         |    (observable)     |
+-------^----------+         +-----------+---------+
        |                                |
        |                                |
        |        dispose logger          |
        +--------------------------------+
            when computations completed

However, the logger doesn't quite get disposed at the right time -- usually one or two extra ticks will occur:

MWE

from rx import Observable

# Some source
source = Observable.interval(1)

# Create logger for source
logged = []
logger = source.subscribe(logged.append)

# Now do stuff/computations with source
calculated = source.map(lambda x: x**2).take_while(lambda x: x < 20)

# Output computed values and stop logging when we're done with our computation
calculated.subscribe(print, print, logger.dispose)

# I expect only values that passed through our computation to have been logged
# The last value should be 5 because 5**2 = 25 which is larger than 20
# which in turn causes our computation to terminate
assert logged == [0, 1, 2, 3, 4, 5], logged

But I get:

Traceback (most recent call last):
  File "C:\Program Files (x86)\Python27\lib\site-packages\IPython\core\interactiveshell.py", line 3035, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-54-e8cb1fb583bf>", line 1, in <module>
    assert logged == [0, 1, 2, 3, 4, 5], logged
AssertionError: [0, 1, 2, 3, 4, 5, 6, 7]

How did 7 get logged? Our computation should terminate after source emits 5, at which point the logger gets disposed.

What am I doing wrong?

mchen
  • 9,808
  • 17
  • 72
  • 125

1 Answers1

0

This is thread synchronization problem. interval() operator launches new threads to invoke on_next() in specified intervals. Once you dispose of subscription it takes time until those other threads detect this signal and stop working. And one millisecond is close to the time it takes.

In order to log messages passing through reactive chain it is more reliable to insert logging function right into that chain:

logged = []
def logger(x):
    logged.append(x)
    return x

calculated = source \
    .map(logger) \
    .map(lambda x: x**2) \
    .take_while(lambda x: x < 20) \
    .subscribe(print, print)
Yaroslav Stavnichiy
  • 20,738
  • 6
  • 52
  • 55