[00:04:19] awight: Let me test! [00:07:24] awight: So... two things. [00:07:40] #1 - The payment seems to have worked. [00:07:58] #2 - Did we break syslog today. [00:08:26] Jeff_Green: ^^ [00:09:30] Okay, this is... mildly exciting. [00:10:48] K4-713: urm, I see *no* logs. [00:10:53] lemme restart tail-f [00:11:39] K4-713: grep worldpay payments-initial payments.error -> nothing [00:11:42] what's happening here? [00:11:52] The last timestamp I'm seeing is GC 1t 17:19:38 UTC. [00:12:02] Were you tailing anything when you did the deploy? [00:12:06] No movement at all? [00:12:42] no. rollback... [00:13:00] that is not a timestamp, actually [00:13:20] current time os Tue Oct 21 00:13:08 UTC 2014 [00:13:25] is [00:13:55] I know. I was reading the last ts from the logs. [00:14:07] K4-713: fyi I might have to run after a devious imp any second [00:14:10] seven hours ago, apparently. [00:14:18] Yeah... that 's not good [00:14:18] I just texted Jeff. [00:14:23] thx [00:14:36] I don't even know if I bother with rollback, now [00:14:45] Rollback? Why rollback? [00:15:01] I just did a payment that went through. [00:15:01] K4-713: well I have no idea if the deployment broke anything. [00:15:05] har. [00:15:14] Yeah, well... let's hold here for a minute. [00:15:16] I'll leave it, if you want to take my deadman switch [00:15:26] btw, ls -ltr that logs dir [00:15:35] just did [00:15:51] All going to misc, apparently? [00:15:58] fffffff [00:16:08] no [00:16:13] misc is moving. [00:16:45] I have to make my "ABCD" less interesting to Mari [00:16:53] sorry, I'll occasionally look here [00:26:20] 7 hours ago is way before the deployment [00:28:57] hehe, I'd be satisfied of nonculpability by "any amount of time more than say a minute" before deployment [00:29:20] har har [00:30:12] sort of creepy that it's almost UTC-PDT, aye? [00:30:25] just a grand coiindidence, tho [00:33:31] I have a suspicious-looking puppet change email from 7 hours ago, in which Jeff "cleans up" the bucketing. [00:33:39] awight RIGHT?! [00:33:44] 10:10 AM our time. [00:34:12] Actually, it says "straighten out log rotation snafu on payments". [00:34:17] ok then. gun smoking :p [00:34:21] mhm [00:34:46] K4-713: you found your data in payments-misc? [00:34:51] Sadly, no. [00:34:53] Just paypal. [00:34:58] ...unless it's also GC. [00:35:01] right. ok then [00:35:08] I grepped worldpay -> fail [00:35:18] just did that too [00:42:20] buckets of fail [00:42:26] Ohai. [00:42:37] hey. so I broke logging eh? [00:42:40] Yep! [00:42:45] But not completely, so that's confusing. [00:42:49] hooray! [00:42:50] Just all the ones I usually look at. [00:42:52] i have theories [00:42:55] right [00:43:04] you're looking on indium right? [00:43:11] Yes. [00:43:12] I have a totally halfassed theory too. [00:43:33] Not that your theories are halfassed. I just have that. [00:43:36] its the new rules I put on the payments boxes, I forgot they would preempt the rule that sends to the central logger [00:43:45] ha [00:43:45] oooh [00:44:11] ah. [00:44:23] good luck team... i've got to run [00:44:28] hasta mañana [00:44:38] Also, if you upgrade rsyslog passed a particular point, ampersands start breaking everything. [00:44:50] oh yes, I've seen that [00:45:28] hmm. my theory just failed [00:45:35] hurm [00:45:40] That's depressing. [00:47:04] appears to be all ending up in /var/log/syslog on the payments servers [00:47:33] That sort of sounds like it's completely choking on the config and not saying anything. [00:47:47] it does, but it doesn't error on reload [00:48:02] ... [00:48:09] That makes no sense. Awesome. [00:49:08] Huh. I just got something potentially interesting in the payments.error log. [00:49:30] From rsyslogd. [00:49:45] what? [00:49:54] Could not open output pipe '/dev/xconsole' [try http://www.rsyslog.com/e/2039 ] [00:49:59] p1001 [00:50:01] ah that's a red herring [00:50:06] I hate those. [00:50:07] it's stupid stock syslog config [00:50:22] it's complaining that it can't log to root console [00:50:30] Oh. Well, yes. [00:50:31] lemme revert the change from today for starters [00:56:07] oh hey, something moved. [00:56:50] Definitely moving again. [00:57:06] good [00:57:43] Jeff_Green: Are we back to stable until tomorrow, or is there more to do now? [00:57:53] we're fully reverted [00:58:07] now I just scratch my head over wtf [00:58:19] okay, neat. [00:58:35] Sorry about the late pings. [00:58:38] i can see why it would have stopped sending logs to the central logger, but I don't see yet why it didn't at least collect locally [00:58:44] oh no problem, sorry for the snafu [01:04:14] awight|not: Let me know if you spontaneously are. At some point. [01:06:54] K4-713: here. looking for backscroll [01:07:18] awight|not: Yay. I'm looking for info about the configuration globals... [01:07:28] looking at the syslog config, i think the old config was misguided and the botched config from today was also misguided [01:07:31] oh. Should be set already, look in LocalSettings [01:07:37] /Snowflake [01:07:58] Er. [01:08:00] Is this... [01:08:09] this is the payments LocalSettings on boron [01:08:15] Is this PS1? [01:08:28] There should be another global. [01:10:04] I don't see another global. [01:10:07] what would it be? [01:10:10] Or, I just had a beautiful dream about another global. :/ [01:10:12] * awight|not looks at gerrit again [01:10:23] So, we actually don't want to assign zero points for cvv. [01:10:25] if yr payment worked... [01:10:27] oh right [01:10:28] ok, I will test/fix syslog fixes tomorrow [01:10:28] We want to assign, like, 80. [01:10:30] ciao [01:10:34] I don't think ejegg|away has done that yet. [01:10:35] Jeff_Green: Thanks! [01:10:49] fwiw i think we've been eating a large percentage of logs [01:11:01] * K4-713 frowns [01:11:03] but why, is a mystery [01:11:06] I'm not... sure I know what that means. [01:11:11] But, okay. :) [01:11:11] not like sporadically, programmatically [01:11:27] Huh. [01:11:30] there were three filters on the payments systems that preempt the central logger rule [01:11:36] rsyslog config > /dev/null... [01:11:38] those three filters were supposed to write to local files [01:11:46] but they don't seem to have been doing that [01:11:50] What would have gone in there? [01:11:54] and they were end rules, so what they matched they ate [01:11:58] sec [01:12:15] * K4-713 grits teeth [01:12:19] if $programname == 'payflowpro_gateway' and $syslogseverity == 7 then <%= @log_dir %>/payflow.debug [01:12:19] & ~ [01:12:19] if $programname == 'payflowpro_gateway' and $syslogseverity != 7 then <%= @log_dir %>/payflow [01:12:19] & ~ [01:12:19] if $programname == 'payflowpro_gateway_trxn' then <%= @log_dir %>/minfraud [01:12:20] & ~ [01:12:28] all payflowpro related [01:12:30] Oh, fuff. [01:12:35] Nobody cares about them anymore. [01:12:40] perfect :-) [01:13:00] tomorrow I'll redo the rules with sane behavior [01:13:04] okbye for real [01:13:06] I like sanity. [01:13:08] Bye! [01:13:26] hurrrrrrrOkay. [01:13:38] awight|not: I'm going to do something else with the antifraud rules for now. [01:13:44] I think... this will work. [01:13:45] O_o [01:13:48] >_> [01:13:49] <)< [01:13:51] woak [01:13:53] AGH [01:13:56] something like... take home on a kindle? [01:14:02] bifurcated. [01:14:17] No... I'll just add penalties in other places temporarily. [01:14:22] heh [01:14:30] Because... we kind of have to before I go home. [01:14:35] This is live. [01:16:11] oh god: rsyslogd-2039: Could not open output pipe '/dev/xconsole' [try http://www.rsyslog.com/e/2039 ] [01:16:28] ok i guess sanity arrived after that [01:16:41] awight|not: That's a red herring. [01:16:48] ...is what Jeff said. [01:16:57] yep, i'm catching up 8) [01:17:11] excuse me while I mutter everything that's been said already [01:18:31] GAH. I'm... really annoyed with myself from twoish years ago right now. [01:19:01] just... don't break up your teenage parents... [01:22:22] At the Enchantment Under The Sea Dance? [01:22:30] Yeah, I try to stay away from there. [01:22:47] (Not really. I'd totally go. That looks *fantastic*) [01:23:17] whoa. /me wonders whether this a movie or parental actual first date. [01:23:27] What, really? [01:23:30] Fired. [01:23:45] :) more time to study pop culture, then [01:25:09] my only reference is Heinlen's "by his bootstraps", derivatives are a blur [01:25:37] * awight|not squirms on moral high ground [01:26:15] Should I book collab for the movie night now, or wait until after we really launch WP? [01:26:21] I'm really behind... [01:26:33] it will have to be a movie month or something... [01:27:04] See, there were those years I threw away on books... like $15 movie tix never happened :x [01:28:15] K4-713: so... WP FR payment worked! U have time to check on logs again, or that it arrived in Civi? [01:28:30] I'm fraudfiltering. [01:28:38] Everything else has been verified as proper. [01:28:43] But don't tell anybody yet. [01:29:18] * awight|not puts on Tuxedo and tries to act normal. [01:30:05] for my information, this process you're doing... you're turning up the other fraud knobs until smaller things fail us? Or will this require a patch, to not kill CVV score? [01:30:16] Yes on both counts. [01:30:22] ok then. i can CR [01:30:35] a bit asynchronously, please SMS if you want low latency. [01:30:46] It's not an either/or situation. I just want to give them something tonight and also go home without worrying about all the fraud coming through the snowflake. [01:30:56] ...which might be the oddest thing I'd ever lose sleep over, but... [01:31:16] I require no more kickball this evening. :) [01:31:51] nvc nnnnnnnn [01:31:52] !log adjusted fraud filters on payments [01:32:01] Logged the message, Master [01:32:07] Mari just showed me that creates new windows in tmux [01:32:08] ...Is that the kid? [01:32:12] haha [01:32:16] 3b2hhnbxx [01:32:24] Really? Tell me more. [01:32:26] xxxxI'bgm on dutty [01:32:34] nbnnbnnnbnb [01:32:41] nbbnnnbnbnnbb [01:32:48] Ah! I always sort of suspected, but this is the first confirmation. [01:32:59] n mrrgh she killed the music [01:33:22] ,, mdccccccccc [01:33:31] Okay... uno mas. Must make sure fraudy things are coming through as expected... [01:33:38] , b b; q1`1111111111111111111111 [01:33:45] ZAZAmjjjjjfn [01:33:47] Oh, right. I forgot. [01:33:55] ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffnnnnnnnnnnnnnnnnnn [01:34:04] That, I already took care of. [01:34:04] nfnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnnn [01:34:24] nnnnfnjbbbbbbbbbbbbbbsde444444444444444444444444444444444444444444444444444444444444444444444444444444444444444445555555555555 [01:34:29] wq1`` [01:35:10] usuAlly, trhis ends in a lid clsoiung [01:35:18] 18:32 <+K4-713> haha [01:35:19] 18:32 < awight|not> 3b2hhnbxx [01:35:19] 18:32 <+K4-713> Really? Tell me more. [01:35:36] Uh-oh. Reality is starting to recurse. [01:35:39] 979777777 [01:35:40] Everybody grab on to something. [01:35:58] I don't know how long we have until we hit the base case. [01:36:19] who needs automated chaos monkeys anyway [01:36:29] We totally have that covered. :) [01:42:25] We like to fuzz-test the coworkers... [01:42:39] * K4-713 chokes [01:43:12] sort of... hypobole... [01:45:55] You know, I was going to tweak these settings more, but I think the first dart I threw is just fine. [01:46:20] woot! [01:46:57] Ooooh now I remember what I wanted to ask before everyone went home [01:47:05] TOO LATE. [01:47:07] ...just kidding. [01:47:18] I don't go home anymore. [01:47:55] :( [01:48:10] It was about that emergency card... [01:48:25] The suspiciously low banner impressions... [01:49:10] https://wikimedia.mingle.thoughtworks.com/projects/online_fundraiser/cards/2066 [01:49:18] * awight|multimonk tunes in [01:49:20] Oh man, look at the time. [01:49:25] :| [01:49:31] Yeah I mean what are you guys still doing there? [01:49:47] awight|multimonk never got all the way in today. [01:49:51] I have no excuse. [01:50:11] K don't mind me, we can figure it out tomorrow :) [01:50:46] the guess in the card looks right. [01:50:55] we can't assume that the parameters are in any particular order. [01:51:05] but I believe the log grep does just that. [01:51:24] I haven't seen the hard data [01:51:46] So I have no idea where to start other than re-reviewing the changes in bannerController that went out on Thursday [01:52:22] What is the pgehres.bannerimpressions table? Is that the same thing that Ellery uses with the Python script? [01:53:15] I can also reply to Anne's e-mail if it's easier to talk about it unsynchronized... [01:54:03] I think ellery's script circumvents the db [01:54:18] there are raw log files on a machine... u probably don't have access to at this moment. [01:54:21] Didn't it pull stuff from a DB? [01:54:34] I thought it was from hadoop? [01:55:02] Ah well that was his more modern move, no? I mean, there's a python script in fundraising tools that we were talking about last week [01:55:04] the script that writes to the drupal db is a really crufty thing [01:55:35] but also, I think the problem is upstream of this, in the udplog grep to filter out RecordImpression stuffs [01:55:37] Mmmm I'm not even fully aware where drupal fits in, tho I think I did hear it mentioned some time ago [01:55:53] u don't want to know... [01:55:55] (Or maybe it was recently and I'm remembering wrong?) [01:57:20] this card is annoyingly lacking in details such as what the expected numbers were [01:58:24] Yeah I did kinda want to know when, where, why, what, how... [01:59:21] To see how severe the difference is, and maybe find some pattern that would point to a cause [01:59:46] Do we know where the drop off is in relation to our CN deploy? [02:03:47] AndyRussG: wrote a snarky email asking for original problem report [02:05:24] oh... but wait, wasn't snarkiness outlawed a month or so ago? [02:05:38] I'm telling. [02:06:06] awight|multimonk: thanks BTW :) [02:06:20] * awight|multimonk double-checks whether my intention can be interpreted as anything but snark. nope [02:07:20] * AndyRussG pretends attempts some snark but it's just too much for his tired old brain today [02:09:07] Thanks all :) [02:09:08] bllbbb gonna rescue a bike [02:09:16] from rusting in the rain [02:09:30] hehe that's what I call it when I cut through the... eherm [02:09:30] If you can't rust it, don't trust it. [02:11:08] that is surprisingly solid advice [02:11:10] because of confusion with regard to cars and rides on Sunday my daughter's bike got left outside tied to a post a few blocks from here [02:11:34] solid unless it rusts and crumbles, but in that case you should trust it, so it's a version of the liar's paradox [12:48:23] Morning ejegg and the-wub :) [12:48:47] morning AndyRussG [12:49:13] How's it going? [12:49:46] alright. I'm busy working on some new banners mainly [12:50:05] Ah... sounds like fun [12:50:30] it really isn't :( [12:52:02] Oh... hmmm... that's too bad :/ [16:14:30] Morning K4-713 :) [16:14:45] Good morning, AndyRussG. [16:15:10] Adam found the banner impressions issue! https://wikimedia.mingle.thoughtworks.com/projects/online_fundraiser/cards/2066 [16:16:39] now we just have to fix it... [16:16:51] Ah, I think this diagnosis makes sense, yeah. [16:17:45] On enwiki right now I'm getting an order of URL parameters that would not be included in that filter [16:18:07] What would reorder those params, though? [16:18:16] Well they're not really ordered per se [16:18:22] It's weird that this has stood for so long, and it is only breaking now, though. [16:18:27] They come from a Javascript object [16:18:59] Object properties are not supposed to be ordered, but they often just happen to be [16:19:09] One of the patches deployed was a bit of cleanup that changed the order that the properties go in [16:19:19] Ah, there it is. :) [16:19:41] Well, I definitely agree that this should be more flexible anyway. [16:19:49] https://gerrit.wikimedia.org/r/#/c/166138/ [16:20:01] Also, now that you're getting in to banner impressions... [16:20:06] Mmmm? [16:20:24] There's something else we want to do there. [16:20:33] Ah OK [16:20:36] BTW this may have already been an issue for some browsers [16:20:49] Yeah, I figured. Just not, like... all of them. [16:20:51] Due to the unreliability of object property ordering [16:20:59] Anyway: Analytics has a new way to get impressions. [16:21:01] https://code.google.com/p/v8/issues/detail?id=164 [16:21:05] Ah right! [16:21:33] We want to not torpedo anything anytime soon, so we have something to fall back to. [16:21:33] Is that now full-on usable? [16:22:01] But, it would be neat to do the work to get their data into our systems. [16:22:22] * AndyRussG unarms the topedos [16:23:19] Full speed ahead! [16:23:19] To get the data from Hive into... other Fundraising systems? [16:23:36] * K4-713 coughs [16:24:02] Something happened to warp drive? [16:24:28] * AndyRussG offers cough drops [16:24:34] So, the new data is probably just going to be another database right alongside the other ones we have. [16:24:44] OK [16:25:02] The hard part is probably going to be importing their data. [16:25:13] I suppose we also have to decide how we want their data. [16:25:21] What do we want from the data? [16:25:48] Oh, impression counts for different banners, possibly aggregated into time slices of [n] seconds... [16:26:29] Ideally, everything that's in the current banner imp database, would still be available. [16:27:06] But, it'll be... oh man, g2g. Tailing logs. :)_ [16:27:25] Worldpay test that might actually work. [16:29:59] Much better than non-existent bannerController tests... (g2g = got to go?) Pls let me know NEtime you want to tell me more about impressions data stuff [16:40:31] !log adjusted payments fraud filters for WP test [16:40:38] Logged the message, Master [16:42:22] It's working, you guys. [16:50:37] mingle is wonderful [16:59:03] Funny story: I am personally getting two emails per donation from Worldpay right now. [16:59:13] INBOXPOCALYPSE. [16:59:24] Hmmm [16:59:38] 562 unread. [16:59:39] Matching e-mails instead of matching donations? [16:59:48] bahaha [17:00:08] Dear Worldpay: My inbox is foaming. [17:00:19] Have I done something to offend you? [17:03:23] I guess Worldpay acheived consciousness [17:05:57] Somebody. :) [17:36:20] (PS2) Ori.livneh: Show a friendly error page when requested banner does not exist [extensions/CentralNotice] - https://gerrit.wikimedia.org/r/157484 (https://bugzilla.wikimedia.org/54180) [17:37:19] (CR) Ori.livneh: [C: 2] Show a friendly error page when requested banner does not exist [extensions/CentralNotice] - https://gerrit.wikimedia.org/r/157484 (https://bugzilla.wikimedia.org/54180) (owner: Ori.livneh) [17:37:34] (Merged) jenkins-bot: Show a friendly error page when requested banner does not exist [extensions/CentralNotice] - https://gerrit.wikimedia.org/r/157484 (https://bugzilla.wikimedia.org/54180) (owner: Ori.livneh) [17:42:46] K4-713: https://git.wikimedia.org/blob/operations%2Fpuppet/2b028c108fc3deaddd9e34620ad55ac08ab17ebd/templates%2Fudp2log%2Ffilters.erbium.erb This stuff is Jeff Green's department? Should I bug him, or someone else, just ask for more info on #wp-operations? [17:45:22] Oh I see he is indeed here (didn't see the "voiced" part of the IRC users thing) [17:45:32] Jeff_Green: :) [17:45:53] whut [17:47:18] Hi! [17:47:27] Uh one sec [17:47:42] We have an issue here in this file: [17:47:42] https://git.wikimedia.org/blob/operations%2Fpuppet/2b028c108fc3deaddd9e34620ad55ac08ab17ebd/templates%2Fudp2log%2Ffilters.erbium.erb [17:48:02] Is this something you deal with? Here is the Mingle card: [17:48:02] https://wikimedia.mingle.thoughtworks.com/projects/online_fundraiser/cards/2066 [17:49:17] It's the filter for banner impressions which is relying on a specific order of URL parameters. Used to be somewhat reliable, but following a deploy last week the typical order changed [17:49:32] i see [17:49:45] is there a proposed regex? [17:49:52] As you can see in the card, Adam is wary of changing the filter [17:49:52] or is that what I'm supposed to come up with? [17:50:06] yeah, understandable [17:50:11] Mmm neither, I'm just trying to get more information, first of all about Adam's concerns [17:50:19] This is a part of the infrastructure that I don't know much about [17:51:02] Making the filter guaranteed to work by hacking around the JS that sends the request would be very hacky [17:51:20] It seems likely that in fact it didn't work 100% before, also [17:51:21] i don't know very much about udp-filter [17:51:50] i mean if someone tells me "it uses PCRE" I could probably come up with a regex that's less picky about order given some time [17:51:55] but I don't know if that's true [17:52:27] also the more complex the regex, the more likely the filter destroys the machine it runs on [17:52:42] OK... I see on the git history a change by andrewbogott, I see him on #wm-operations [17:52:57] ya he probably knows more about udp-filter [17:53:02] Ah hmm that does sound dangerous [17:53:21] yeah, these regexes are hit very hard [17:53:54] Hmm [17:53:58] Quoting Adam: " the initial param in the grep expression was hiding some kind of data which is incompatible with the mayonnaise-based banner impression loader, and will heat up when we send more interesting URL params" [17:55:19] can you think of any other... er... interpretations? [17:55:22] which filter line are we talking about? [17:55:28] in https://git.wikimedia.org/blob/operations%2Fpuppet/2b028c108fc3deaddd9e34620ad55ac08ab17ebd/templates%2Fudp2log%2Ffilters.erbium.erb [17:55:51] Line 13 [17:56:35] I wonder why we have to filter for a URL param at all, I guess it's just to get rid of false hits [17:58:19] because otherwise you'd just collect 1% of all hits, not hits you're interested in [17:58:37] so you'd fill disk with irrelevant logs [17:59:02] honestly I'm not sure what Adam is sayin ghtere [17:59:11] Hmm [17:59:35] maybe "the regex is there to filter away irrelevant hits that cruft up the fundraising stats" [17:59:52] "because the fundraising stats processor is stupid" [18:00:06] so fixes could be: [18:00:07] OK, yeah I imagine Special:RecordImpression doesn't get many hits elsewhere, but I don't really know much [18:00:29] 1) make a smarter filter regex (with risks of overloading the host the filter runs on) [18:00:54] 2) make the banner stats processor smarter, capable of filtering away irrelevant logs [18:01:09] 3) add an intermediary step [18:01:48] How could we test option 1? [18:02:24] i think you can feed udp-filter a stream of logs i.e. from a saved file [18:03:05] I think we could grab some sample logs from the unfiltered sample set, and see that it classifies them correctly [18:03:21]