aw-server randomly crashes on start up (WinError 10013)

[macbrayne]

• [x] I am on the latest ActivityWatch version.
• [x] I have searched the issues of this repo and believe that this is not a duplicate.

• OS name and version: Windows 10 2004 Build 19041.804 (System language: DE)
• ActivityWatch version: 0.10.0

Describe the bug

Randomly, the aw-server fails to launch and keeps crashing whether the module is restarted or the program is completely shutdown using the "Quit ActivityWatch" button in tray icon menu and restarted. This doesn't always happen: sometimes the program runs smoothly over the course of multiple restarts, other times it repeatedly crashes even after restarting the computer. The resulting error is always WinError 10013.

To Reproduce

I haven't tested enough to reliably reproduce this error.

Expected behavior

The program should start up correctly on every system start.

Documentation

2021-02-28 17:48:02 [INFO ]: Using storage method: peewee  (aw_server.main:26)
2021-02-28 17:48:02 [INFO ]: Starting up...  (aw_server.main:31)
2021-02-28 17:48:02 [INFO ]: Using database file: C:\Users\macbr\AppData\Local\activitywatch\activitywatch\aw-server\peewee-sqlite.v2.db  (aw_datastore.storages.peewee:116)
2021-02-28 17:48:02 [ERROR]: [WinError 10013] Der Zugriff auf einen Socket war aufgrund der Zugriffsrechte des Sockets unzulässig  (aw_server.server:93)
2021-02-28 17:48:02 [ERROR]: Unhandled exception  (root:43)
Traceback (most recent call last):
  File "__main__.py", line 3, in <module>
  File "aw_server\main.py", line 33, in main
  File "aw_server\server.py", line 94, in _start
  File "aw_server\server.py", line 91, in _start
  File "lib\site-packages\flask\app.py", line 990, in run
  File "lib\site-packages\werkzeug\serving.py", line 1012, in run_simple
  File "lib\site-packages\werkzeug\serving.py", line 965, in inner
  File "lib\site-packages\werkzeug\serving.py", line 823, in make_server
  File "lib\site-packages\werkzeug\serving.py", line 701, in __init__
  File "socketserver.py", line 452, in __init__
  File "http\server.py", line 137, in server_bind
  File "socketserver.py", line 466, in server_bind
OSError: [WinError 10013] Der Zugriff auf einen Socket war aufgrund der Zugriffsrechte des Sockets unzulässig

Screenshot of the log folder: all 2kb files are erroring start-up attempts

Programs trying to send data to port 5600 during startup:

PS C:\Users\macbr> Get-NetTCPConnection |where {($_.RemotePort -eq 5600)} |Foreach {(Get-Process -Id $_.OwningProcess)}
Handles  NPM(K)    PM(K)      WS(K)     CPU(s)     Id  SI ProcessName
-------  ------    -----      -----     ------     --  -- -----------
    215      20    18280      27432       0,52  12612   1 aw-watcher-afk
    259      26    20904      34924      19,45  12664   1 aw-watcher-window

Trying to query programs listening on port 5600 yielded no results.

Additional context

aw-qt_2021-02-28T18-53-35.log

2021-02-28 18:53:35 [INFO ]: Searching for bundled modules in: ['C:\\Users\\macbr\\AppData\\Local\\Programs\\ActivityWatch\\aw_qt', 'C:\\Users\\macbr\\AppData\\Local\\Programs\\ActivityWatch']  (aw_qt.manager:67)
2021-02-28 18:53:35 [WARNING]: Found matching file but was not executable: C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-qt.desktop  (aw_qt.manager:55)
2021-02-28 18:53:35 [WARNING]: Found matching file but was not executable: C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-qt.exe.manifest  (aw_qt.manager:55)
2021-02-28 18:53:35 [WARNING]: Found matching file but was not executable: C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-server\aw-server.exe.manifest  (aw_qt.manager:55)
2021-02-28 18:53:35 [WARNING]: Found matching file but was not executable: C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-server-rust\aw-server.service  (aw_qt.manager:55)
2021-02-28 18:53:35 [WARNING]: Found matching file but was not executable: C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-watcher-afk\aw-watcher-afk.exe.manifest  (aw_qt.manager:55)
2021-02-28 18:53:35 [WARNING]: Found matching file but was not executable: C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-watcher-window\aw-watcher-window.exe.manifest  (aw_qt.manager:55)
2021-02-28 18:53:35 [INFO ]: Found bundled modules:  (aw_qt.manager:72)
2021-02-28 18:53:35 [INFO ]:  - aw-qt at C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-qt.exe  (aw_qt.manager:24)
2021-02-28 18:53:35 [INFO ]:  - aw-server at C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-server\aw-server.exe  (aw_qt.manager:24)
2021-02-28 18:53:35 [INFO ]:  - aw-server-rust at C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-server-rust\aw-server-rust.exe  (aw_qt.manager:24)
2021-02-28 18:53:35 [INFO ]:  - aw-watcher-afk at C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-watcher-afk\aw-watcher-afk.exe  (aw_qt.manager:24)
2021-02-28 18:53:35 [INFO ]:  - aw-watcher-window at C:\Users\macbr\AppData\Local\Programs\ActivityWatch\aw-watcher-window\aw-watcher-window.exe  (aw_qt.manager:24)
2021-02-28 18:53:35 [INFO ]: Found system modules:  (aw_qt.manager:99)
2021-02-28 18:53:35 [INFO ]: Starting module aw-server  (aw_qt.manager:128)
2021-02-28 18:53:35 [INFO ]: Starting module aw-watcher-afk  (aw_qt.manager:128)
2021-02-28 18:53:35 [INFO ]: Starting module aw-watcher-window  (aw_qt.manager:128)
2021-02-28 18:53:35 [INFO ]: Creating trayicon...  (aw_qt.trayicon:200)
2021-02-28 18:53:35 [INFO ]: Initialized aw-qt and trayicon succesfully  (aw_qt.trayicon:235)
2021-02-28 18:53:38 [WARNING]: Tried to stop module aw-server, but it wasn't running  (aw_qt.manager:171)

[github-actions[bot]]

Hi there! As you're new to this repo, please make sure you've used an appropriate issue template and searched for duplicates (it helps us focus on actual development!). We'd also like to suggest that you read our contribution guidelines and our code of conduct. Thanks a bunch for opening your first issue! 🙏

[johan-bjareholt]

This issue can occur because either of two reasons:

1. Another process is using port 5600, so aw-server can't bind it and therefore not start
2. aw-server is already running in the background, but doing so without aw-qt. Possibly a bug when quitting aw-qt and aw-server fails to quit with it.

Could you start with narrowing down which of these two cases it seems to be?

[macbrayne]

I'm pretty sure it's not the second case because the issue even occurs on system startup. I can't fully rule out the first case however I couldn't find any applications listening on the port 5600:

Get-NetTCPConnection |where {($_.LocalPort -eq 5600)} |Foreach {(Get-Process -Id $_.OwningProcess)}

When the program starts up successfully:

Get-NetTCPConnection |where {($_.LocalPort -eq 5600)} |Foreach {(Get-Process -Id $_.OwningProcess)}
    251      29    31328      42500       0,45  15244   1 aw-server
    251      29    31328      42500       0,45  15244   1 aw-server
    251      29    31328      42500       0,45  15244   1 aw-server
      0       0       60          8                 0   0 Idle
    251      29    31328      42500       0,45  15244   1 aw-server

In the case of this issue occurring that command doesn't output anything, This should mean that this port isn't used.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[macbrayne]

I've mitigated the issue by stopping and starting winnat every time it crashes and finally solved it by following the instructions on this GitHub issue (https://github.com/docker/for-win/issues/3171#issuecomment-554587817) and adding the port 5600 to the port exclusion range.

The reason for the crash seemed to be WSL / HyperV reserving a huge range of ports for VMs and applications accessing them getting a "Access denied" error.

To exclude the port required for ActivityWatch run netsh int ipv4 add excludedportrange protocol=tcp startport=5600 numberofports=1

The current range is checkable via netsh interface ipv4 show excludedportrange protocol=tcp

I don't remember whether I had to do anything regarding udp port ranges.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[macbrayne]

Maybe this fix could be documented?