search

gaogaotiantian / watchpoints

watchpoints is an easy-to-use, intuitive variable/object monitor tool for python that behaves similar to watchpoints in gdb.
Apache License 2.0
497 stars 20 forks source link

strange behavior when watching `os.environ` #21

Closed dvirtz closed 3 years ago

dvirtz commented 3 years ago

running the code

import os
from watchpoints import watch

os.environ['a'] = 'before'
watch(os.environ['a'])
os.environ['a'] = 'after'

results in the following

verbose output ``` ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:5): > watch(os.environ['a']) __call__ (/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py:50): > self.start_trace(frame) start_trace (/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py:66): > threading.settrace(self.tracefunc) (./watch_environ.py:5): > watch(os.environ['a']) os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:5): > watch(os.environ['a']) __call__ (/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py:50): > self.start_trace(frame) start_trace (/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py:66): > threading.settrace(self.tracefunc) settrace (/usr/lib64/python3.6/threading.py:60): > def settrace(func): os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:5): > watch(os.environ['a']) __call__ (/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py:50): > self.start_trace(frame) start_trace (/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py:66): > threading.settrace(self.tracefunc) settrace (/usr/lib64/python3.6/threading.py:68): > _trace_hook = func os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): settrace (/usr/lib64/python3.6/threading.py:68): > _trace_hook = func os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' (./watch_environ.py:6): > os.environ['a'] = 'after' os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:672): > def __setitem__(self, key, value): os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:673): > key = self.encodekey(key) __setitem__ (/usr/lib64/python3.6/os.py:673): > key = self.encodekey(key) os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:673): > key = self.encodekey(key) encode (/usr/lib64/python3.6/os.py:742): > def encode(value): os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:673): > key = self.encodekey(key) encode (/usr/lib64/python3.6/os.py:743): > if not isinstance(value, str): os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:673): > key = self.encodekey(key) encode (/usr/lib64/python3.6/os.py:745): > return value.encode(encoding, 'surrogateescape') os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' encode (/usr/lib64/python3.6/os.py:745): > return value.encode(encoding, 'surrogateescape') os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:674): > value = self.encodevalue(value) __setitem__ (/usr/lib64/python3.6/os.py:674): > value = self.encodevalue(value) os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:674): > value = self.encodevalue(value) encode (/usr/lib64/python3.6/os.py:742): > def encode(value): os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:674): > value = self.encodevalue(value) encode (/usr/lib64/python3.6/os.py:743): > if not isinstance(value, str): os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:674): > value = self.encodevalue(value) encode (/usr/lib64/python3.6/os.py:745): > return value.encode(encoding, 'surrogateescape') os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' encode (/usr/lib64/python3.6/os.py:745): > return value.encode(encoding, 'surrogateescape') os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:675): > self.putenv(key, value) os.environ['a']: before -> before ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' __setitem__ (/usr/lib64/python3.6/os.py:676): > self._data[key] = value os.environ['a']: before -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): __setitem__ (/usr/lib64/python3.6/os.py:676): > self._data[key] = value os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): (./watch_environ.py:6): > os.environ['a'] = 'after' os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1279): > def _shutdown(): os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1285): > tlock = _main_thread._tstate_lock os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1288): > assert tlock is not None os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1289): > assert tlock.locked() os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1290): > tlock.release() os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _stop (/usr/lib64/python3.6/threading.py:966): > def _stop(self): os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _stop (/usr/lib64/python3.6/threading.py:983): > lock = self._tstate_lock os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _stop (/usr/lib64/python3.6/threading.py:984): > if lock is not None: os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _stop (/usr/lib64/python3.6/threading.py:985): > assert not lock.locked() os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _stop (/usr/lib64/python3.6/threading.py:986): > self._is_stopped = True os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1291): > _main_thread._stop() _stop (/usr/lib64/python3.6/threading.py:987): > self._tstate_lock = None os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _stop (/usr/lib64/python3.6/threading.py:987): > self._tstate_lock = None os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1292): > t = _pickSomeNonDaemonThread() _shutdown (/usr/lib64/python3.6/threading.py:1292): > t = _pickSomeNonDaemonThread() os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1292): > t = _pickSomeNonDaemonThread() _pickSomeNonDaemonThread (/usr/lib64/python3.6/threading.py:1297): > def _pickSomeNonDaemonThread(): os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1292): > t = _pickSomeNonDaemonThread() _pickSomeNonDaemonThread (/usr/lib64/python3.6/threading.py:1298): > for t in enumerate(): _pickSomeNonDaemonThread (/usr/lib64/python3.6/threading.py:1298): > for t in enumerate(): os.environ['a']: after -> after ====== Watchpoints Triggered ====== Call Stack (most recent call last): _shutdown (/usr/lib64/python3.6/threading.py:1292): > t = _pickSomeNonDaemonThread() _pickSomeNonDaemonThread (/usr/lib64/python3.6/threading.py:1298): > for t in enumerate(): enumerate (/usr/lib64/python3.6/threading.py:1260): > def enumerate(): os.environ['a']: after -> after ====== Watchpoints Triggered ====== ```

the execution than hangs as if in a deadlock, and killing it prints

^CException ignored in: <module 'threading' from '/usr/lib64/python3.6/threading.py'>
Traceback (most recent call last):
  File "/usr/lib64/python3.6/threading.py", line 1292, in _shutdown
    t = _pickSomeNonDaemonThread()
  File "/usr/lib64/python3.6/threading.py", line 1298, in _pickSomeNonDaemonThread
    for t in enumerate():
  File "/usr/lib64/python3.6/threading.py", line 1269, in enumerate
    return list(_active.values()) + list(_limbo.values())
  File "/usr/lib64/python3.6/threading.py", line 1269, in enumerate
    return list(_active.values()) + list(_limbo.values())
  File "/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py", line 133, in tracefunc
    self._callback(frame, elem, (self._prev_funcname, self._prev_filename, self._prev_lineno))
  File "/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py", line 158, in _default_callback
    elem.watch_print(frame, elem, exec_info)
  File "/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch_print.py", line 20, in __call__
    if threading.active_count() > 1:
  File "/usr/lib64/python3.6/threading.py", line 1251, in active_count
    with _active_limbo_lock:
KeyboardInterrupt:
gaogaotiantian commented 3 years ago

This is a weird issue and I guess it has something to do with the mechanism of os.environ. I'm not able to crack it to the bottom, but I changed the way watchpoints monitors variables. In short, when you assign a string a with a different id to a variable that has a already, it won't trigger the monitor now. The fix should be released soon.

As for the deadlock, I can reproduce it in VSCode terminal, but not with pure WSL Ubuntu. Are you doing this in VSCode as well? I suspected it has something to do with VSCode. And it's also fixed with the patch(for me).

dvirtz commented 3 years ago

Thanks. I did use VSCode terminal. I'll check the fix when it will be released.

gaogaotiantian commented 3 years ago

The fix is released with 0.2.3

dvirtz commented 3 years ago

I can verify the original code works with 0.2.3, however, if I try to add a watch inside a function like in

import os
from watchpoints import watch

def run():
  os.environ['a'] = 'before'
  watch(os.environ['a'])
  os.environ['a'] = 'after'

if __name__ == '__main__':
    run()

I get

Traceback (most recent call last):
  File "./watch_environ.py", line 10, in <module>
    run()
  File "./watch_environ.py", line 6, in run
    watch(os.environ['a'])
  File "/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch.py", line 44, in __call__
    stack_limit=kwargs.get("stack_limit", self.stack_limit)
  File "/home/conan/.local/lib/python3.6/site-packages/watchpoints/watch_element.py", line 14, in __init__
    exec(code, {}, f_locals)
  File "<string>", line 1, in <module>
NameError: name 'os' is not defined
gaogaotiantian commented 3 years ago

Good catch, this is a valid bug.

gaogaotiantian commented 3 years ago

Should be fixed in 0.2.4, thanks for noticing it.