ActivityWatch / aw-watcher-window

Cross-platform window watcher (for use with ActivityWatch)
Mozilla Public License 2.0
91 stars 53 forks source link

Got BadWindow exception while trying to get active window on Linux #19

Closed ErikBjare closed 7 years ago

ErikBjare commented 7 years ago

Got this while running aw-watcher-window (commit 7612c4a9377ad9daa274e0242b09d59fba830d7c):

2017-06-28 12:36:49,972 [INFO ]: Running watcher with poll time 1.0 seconds  (aw_watcher_window.main:35)            
2017-06-28 12:36:49,973 [INFO ]: aw-watcher-window has started  (aw_watcher_window.main:43)                         
2017-06-28 12:36:50,019 [INFO ]: Connection to aw-server established  (aw_client.client:251)                        
2017-06-28 12:36:50,030 [INFO ]: Loaded 1 failed requests from queuefile  (aw_client.client:236)                    
2017-06-28 20:43:26,199 [WARNING]: Unable to get window class, got a BadWindow exception.  (root:74)                

2017-06-28 20:43:26,199 [WARNING]: Code made an unclear branch  (root:79)                                           
2017-06-28 20:43:26,202 [ERROR]: Exception thrown while trying to get active window: <class 'Xlib.error.BadWindow'>: code = 3, resource_id = <class 'Xlib.xobject.resource.Resource'>(0x00c00004), sequence_number = 43768, major_opcode = 15, minor_opcode = 0  (aw_watcher_window.main:64)
Traceback (most recent call last):                        
  File "/home/erb/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 61, in heartbeat_loop
    current_window = get_current_window()                 
  File "/home/erb/Programming/activitywatch/aw-watcher-window/aw_watcher_window/lib.py", line 44, in get_current_window
    return get_current_window_linux()                     
  File "/home/erb/Programming/activitywatch/aw-watcher-window/aw_watcher_window/lib.py", line 13, in get_current_window_linux
    cls = xlib.get_window_class(window)                   
  File "/home/erb/Programming/activitywatch/aw-watcher-window/aw_watcher_window/xlib.py", line 80, in get_window_class
    window = window.query_tree().parent                   
  File "/home/erb/Programming/activitywatch/venv_main2/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/xobject/drawable.py", line 425, in query_tree
  File "/home/erb/Programming/activitywatch/venv_main2/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/protocol/rq.py", line 1360, in __init__
  File "/home/erb/Programming/activitywatch/venv_main2/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/protocol/rq.py", line 1380, in reply
Xlib.error.BadWindow: <class 'Xlib.error.BadWindow'>: code = 3, resource_id = <class 'Xlib.xobject.resource.Resource'>(0x00c00004), sequence_number = 43768, major_opcode = 15, minor_opcode = 0

During handling of the above exception, another exception occurred:                                                 

Traceback (most recent call last):                        
  File "/usr/lib64/python3.6/runpy.py", line 193, in _run_module_as_main                                            
    "__main__", mod_spec)    
  File "/usr/lib64/python3.6/runpy.py", line 85, in _run_code                                                       
    exec(code, run_globals)  
  File "aw_watcher_window/__main__.py", line 3, in <module>                                                         
    main()                   
  File "/home/erb/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 45, in main          
    heartbeat_loop(client, bucket_id, poll_time=args.poll_time, exclude_title=args.exclude_title)                   
  File "/home/erb/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 65, in heartbeat_loop
    traceback.print_exc(e)   
  File "/usr/lib64/python3.6/traceback.py", line 159, in print_exc                                                  
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)                                           
  File "/usr/lib64/python3.6/traceback.py", line 100, in print_exception                                            
    type(value), value, tb, limit=limit).format(chain=chain):                                                       
  File "/usr/lib64/python3.6/traceback.py", line 497, in __init__                                                   
    capture_locals=capture_locals)                        
  File "/usr/lib64/python3.6/traceback.py", line 332, in extract                                                    
    if limit >= 0:           
TypeError: '>=' not supported between instances of 'BadWindow' and 'int'                                            
johan-bjareholt commented 7 years ago

Also got a crash now, log seems kind of different so cause is likely different though.

2017-07-01 18:00:25,809 [INFO ]: Running watcher with poll time 1.0 seconds  (aw_watcher_window.main:35)
2017-07-01 18:00:25,811 [INFO ]: aw-watcher-window has started  (aw_watcher_window.main:43)
2017-07-01 18:00:25,889 [INFO ]: Connection to aw-server established  (aw_client.client:257)
2017-07-01 18:00:25,969 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:26,971 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:27,986 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:28,988 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:29,991 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:30,993 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:31,996 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:32,997 [WARNING]: window_prop was None  (root:21)
2017-07-01 18:00:33,999 [ERROR]: Exception thrown while trying to get active window: 'NoneType' object is not subscriptable  (aw_watche
Traceback (most recent call last):
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 61, in heartbeat_loop
    current_window = get_current_window()
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/lib.py", line 44, in get_current_window
    return get_current_window_linux()
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/lib.py", line 13, in get_current_window_linux
    cls = xlib.get_window_class(window)
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/xlib.py", line 72, in get_window_class
    cls = cls[1]
TypeError: 'NoneType' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/aw-watcher-window", line 11, in <module>
    load_entry_point('aw-watcher-window', 'console_scripts', 'aw-watcher-window')()
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 45, in main
    heartbeat_loop(client, bucket_id, poll_time=args.poll_time, exclude_title=args.exclude_title)
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 65, in heartbeat_loop
    traceback.print_exc(e)
  File "/usr/lib/python3.6/traceback.py", line 159, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "/usr/lib/python3.6/traceback.py", line 100, in print_exception
    type(value), value, tb, limit=limit).format(chain=chain):
  File "/usr/lib/python3.6/traceback.py", line 497, in __init__
    capture_locals=capture_locals)
  File "/usr/lib/python3.6/traceback.py", line 332, in extract
    if limit >= 0:
TypeError: '>=' not supported between instances of 'TypeError' and 'int'
nikanar commented 7 years ago

Got the same one as @johan-bjareholt :

2017-07-16 14:04:20,395 [INFO ]: No longer AFK  (aw_watcher_afk.afk:111)
2017-07-16 14:04:20,427 [WARNING]: Event initializer did not receive a timestamp argument, using now as timestamp  (aw_core.models:48)
2017-07-16 16:29:45,466 [ERROR]: Exception thrown while trying to get active window: 'NoneType' object is not subscriptable  (aw_watcher_window.main:64)
Traceback (most recent call last):
File "/usr/lib/python3.6/site-packages/aw_watcher_window/main.py", line 61, in heartbeat_loop
    current_window = get_current_window()
  File "/usr/lib/python3.6/site-packages/aw_watcher_window/lib.py", line 44, in get_current_window
    return get_current_window_linux()
  File "/usr/lib/python3.6/site-packages/aw_watcher_window/lib.py", line 13, in get_current_window_linux
    cls = xlib.get_window_class(window)
  File "/usr/lib/python3.6/site-packages/aw_watcher_window/xlib.py", line 72, in get_window_class
    cls = cls[1]
TypeError: 'NoneType' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/aw-watcher-window", line 11, in <module>
    load_entry_point('aw-watcher-window==0.2', 'console_scripts', 'aw-watcher-window')()
  File "/usr/lib/python3.6/site-packages/aw_watcher_window/main.py", line 45, in main
    heartbeat_loop(client, bucket_id, poll_time=args.poll_time, exclude_title=args.exclude_title)
  File "/usr/lib/python3.6/site-packages/aw_watcher_window/main.py", line 65, in heartbeat_loop
    traceback.print_exc(e)
  File "/usr/lib/python3.6/traceback.py", line 159, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "/usr/lib/python3.6/traceback.py", line 100, in print_exception
    type(value), value, tb, limit=limit).format(chain=chain):
  File "/usr/lib/python3.6/traceback.py", line 497, in __init__
    capture_locals=capture_locals)
  File "/usr/lib/python3.6/traceback.py", line 332, in extract
    if limit >= 0:
TypeError: '>=' not supported between instances of 'TypeError' and 'int'
Reading active process stderr...
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/aw_qt-0.1-py3.6.egg/aw_qt/trayicon.py", line 110, in rebuild_modules_menu
    show_module_failed_dialog(module)
  File "/usr/lib/python3.6/site-packages/aw_qt-0.1-py3.6.egg/aw_qt/trayicon.py", line 96, in show_module_failed_dialog
    box.setDetailedText(module.stderr())
  File "/usr/lib/python3.6/site-packages/aw_qt-0.1-py3.6.egg/aw_qt/manager.py", line 108, in stderr
    self._log += self._process.stderr.read()
AttributeError: 'NoneType' object has no attribute 'read'
Aborted (core dumped)

RT says I exclusively opened google-chrome/emacs/terminator at that time (as I always do), so it ain't due to a specific window.

and relatedly to https://github.com/ActivityWatch/aw-qt/issues/19, aw-server and aw-watcher-afk didn't crash, only aw-watcher-window and aw-qt.

and again at

2017-07-16 17:30:08,725 [ERROR]: Exception thrown while trying to get active window: 'NoneType' object is not subscriptable  (aw_watcher_window.main:64)
[same]
johan-bjareholt commented 7 years ago

Looked more closely at the code and the issue I and @nikanar stumbled upon was quite obvious. Commited straight to master here https://github.com/ActivityWatch/aw-watcher-window/commit/a8e704ffa4f5be0630462ff5ff9f30269257226b

We need to handle the Xlib.error.BadWindow exception properly to fix the original problem which @ErikBjare posted though.

johan-bjareholt commented 7 years ago

After running for almost two weeks, I didn't get BadWindow but instead a BadValue exception.

2017-07-08 10:32:45,844 [INFO ]: Running watcher with poll time 1.0 seconds  (aw_watcher_window.main:35)
2017-07-08 10:32:45,846 [INFO ]: aw-watcher-window has started  (aw_watcher_window.main:43)
2017-07-08 10:32:45,936 [INFO ]: Connection to aw-server established  (aw_client.client:257)
2017-07-08 10:32:46,020 [WARNING]: window_prop was None  (root:21)
2017-07-08 10:32:47,022 [WARNING]: window_prop was None  (root:21)
2017-07-08 10:32:48,023 [WARNING]: window_prop was None  (root:21)
2017-07-08 10:32:49,025 [WARNING]: window_prop was None  (root:21)
2017-07-08 10:32:50,027 [WARNING]: window_prop was None  (root:21)
2017-07-08 10:32:51,028 [WARNING]: window_prop was None  (root:21)
2017-07-08 10:32:52,030 [WARNING]: window_prop was None  (root:21)
2017-07-22 18:41:47,207 [ERROR]: Exception thrown while trying to get active window: <class 'Xlib.error.BadValue'>: code = 2, resource_id = 10, sequence_number = 16630, major_opcode = 20, minor_opcode = 0  (aw_watcher_window.main:64)
Traceback (most recent call last):
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 61, in heartbeat_loop
    if os.getppid() == 1:
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/lib.py", line 44, in get_current_window
    return get_current_window_linux()
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/lib.py", line 14, in get_current_window_linux
    name = xlib.get_window_name(window)
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/xlib.py", line 49, in get_window_name
    d = window.get_full_property(NET_WM_NAME, UTF8_STRING)
  File "/usr/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/xobject/drawable.py", line 477, in get_full_property
  File "/usr/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/xobject/drawable.py", line 461, in get_property
  File "/usr/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/protocol/rq.py", line 1360, in __init__
  File "/usr/lib/python3.6/site-packages/python_xlib-0.19-py3.6.egg/Xlib/protocol/rq.py", line 1380, in reply
Xlib.error.BadValue: <class 'Xlib.error.BadValue'>: code = 2, resource_id = 10, sequence_number = 16630, major_opcode = 20, minor_opcode = 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/bin/aw-watcher-window", line 11, in <module>
    load_entry_point('aw-watcher-window', 'console_scripts', 'aw-watcher-window')()
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 45, in main
    with client:
  File "/home/johan/Programming/activitywatch/aw-watcher-window/aw_watcher_window/main.py", line 65, in heartbeat_loop
    try:
  File "/usr/lib/python3.6/traceback.py", line 159, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "/usr/lib/python3.6/traceback.py", line 100, in print_exception
    type(value), value, tb, limit=limit).format(chain=chain):
  File "/usr/lib/python3.6/traceback.py", line 497, in __init__
    capture_locals=capture_locals)
  File "/usr/lib/python3.6/traceback.py", line 332, in extract
    if limit >= 0:
TypeError: '>=' not supported between instances of 'BadValue' and 'int'
nikanar commented 7 years ago

Got one BadWindow this time, which looks like the same as OP :

2017-07-25 20:44:26,433 [WARNING]: Unable to get window class, got a BadWindow exception.  (root:73)

2017-07-25 20:44:26,433 [WARNING]: Code made an unclear branch  (root:78)
2017-07-25 20:44:26,438 [ERROR]: Exception thrown while trying to get active window: <class 'Xlib.error.BadWindow'>: code = 3, resource_id = <class 'Xlib.xobject.resource.Resource'>(0x01e005f4), sequence_number = 118, major_opcode = 15, minor_opcode = 0  (aw_watcher_window.main:69)
Traceback (most recent call last):
  File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/main.py", line 66, in heartbeat_loop
    current_window = get_current_window()
  File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/lib.py", line 44, in get_current_window
    return get_current_window_linux()
  File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/lib.py", line 13, in get_current_window_linux
    cls = xlib.get_window_class(window)
  File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/xlib.py", line 79, in get_window_class
    window = window.query_tree().parent
  File "/home/will/.local/lib/python3.6/site-packages/Xlib/xobject/drawable.py", line 425, in query_tree
    window = self.id)
  File "/home/will/.local/lib/python3.6/site-packages/Xlib/protocol/rq.py", line 1360, in __init__
    self.reply()
  File "/home/will/.local/lib/python3.6/site-packages/Xlib/protocol/rq.py", line 1380, in reply
    raise self._error
Xlib.error.BadWindow: <class 'Xlib.error.BadWindow'>: code = 3, resource_id = <class 'Xlib.xobject.resource.Resource'>(0x01e005f4), sequence_number = 118, major_opcode = 15, minor_opcode = 0

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/will/.local/bin/aw-watcher-window", line 11, in <module>
    load_entry_point('aw-watcher-window==0.2', 'console_scripts', 'aw-watcher-window')()
  File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/main.py", line 46, in main
    heartbeat_loop(client, bucket_id, poll_time=args.poll_time, exclude_title=args.exclude_title)
  File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/main.py", line 70, in heartbeat_loop
    traceback.print_exc(e)
  File "/usr/lib/python3.6/traceback.py", line 159, in print_exc
    print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain)
  File "/usr/lib/python3.6/traceback.py", line 100, in print_exception
    type(value), value, tb, limit=limit).format(chain=chain):
  File "/usr/lib/python3.6/traceback.py", line 497, in __init__
    capture_locals=capture_locals)
  File "/usr/lib/python3.6/traceback.py", line 332, in extract
    if limit >= 0:
TypeError: '>=' not supported between instances of 'BadWindow' and 'int'
Reading active process stderr...
Traceback (most recent call last):
  File "/home/will/.local/lib/python3.6/site-packages/aw_qt-0.1-py3.6.egg/aw_qt/trayicon.py", line 110, in rebuild_modules_menu
    show_module_failed_dialog(module)
  File "/home/will/.local/lib/python3.6/site-packages/aw_qt-0.1-py3.6.egg/aw_qt/trayicon.py", line 96, in show_module_failed_dialog
    box.setDetailedText(module.stderr())
  File "/home/will/.local/lib/python3.6/site-packages/aw_qt-0.1-py3.6.egg/aw_qt/manager.py", line 108, in stderr
    self._log += self._process.stderr.read()
AttributeError: 'NoneType' object has no attribute 'read'
2017-07-25 20:44:28,414 [INFO ]: afkwatcher stopped because parent process died  (aw_watcher_afk.afk:81)

Might be linked to a window that was behaving very badly, a single chrome google-sheets tab which wasn't displayed at all by my awesome wm, it would appear when I fullscreened it, but again disappear entirely when I un-fullscreen it back, I had to toggle use system title bar and borders to get it in line.

ErikBjare commented 7 years ago

I'm guessing we could work around this issue by catching XError's and retrying, or simply returning None which would indicate the active window was unknown (probably better since we won't have to worry about very fast retries).

I think it's caused by the window.query_tree().parent, perhaps because the window disappears before the tree is queried? Something similar could be the case for the BadValue exception.

See xlib source here: https://github.com/python-xlib/python-xlib/blob/master/Xlib/error.py

Also, that traceback.print_exc(e) line is wrong, the e argument shouldn't be there (that's why we get the weird limit errors).

Wrote this while a bit sleep deprived during a 7h layover at the Vaclav Havel Airport in Prague... Results may vary.

nikanar commented 7 years ago

and now I got the same BadValue as @johan-bjareholt, too :

``` 2017-07-30 15:03:22,689 [ERROR]: Exception thrown while trying to get active window: : code = 2, resource_id = 10, sequence_number = 7254, major_opcode = 20, minor_opcode = 0 (aw_watcher_window.main:69) Traceback (most recent call last): File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/main.py", line 66, in heartbeat_loop current_window = get_current_window() File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/lib.py", line 44, in get_current_window return get_current_window_linux() File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/lib.py", line 14, in get_current_window_linux name = xlib.get_window_name(window) File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/xlib.py", line 51, in get_window_name d = window.get_full_property(NET_WM_NAME, UTF8_STRING) File "/home/will/.local/lib/python3.6/site-packages/Xlib/xobject/drawable.py", line 477, in get_full_property prop.bytes_after // 4 + 1) File "/home/will/.local/lib/python3.6/site-packages/Xlib/xobject/drawable.py", line 461, in get_property long_length = length) File "/home/will/.local/lib/python3.6/site-packages/Xlib/protocol/rq.py", line 1360, in __init__ self.reply() File "/home/will/.local/lib/python3.6/site-packages/Xlib/protocol/rq.py", line 1380, in reply raise self._error Xlib.error.BadValue: : code = 2, resource_id = 10, sequence_number = 7254, major_opcode = 20, minor_opcode = 0 During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/will/.local/bin/aw-watcher-window", line 11, in load_entry_point('aw-watcher-window==0.2', 'console_scripts', 'aw-watcher-window')() File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/main.py", line 46, in main heartbeat_loop(client, bucket_id, poll_time=args.poll_time, exclude_title=args.exclude_title) File "/home/will/.local/lib/python3.6/site-packages/aw_watcher_window/main.py", line 70, in heartbeat_loop traceback.print_exc(e) File "/usr/lib/python3.6/traceback.py", line 159, in print_exc print_exception(*sys.exc_info(), limit=limit, file=file, chain=chain) File "/usr/lib/python3.6/traceback.py", line 100, in print_exception type(value), value, tb, limit=limit).format(chain=chain): File "/usr/lib/python3.6/traceback.py", line 497, in __init__ capture_locals=capture_locals) File "/usr/lib/python3.6/traceback.py", line 332, in extract if limit >= 0: TypeError: '>=' not supported between instances of 'BadValue' and 'int' ```

Will try and patch things up as @ErikBjare suggested... done. We should get more warnings and less crashes now, which sounds like a good thing to me !

johan-bjareholt commented 7 years ago

This should hopefully be fixed now with @nikanar 's PR. Please reopen if anyone encounters this issue again.