aw-server-rust & aw-watcher-window: Persistent fatal error "unexpected end of hex escape"

[s9menine]

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

• OS name and version: Windows 10 LTSC Build 17763
• ActivityWatch version: v0.12.1 (rust)

Describe the bug

The ActivityWatch web UI silently stops updating data, and logs with huge filesizes are created.
The issue persists after you close the explorer.exe window, restart ActivityWatch, and even through rebooting the computer.

To Reproduce

Repro steps are my best guess from looking at the logs, given that I can't re-trigger the bug without somehow fixing it first:

1. Create a new folder named 1719158 (100) - 𝕎𝕚𝕟𝕥𝕖𝕣❄️メイキング
2. Open this folder with the Windows explorer
3. Watch AppData\Local\activitywatch\activitywatch\Logs\aw-watcher-window and AppData\Local\activitywatch\Logs\aw-server-rust explode

Expected behavior

Either keep tracking and reporting data as usual, or fail loudly with an error telling me that the window watcher has stopped working.

Documentation

Snippet from logs. It's the same messages repeated thousands of times.

aw-server_2022-10-26T14-22-29+0800.log

[2022-10-26 14:22:29][�[32mINFO�[0m][aw_server]: Using DB at path "C:\\Users\\s9menine\\AppData\\Local\\activitywatch\\aw-server-rust\\sqlite.db"
[2022-10-26 14:22:29][�[32mINFO�[0m][aw_server]: Using aw-webui assets at path "C:\\Users\\s9menine\\AppData\\Local\\Programs\\ActivityWatch\\aw-server-rust\\./static/"
[2022-10-26 14:22:29][�[32mINFO�[0m][aw_server::endpoints]: Starting aw-server-rust at 127.0.0.1:5600
[2022-10-26 14:22:30][�[33mWARN�[0m][_]: Data guard `Json < Event >` failed: Parse("{\"id\": null, \"timestamp\": \"2022-10-15T12:34:03.230000+00:00\", \"duration\": 1.059, \"data\": {\"app\": \"explorer.exe\", \"title\": \"D:\\\\[[REDACTED]]\\\\1719158 (100) - \\ud835\\udd4e\\ud835\\udd5a\\ud835\\udd5f\\ud835\"}}", Error("unexpected end of hex escape", line: 1, column: 261)).
[2022-10-26 14:22:30][�[33mWARN�[0m][_]: No 400 catcher registered. Using Rocket default.
[2022-10-26 14:22:30][�[33mWARN�[0m][_]: Data guard `Json < Event >` failed: Parse("{\"id\": null, \"timestamp\": \"2022-10-15T12:34:03.230000+00:00\", \"duration\": 1.059, \"data\": {\"app\": \"explorer.exe\", \"title\": \"D:\\\\[[REDACTED]]\\\\1719158 (100) - \\ud835\\udd4e\\ud835\\udd5a\\ud835\\udd5f\\ud835\"}}", Error("unexpected end of hex escape", line: 1, column: 261)).
[2022-10-26 14:22:30][�[33mWARN�[0m][_]: No 400 catcher registered. Using Rocket default.
[2022-10-26 14:22:30][�[33mWARN�[0m][_]: Data guard `Json < Event >` failed: Parse("{\"id\": null, \"timestamp\": \"2022-10-15T12:34:03.230000+00:00\", \"duration\": 1.059, \"data\": {\"app\": \"explorer.exe\", \"title\": \"D:\\\\[[REDACTED]]\\\\1719158 (100) - \\ud835\\udd4e\\ud835\\udd5a\\ud835\\udd5f\\ud835\"}}", Error("unexpected end of hex escape", line: 1, column: 261)).
[2022-10-26 14:22:30][�[33mWARN�[0m][_]: No 400 catcher registered. Using Rocket default.

aw-watcher-window_2022-10-26T14-22-29.log

2022-10-26 14:22:29 [INFO ]: aw-watcher-window started  (aw_watcher_window.main:62)
2022-10-26 14:22:30 [INFO ]: Connection to aw-server established by aw-watcher-window  (aw_client.client:429)
2022-10-26 14:22:30 [WARNING]: 400 Client Error: Bad Request for url: http://127.0.0.1:5600/api/0/buckets/aw-watcher-window_[[REDACTED-MACHINE-NAME]]/heartbeat?pulsetime=2.0  (aw_client.client:28)
2022-10-26 14:22:30 [WARNING]: Failed to send request to aw-server, will queue requests until connection is available.  (aw_client.client:455)
2022-10-26 14:22:30 [INFO ]: Connection to aw-server established by aw-watcher-window  (aw_client.client:429)
2022-10-26 14:22:30 [WARNING]: 400 Client Error: Bad Request for url: http://127.0.0.1:5600/api/0/buckets/aw-watcher-window_[[REDACTED-MACHINE-NAME]]/heartbeat?pulsetime=2.0  (aw_client.client:28)
2022-10-26 14:22:30 [WARNING]: Failed to send request to aw-server, will queue requests until connection is available.  (aw_client.client:455)
2022-10-26 14:22:30 [INFO ]: Connection to aw-server established by aw-watcher-window  (aw_client.client:429)
2022-10-26 14:22:30 [WARNING]: 400 Client Error: Bad Request for url: http://127.0.0.1:5600/api/0/buckets/aw-watcher-window_[[REDACTED-MACHINE-NAME]]/heartbeat?pulsetime=2.0  (aw_client.client:28)
2022-10-26 14:22:30 [WARNING]: Failed to send request to aw-server, will queue requests until connection is available.  (aw_client.client:455)
2022-10-26 14:22:30 [INFO ]: Connection to aw-server established by aw-watcher-window  (aw_client.client:429)

Additional context

These were fun to discover.

[github-actions]

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! 🙏

[ErikBjare]

Yikes!

The logfile size issue is fixed in: ActivityWatch/aw-core#114
The endless queueing of bad events (that should not be retried, because they will keep failing) is fixed in: ActivityWatch/aw-client#68

The underlying encoding issue on the aw-server-rust side does not yet have a fix.

[ErikBjare]

@johan-bjareholt Could you take a look at this encoding issue?

[s9menine]

Thanks for the log size fix! Are there alpha or nightly builds with this fix I could use? I tried the build at the bottom of this page, but it seems like the log file fix isn't included in it, as log files can still grow to 100+ MB after a while.

[johan-bjareholt]

@ErikBjare Are we sure if the encoding issue actually is on the aw-server-rust side? Or could it be in aw-watcher-window?

Regardless, we need to define how we require utf chars to be escaped in aw-server. For example, do we allow utf-16 or do we only intend to support utf-8, and which components use what today? This could potentially also be an issue in aw-watcher-web.

[johan-bjareholt]

If I recall correctly, I had some issues with escaping in the code migrating from the aw-server-python database to the aw-server-rust db, but I don't recall how I fixed it. Could be a hint.

[johan-bjareholt]

@ErikBjare Found the aw-server-rust issue and PR, what I did was just drop the events completely because they contained invalid UTF-8

ActivityWatch/aw-server-rust#173

ActivityWatch/aw-server-rust#162

IMO, the more right way would probably be to only delete the invalid chars, but if I recall correctly I attempted to do that but it was quite hard so I gave up.

EDIT: Here's the mentioning of it being hard to implement ActivityWatch/aw-server-rust#173 (comment)

[s9menine]

In the meantime, I figured out a workaround to restore the functionality of my window watcher: I backed up and deleted the folder named aw-watcher-window.v1.persistqueue under activitywatch\aw-client\queued, and everything's up and running again.