On Aug 28, 2014, at 2:15 PM, Sean Dague <s...@dague.net> wrote:

> On 08/28/2014 01:48 PM, Doug Hellmann wrote:
>> On Aug 28, 2014, at 1:17 PM, Sean Dague <s...@dague.net> wrote:
>>> On 08/28/2014 12:48 PM, Doug Hellmann wrote:
>>>> On Aug 27, 2014, at 5:56 PM, Sean Dague <s...@dague.net> wrote:
>>>>> On 08/27/2014 05:27 PM, Doug Hellmann wrote:
>>>>>> On Aug 27, 2014, at 2:54 PM, Sean Dague <s...@dague.net> wrote:
>>>>>>> Note: thread intentionally broken, this is really a different topic.
>>>>>>> On 08/27/2014 02:30 PM, Doug Hellmann wrote:>
>>>>>>>> On Aug 27, 2014, at 1:30 PM, Chris Dent <chd...@redhat.com> wrote:
>>>>>>>>> On Wed, 27 Aug 2014, Doug Hellmann wrote:
>>>>>>>>>> I have found it immensely helpful, for example, to have a written set
>>>>>>>>>> of the steps involved in creating a new library, from importing the
>>>>>>>>>> git repo all the way through to making it available to other 
>>>>>>>>>> projects.
>>>>>>>>>> Without those instructions, it would have been much harder to split 
>>>>>>>>>> up
>>>>>>>>>> the work. The team would have had to train each other by word of
>>>>>>>>>> mouth, and we would have had constant issues with inconsistent
>>>>>>>>>> approaches triggering different failures. The time we spent building
>>>>>>>>>> and verifying the instructions has paid off to the extent that we 
>>>>>>>>>> even
>>>>>>>>>> had one developer not on the core team handle a graduation for us.
>>>>>>>>> +many more for the relatively simple act of just writing stuff down
>>>>>>>> "Write it down.” is my theme for Kilo.
>>>>>>> I definitely get the sentiment. "Write it down" is also hard when you
>>>>>>> are talking about things that do change around quite a bit. OpenStack as
>>>>>>> a whole sees 250 - 500 changes a week, so the interaction pattern moves
>>>>>>> around enough that it's really easy to have *very* stale information
>>>>>>> written down. Stale information is even more dangerous than no
>>>>>>> information some times, as it takes people down very wrong paths.
>>>>>>> I think we break down on communication when we get into a conversation
>>>>>>> of "I want to learn gate debugging" because I don't quite know what that
>>>>>>> means, or where the starting point of understanding is. So those
>>>>>>> intentions are well meaning, but tend to stall. The reality was there
>>>>>>> was no road map for those of us that dive in, it's just understanding
>>>>>>> how OpenStack holds together as a whole and where some of the high risk
>>>>>>> parts are. And a lot of that comes with days staring at code and logs
>>>>>>> until patterns emerge.
>>>>>>> Maybe if we can get smaller more targeted questions, we can help folks
>>>>>>> better? I'm personally a big fan of answering the targeted questions
>>>>>>> because then I also know that the time spent exposing that information
>>>>>>> was directly useful.
>>>>>>> I'm more than happy to mentor folks. But I just end up finding the "I
>>>>>>> want to learn" at the generic level something that's hard to grasp onto
>>>>>>> or figure out how we turn it into action. I'd love to hear more ideas
>>>>>>> from folks about ways we might do that better.
>>>>>> You and a few others have developed an expertise in this important 
>>>>>> skill. I am so far away from that level of expertise that I don’t know 
>>>>>> the questions to ask. More often than not I start with the console log, 
>>>>>> find something that looks significant, spend an hour or so tracking it 
>>>>>> down, and then have someone tell me that it is a red herring and the 
>>>>>> issue is really some other thing that they figured out very quickly by 
>>>>>> looking at a file I never got to.
>>>>>> I guess what I’m looking for is some help with the patterns. What made 
>>>>>> you think to look in one log file versus another? Some of these jobs 
>>>>>> save a zillion little files, which ones are actually useful? What tools 
>>>>>> are you using to correlate log entries across all of those files? Are 
>>>>>> you doing it by hand? Is logstash useful for that, or is that more 
>>>>>> useful for finding multiple occurrences of the same issue?
>>>>>> I realize there’s not a way to write a how-to that will live forever. 
>>>>>> Maybe one way to deal with that is to write up the research done on bugs 
>>>>>> soon after they are solved, and publish that to the mailing list. Even 
>>>>>> the retrospective view is useful because we can all learn from it 
>>>>>> without having to live through it. The mailing list is a fairly 
>>>>>> ephemeral medium, and something very old in the archives is understood 
>>>>>> to have a good chance of being out of date so we don’t have to keep 
>>>>>> adding disclaimers.
>>>>> Sure. Matt's actually working up a blog post describing the thing he
>>>>> nailed earlier in the week.
>>>> Yes, I appreciate that both of you are responding to my questions. :-)
>>>> I have some more specific questions/comments below. Please take all of 
>>>> this in the spirit of trying to make this process easier by pointing out 
>>>> where I’ve found it hard, and not just me complaining. I’d like to work on 
>>>> fixing any of these things that can be fixed, by writing or reviewing 
>>>> patches for early in kilo.
>>>>> Here is my off the cuff set of guidelines:
>>>>> #1 - is it a test failure or a setup failure
>>>>> This should be pretty easy to figure out. Test failures come at the end
>>>>> of console log and say that tests failed (after you see a bunch of
>>>>> passing tempest tests).
>>>>> Always start at *the end* of files and work backwards.
>>>> That’s interesting because in my case I saw a lot of failures after the 
>>>> initial “real” problem. So I usually read the logs like C compiler output: 
>>>> Assume the first error is real, and the others might have been caused by 
>>>> that one. Do you work from the bottom up to a point where you don’t see 
>>>> any more errors instead of reading top down?
>>> Bottom up to get to problems, then figure out if it's in a subprocess so
>>> the problems could exist for a while. That being said, not all tools do
>>> useful things like actually error when they fail (I'm looking at you
>>> yum....) so there are always edge cases here.
>>>>> #2 - if it's a test failure, what API call was unsuccessful.
>>>>> Start with looking at the API logs for the service at the top level, and
>>>>> see if there is a simple traceback at the right timestamp. If not,
>>>>> figure out what that API call was calling out to, again look at the
>>>>> simple cases assuming failures will create ERRORS or TRACES (though they
>>>>> often don't).
>>>> In my case, a neutron call failed. Most of the other services seem to have 
>>>> a *-api.log file, but neutron doesn’t. It took a little while to find the 
>>>> API-related messages in screen-q-svc.txt (I’m glad I’ve been around long 
>>>> enough to know it used to be called “quantum”). I get that screen-n-*.txt 
>>>> would collide with nova. Is it necessary to abbreviate those filenames at 
>>>> all?
>>> Yeh... service naming could definitely be better, especially with
>>> neutron. There are implications for long names in screen, but maybe we
>>> just get over it as we already have too many tabs to be in one page in
>>> the console anymore anyway.
>>>>> Hints on the service log order you should go after are on the footer
>>>>> over every log page -
>>>>> http://logs.openstack.org/76/79776/15/gate/gate-tempest-dsvm-full/700ee7e/logs/
>>>>> (it's included as an Apache footer) for some services. It's been there
>>>>> for about 18 months, I think people are fully blind to it at this point.
>>>> Where would I go to edit that footer to add information about the neutron 
>>>> log files? Is that Apache footer defined in an infra repo?
>>> Note the following at the end of the footer output:
>>> About this Help
>>> This help file is part of the openstack-infra/config project, and can be
>>> found at modules/openstack_project/files/logs/help/tempest_logs.html .
>>> The file can be updated via the standard OpenStack Gerrit Review process.
>> /me smacks forehead
> :)
> Also note an early version of this base email is at the top level for
> all runs - (i.e. -
> http://logs.openstack.org/76/79776/15/gate/gate-tempest-dsvm-full/700ee7e/)
> It's been there about 18 months. People look right past it. Which is
> part of where my skepticism on just writing things down being the
> solution. Because a bunch of it has been written down. But until people
> are in a mode of pulling the information in, pushing it out doesn't help.

Fair enough.

>>>> Another specific issue I’ve seen is a message that says something to the 
>>>> effect “the setup for this job failed, check the appropriate log”. I found 
>>>> 2 files with “setup” in the name, but the failure was actually logged in a 
>>>> different file (devstacklog.txt). Is the job definition too far “removed” 
>>>> from the scripts to know what the real filename is? Is it running scripts 
>>>> that log to multiple files during the setup phase, and so it doesn’t know 
>>>> which to refer me to? Or maybe I overlooked a message about when logging 
>>>> to a specific file started.
>>> Part of the issue here is that devstack-gate runs a lot of different
>>> gate_hooks. So that's about as specific as we can get unless you can
>>> figure out how to introspect that info in bash... which I couldn’t.
>> Are all of the hooks logging to the same file? If not, why not? Would it 
>> make sense to change that so the error messages could be more specific?
> They are not, output direction is actually typically a function of the
> hook script and not devstack gate.
> Some of this is because the tools when run locally need to be able to
> natively support logging. Some of this is because processing logs into
> elastic search requires that we know we understand the log format (a
> generic gate_hook log wouldn't work well there). Some of it is historical.

OK, that makes sense.

> I did spend a bunch of time cleaning up the grenade summary log so in
> the console you get some basic idea of what's going on, and what part
> you failed in. Definitely could be better. Taking some of those summary
> lessons into devstack wouldn't hurt either.

I don't think I've hit a grenade issue, so I haven’t seen that.

> So patches here are definitely accepted. Which is very much not a blow
> off, but in cleaning d-g up over the last 6 months “the setup for this

Yep, I’m asking if I’m even thinking in the right directions, and that sounds 
like a “yes” rather than a blow off.

> job failed, check the appropriate log” was about as good as we could
> figure out. Previously the script just died and people usually blamed an
> error message about uploading artifacts in the jenkins output for the
> failure. So if you can figure out a better UX given the constraints
> we're in, definitely appreciated.

I’ll look at the job definitions and see if I can come up with a way to 
parameterize them or automate the step of figuring out which file is meant for 
each phase.

>>>>> If nothing jumps out at ERROR or TRACE, go back to DEBUG level and
>>>>> figure out what's happening at the time of failure, especially keeping
>>>>> an eye out of areas where other workers are doing interesting things at
>>>>> the same time, possibly indicating state corruption in OpenStack as a 
>>>>> race.
>>>>> #3 - if it's a console failure, start at the end and work backwards
>>>>> devstack and grenade run under set -o errexit so that they will
>>>>> critically exit if a command fails. They will typically dump some debug
>>>>> when they do that. So the failing command won't be the last line in the
>>>>> file, but it will be close. The words 'error' typically aren't useful at
>>>>> all in shell because lots of things say error when they aren't, we mask
>>>>> their exit codes if their failure is generally irrelevant.
>>>>> #4 - general principle the closer to root cause the better
>>>>> If we think of exposure of bugs as layers we probably end up
>>>>> withsomething like this
>>>>> - Console log
>>>>> - Test Name + Failure
>>>>> - Failure inside an API service
>>>>> - Failure inside a worker process
>>>>> - Actual failure figured out in OpenStack code path
>>>>> - Failure in something below OpenStack (kernel, libvirt)
>>>>> This is why signatures that are just test names aren't all that useful
>>>>> much of the time (and why we try not to add those to ER), as that's
>>>>> going to be hitting an API, but the why of things is very much still
>>>>> undiscovered.
>>>>> #5 - if it's an infrastructure level setup bug (failing to download or
>>>>> install something) figure out if there are other likewise events at the
>>>>> same time (i.e. it's a network issue, which we can't fix) vs. a
>>>>> structural issue.
>>>>> I find Elastic Search good for step 5, but realistically for all other
>>>>> steps it's manual log sifting. I open lots of tabs in Chrome, and search
>>>>> by timestamp.
>>>> This feels like something we could improve on. If we had a tool to 
>>>> download the logs and interleave the messages using their timestamps, 
>>>> would that make it easier? We could probably make the job log everything 
>>>> to a single file, but I can see where sometimes only having part of the 
>>>> data to look at would be more useful.
>>> Maybe, I find the ability to change the filtering level dynamically to
>>> be pretty important. We actually did some of this once when we used
>>> syslog. Personally I found it a ton harder to get to the bottom of things.
>>> A gate run has 25+ services running, it's a rare issue that combines
>>> interactions between > 4 of them to get to a solution. So I expect you'd
>>> exchange context jumping, for tons of irrelevancy. That's a personal
>>> opinion based on personal workflow, and why I never spent time on it.
>>> Instead I built os-loganalyze that does the filtering and coloring
>>> dynamically on the server side, as it was a zero install solution that
>>> provided additional benefits of being able to link to a timestamp in a
>>> log for sharing purposes.
>> Sure, that makes sense.
>>>>> A big part of the experience also just comes from a manual bayesian
>>>>> filter. Certain scary looking things in the console log aren't, but you
>>>>> don't know that unless you look at setup logs enough (either in gate or
>>>>> in your own devstacks) to realize that. Sanitizing the output of that
>>>>> part of the process is pretty intractable... because shell (though I've
>>>>> put some serious effort into it over the last 6 months).
>>>> Maybe our scripts can emit messages to explain the scary stuff? “This is 
>>>> going to report a problem, but you can ignore it unless X happens.”?
>>> Maybe, like I said it's a lot better than it used to be. But very few
>>> people are putting in effort here, and I'm not convinced it's really
>>> solveable in bash.
>> OK, well, if the answers to these questions are “yes” then I should have 
>> time to help, which is why I’m exploring options.
> Yeh, the issue is you'd need a couple hundred different messages like
> that, and realistically I think they'd lead to more confusion rather
> than less.
> Honestly, I did a huge amount of selective filtering out of xtrace logs
> in the last six months and was able to drop the size of the devstack
> logs by over 50% getting rid of some of the more confusing trace bits.
> But it's something that you make progress on 1% at a time.
> At some point we do need to say "you have to understand OpenStack and
> the Test run process ^this much^ to be able to ride", because cleaning
> up every small thing isn't really possible.
> Now, providing a better flow explaining the parts here might be good. We
> do it during Infra bootcamps, and people find it helpful. But again,
> that's a mostly pull model because the people showing up did so
> specifically to learn, so are much more receptive to gaining the
> information at hand.
>>>>> Sanitizing the OpenStack logs to be crisp about actual things going
>>>>> wrong, vs. not, shouldn't be intractable, but it feels like it some
>>>>> times. Which is why all operators run at DEBUG level. The thing that
>>>>> makes it hard for developers to see the issues here is the same thing
>>>>> that makes it *really* hard for operators to figure out failures. It's
>>>>> also why I tried (though executed poorly on, sorry about that) getting
>>>>> log cleanups rolling this cycle.
>>>> I would like to have the TC back an official cross-project effort to clean 
>>>> up the logs for Kilo, and get all of the integrated projects to commit to 
>>>> working on it as a priority.
>>>> Doug
>>>>>   -Sean
>>>>> -- 
>>>>> Sean Dague
>>>>> http://dague.net
>>>>> _______________________________________________
>>>>> OpenStack-dev mailing list
>>>>> OpenStack-dev@lists.openstack.org
>>>>> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
>>>> _______________________________________________
>>>> OpenStack-dev mailing list
>>>> OpenStack-dev@lists.openstack.org
>>>> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
>>> -- 
>>> Sean Dague
>>> http://dague.net
>>> _______________________________________________
>>> OpenStack-dev mailing list
>>> OpenStack-dev@lists.openstack.org
>>> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
>> _______________________________________________
>> OpenStack-dev mailing list
>> OpenStack-dev@lists.openstack.org
>> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev
> -- 
> Sean Dague
> http://dague.net
> _______________________________________________
> OpenStack-dev mailing list
> OpenStack-dev@lists.openstack.org
> http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev

OpenStack-dev mailing list

Reply via email to