<div dir="ltr"><br><div class="gmail_extra"><br><br><div class="gmail_quote">On Thu, Aug 28, 2014 at 10:17 AM, Sean Dague <span dir="ltr"><<a href="mailto:sean@dague.net" target="_blank">sean@dague.net</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div class=""><div class="h5">On 08/28/2014 12:48 PM, Doug Hellmann wrote:<br>
><br>
> On Aug 27, 2014, at 5:56 PM, Sean Dague <<a href="mailto:sean@dague.net">sean@dague.net</a>> wrote:<br>
><br>
>> On 08/27/2014 05:27 PM, Doug Hellmann wrote:<br>
>>><br>
>>> On Aug 27, 2014, at 2:54 PM, Sean Dague <<a href="mailto:sean@dague.net">sean@dague.net</a>> wrote:<br>
>>><br>
>>>> Note: thread intentionally broken, this is really a different topic.<br>
>>>><br>
>>>> On 08/27/2014 02:30 PM, Doug Hellmann wrote:><br>
>>>>> On Aug 27, 2014, at 1:30 PM, Chris Dent <<a href="mailto:chdent@redhat.com">chdent@redhat.com</a>> wrote:<br>
>>>>><br>
>>>>>> On Wed, 27 Aug 2014, Doug Hellmann wrote:<br>
>>>>>><br>
>>>>>>> I have found it immensely helpful, for example, to have a written set<br>
>>>>>>> of the steps involved in creating a new library, from importing the<br>
>>>>>>> git repo all the way through to making it available to other projects.<br>
>>>>>>> Without those instructions, it would have been much harder to split up<br>
>>>>>>> the work. The team would have had to train each other by word of<br>
>>>>>>> mouth, and we would have had constant issues with inconsistent<br>
>>>>>>> approaches triggering different failures. The time we spent building<br>
>>>>>>> and verifying the instructions has paid off to the extent that we even<br>
>>>>>>> had one developer not on the core team handle a graduation for us.<br>
>>>>>><br>
>>>>>> +many more for the relatively simple act of just writing stuff down<br>
>>>>><br>
>>>>> "Write it down.” is my theme for Kilo.<br>
>>>><br>
>>>> I definitely get the sentiment. "Write it down" is also hard when you<br>
>>>> are talking about things that do change around quite a bit. OpenStack as<br>
>>>> a whole sees 250 - 500 changes a week, so the interaction pattern moves<br>
>>>> around enough that it's really easy to have *very* stale information<br>
>>>> written down. Stale information is even more dangerous than no<br>
>>>> information some times, as it takes people down very wrong paths.<br>
>>>><br>
>>>> I think we break down on communication when we get into a conversation<br>
>>>> of "I want to learn gate debugging" because I don't quite know what that<br>
>>>> means, or where the starting point of understanding is. So those<br>
>>>> intentions are well meaning, but tend to stall. The reality was there<br>
>>>> was no road map for those of us that dive in, it's just understanding<br>
>>>> how OpenStack holds together as a whole and where some of the high risk<br>
>>>> parts are. And a lot of that comes with days staring at code and logs<br>
>>>> until patterns emerge.<br>
>>>><br>
>>>> Maybe if we can get smaller more targeted questions, we can help folks<br>
>>>> better? I'm personally a big fan of answering the targeted questions<br>
>>>> because then I also know that the time spent exposing that information<br>
>>>> was directly useful.<br>
>>>><br>
>>>> I'm more than happy to mentor folks. But I just end up finding the "I<br>
>>>> want to learn" at the generic level something that's hard to grasp onto<br>
>>>> or figure out how we turn it into action. I'd love to hear more ideas<br>
>>>> from folks about ways we might do that better.<br>
>>><br>
>>> 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.<br>
>>><br>
>>> 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?<br>
>>><br>
>>> 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.<br>
>><br>
>> Sure. Matt's actually working up a blog post describing the thing he<br>
>> nailed earlier in the week.<br>
><br>
> Yes, I appreciate that both of you are responding to my questions. :-)<br>
><br>
> 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.<br>
><br>
>><br>
>> Here is my off the cuff set of guidelines:<br>
>><br>
>> #1 - is it a test failure or a setup failure<br>
>><br>
>> This should be pretty easy to figure out. Test failures come at the end<br>
>> of console log and say that tests failed (after you see a bunch of<br>
>> passing tempest tests).<br>
>><br>
>> Always start at *the end* of files and work backwards.<br>
><br>
> 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?<br>
<br>
</div></div>Bottom up to get to problems, then figure out if it's in a subprocess so<br>
the problems could exist for a while. That being said, not all tools do<br>
useful things like actually error when they fail (I'm looking at you<br>
yum....) so there are always edge cases here.<br>
<div class=""><br>
>><br>
>> #2 - if it's a test failure, what API call was unsuccessful.<br>
>><br>
>> Start with looking at the API logs for the service at the top level, and<br>
>> see if there is a simple traceback at the right timestamp. If not,<br>
>> figure out what that API call was calling out to, again look at the<br>
>> simple cases assuming failures will create ERRORS or TRACES (though they<br>
>> often don't).<br>
><br>
> 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?<br>
<br>
</div>Yeh... service naming could definitely be better, especially with<br>
neutron. There are implications for long names in screen, but maybe we<br>
just get over it as we already have too many tabs to be in one page in<br>
the console anymore anyway.<br>
<div class=""><br>
>> Hints on the service log order you should go after are on the footer<br>
>> over every log page -<br>
>> <a href="http://logs.openstack.org/76/79776/15/gate/gate-tempest-dsvm-full/700ee7e/logs/" target="_blank">http://logs.openstack.org/76/79776/15/gate/gate-tempest-dsvm-full/700ee7e/logs/</a><br>
>> (it's included as an Apache footer) for some services. It's been there<br>
>> for about 18 months, I think people are fully blind to it at this point.<br>
><br>
> 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?<br>
<br>
</div>Note the following at the end of the footer output:<br>
<br>
About this Help<br>
<br>
This help file is part of the openstack-infra/config project, and can be<br>
found at modules/openstack_project/files/logs/help/tempest_logs.html .<br>
The file can be updated via the standard OpenStack Gerrit Review process.<br></blockquote><div><br></div><div>I took a first whack at trying to add some more information to the footer here: <a href="https://review.openstack.org/#/c/117390/">https://review.openstack.org/#/c/117390/</a></div>
<div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<div class=""><br>
> 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.<br>
<br>
</div>Part of the issue here is that devstack-gate runs a lot of different<br>
gate_hooks. So that's about as specific as we can get unless you can<br>
figure out how to introspect that info in bash... which I couldn't.<br>
<div><div class="h5"><br>
>> If nothing jumps out at ERROR or TRACE, go back to DEBUG level and<br>
>> figure out what's happening at the time of failure, especially keeping<br>
>> an eye out of areas where other workers are doing interesting things at<br>
>> the same time, possibly indicating state corruption in OpenStack as a race.<br>
>><br>
>> #3 - if it's a console failure, start at the end and work backwards<br>
>><br>
>> devstack and grenade run under set -o errexit so that they will<br>
>> critically exit if a command fails. They will typically dump some debug<br>
>> when they do that. So the failing command won't be the last line in the<br>
>> file, but it will be close. The words 'error' typically aren't useful at<br>
>> all in shell because lots of things say error when they aren't, we mask<br>
>> their exit codes if their failure is generally irrelevant.<br>
>><br>
>> #4 - general principle the closer to root cause the better<br>
>><br>
>> If we think of exposure of bugs as layers we probably end up<br>
>> withsomething like this<br>
>><br>
>> - Console log<br>
>> - Test Name + Failure<br>
>> - Failure inside an API service<br>
>> - Failure inside a worker process<br>
>> - Actual failure figured out in OpenStack code path<br>
>> - Failure in something below OpenStack (kernel, libvirt)<br>
>><br>
>> This is why signatures that are just test names aren't all that useful<br>
>> much of the time (and why we try not to add those to ER), as that's<br>
>> going to be hitting an API, but the why of things is very much still<br>
>> undiscovered.<br>
>><br>
>> #5 - if it's an infrastructure level setup bug (failing to download or<br>
>> install something) figure out if there are other likewise events at the<br>
>> same time (i.e. it's a network issue, which we can't fix) vs. a<br>
>> structural issue.<br>
>><br>
>><br>
>> I find Elastic Search good for step 5, but realistically for all other<br>
>> steps it's manual log sifting. I open lots of tabs in Chrome, and search<br>
>> by timestamp.<br>
><br>
> 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.<br>
<br>
</div></div>Maybe, I find the ability to change the filtering level dynamically to<br>
be pretty important. We actually did some of this once when we used<br>
syslog. Personally I found it a ton harder to get to the bottom of things.<br>
<br>
A gate run has 25+ services running, it's a rare issue that combines<br>
interactions between > 4 of them to get to a solution. So I expect you'd<br>
exchange context jumping, for tons of irrelevancy. That's a personal<br>
opinion based on personal workflow, and why I never spent time on it.<br>
Instead I built os-loganalyze that does the filtering and coloring<br>
dynamically on the server side, as it was a zero install solution that<br>
provided additional benefits of being able to link to a timestamp in a<br>
log for sharing purposes.<br>
<div class=""><br>
><br>
>><br>
>><br>
>> A big part of the experience also just comes from a manual bayesian<br>
>> filter. Certain scary looking things in the console log aren't, but you<br>
>> don't know that unless you look at setup logs enough (either in gate or<br>
>> in your own devstacks) to realize that. Sanitizing the output of that<br>
>> part of the process is pretty intractable... because shell (though I've<br>
>> put some serious effort into it over the last 6 months).<br>
><br>
> 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.”?<br>
<br>
</div>Maybe, like I said it's a lot better than it used to be. But very few<br>
people are putting in effort here, and I'm not convinced it's really<br>
solveable in bash.<br>
<div class=""><div class="h5"><br>
>> Sanitizing the OpenStack logs to be crisp about actual things going<br>
>> wrong, vs. not, shouldn't be intractable, but it feels like it some<br>
>> times. Which is why all operators run at DEBUG level. The thing that<br>
>> makes it hard for developers to see the issues here is the same thing<br>
>> that makes it *really* hard for operators to figure out failures. It's<br>
>> also why I tried (though executed poorly on, sorry about that) getting<br>
>> log cleanups rolling this cycle.<br>
><br>
> 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.<br>
><br>
> Doug<br>
><br>
>><br>
>> -Sean<br>
>><br>
>> --<br>
>> Sean Dague<br>
>> <a href="http://dague.net" target="_blank">http://dague.net</a><br>
>><br>
>> _______________________________________________<br>
>> OpenStack-dev mailing list<br>
>> <a href="mailto:OpenStack-dev@lists.openstack.org">OpenStack-dev@lists.openstack.org</a><br>
>> <a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev</a><br>
><br>
><br>
> _______________________________________________<br>
> OpenStack-dev mailing list<br>
> <a href="mailto:OpenStack-dev@lists.openstack.org">OpenStack-dev@lists.openstack.org</a><br>
> <a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev</a><br>
><br>
<br>
<br>
--<br>
Sean Dague<br>
<a href="http://dague.net" target="_blank">http://dague.net</a><br>
<br>
_______________________________________________<br>
OpenStack-dev mailing list<br>
<a href="mailto:OpenStack-dev@lists.openstack.org">OpenStack-dev@lists.openstack.org</a><br>
<a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack-dev</a><br>
</div></div></blockquote></div><br></div></div>