[00:20:41] <mforns>	 nuria, yt?
[00:48:43] <grrrit-wm>	 (PS1) Ottomata: Fix WMF Archiva release repository name and url [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187844 (https://phabricator.wikimedia.org/T88137)
[00:49:35] <grrrit-wm>	 (PS2) Ottomata: Fix WMF Archiva release repository name and url [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187844 (https://phabricator.wikimedia.org/T88137)
[00:49:40] <grrrit-wm>	 (CR) Ottomata: [C: 2 V: 2] Fix WMF Archiva release repository name and url [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187844 (https://phabricator.wikimedia.org/T88137) (owner: Ottomata)
[00:52:44] <grrrit-wm>	 (PS1) Ottomata: Git ignore maven-release-plugin's release.properties file [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187845
[00:52:59] <grrrit-wm>	 (CR) Ottomata: [C: 2 V: 2] Git ignore maven-release-plugin's release.properties file [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187845 (owner: Ottomata)
[01:04:02] <mforns>	 milimetric, yt?
[01:06:04] <milimetric>	 hi mforns
[01:06:11] <mforns>	 hey, just one question
[01:06:36] <mforns>	 is it normal that rolling surviving new active editor reports take a long tima?
[01:06:42] <milimetric>	 your quota with me is unlimited, but feel free to ask just one :)
[01:06:46] <milimetric>	 yes
[01:06:48] <mforns>	 xD
[01:06:50] <mforns>	 ok ok
[01:06:59] <milimetric>	 most of the "rolling" reports take quite a bit
[01:07:05] <milimetric>	 the exception is "rolling new active editor"
[01:07:12] <mforns>	 I see
[01:07:21] <milimetric>	 which filters down the amount of data it looks at by looking at "newly registered" first
[01:07:48] <mforns>	 and...
[01:08:11] <mforns>	 you said that when the puppet agent runs, the reports that are running crash, right?
[01:08:36] <milimetric>	 not sure about that... if it still restarts the queue, then yes
[01:08:56] <milimetric>	 so after running puppet and cleaning all that stuff up, you should do puppet agent --disable or however that works
[01:10:49] <mforns>	 I did some tests in staging with running the agent while executing reports
[01:10:56] <mforns>	 and all reports went fine
[01:11:06] <mforns>	 and the queue did not restart
[01:11:42] <mforns>	 however, I'll leave the agent disabled in production for the weekend
[01:13:13] <milimetric>	 mforns: that sounds reasonable
[01:13:29] <mforns>	 milimetric, ok
[01:15:05] <wikibugs>	 Analytics-Engineering, Analytics-Wikimetrics: Wikimetrics should run latest puppet w/o local changes - https://phabricator.wikimedia.org/T88116#1005768 (mforns) Open>Resolved After some hours of fighting puppet, no code change was needed in puppet repositories, just repository updates. So, now both wiki...
[01:19:42] <milimetric>	 ori / nuria: question about EL timestamps
[01:19:55] <nuria>	 milimetric: yesss
[01:20:07] <nuria>	 mforns: just got back
[01:20:14] <milimetric>	 so what if two events got sent
[01:20:17] <milimetric>	 and you cared about the order
[01:20:30] <milimetric>	 their timestamps wouldn't necessarily be in order right?
[01:20:57] <nuria>	 they got sent from the client in sequrnce?
[01:21:00] <nuria>	 *sequence
[01:21:02] <milimetric>	 yes
[01:21:19] <nuria>	 then if you send a timestamp field they should be in order yes
[01:21:38] <milimetric>	 no, the timestamp is coming from the capsule
[01:21:48] <mforns>	 nuria, np
[01:21:56] <nuria>	 right, but events are not buffered on the client
[01:22:02] <grrrit-wm>	 (PS1) Ottomata: Ignore *.releaseBackup and target in root [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187856
[01:22:20] <mforns>	 maybe the user is using 2 browser tabs simultaneously?
[01:22:24] <milimetric>	 not buffered, no, but sent async, right
[01:22:27] <nuria>	 milimetric: because there is no buffer they get "build" when created
[01:22:37] <nuria>	 but teh "async" does build teh event
[01:22:42] <nuria>	 just sends it
[01:22:50] <milimetric>	 right
[01:23:01] <milimetric>	 so when you go "emit" that's when the timestamp is set
[01:23:02] <milimetric>	 ok
[01:23:17] <nuria>	 milimetric: a bunch of json is build (that contains a tiemestamp) , that is send whenever if sendbeacon is available
[01:23:22] <nuria>	 imediately if it's not
[01:23:29] <nuria>	 yes, when you log
[01:23:42] <milimetric>	 but the "a bunch of json is built" happens synchronously when you call mw.event right?
[01:23:47] <grrrit-wm>	 (CR) Ottomata: [C: 2 V: 2] Ignore *.releaseBackup and target in root [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187856 (owner: Ottomata)
[01:23:49] <nuria>	 milimetric: yes
[01:23:56] <milimetric>	 k, that's worrysome :)
[01:24:17] <nuria>	 milimetric: why? i think taht is the correct behaviour, as we do not buffer
[01:24:33] <milimetric>	 oh sorry, you didn't see the email
[01:24:46] <milimetric>	 I found a bunch (like 1%) of events that are in weird order
[01:24:50] <milimetric>	 like abort then init
[01:24:52] <milimetric>	 or ready then init
[01:25:31] <grrrit-wm>	 (PS1) Ottomata: Update README.md with instructions for release deployment [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187857 (https://phabricator.wikimedia.org/T88137)
[01:25:44] <nuria>	 but that points to events firing on the bad order dan, which i svery possible
[01:26:13] <nuria>	 if init takes 100 ms to notify all its listeners
[01:26:24] <milimetric>	 right, no, totally
[01:26:32] <milimetric>	 and that's what I just replied to Roan with
[01:26:38] <milimetric>	 but that's still worrisome, right?
[01:26:39] <nuria>	 milimetrics: and abort fires right after and takes 5 secs to notify all its listeners
[01:26:46] <nuria>	 abort will will fitre before init
[01:26:55] <nuria>	 abort will *fire before init
[01:27:26] <nuria>	 milimetric: from a product standpoint yes, but not surprising with event driven code
[01:27:36] <milimetric>	 right, I just think it's weird because Roan thinks it's weird (which indicates that it doesn't make sense from what he knows of the instrumentation)
[01:27:41] <nuria>	 probably teh login for all events is happening at event completition
[01:28:16] <milimetric>	 :) this is one of the reasons I don't love event programming
[01:28:35] <nuria>	 milimetric: thus, events might get out of sequence if one of them does something async thus  releasing the thread before completing
[01:29:09] <milimetric>	 yeah, i can totally see how it would happen, again it's just weird because Roan didn't see it and he'd know if he's using async stuff between init and ready
[01:29:39] <milimetric>	 like, if it's like this:
[01:30:20] <milimetric>	 mw.event.log ('init')
[01:30:20] <milimetric>	 // load VE
[01:30:20] <milimetric>	     .done( => mw.event.log ('ready'))
[01:30:24] <milimetric>	 then it wouldn't make sense
[01:30:52] <milimetric>	 but if it's like doAsync (mw.event.log ('init')), then that makes sense
[01:33:02] <nuria>	 w/o looking at the code is hard to say but yes there are many patterns that could lead to that
[01:48:57] <nuria>	 milimetric: do you know where there is their piece of code that is logging events?
[01:50:24] <nuria>	 milimetric: FYI: https://github.com/wikimedia/mediawiki-extensions-EventLogging/blob/master/modules/ext.eventLogging.core.js#L211
[01:51:27] <milimetric>	 nuria: yeah, i was going to look around a bit, but i'm packing for a weekend trip now
[01:51:35] <milimetric>	 i'll look again Sunday
[01:51:36] <nuria>	 milimetric: ok, see you MOnday!
[01:51:39] <milimetric>	 have a nice weekend
[01:54:56] <milimetric>	 nuria: hm... but where's the code that sets the timestamp?
[01:55:17] <nuria>	 it's before when the event get swrapped
[01:55:46] <milimetric>	 I'm looking at prepareEvent, and it looks like it's before that, right?
[01:55:51] <milimetric>	 but ... where?
[02:00:38] <nuria>	 let me see that i did not lied
[02:09:14] <nuria>	 milimetric: a nav timing event: http://localhost:8080/event.gif?{"event":{"isHttps":false,"isAnon":true,"mediaWikiLoadComplete":245,"pageId":1,"namespaceId":0,"revId":1,"action":"view"},"clientValidated":true,"revision":10785754,"schema":"NavigationTiming","webHost":"localhost","wiki":"wiki"};
[02:09:34] <nuria>	 argh , wait...
[02:09:37] <milimetric>	 :)
[02:09:38] <milimetric>	 right
[02:09:39] <milimetric>	 no timestamp
[02:09:46] <milimetric>	 so it's happening on the ... server?!
[02:10:13] <nuria>	 ah yes, it's happening by the consumer that does the de-code of the url
[02:12:03] <milimetric>	 ok, i'll reply to the thread
[02:12:37] <nuria>	 milimetric: i was just doing that
[02:12:46] <milimetric>	 nuria: go ahead then, no problem
[02:12:53] <nuria>	 milimetric: let me send a link to the code
[02:13:43] <milimetric>	 i was just gonna say "our fault" and that I will re-order these events as we would expect to see them
[02:19:01] <nuria>	 milimetric: https://github.com/wikimedia/mediawiki-extensions-EventLogging/blob/master/server/eventlogging/parse.py
[02:19:08] <nuria>	 milimetric: no, it changes nothing
[02:19:21] <nuria>	 they got to varnish at different times
[02:19:25] <nuria>	 it's teh same issue
[02:19:33] <nuria>	 milimetric: no fault
[02:20:36] <nuria>	 milimetric: please do bot correct the events
[02:21:23] <milimetric>	 nuria: wait huh?
[02:21:40] <milimetric>	 these sessions would be discarded then
[02:21:43] <nuria>	 milimetric: there is no errror those events were posted out of sequence
[02:22:06] <nuria>	 milimetric: we can discard the data as incorrect
[02:22:22] <milimetric>	 but... it's not incorrect, it's just a flaw in the logging
[02:22:22] <nuria>	 milimetric: i was just saying that the order you see is what the client sent
[02:22:31] <nuria>	 milimetric: no, it's a flaw in the client
[02:22:42] <milimetric>	 no, it's not the order the client sent
[02:22:51] <milimetric>	 it's the order the server saw, which could be different
[02:23:03] <nuria>	 milimetric: with mno buffering client side, how?
[02:23:16] <milimetric>	 like, network lag
[02:23:21] <milimetric>	 they're separate messages
[02:23:30] <milimetric>	 separate HTTP round-trips
[02:24:36] <nuria>	 yes, network could cause it.
[02:25:24] <nuria>	 but if that is teh case it should be VERY rare
[02:25:33] <nuria>	 *the
[02:25:44] <milimetric>	 it's not that rare, it looks like less than 1% but that's not rare
[02:26:20] <nuria>	 with a desktop connection and same messages sizes i very much doubt 1% of your petitions will be out of order
[02:26:27] <nuria>	 in mobile it's nother deal
[02:26:30] <nuria>	 *another
[02:26:53] <nuria>	 milimetric: that s a hard sale on desktop
[02:27:16] <milimetric>	 :) yea, but it seems to me like these events are quite fine otherwise
[02:27:21] <milimetric>	 so no harm re-ordering them
[02:27:28] <nuria>	 milimetric: possible but unlikely i think, but , of coourse we can quantify that
[02:27:29] <milimetric>	 well, except it happens to be kind of tricky to do in sql
[02:28:34] <milimetric>	 but it's not just network lag though
[02:28:48] <milimetric>	 it's lag through our hole pipeline up to the event processor
[02:29:04] <milimetric>	 which could be substantial (VCL, etc)
[02:29:10] <milimetric>	 *whole pipeline
[02:30:23] <nuria>	 how so, events received on event.gif are timestamped by varnish
[02:30:26] <nuria>	 right away
[02:30:51] <nuria>	 milimetric:what other lag do you see?
[02:31:06] <milimetric>	 oh the parser is parsing the varnish timestamp?
[02:31:13] <nuria>	 milimetric: yes
[02:31:47] <nuria>	 milimetric: varnish wraps with info when it logs to varnishncsa
[02:31:49] <milimetric>	 oh i see
[02:31:55] <milimetric>	 i just read the code you pasted
[02:32:08] <milimetric>	 that makes sense, so it should be fairly rare
[02:32:18] <nuria>	 that is why i was saying
[02:32:22] <milimetric>	 hm... but it's still 1%, so there could be some client side stuff happening here too
[02:32:24] <nuria>	 1% seems too much
[02:32:25] <milimetric>	 it could be both
[02:32:41] <milimetric>	 ok, happy with this for now, i'm going away now
[02:32:45] <milimetric>	 have a nice night
[02:33:10] <nuria>	 milimetric: ciao!
[10:46:53] <rtnpro>	 YuviPanda, Hi
[10:47:01] <rtnpro>	 YuviPanda, what's up?
[14:26:40] <grrrit-wm>	 (PS1) QChris: Drop red herings from documentation of Geocoding UDFs [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187906
[14:28:12] <grrrit-wm>	 (PS2) QChris: Drop red herings from documentation of Geocoding UDFs [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187906
[14:30:20] <grrrit-wm>	 (CR) QChris: Drop red herings from documentation of Geocoding UDFs (1 comment) [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187906 (owner: QChris)
[15:30:43] <grrrit-wm>	 (CR) QChris: [C: 2 V: 2] "\o/" [analytics/refinery/source] - https://gerrit.wikimedia.org/r/187857 (https://phabricator.wikimedia.org/T88137) (owner: Ottomata)
[16:06:16] <wikibugs>	 Analytics-Engineering, Analytics-Cluster: Streamline analytics/refinery/source release and deployment process - https://phabricator.wikimedia.org/T88137#1006296 (Ottomata) Open>Resolved