New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Incorrect time usage collection #179

Open
dufferzafar opened this Issue Mar 18, 2018 · 34 comments

Comments

Projects
None yet
5 participants
@dufferzafar
Copy link

dufferzafar commented Mar 18, 2018

My machine has been running for the past 14 hours (~13 hours counted on March 18 and the last hour counted on March 19.)

But activitywatch only shows data for ~9 hours and that too on March 18:

image

and there's no data for March 19:

image

I looked into the logs folder and there's no log file for March 19 either.

$ tree /home/dufferzafar/.cache/activitywatch/log/
├── aw-qt
│   ├── aw-qt_2018-03-17T22-31-45.log
│   ├── aw-qt_2018-03-18T00-36-02.log
│   ├── aw-qt_2018-03-18T00-36-09.log
│   ├── aw-qt_2018-03-18T00-36-47.log
│   ├── aw-qt_2018-03-18T00-37-43.log
│   ├── aw-qt_2018-03-18T10-29-05.log
│   ├── aw-qt_2018-03-18T10-34-25.log
│   ├── aw-qt_2018-03-18T11-00-27.log
│   ├── aw-qt_2018-03-18T11-03-17.log
│   └── aw-qt_2018-03-18T13-02-07.log
├── aw-server
│   ├── aw-server_2018-03-17T22-31-46.log.json
│   ├── aw-server_2018-03-18T10-34-25.log.json
│   ├── aw-server_2018-03-18T11-03-17.log.json
│   └── aw-server_2018-03-18T13-02-07.log.json
├── aw-watcher-afk
│   ├── aw-watcher-afk_2018-03-17T22-31-46.log
│   ├── aw-watcher-afk_2018-03-18T10-34-25.log
│   ├── aw-watcher-afk_2018-03-18T11-03-17.log
│   └── aw-watcher-afk_2018-03-18T13-02-07.log
└── aw-watcher-window
    ├── aw-watcher-window_2018-03-17T22-31-46.log
    ├── aw-watcher-window_2018-03-18T10-34-25.log
    ├── aw-watcher-window_2018-03-18T11-03-17.log
    └── aw-watcher-window_2018-03-18T13-02-07.log

How do I troubleshoot this?

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Mar 19, 2018

What's the last event timestamp in the timeline?
We have a known issue where events might be delayed up to a few hours in worst case which should be fixed in v0.8.
If that's not the issue, I'll have some more questions but that's the most likely one.
If you want to look at the raw data activitywatch has collected you can see that for each bucket/client in the "raw data" tab.

I looked into the logs folder and there's no log file for March 19 either.

The log name includes the time when the watcher starts, so if you started it the 18th and it hasn't crashed the last one on the 18th or march should be the current log.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 19, 2018

I ran activitywatch again today (still haven't gotten it to autostart properly) and the events that I mentioned earlier today are just not present, so they were not delayed but got lost entirely!

There was also this logline:
2018-03-19 23:49:27 [INFO ]: Loaded 10 failed requests from queuefile (aw_client.client:301)

I wonder if it has anything to do with it.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 19, 2018

It's 20th March - 12:03 am (in India) right now and activity watch has no data for today, while it has been running for ~30 minutes.

So does this mean it only collects data on the day it was run? or something similar?

@johan-bjareholt You mentioned that:

We have a known issue where events might be delayed up to a few hours in worst case which should be fixed in v0.8.

Has this already been fixed? Since I'm running directly from source, this shouldn't be happening.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 19, 2018

Some more observations:

$ curl -X GET --header 'Accept: application/json' 'http://localhost:5600/api/0/buckets/aw-watcher-window_dufferZafar-Dell/events?limit=1'

[
  {
    "id": 9770,
    "duration": 7.02,
    "data": {
      "app": "Firefox",
      "title": "API - Mozilla Firefox"
    },
    "timestamp": "2018-03-19T18:41:10.093000+00:00"
  }
]

So, the last event stamp is from the previous day.

I'm using three watchers: AFK, Window and Firefox.

Firefox watcher shows:

image

So it is syncing properly.

Firefox debug info (just in case):

Number of active tabs: 1
Tabs:
{
    "id": 58,
    "index": 4,
    "windowId": 3,
    "highlighted": true,
    "active": true,
    "pinned": false,
    "status": "complete",
    "hidden": false,
    "discarded": false,
    "incognito": false,
    "width": 1920,
    "height": 966,
    "lastAccessed": 1521485121870,
    "audible": false,
    "mutedInfo": {
        "muted": false
    },
    "isArticle": false,
    "isInReaderMode": false,
    "sharingState": {
        "camera": false,
        "microphone": false
    },
    "url": "https://github.com/ActivityWatch/activitywatch/issues/179",
    "title": "Incorrect time usage collection · Issue #179 · ActivityWatch/activitywatch",
    "favIconUrl": "https://assets-cdn.github.com/favicon.ico"
}

{"testing":null,"lastSyncSuccess":true}
@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 19, 2018

All of the buckets are not getting updated (as they were last updated yesterday):

$ curl -X GET --header 'Accept: application/json' 'http://localhost:5600/api/0/buckets/'
{
  "aw-watcher-afk_dufferZafar-Dell": {
    "last_updated": "2018-03-19T18:46:35.007000+00:00",
    "type": "afkstatus",
    "id": "aw-watcher-afk_dufferZafar-Dell",
    "name": null,
    "client": "aw-watcher-afk",
    "hostname": "dufferZafar-Dell",
    "created": "2018-03-17T22:31:47.236823"
  },
  "aw-watcher-window_dufferZafar-Dell": {
    "last_updated": "2018-03-19T18:46:37.311000+00:00",
    "type": "currentwindow",
    "id": "aw-watcher-window_dufferZafar-Dell",
    "name": null,
    "client": "aw-watcher-window",
    "hostname": "dufferZafar-Dell",
    "created": "2018-03-17T22:31:56.242534"
  },
  "aw-watcher-web-firefox": {
    "last_updated": "2018-03-19T18:46:30.788000+00:00",
    "type": "web.tab.current",
    "id": "aw-watcher-web-firefox",
    "name": null,
    "client": "aw-watcher-web",
    "hostname": "unknown",
    "created": "2018-03-17T22:35:37.053245"
  }
}

@ErikBjare ErikBjare added the type: bug label Mar 20, 2018

@ErikBjare

This comment has been minimized.

Copy link
Member

ErikBjare commented Mar 20, 2018

Weird. Both the window and AFK watcher have a request queue that sometimes fills up and then takes a while to get through. I'd bet that this issue is related to #164 which is very similar.

It does seem like events are arriving for you now though. You made the comment on 2018-03-19T18:47:31Z (UTC) and last_updated for your buckets is just a minute before that, so seems to be working now at least. Let me know if the Activity view still isn't showing anything, and thanks for reporting!

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 20, 2018

@ErikBjare

This comment has been minimized.

Copy link
Member

ErikBjare commented Mar 20, 2018

Yeah, all timestamps are stored as UTC. It should show up in the Activity-view for the right date as it takes your timezone into account when querying (it hasn't in the past, but should have been fixed long ago). It does get logged for the right time, it's just that the raw timestamp will be in UTC.

The reason is that it is lot easier to store everything in UTC and wait to take timezones into account until querying. We've discussed this before, and might add timezone info to events in the future: #72

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 22, 2018

Yeah, storing times in UTC does make sense to keep things straightforward.

But the UI not showing the times still is an issue right?

I feel this consistently happens when I the date changes (~12 am) so I'll keep this in mind when I work at night and will report what more I can find.

@ErikBjare off the top of your head, where do you think the issue might be? I'm fairly proficient with Python so I don't mind digging into the codebase.

@ErikBjare

This comment has been minimized.

Copy link
Member

ErikBjare commented Mar 22, 2018

If the UI does not show the activity for the date despite the data being there in both the watcher and AFK-buckets, then that is an issue yes.

Perhaps something happened to timezone handling in the web UI when we switched to the query2 stuff @johan-bjareholt?

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Mar 22, 2018

@ErikBjare Very likely. Will take a look at it later tonight.

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Mar 22, 2018

Seems to work correctly for me in the webui.

When doing console.log(this.date) in Activity.vue i get 2018-03-22T00:00:00+01:00 as I should.
Also the newest events are displayed correct on the hour, so can't reproduce.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 26, 2018

I was up late at night and as expected this bug happened again.

Notice how the event data seems to be missing for the first hour or so, it is also missing from the timeline view:

image

But, I looked at raw event entries using the API and it seems to be there in the DB. It's just not getting reflected in the UI.

I'm willing to privately share the JSON entries (or my entire DB) with you if that may help debug this.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 26, 2018

Basically, this entry is is not getting reflected in the UI.

  {
    "timestamp": "2018-03-26T18:16:26.641000+00:00",
    "duration": 3208.183,
    "data": {
      "title": "Iron Man 2 2010 1080p 10bit BluRay x265 HEVC 6CH-MRN - mpv",
      "app": "mpv"
    },
    "id": 16493
  }

It is an event that started from 23:46 PM local time and went on for about 53 minutes. That'd be till around 00:39 the next day.

This is exactly what is missing from the UI.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Mar 26, 2018

The next event in the DB is this:

  {
    "timestamp": "2018-03-26T19:09:55.827000+00:00",
    "duration": 0,
    "data": {
      "title": "Reddit - Mozilla Firefox",
      "app": "Firefox"
    },
    "id": 16506
  },

Which converts to 00:39 local time and this event is visible in the timeline.

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Apr 7, 2018

It is an event that started from 23:46 PM local time and went on for about 53 minutes. That'd be till around 00:39 the next day.

This is a seperate issue we have regarding events which stretch between two different dates.
We are aware of it but to fix it we have to rewrite how our datastore saves events so we need to write code for migrating from the old format to the new one before being able to fix this. It's planned but we haven't started working on it yet.

@toXel

This comment has been minimized.

Copy link

toXel commented Apr 27, 2018

Are there any updates on this? I'm in UTC+1 timezone with DST so I have to wait two hours before I can see the data in ActivityWatch...

grafik

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Apr 27, 2018

@toXel You seem to have a different issue. As you can see in your picture the afk-events are correct at "now" but your window events are lagging behind. Are you running 0.7 or the master version from git? We are having a performance issue in aw-server which might make the events queue up, it's slightly improved in master but pretty bad in 0.7.

@toXel

This comment has been minimized.

Copy link

toXel commented Apr 27, 2018

@johan-bjareholt I'm running 0.7 on Windows at the moment. But I can switch to master and try it out. Is there already an issue for this bug or should I open a new one?

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Apr 27, 2018

I'm running 0.7 on Windows at the moment. But I can switch to master and try it out. Is there already an issue for this bug or should I open a new one?

@toXel Had to dig a bit but found the issue #94
It is a hassle to run activitywatch from master on windows so I don't believe we have actually ever tested the performance fix there yet actually, if you have the time to see if it is improved it would be great.

@toXel

This comment has been minimized.

Copy link

toXel commented Apr 27, 2018

@johan-bjareholt Is the Windows setup in the docs? Do I need MSYS or Mingw to build it?

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Apr 28, 2018

@toXel You shouldn't need MSYS or MinGW to build it.
The only requirements are git, python3.5 for the watchers+server as well as node for the webui.
If you are not familiar with installing python packages it will be pretty hard, but if you are it is possible to follow the "Installing from source" section in the docs with some modifications for how the tools work for windows (otherwise the steps should be the same). https://activitywatch.readthedocs.io/en/latest/installing-from-source.html

@toXel

This comment has been minimized.

Copy link

toXel commented Apr 28, 2018

@johan-bjareholt But I can't use the Makefile on Windows. So I just have to follow the steps from the Makefiles manually and it should work? I'm familiar with Python and Node so I don't think this will be a problem. But I have to wait till Wednesday cause I only use Linux at home.

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Apr 28, 2018

@toXel Pretty much yeah.
The only thing the Makefiles do is simply "python ./setup.py install" or something equivalent recursively on each package as well as build and copy the webui to aw-server, so it's nothing advanced.

@ErikBjare

This comment has been minimized.

Copy link
Member

ErikBjare commented May 1, 2018

@toXel We use MinGW to build it in the CI for Windows, see here: https://github.com/ActivityWatch/activitywatch/blob/master/.appveyor.yml

@toXel

This comment has been minimized.

Copy link

toXel commented May 8, 2018

So it seems the 0.8.0 beta fixed this problem. Thanks for that! And sorry that I couldn't test master on Windows yet. I just don't have the time for it at the moment.

@ErikBjare

This comment has been minimized.

Copy link
Member

ErikBjare commented May 8, 2018

@toXel Great to hear!

No worries about not testing master on Windows, more importantly: did you test the beta on Windows?

@toXel

This comment has been minimized.

Copy link

toXel commented May 8, 2018

Yes I'm testing on Windows but I think I spoke to early... The problem appears again:
grafik

@toXel

This comment has been minimized.

Copy link

toXel commented May 8, 2018

Little update after using 0.8.0 on Windows for a full work day: it's in the same state as 0.7.1:
grafik

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented May 16, 2018

This might simply be a performance issue of too frequent heartbeats to aw-server. I worked a lot on optimization last week by adding client-side pre-merging of heartbeats (which should be good enough for this issue) but also wrote a new pure-sqlite datastore which can handle much more throughput thanks to utilizing transactions as well as optimized SQL queries for our heartbeat/replace usecase.

Hopefully at least one of these changes should be in the next beta, so let's try again then.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Sep 19, 2018

I'm running directly from source and am seeing this again.

@dufferzafar

This comment has been minimized.

Copy link

dufferzafar commented Sep 19, 2018

No activity for 20th September:

image

But there seems to be raw data for 20th:

image

@Chemrat

This comment has been minimized.

Copy link

Chemrat commented Sep 19, 2018

@dufferzafar probably caused by issue #190
If you have any not-afk events spanning over 0:00 into next day (like on the second screenshot), that activity is filtered out as afk past 0:00

@johan-bjareholt

This comment has been minimized.

Copy link
Member

johan-bjareholt commented Sep 19, 2018

@Chemrat Correct, you can clearly see how the not-afk event spans past the 00:00 mark which makes this fail.
Once the sqlite datastore lands this should be pretty easy to fix.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment